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.
