Hi, I've already tried to answer a similar question some time ago (and I'm probably not the only one) but anyways... The cause of the problems probably is some delay or packet loss or something like that. Notice the Acct-Delay-Time value increasing as the NAS retries to send the "lost" accounting packet (although - at least in my case - it wasn't lost but just its processing was delayed). I've experienced such issues with Cisco VoIP routers - the router's log is flooded with RADIUS Server DEAD - and then ... ALIVE messages and in the FR log you can see the retries with the values of Acct-Delay-Time increasing. The main cause of the problem may be different, so you'll have to check it in your case. In my case it was caused by the thread pool settings not being appropriate for the load. In this case the CPU usage stays low but it's not used because you cannot achieve good concurrency and request have to await each other to finish. So find the main cause for your problems and eliminate it. The other thing is that most NASs have options to configure the RADIUS timeout, dead, retransmit etc times. E.g.for Cisco you could try "radius-server retransmit 0". On 28.05.2009, at 10:53, lamersons wrote:
Hello there, i have posted here few times and got very helpfull answers, so i desided to try my luck once more.
Im using FreeRADIUS Version 2.0.4(slackware+postgre) on powerfull x86 server with alot of RAM, connected with gigabit to NAS. Load is about 5-15record/sec
Once in a while we get double accounting records. I started to take traces at NAS side and saw that sometimes AAA doesnt responce to accounting record, NAS thinks that AAA didnt get it and sends it one more time. But AAA gets the first one even if it doesnt responce to request, therefore we get double record.(debug info is below)
I have made debug trace at AAA side. Is it somehow possible to see from that trace that AAA did respond and that is NASes(or network) problem that it did not recieve responce ?(debug info is below)
p.s. ------------------------------------------------------------------- I sent information to NAS vendor: Dear,
Yesterday at 02:27:38 PDSN sent the "Accounting request start" message and then PDSN sent the same Accounting request start massage at 02:27:43 (see in traces of PI interface).
Thanks Best regards,
They answered me: • The AAA can’t start the new accounting session, until it stops the first one, so the AAA doesn’t reply to the Accounting Request Start. • The PDSN wait for TIMEOUT which is 5 seconds, and resend the Accounting message again. • When the PDSN resend the Accounting message, the AAA replies to it. -----------------------------------------------------------------------
########################### First start record : request 11309
Acct-Status-Type = Start User-Name = "triatel@triatel.lv" Calling-Station-Id = "247033715823092" Framed-IP-Address = 192.168.172.128 NAS-IP-Address = 192.168.145.1 Event-Timestamp = "Jul 18 2008 02:27:39 EEST" Acct-Session-Id = "0000000\000" NAS-Port-Type = Virtual NAS-Port = 1813 Acct-Delay-Time = 0 Service-Type = Framed-User Acct-Authentic = RADIUS 3GPP2-ESN = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000" 3GPP2-Attr-116 = 0x0000000000000000000000000000 3GPP2-Correlation-Id = "17934924" 3GPP2-Service-Reference-Id = 0x0104000102040001 3GPP2-Home-Agent-IP-Address = 0.0.0.0 3GPP2-PCF-IP-Address = 129.11.17.230 3GPP2-BSID = "2A2100021102" 3GPP2-User-Id = 0 3GPP2-Forward-FCH-Mux-Option = 0 3GPP2-Reverse-FCH-Mux-Option = 0 3GPP2-Service-Option = 59 3GPP2-Forward-Traffic-Type = 0 3GPP2-Reverse-Traffic-Type = 0 3GPP2-FCH-Frame-Size = 0 3GPP2-Forward-FCH-RC = 0 3GPP2-Reverse-FCH-RC = 0 3GPP2-IP-Technology = 1 3GPP2-Compulsory-Tunnel-Indicator = 0 3GPP2-DCCH-Frame-Size = 0 3GPP2-Attr-78 = 0x00000000 3GPP2-Forward-PDCH-RC = 0 3GPP2-Forward-DCCH-Mux-Option = 0 3GPP2-Reverse-DCCH-Mux-Option = 0 3GPP2-Forward-DCCH-RC = 0 3GPP2-Reverse-DHHC-RC = 0 3GPP2-Attr-114 = 0x00000000 3GPP2-IP-QoS = 10 3GPP2-Airlink-Priority = 0 +- entering group preacct rlm_realm: Looking up realm "triatel.lv" for User-Name = "triatel@triatel.lv" rlm_realm: No such realm "triatel.lv" ++[suffix] returns noop +- entering group accounting rlm_acct_unique: Hashing '3GPP2-Correlation-Id = "17934924",Acct- Session-Id = "0000000\000",Calling-Station-Id = "247033715823092"' rlm_acct_unique: Acct-Unique-Session-ID = "33187f91caa26b34". ++[acct_unique] returns ok expand: %{User-Name} -> triatel@triatel.lv rlm_sql (sql): sql_set_user escaped user --> 'triatel@triatel.lv' expand: INSERT into radacct (AcctSessionId, AcctUniqueId, CallingStationId, AcctStartTime, AcctStopTime, CDMAActiveTime, AcctInputOctets, AcctOutputOctets, FramedIPAddress, UserName, ReleaseIndicator, CDMABadPPPFrameCount, CDMACorrelationId, AcctSessionTime, NASIPAddress) values('%{Acct-Session-Id}', '%{Acct-Unique-Session- Id}', '%{Calling-Station-Id}', '%{Event-Timestamp}', NULL,'0', '0', '0', '%{Framed-IP-Address}', trim('%{SQL-User-Name}'), '0', '0', '%{3GPP2-Correlation-Id}', '0', '%{NAS-IP-Address}') -> INSERT into radacct (AcctSessionId, AcctUniqueId, CallingStationId, AcctStartTime, AcctStopTime, CDMAActiveTime, AcctInputOctets, AcctOutputOctets, FramedIPAddress, UserName, ReleaseIndicator, CDMABadPPPFrameCount, CDMACorrelationId, AcctSessionTime, NASIPAddress) values('0000000', '33187f91caa26b34', '247033715823092', 'Jul 18 2008 02:27:39 EEST', NULL,'0', '0', '0', '192.168.172.128', trim('triatel@triatel.lv'), '0', '0', '17934924', '0', '192.168.145.1') rlm_sql (sql): Reserving sql socket id: 18 rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 1 rlm_sql (sql): Released sql socket id: 18 ++[sql] returns ok Finished request 11309. Cleaning up request 11309 ID 18 with timestamp +769 Going to the next request
##################### second Start record : request 11380
Acct-Status-Type = Start User-Name = "triatel@triatel.lv" Calling-Station-Id = "247033715823092" Framed-IP-Address = 192.168.172.128 NAS-IP-Address = 192.168.145.1 Event-Timestamp = "Jul 18 2008 02:27:39 EEST" Acct-Session-Id = "0000000\000" NAS-Port-Type = Virtual NAS-Port = 1813 Acct-Delay-Time = 5 Service-Type = Framed-User Acct-Authentic = RADIUS 3GPP2-ESN = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000" 3GPP2-Attr-116 = 0x0000000000000000000000000000 3GPP2-Correlation-Id = "17934924" 3GPP2-Service-Reference-Id = 0x0104000102040001 3GPP2-Home-Agent-IP-Address = 0.0.0.0 3GPP2-PCF-IP-Address = 129.11.17.230 3GPP2-BSID = "2A2100021102" 3GPP2-User-Id = 0 3GPP2-Forward-FCH-Mux-Option = 0 3GPP2-Reverse-FCH-Mux-Option = 0 3GPP2-Service-Option = 59 3GPP2-Forward-Traffic-Type = 0 3GPP2-Reverse-Traffic-Type = 0 3GPP2-FCH-Frame-Size = 0 3GPP2-Forward-FCH-RC = 0 3GPP2-Reverse-FCH-RC = 0 3GPP2-IP-Technology = 1 3GPP2-Compulsory-Tunnel-Indicator = 0 3GPP2-DCCH-Frame-Size = 0 3GPP2-Attr-78 = 0x00000000 3GPP2-Forward-PDCH-RC = 0 3GPP2-Forward-DCCH-Mux-Option = 0 3GPP2-Reverse-DCCH-Mux-Option = 0 3GPP2-Forward-DCCH-RC = 0 3GPP2-Reverse-DHHC-RC = 0 3GPP2-Attr-114 = 0x00000000 3GPP2-IP-QoS = 10 3GPP2-Airlink-Priority = 0 +- entering group preacct rlm_realm: Looking up realm "triatel.lv" for User-Name = "triatel@triatel.lv" rlm_realm: No such realm "triatel.lv" ++[suffix] returns noop +- entering group accounting rlm_acct_unique: Hashing '3GPP2-Correlation-Id = "17934924",Acct- Session-Id = "0000000\000",Calling-Station-Id = "247033715823092"' rlm_acct_unique: Acct-Unique-Session-ID = "33187f91caa26b34". ++[acct_unique] returns ok expand: %{User-Name} -> triatel@triatel.lv rlm_sql (sql): sql_set_user escaped user --> 'triatel@triatel.lv' expand: INSERT into radacct (AcctSessionId, AcctUniqueId, CallingStationId, AcctStartTime, AcctStopTime, CDMAActiveTime, AcctInputOctets, AcctOutputOctets, FramedIPAddress, UserName, ReleaseIndicator, CDMABadPPPFrameCount, CDMACorrelationId, AcctSessionTime, NASIPAddress) values('%{Acct-Session-Id}', '%{Acct-Unique-Session- Id}', '%{Calling-Station-Id}', '%{Event-Timestamp}', NULL,'0', '0', '0', '%{Framed-IP-Address}', trim('%{SQL-User-Name}'), '0', '0', '%{3GPP2-Correlation-Id}', '0', '%{NAS-IP-Address}') -> INSERT into radacct (AcctSessionId, AcctUniqueId, CallingStationId, AcctStartTime, AcctStopTime, CDMAActiveTime, AcctInputOctets, AcctOutputOctets, FramedIPAddress, UserName, ReleaseIndicator, CDMABadPPPFrameCount, CDMACorrelationId, AcctSessionTime, NASIPAddress) values('0000000', '33187f91caa26b34', '247033715823092', 'Jul 18 2008 02:27:39 EEST', NULL,'0', '0', '0', '192.168.172.128', trim('triatel@triatel.lv'), '0', '0', '17934924', '0', '192.168.145.1') rlm_sql (sql): Reserving sql socket id: 43 rlm_sql_postgresql: Status: PGRES_FATAL_ERROR rlm_sql_postgresql: Error duplicate key value violates unique constraint "radacct_acctuniqueid" rlm_sql_postgresql: Postgresql Fatal Error: [23505: UNIQUE VIOLATION] Occurred!! rlm_sql (sql): Couldn't insert SQL accounting START record - ERROR: duplicate key value violates unique constraint "radacct_acctuniqueid" expand: -> rlm_sql (sql): Released sql socket id: 43 ++[sql] returns ok Finished request 11380.
############################## Interim record ################### Ready to process requests. Acct-Status-Type = Interim-Update User-Name = "triatel@triatel.lv" Calling-Station-Id = "247033715823092" Framed-IP-Address = 192.168.172.128 NAS-IP-Address = 192.168.145.1 Event-Timestamp = "Jul 18 2008 02:42:39 EEST" Acct-Session-Id = "0000000\000" NAS-Port-Type = Virtual NAS-Port = 1813 Acct-Delay-Time = 0 Acct-Session-Time = 900 Acct-Output-Octets = 0 Acct-Input-Octets = 0 Acct-Input-Packets = 0 Acct-Output-Packets = 0 Acct-Multi-Session-Id = "17934924" Service-Type = Framed-User Acct-Authentic = RADIUS 3GPP2-ESN = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000" 3GPP2-Attr-116 = 0x0000000000000000000000000000 3GPP2-Correlation-Id = "17934924" 3GPP2-Session-Continue = 1 3GPP2-Service-Reference-Id = 0x0104000102040001 3GPP2-Home-Agent-IP-Address = 0.0.0.0 3GPP2-PCF-IP-Address = 129.11.17.230 3GPP2-BSID = "2A2100021102" 3GPP2-User-Id = 0 3GPP2-Forward-FCH-Mux-Option = 0 3GPP2-Reverse-FCH-Mux-Option = 0 3GPP2-Service-Option = 59 3GPP2-Forward-Traffic-Type = 0 3GPP2-Reverse-Traffic-Type = 0 3GPP2-FCH-Frame-Size = 0 3GPP2-Forward-FCH-RC = 0 3GPP2-Reverse-FCH-RC = 0 3GPP2-IP-Technology = 1 3GPP2-Compulsory-Tunnel-Indicator = 0 3GPP2-DCCH-Frame-Size = 0 3GPP2-Attr-78 = 0x00000000 3GPP2-Forward-PDCH-RC = 0 3GPP2-Forward-DCCH-Mux-Option = 0 3GPP2-Reverse-DCCH-Mux-Option = 0 3GPP2-Forward-DCCH-RC = 0 3GPP2-Reverse-DHHC-RC = 0 3GPP2-Attr-114 = 0x00000000 3GPP2-Bad-PPP-Frame-Count = 0 3GPP2-Active-Time = 33 3GPP2-Number-Active-Transitions = 0 3GPP2-Received-HDLC-Octets = 0 3GPP2-Inbound-Mobile-IP-Sig-Octets = 0 3GPP2-Outbound-Mobile-IP-Sig-Octets = 0 3GPP2-Last-User-Activity-Time = 1216337292 3GPP2-IP-QoS = 10 3GPP2-Airlink-Priority = 0 +- entering group preacct rlm_realm: Looking up realm "triatel.lv" for User-Name = "triatel@triatel.lv" rlm_realm: No such realm "triatel.lv" ++[suffix] returns noop +- entering group accounting rlm_acct_unique: Hashing '3GPP2-Correlation-Id = "17934924",Acct- Session-Id = "0000000\000",Calling-Station-Id = "247033715823092"' rlm_acct_unique: Acct-Unique-Session-ID = "33187f91caa26b34". ++[acct_unique] returns ok expand: %{User-Name} -> triatel@triatel.lv rlm_sql (sql): sql_set_user escaped user --> 'triatel@triatel.lv' expand: -> rlm_sql (sql): Reserving sql socket id: 2 rlm_sql (sql): Released sql socket id: 2 ++[sql] returns ok Finished request 21837. ##########################################STOP record ##########
Acct-Status-Type = Stop User-Name = "triatel@triatel.lv" Calling-Station-Id = "247033715823092" Framed-IP-Address = 192.168.172.128 NAS-IP-Address = 192.168.145.1 Event-Timestamp = "Jul 18 2008 02:43:01 EEST" Acct-Session-Id = "0000000\000" NAS-Port-Type = Virtual NAS-Port = 1813 Acct-Delay-Time = 0 Acct-Session-Time = 922 Acct-Output-Octets = 0 Acct-Input-Octets = 0 Acct-Input-Packets = 0 Acct-Output-Packets = 0 Acct-Terminate-Cause = Idle-Timeout Acct-Multi-Session-Id = "17934924" Service-Type = Framed-User Acct-Authentic = RADIUS 3GPP2-ESN = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000" 3GPP2-Attr-116 = 0x0000000000000000000000000000 3GPP2-Correlation-Id = "17934924" 3GPP2-Session-Continue = 0 3GPP2-Service-Reference-Id = 0x0104000102040001 3GPP2-Home-Agent-IP-Address = 0.0.0.0 3GPP2-PCF-IP-Address = 129.11.17.230 3GPP2-BSID = "2A2100021102" 3GPP2-User-Id = 0 3GPP2-Forward-FCH-Mux-Option = 0 3GPP2-Reverse-FCH-Mux-Option = 0 3GPP2-Service-Option = 59 3GPP2-Forward-Traffic-Type = 0 3GPP2-Reverse-Traffic-Type = 0 3GPP2-FCH-Frame-Size = 0 3GPP2-Forward-FCH-RC = 0 3GPP2-Reverse-FCH-RC = 0 3GPP2-IP-Technology = 1 3GPP2-Compulsory-Tunnel-Indicator = 0 3GPP2-Release-Indicator = 7 3GPP2-DCCH-Frame-Size = 0 3GPP2-Attr-78 = 0x00000000 3GPP2-Forward-PDCH-RC = 0 3GPP2-Forward-DCCH-Mux-Option = 0 3GPP2-Reverse-DCCH-Mux-Option = 0 3GPP2-Forward-DCCH-RC = 0 3GPP2-Reverse-DHHC-RC = 0 3GPP2-Attr-114 = 0x00000000 3GPP2-Bad-PPP-Frame-Count = 0 3GPP2-Active-Time = 33 3GPP2-Number-Active-Transitions = 0 3GPP2-Received-HDLC-Octets = 0 3GPP2-Inbound-Mobile-IP-Sig-Octets = 0 3GPP2-Outbound-Mobile-IP-Sig-Octets = 0 3GPP2-Last-User-Activity-Time = 1216337292 3GPP2-IP-QoS = 10 3GPP2-Airlink-Priority = 0 +- entering group preacct rlm_realm: Looking up realm "triatel.lv" for User-Name = "triatel@triatel.lv" rlm_realm: No such realm "triatel.lv" ++[suffix] returns noop +- entering group accounting rlm_acct_unique: Hashing '3GPP2-Correlation-Id = "17934924",Acct- Session-Id = "0000000\000",Calling-Station-Id = "247033715823092"' rlm_acct_unique: Acct-Unique-Session-ID = "33187f91caa26b34". ++[acct_unique] returns ok expand: %{User-Name} -> triatel@triatel.lv rlm_sql (sql): sql_set_user escaped user --> 'triatel@triatel.lv' expand: UPDATE radacct SET AcctStopTime = '%{Event-Timestamp}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', OutputPacket = '%{Acct-Output-Packets}', InputPacket = '%{Acct-Input-Packets}', AcctOutputOctets = '%{Acct-Output-Octets}', ReleaseIndicator = '%{Acct-Terminate-Cause}', CDMABadPPPFrameCount = '%{3GPP2-Bad-PPP-Frame-Count}', CDMACorrelationId = '%{3GPP2-Correlation-Id}', CDMAActiveTime = '%{3GPP2-Active-Time}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' -> UPDATE radacct SET AcctStopTime = 'Jul 18 2008 02:43:01 EEST', AcctSessionTime = '922', AcctInputOctets = '0', OutputPacket = '0', InputPacket = '0', AcctOutputOctets = '0', ReleaseIndicator = 'Idle-Timeout', CDMABadPPPFrameCount = '0', CDMACorrelationId = '17934924', CDMAActiveTime = '33' WHERE AcctUniqueId = '33187f91caa26b34' rlm_sql (sql): Reserving sql socket id: 25 rlm_sql_postgresql: Status: PGRES_COMMAND_OK rlm_sql_postgresql: query affected rows = 1 rlm_sql (sql): Released sql socket id: 25 ++[sql] returns ok Finished request 22102.
-- View this message in context: http://www.nabble.com/Accounting-responce-question.-tp23756895p23756895.html Sent from the FreeRadius - User mailing list archive at Nabble.com.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html