Problem with sql entry

Miha Zoubek miha at softnet.si
Tue Dec 20 09:55:06 CET 2011


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.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20111220/68ac09b2/attachment.html>


More information about the Freeradius-Users mailing list