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!