Accounting responce question.

lamersons m at baltia.net
Thu May 28 09:53:20 CEST 2009


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.





More information about the Freeradius-Users mailing list