Accounting responce question.
Borislav Dimitrov
b.dimitrov at ngsystems.net
Thu May 28 11:23:57 CEST 2009
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 at 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 at 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 at triatel.lv
> rlm_sql (sql): sql_set_user escaped user --> 'triatel at 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 at 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 at 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 at 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 at triatel.lv
> rlm_sql (sql): sql_set_user escaped user --> 'triatel at 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 at 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 at 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 at 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 at triatel.lv
> rlm_sql (sql): sql_set_user escaped user --> 'triatel at 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 at 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 at 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 at triatel.lv
> rlm_sql (sql): sql_set_user escaped user --> 'triatel at 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
More information about the Freeradius-Users
mailing list