Hi, please help me out why I am getting two entries in mysql table (radacct) for outgoing call. If the call is answered I get two entries and one entry if the call is not answered (this is ok). Reason that I am asking this is that I do not see that my NAS is sending two start packet and to stop packet for answered call (you can see below). Please help me out understand why radius add two entries for stop packet if only one is send from NAS. 1. Call is not answered. 3126.504593 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS Accounting-Request(4) (id=192, l=265) 3126.506361 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS Accounting-Response(5) (id=192, l=20) 3128.512626 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS Access-Request(1) (id=193, l=61) 3128.514192 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS Access-Accept(2) (id=193, l=20) 3135.215365 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS Accounting-Request(4) (id=194, l=362) 3135.217317 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS Accounting-Response(5) (id=194, l=20) 2. Call is answered. 3142.992787 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS Accounting-Request(4) (id=195, l=265) 3142.994570 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS Accounting-Response(5) (id=195, l=20) 3145.001503 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS Access-Request(1) (id=196, l=61) 3145.003161 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS Access-Accept(2) (id=196, l=20) 3154.440904 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS Accounting-Request(4) (id=197, l=401) 3154.443202 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS Accounting-Response(5) (id=197, l=20) Bellow I am pasting only radius log for answered call. rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx port 48752, id=198, length=265 Acct-Status-Type = Start Acct-Session-Id = "d446d20a-6d1c-4ffd-9b59-1aedbf63b74c" User-Name = "123456789" Freeswitch-Src = "123456789" Freeswitch-CLID = "123456789" Freeswitch-Dst = "051357952" Freeswitch-Dialplan = "XML" Framed-IP-Address = zzz.zzz.zzz.zzz Freeswitch-Context = "default" Freeswitch-Ani = "123456789" Freeswitch-Source = "mod_sofia" Freeswitch-Callstartdate = "2011-12-20T09:49:22.535428+0100" NAS-Port = 0 Acct-Delay-Time = 0 NAS-IP-Address = xxx.xxx.xxx.xxx # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address = xxx.xxx.xxx.xxx,NAS-IP-Address = xxx.xxx.xxx.xxx,Acct-Session-Id = "d446d20a-6d1c-4ffd-9b59-1aedbf63b74c",User-Name = "123456789"' [acct_unique] Acct-Unique-Session-ID = "01f7930c1c838911". ++[acct_unique] returns ok [suffix] No '@' in User-Name = "123456789", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop ++[files] returns noop # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default +- entering group accounting {...} [detail] expand: %{Packet-Src-IP-Address} -> xxx.xxx.xxx.xxx [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20111220 [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20111220 [detail] expand: %t -> Tue Dec 20 09:49:38 2011 ++[detail] returns ok ++[unix] returns ok [radutmp] expand: /usr/local/var/log/radius/radutmp -> /usr/local/var/log/radius/radutmp [radutmp] expand: %{User-Name} -> 123456789 ++[radutmp] returns ok [sql] expand: %{User-Name} -> 123456789 [sql] sql_set_user escaped user --> '123456789' [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', rlm_sql (sql): Reserving sql socket id: 1 rlm_sql (sql): Released sql socket id: 1 ++[sql] returns ok ++[exec] returns noop [attr_filter.accounting_response] expand: %{User-Name} -> 123456789 attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated Sending Accounting-Response of id 198 to xxx.xxx.xxx.xxx port 48752 Finished request 48. Cleaning up request 48 ID 198 with timestamp +5699 Going to the next request Ready to process requests. rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port 46971, id=199, length=61 User-Name = "123456789" User-Password = "1234" NAS-Port = 0 NAS-IP-Address = xxx.xxx.xxx.xxx # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default +- entering group authorize {...} ++[preprocess] returns ok ++[chap] returns noop ++[mschap] returns noop ++[digest] returns noop [suffix] No '@' in User-Name = "123456789", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop [eap] No EAP-Message, not doing EAP ++[eap] returns noop ++[files] returns noop [sql] expand: %{User-Name} -> 123456789 [sql] sql_set_user escaped user --> '123456789' rlm_sql (sql): Reserving sql socket id: 0 [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '123456789' ORDER BY id [sql] User found in radcheck table [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = '123456789' ORDER BY id [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '123456789' ORDER BY priority rlm_sql (sql): Released sql socket id: 0 ++[sql] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated Found Auth-Type = PAP # Executing group from file /usr/local/etc/raddb/sites-enabled/default +- entering group PAP {...} [pap] login attempt with password "1234" [pap] Using clear text password "1234" [pap] User authenticated successfully ++[pap] returns ok # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default +- entering group post-auth {...} ++[exec] returns noop Sending Access-Accept of id 199 to xxx.xxx.xxx.xxx port 46971 Finished request 49. Going to the next request Waking up in 4.9 seconds. Cleaning up request 49 ID 199 with timestamp +5701 Ready to process requests. rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx port 35569, id=200, length=401 Acct-Status-Type = Stop Acct-Session-Id = "68507972-f9d9-46c7-bf22-59020602ffe2" Freeswitch-Hangupcause = Normal-Clearing User-Name = "123456789" Freeswitch-Src = "123456789" Freeswitch-CLID = "Extension 123456789" Freeswitch-Dst = "38651357952" Freeswitch-Dialplan = "XML" Framed-IP-Address = yyy.yyy.yyy.yyy Freeswitch-Context = "default" Freeswitch-Ani = "123456789" Freeswitch-Source = "mod_sofia" Freeswitch-Billusec = 3089990 Freeswitch-Callstartdate = "2011-12-20T09:49:24.552424+0100" Freeswitch-Callanswerdate = "2011-12-20T09:49:30.669405+0100" Freeswitch-Callenddate = "2011-12-20T09:49:33.759395+0100" Acct-Session-Time = 3 Freeswitch-Signalbond = "outbound" NAS-Port = 0 Acct-Delay-Time = 0 NAS-IP-Address = xxx.xxx.xxx.xxx # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address = xxx.xxx.xxx.xxx,NAS-IP-Address = xxx.xxx.xxx.xxx,Acct-Session-Id = "68507972-f9d9-46c7-bf22-59020602ffe2",User-Name = "123456789"' [acct_unique] Acct-Unique-Session-ID = "a2fd914fe7c27b9c". ++[acct_unique] returns ok [suffix] No '@' in User-Name = "123456789", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop ++[files] returns noop # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default +- entering group accounting {...} [detail] expand: %{Packet-Src-IP-Address} -> xxx.xxx.xxx.xxx [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20111220 [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20111220 [detail] expand: %t -> Tue Dec 20 09:49:49 2011 ++[detail] returns ok ++[unix] returns ok [radutmp] expand: /usr/local/var/log/radius/radutmp -> /usr/local/var/log/radius/radutmp [radutmp] expand: %{User-Name} -> 123456789 rlm_radutmp: Logout entry for NAS xxx.xxx.xxx.xxx port 0 has wrong ID ++[radutmp] returns ok [sql] expand: %{User-Name} -> 123456789 [sql] sql_set_user escaped user --> '123456789' [sql] expand: %{Acct-Input-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Input-Octets} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Output-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Output-Octets} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: UPDATE radacct SET acctstarttime = '%{Freeswitch-Callanswerdate}', acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}' -> UPDATE radacct SET acctstarttime = '2011-12-20T09:49:30.669405=2B0100', acctstoptime = '2011-12-20 09:49:49', acctsessiontime = '3', acctinputoctets = '0' << rlm_sql (sql): Reserving sql socket id: 4 [sql] expand: %{Acct-Session-Time} -> 3 [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: %{Acct-Input-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Input-Octets} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Output-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Output-Octets} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Inpu rlm_sql (sql): Released sql socket id: 4 ++[sql] returns ok ++[exec] returns noop [attr_filter.accounting_response] expand: %{User-Name} -> 123456789 attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated Sending Accounting-Response of id 200 to xxx.xxx.xxx.xxx port 35569 Finished request 50. Cleaning up request 50 ID 200 with timestamp +5710 Going to the next request Ready to process requests. -- Best regards / Lep Pozdrav Miha Zoubek Softnet d.o.o.