<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=ISO-8859-1">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hi,<br>
<br>
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).<br>
<br>
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).<br>
<br>
Please help me out understand why radius add two entries for stop
packet if only one is send from NAS.<br>
<br>
1. Call is not answered.<br>
<small>3126.504593 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS
Accounting-Request(4) (id=192, l=265)<br>
3126.506361 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS
Accounting-Response(5) (id=192, l=20)<br>
3128.512626 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS
Access-Request(1) (id=193, l=61)<br>
3128.514192 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS
Access-Accept(2) (id=193, l=20)<br>
3135.215365 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS
Accounting-Request(4) (id=194, l=362)<br>
3135.217317 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS
Accounting-Response(5) (id=194, l=20)</small><br>
<br>
<br>
2. Call is answered.<br>
<small>3142.992787 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS
Accounting-Request(4) (id=195, l=265)<br>
3142.994570 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS
Accounting-Response(5) (id=195, l=20)<br>
3145.001503 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS
Access-Request(1) (id=196, l=61)<br>
3145.003161 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS
Access-Accept(2) (id=196, l=20)<br>
3154.440904 xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy RADIUS
Accounting-Request(4) (id=197, l=401)<br>
3154.443202 yyy.yyy.yyy.yyy -> xxx.xxx.xxx.xxx RADIUS
Accounting-Response(5) (id=197, l=20)</small><br>
<br>
<br>
Bellow I am pasting only radius log for answered call.<br>
<br>
<small>rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx
port 48752, id=198, length=265<br>
Acct-Status-Type = Start<br>
Acct-Session-Id = "d446d20a-6d1c-4ffd-9b59-1aedbf63b74c"<br>
User-Name = "123456789"<br>
Freeswitch-Src = "123456789"<br>
Freeswitch-CLID = "123456789"<br>
Freeswitch-Dst = "051357952"<br>
Freeswitch-Dialplan = "XML"<br>
Framed-IP-Address = zzz.zzz.zzz.zzz<br>
Freeswitch-Context = "default"<br>
Freeswitch-Ani = "123456789"<br>
Freeswitch-Source = "mod_sofia"<br>
Freeswitch-Callstartdate =
"2011-12-20T09:49:22.535428+0100"<br>
NAS-Port = 0<br>
Acct-Delay-Time = 0<br>
NAS-IP-Address = xxx.xxx.xxx.xxx<br>
# Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default<br>
+- entering group preacct {...}<br>
++[preprocess] returns ok<br>
[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"'<br>
[acct_unique] Acct-Unique-Session-ID = "01f7930c1c838911".<br>
++[acct_unique] returns ok<br>
[suffix] No '@' in User-Name = "123456789", looking up realm NULL<br>
[suffix] No such realm "NULL"<br>
++[suffix] returns noop<br>
++[files] returns noop<br>
# Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default<br>
+- entering group accounting {...}<br>
[detail] expand: %{Packet-Src-IP-Address} ->
xxx.xxx.xxx.xxx<br>
[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<br>
[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<br>
[detail] expand: %t -> Tue Dec 20 09:49:38 2011<br>
++[detail] returns ok<br>
++[unix] returns ok<br>
[radutmp] expand: /usr/local/var/log/radius/radutmp ->
/usr/local/var/log/radius/radutmp<br>
[radutmp] expand: %{User-Name} -> 123456789<br>
++[radutmp] returns ok<br>
[sql] expand: %{User-Name} -> 123456789<br>
[sql] sql_set_user escaped user --> '123456789'<br>
[sql] expand: %{Acct-Delay-Time} -> 0<br>
[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}', <br>
rlm_sql (sql): Reserving sql socket id: 1<br>
rlm_sql (sql): Released sql socket id: 1<br>
++[sql] returns ok<br>
++[exec] returns noop<br>
[attr_filter.accounting_response] expand: %{User-Name} ->
123456789<br>
attr_filter: Matched entry DEFAULT at line 12<br>
++[attr_filter.accounting_response] returns updated<br>
Sending Accounting-Response of id 198 to xxx.xxx.xxx.xxx port
48752<br>
Finished request 48.<br>
Cleaning up request 48 ID 198 with timestamp +5699<br>
Going to the next request<br>
Ready to process requests.<br>
rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port
46971, id=199, length=61<br>
User-Name = "123456789"<br>
User-Password = "1234"<br>
NAS-Port = 0<br>
NAS-IP-Address = xxx.xxx.xxx.xxx<br>
# Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default<br>
+- entering group authorize {...}<br>
++[preprocess] returns ok<br>
++[chap] returns noop<br>
++[mschap] returns noop<br>
++[digest] returns noop<br>
[suffix] No '@' in User-Name = "123456789", looking up realm NULL<br>
[suffix] No such realm "NULL"<br>
++[suffix] returns noop<br>
[eap] No EAP-Message, not doing EAP<br>
++[eap] returns noop<br>
++[files] returns noop<br>
[sql] expand: %{User-Name} -> 123456789<br>
[sql] sql_set_user escaped user --> '123456789'<br>
rlm_sql (sql): Reserving sql socket id: 0<br>
[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<br>
[sql] User found in radcheck table<br>
[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<br>
[sql] expand: SELECT groupname FROM
radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority -> SELECT
groupname FROM radusergroup WHERE username =
'123456789' ORDER BY priority<br>
rlm_sql (sql): Released sql socket id: 0<br>
++[sql] returns ok<br>
++[expiration] returns noop<br>
++[logintime] returns noop<br>
++[pap] returns updated<br>
Found Auth-Type = PAP<br>
# Executing group from file
/usr/local/etc/raddb/sites-enabled/default<br>
+- entering group PAP {...}<br>
[pap] login attempt with password "1234"<br>
[pap] Using clear text password "1234"<br>
[pap] User authenticated successfully<br>
++[pap] returns ok<br>
# Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/default<br>
+- entering group post-auth {...}<br>
++[exec] returns noop<br>
Sending Access-Accept of id 199 to xxx.xxx.xxx.xxx port 46971<br>
Finished request 49.<br>
Going to the next request<br>
Waking up in 4.9 seconds.<br>
Cleaning up request 49 ID 199 with timestamp +5701<br>
Ready to process requests.<br>
rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx port
35569, id=200, length=401<br>
Acct-Status-Type = Stop<br>
Acct-Session-Id = "68507972-f9d9-46c7-bf22-59020602ffe2"<br>
Freeswitch-Hangupcause = Normal-Clearing<br>
User-Name = "123456789"<br>
Freeswitch-Src = "123456789"<br>
Freeswitch-CLID = "Extension 123456789"<br>
Freeswitch-Dst = "38651357952"<br>
Freeswitch-Dialplan = "XML"<br>
Framed-IP-Address = yyy.yyy.yyy.yyy<br>
Freeswitch-Context = "default"<br>
Freeswitch-Ani = "123456789"<br>
Freeswitch-Source = "mod_sofia"<br>
Freeswitch-Billusec = 3089990<br>
Freeswitch-Callstartdate =
"2011-12-20T09:49:24.552424+0100"<br>
Freeswitch-Callanswerdate =
"2011-12-20T09:49:30.669405+0100"<br>
Freeswitch-Callenddate = "2011-12-20T09:49:33.759395+0100"<br>
Acct-Session-Time = 3<br>
Freeswitch-Signalbond = "outbound"<br>
NAS-Port = 0<br>
Acct-Delay-Time = 0<br>
NAS-IP-Address = xxx.xxx.xxx.xxx<br>
# Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default<br>
+- entering group preacct {...}<br>
++[preprocess] returns ok<br>
[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"'<br>
[acct_unique] Acct-Unique-Session-ID = "a2fd914fe7c27b9c".<br>
++[acct_unique] returns ok<br>
[suffix] No '@' in User-Name = "123456789", looking up realm NULL<br>
[suffix] No such realm "NULL"<br>
++[suffix] returns noop<br>
++[files] returns noop<br>
# Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default<br>
+- entering group accounting {...}<br>
[detail] expand: %{Packet-Src-IP-Address} ->
xxx.xxx.xxx.xxx<br>
[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<br>
[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<br>
[detail] expand: %t -> Tue Dec 20 09:49:49 2011<br>
++[detail] returns ok<br>
++[unix] returns ok<br>
[radutmp] expand: /usr/local/var/log/radius/radutmp ->
/usr/local/var/log/radius/radutmp<br>
[radutmp] expand: %{User-Name} -> 123456789<br>
rlm_radutmp: Logout entry for NAS xxx.xxx.xxx.xxx port 0 has wrong
ID<br>
++[radutmp] returns ok<br>
[sql] expand: %{User-Name} -> 123456789<br>
[sql] sql_set_user escaped user --> '123456789'<br>
[sql] expand: %{Acct-Input-Gigawords} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Input-Octets} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Output-Gigawords} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Output-Octets} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Delay-Time} -> 0<br>
[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' << <br>
rlm_sql (sql): Reserving sql socket id: 4<br>
[sql] expand: %{Acct-Session-Time} -> 3<br>
[sql] expand: %{Acct-Delay-Time} -> 0<br>
[sql] expand: %{Acct-Input-Gigawords} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Input-Octets} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Output-Gigawords} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Output-Octets} -> <br>
[sql] ... expanding second conditional<br>
[sql] expand: %{Acct-Delay-Time} -> 0<br>
[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<br>
rlm_sql (sql): Released sql socket id: 4<br>
++[sql] returns ok<br>
++[exec] returns noop<br>
[attr_filter.accounting_response] expand: %{User-Name} ->
123456789<br>
attr_filter: Matched entry DEFAULT at line 12<br>
++[attr_filter.accounting_response] returns updated<br>
Sending Accounting-Response of id 200 to xxx.xxx.xxx.xxx port
35569<br>
Finished request 50.<br>
Cleaning up request 50 ID 200 with timestamp +5710<br>
Going to the next request<br>
Ready to process requests.</small><br>
<br>
<pre class="moz-signature" cols="72">--
Best regards / Lep Pozdrav
Miha Zoubek
Softnet d.o.o. </pre>
</body>
</html>