Fwd: Help unsual debug log!
Haviaras Kostas
koshalirod at gmail.com
Thu Sep 25 13:56:25 CEST 2014
Hello everyone, I was observing my debug mode on server and I notice, when
I am logging out a user the radius server make the same 3 times! It is
normal behavior ??? I have configure my FreeRadius to work with MySQL.
Here is my log:
Ready to process requests
Received Accounting-Request Id 198 from 192.168.40.101:58545 to
192.168.40.12:1813 length 194
Acct-Status-Type = Stop
Acct-Terminate-Cause = User-Request
NAS-Port-Type = Wireless-802.11
Calling-Station-Id = '30:39:26:86:CC:EA'
Called-Station-Id = 'hotspot1'
NAS-Port-Id = 'citystore_test'
User-Name = 'user1'
NAS-Port = 2151678022
Acct-Session-Id = '80400046'
Framed-IP-Address = 10.5.50.254
Mikrotik-Host-IP = 10.5.50.254
Event-Timestamp = 'Sep 24 2014 14:28:16 EEST'
Acct-Input-Octets = 2197666
Acct-Output-Octets = 18331654
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Acct-Input-Packets = 16603
Acct-Output-Packets = 16236
Acct-Session-Time = 1448
NAS-Identifier = 'MikroTik'
Acct-Delay-Time = 0
NAS-IP-Address = 192.168.40.101
(5) Received Accounting-Request packet from host 192.168.40.101 port 58545,
id=198, length=194
(5) Acct-Status-Type = Stop
(5) Acct-Terminate-Cause = User-Request
(5) NAS-Port-Type = Wireless-802.11
(5) Calling-Station-Id = '30:39:26:86:CC:EA'
(5) Called-Station-Id = 'hotspot1'
(5) NAS-Port-Id = 'citystore_test'
(5) User-Name = 'user1'
(5) NAS-Port = 2151678022
(5) Acct-Session-Id = '80400046'
(5) Framed-IP-Address = 10.5.50.254
(5) Mikrotik-Host-IP = 10.5.50.254
(5) Event-Timestamp = 'Sep 24 2014 14:28:16 EEST'
(5) Acct-Input-Octets = 2197666
(5) Acct-Output-Octets = 18331654
(5) Acct-Input-Gigawords = 0
(5) Acct-Output-Gigawords = 0
(5) Acct-Input-Packets = 16603
(5) Acct-Output-Packets = 16236
(5) Acct-Session-Time = 1448
(5) NAS-Identifier = 'MikroTik'
(5) Acct-Delay-Time = 0
(5) NAS-IP-Address = 192.168.40.101
(5) # Executing section preacct from file
/etc/freeradius/sites-enabled/default
(5) preacct {
(5) [preprocess] = ok
(5) acct_unique acct_unique {
(5) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i)
(5) EXPAND %{string:Class}
(5) -->
(5) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE
(5) else else {
(5) update request {
(5) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(5) --> cd7c5cd7ff1adea4aeffeb8b6c859901
(5) Acct-Unique-Session-Id := "cd7c5cd7ff1adea4aeffeb8b6c859901"
(5) } # update request = noop
(5) } # else else = noop
(5) } # acct_unique acct_unique = noop
(5) suffix : Checking for suffix after "@"
(5) suffix : No '@' in User-Name = "user1", looking up realm NULL
(5) suffix : No such realm "NULL"
(5) [suffix] = noop
(5) [files] = noop
(5) } # preacct = ok
(5) # Executing section accounting from file
/etc/freeradius/sites-enabled/default
(5) accounting {
(5) detail : EXPAND
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(5) detail : --> /var/log/freeradius/radacct/
192.168.40.101/detail-20140925
(5) detail :
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/192.168.40.101/detail-20140925
(5) detail : EXPAND %t
(5) detail : --> Thu Sep 25 14:24:47 2014
(5) [detail] = ok
(5) [unix] = ok
(5) radutmp : EXPAND /var/log/freeradius/radutmp
(5) radutmp : --> /var/log/freeradius/radutmp
(5) radutmp : EXPAND %{User-Name}
(5) radutmp : --> user1
(5) [radutmp] = ok
(5) sql : EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(5) sql : --> type.stop.query
(5) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (6)
(5) sql : EXPAND %{User-Name}
(5) sql : --> user1
(5) sql : SQL-User-Name set to 'user1'
(5) sql : EXPAND UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(%{integer:Event-Timestamp}), 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}', connectinfo_stop =
'%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username =
'%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'
(5) sql : --> UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1411558096), acctsessiontime = '1448', acctinputoctets = '0'
<< 32 | '2197666', acctoutputoctets = '0' << 32 | '18331654',
acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE
acctsessionid = '80400046' AND username = 'user1' AND nasipaddress =
'192.168.40.101'
rlm_sql (sql): Executing query: 'UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1411558096), acctsessiontime = '1448', acctinputoctets = '0'
<< 32 | '2197666', acctoutputoctets = '0' << 32 | '18331654',
acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE
acctsessionid = '80400046' AND username = 'user1' AND nasipaddress =
'192.168.40.101''
rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0
rlm_sql (sql): Released connection (6)
rlm_sql (sql): 0 of 3 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (7)
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 1449
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 1467
seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
(5) [sql] = ok
(5) [exec] = noop
(5) attr_filter.accounting_response : EXPAND %{User-Name}
(5) attr_filter.accounting_response : --> user1
(5) attr_filter.accounting_response : Matched entry DEFAULT at line 12
(5) [attr_filter.accounting_response] = updated
(5) } # accounting = updated
(5) Sending Accounting-Response packet to host 192.168.40.101 port 58545,
id=198, length=0
Sending Accounting-Response Id 198 from 192.168.40.12:1813 to
192.168.40.101:58545
(5) Finished request
(5) Cleaning up request packet ID 198 with timestamp +1572
Received Accounting-Request Id 198 from 192.168.40.101:58545 to
192.168.40.12:1813 length 194
Acct-Status-Type = Stop
Acct-Terminate-Cause = User-Request
NAS-Port-Type = Wireless-802.11
Calling-Station-Id = '30:39:26:86:CC:EA'
Called-Station-Id = 'hotspot1'
NAS-Port-Id = 'citystore_test'
User-Name = 'user1'
NAS-Port = 2151678022
Acct-Session-Id = '80400046'
Framed-IP-Address = 10.5.50.254
Mikrotik-Host-IP = 10.5.50.254
Event-Timestamp = 'Sep 24 2014 14:28:16 EEST'
Acct-Input-Octets = 2197666
Acct-Output-Octets = 18331654
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Acct-Input-Packets = 16603
Acct-Output-Packets = 16236
Acct-Session-Time = 1448
NAS-Identifier = 'MikroTik'
Acct-Delay-Time = 0
NAS-IP-Address = 192.168.40.101
(6) Received Accounting-Request packet from host 192.168.40.101 port 58545,
id=198, length=194
(6) Acct-Status-Type = Stop
(6) Acct-Terminate-Cause = User-Request
(6) NAS-Port-Type = Wireless-802.11
(6) Calling-Station-Id = '30:39:26:86:CC:EA'
(6) Called-Station-Id = 'hotspot1'
(6) NAS-Port-Id = 'citystore_test'
(6) User-Name = 'user1'
(6) NAS-Port = 2151678022
(6) Acct-Session-Id = '80400046'
(6) Framed-IP-Address = 10.5.50.254
(6) Mikrotik-Host-IP = 10.5.50.254
(6) Event-Timestamp = 'Sep 24 2014 14:28:16 EEST'
(6) Acct-Input-Octets = 2197666
(6) Acct-Output-Octets = 18331654
(6) Acct-Input-Gigawords = 0
(6) Acct-Output-Gigawords = 0
(6) Acct-Input-Packets = 16603
(6) Acct-Output-Packets = 16236
(6) Acct-Session-Time = 1448
(6) NAS-Identifier = 'MikroTik'
(6) Acct-Delay-Time = 0
(6) NAS-IP-Address = 192.168.40.101
(6) # Executing section preacct from file
/etc/freeradius/sites-enabled/default
(6) preacct {
(6) [preprocess] = ok
(6) acct_unique acct_unique {
(6) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i)
(6) EXPAND %{string:Class}
(6) -->
(6) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE
(6) else else {
(6) update request {
(6) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(6) --> cd7c5cd7ff1adea4aeffeb8b6c859901
(6) Acct-Unique-Session-Id := "cd7c5cd7ff1adea4aeffeb8b6c859901"
(6) } # update request = noop
(6) } # else else = noop
(6) } # acct_unique acct_unique = noop
(6) suffix : Checking for suffix after "@"
(6) suffix : No '@' in User-Name = "user1", looking up realm NULL
(6) suffix : No such realm "NULL"
(6) [suffix] = noop
(6) [files] = noop
(6) } # preacct = ok
(6) # Executing section accounting from file
/etc/freeradius/sites-enabled/default
(6) accounting {
(6) detail : EXPAND
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(6) detail : --> /var/log/freeradius/radacct/
192.168.40.101/detail-20140925
(6) detail :
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/192.168.40.101/detail-20140925
(6) detail : EXPAND %t
(6) detail : --> Thu Sep 25 14:24:47 2014
(6) [detail] = ok
(6) [unix] = ok
(6) radutmp : EXPAND /var/log/freeradius/radutmp
(6) radutmp : --> /var/log/freeradius/radutmp
(6) radutmp : EXPAND %{User-Name}
(6) radutmp : --> user1
(6) WARNING: radutmp : Logout for NAS mikrotik port 2151678022, but no
Login record
(6) [radutmp] = ok
(6) sql : EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(6) sql : --> type.stop.query
(6) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (7)
(6) sql : EXPAND %{User-Name}
(6) sql : --> user1
(6) sql : SQL-User-Name set to 'user1'
(6) sql : EXPAND UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(%{integer:Event-Timestamp}), 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}', connectinfo_stop =
'%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username =
'%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'
(6) sql : --> UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1411558096), acctsessiontime = '1448', acctinputoctets = '0'
<< 32 | '2197666', acctoutputoctets = '0' << 32 | '18331654',
acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE
acctsessionid = '80400046' AND username = 'user1' AND nasipaddress =
'192.168.40.101'
rlm_sql (sql): Executing query: 'UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1411558096), acctsessiontime = '1448', acctinputoctets = '0'
<< 32 | '2197666', acctoutputoctets = '0' << 32 | '18331654',
acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE
acctsessionid = '80400046' AND username = 'user1' AND nasipaddress =
'192.168.40.101''
rlm_sql_mysql: Rows matched: 1 Changed: 0 Warnings: 0
rlm_sql (sql): Released connection (7)
(6) [sql] = ok
(6) [exec] = noop
(6) attr_filter.accounting_response : EXPAND %{User-Name}
(6) attr_filter.accounting_response : --> user1
(6) attr_filter.accounting_response : Matched entry DEFAULT at line 12
(6) [attr_filter.accounting_response] = updated
(6) } # accounting = updated
(6) Sending Accounting-Response packet to host 192.168.40.101 port 58545,
id=198, length=0
Sending Accounting-Response Id 198 from 192.168.40.12:1813 to
192.168.40.101:58545
(6) Finished request
Waking up in 0.3 seconds.
Received Accounting-Request Id 198 from 192.168.40.101:58545 to
192.168.40.12:1813 length 194
(6) Cleaning up request packet ID 198 with timestamp +1572
Acct-Status-Type = Stop
Acct-Terminate-Cause = User-Request
NAS-Port-Type = Wireless-802.11
Calling-Station-Id = '30:39:26:86:CC:EA'
Called-Station-Id = 'hotspot1'
NAS-Port-Id = 'citystore_test'
User-Name = 'user1'
NAS-Port = 2151678022
Acct-Session-Id = '80400046'
Framed-IP-Address = 10.5.50.254
Mikrotik-Host-IP = 10.5.50.254
Event-Timestamp = 'Sep 24 2014 14:28:16 EEST'
Acct-Input-Octets = 2197666
Acct-Output-Octets = 18331654
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Acct-Input-Packets = 16603
Acct-Output-Packets = 16236
Acct-Session-Time = 1448
NAS-Identifier = 'MikroTik'
Acct-Delay-Time = 1
NAS-IP-Address = 192.168.40.101
(7) Received Accounting-Request packet from host 192.168.40.101 port 58545,
id=198, length=194
(7) Acct-Status-Type = Stop
(7) Acct-Terminate-Cause = User-Request
(7) NAS-Port-Type = Wireless-802.11
(7) Calling-Station-Id = '30:39:26:86:CC:EA'
(7) Called-Station-Id = 'hotspot1'
(7) NAS-Port-Id = 'citystore_test'
(7) User-Name = 'user1'
(7) NAS-Port = 2151678022
(7) Acct-Session-Id = '80400046'
(7) Framed-IP-Address = 10.5.50.254
(7) Mikrotik-Host-IP = 10.5.50.254
(7) Event-Timestamp = 'Sep 24 2014 14:28:16 EEST'
(7) Acct-Input-Octets = 2197666
(7) Acct-Output-Octets = 18331654
(7) Acct-Input-Gigawords = 0
(7) Acct-Output-Gigawords = 0
(7) Acct-Input-Packets = 16603
(7) Acct-Output-Packets = 16236
(7) Acct-Session-Time = 1448
(7) NAS-Identifier = 'MikroTik'
(7) Acct-Delay-Time = 1
(7) NAS-IP-Address = 192.168.40.101
(7) # Executing section preacct from file
/etc/freeradius/sites-enabled/default
(7) preacct {
(7) [preprocess] = ok
(7) acct_unique acct_unique {
(7) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i)
(7) EXPAND %{string:Class}
(7) -->
(7) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE
(7) else else {
(7) update request {
(7) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(7) --> cd7c5cd7ff1adea4aeffeb8b6c859901
(7) Acct-Unique-Session-Id := "cd7c5cd7ff1adea4aeffeb8b6c859901"
(7) } # update request = noop
(7) } # else else = noop
(7) } # acct_unique acct_unique = noop
(7) suffix : Checking for suffix after "@"
(7) suffix : No '@' in User-Name = "user1", looking up realm NULL
(7) suffix : No such realm "NULL"
(7) [suffix] = noop
(7) [files] = noop
(7) } # preacct = ok
(7) # Executing section accounting from file
/etc/freeradius/sites-enabled/default
(7) accounting {
(7) detail : EXPAND
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(7) detail : --> /var/log/freeradius/radacct/
192.168.40.101/detail-20140925
(7) detail :
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/192.168.40.101/detail-20140925
(7) detail : EXPAND %t
(7) detail : --> Thu Sep 25 14:24:47 2014
(7) [detail] = ok
(7) [unix] = ok
(7) radutmp : EXPAND /var/log/freeradius/radutmp
(7) radutmp : --> /var/log/freeradius/radutmp
(7) radutmp : EXPAND %{User-Name}
(7) radutmp : --> user1
(7) WARNING: radutmp : Logout for NAS mikrotik port 2151678022, but no
Login record
(7) [radutmp] = ok
(7) sql : EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(7) sql : --> type.stop.query
(7) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (7)
(7) sql : EXPAND %{User-Name}
(7) sql : --> user1
(7) sql : SQL-User-Name set to 'user1'
(7) sql : EXPAND UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(%{integer:Event-Timestamp}), 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}', connectinfo_stop =
'%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username =
'%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'
(7) sql : --> UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1411558096), acctsessiontime = '1448', acctinputoctets = '0'
<< 32 | '2197666', acctoutputoctets = '0' << 32 | '18331654',
acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE
acctsessionid = '80400046' AND username = 'user1' AND nasipaddress =
'192.168.40.101'
rlm_sql (sql): Executing query: 'UPDATE radacct SET acctstoptime =
FROM_UNIXTIME(1411558096), acctsessiontime = '1448', acctinputoctets = '0'
<< 32 | '2197666', acctoutputoctets = '0' << 32 | '18331654',
acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE
acctsessionid = '80400046' AND username = 'user1' AND nasipaddress =
'192.168.40.101''
rlm_sql_mysql: Rows matched: 1 Changed: 0 Warnings: 0
rlm_sql (sql): Released connection (7)
(7) [sql] = ok
(7) [exec] = noop
(7) attr_filter.accounting_response : EXPAND %{User-Name}
(7) attr_filter.accounting_response : --> user1
(7) attr_filter.accounting_response : Matched entry DEFAULT at line 12
(7) [attr_filter.accounting_response] = updated
(7) } # accounting = updated
(7) Sending Accounting-Response packet to host 192.168.40.101 port 58545,
id=198, length=0
Sending Accounting-Response Id 198 from 192.168.40.12:1813 to
192.168.40.101:58545
(7) Finished request
Waking up in 0.2 seconds.
(7) Cleaning up request packet ID 198 with timestamp +1572
Thanks for your attention and time!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140925/fca81046/attachment-0001.html>
More information about the Freeradius-Users
mailing list