Hello, I am trying to upgrade my FreeRadius servers to version 3.0.12. We are making some changes in the structure of the company and this is going to be needed. Today I run FreeRadius 2.1.10 and I make my check and accounting on MySQL and IPPool on PostgreSQL. Now I am changing the structure to FreeRadius 3.0.12 and all check, accounting and ippool going to a MaxScale/MariaDB cluster. I've already tested the MariaDB server and all requests are being replied in 0,006 seconds. It's fast enough right now. I compiled from source FreeRadius 3.0.12 on a Debian 8.6 (Linux HA-Radius-2 3.16.0-4-amd64 #1 SMP Debian 3.16.36-1+deb8u1 (2016-09-03) x86_64 GNU/Linux). The problem is that for some reason FreeRadius is taking a long time to answer to NAS Access-Request and the NAS send a lot of requests to receive an answer. Bellow I show a FreeRadius log and later I will explain what I saw in this (for the purpose of this log I disabled SQL IPPool and Simultaneous-Check): Ready to process requests (0) Received Access-Request Id 17 from 187.19.96.40:35728 to 172.31.255.188:1812 length 136 (0) Service-Type = Framed-User (0) Framed-Protocol = PPP (0) NAS-Port = 15728647 (0) NAS-Port-Type = Ethernet (0) User-Name = "teste-sql" (0) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (0) Called-Station-Id = "CSC-755-rt-01" (0) NAS-Port-Id = "vlan14" (0) User-Password = "senha34" (0) NAS-Identifier = "CSC-755-rt-01" (0) NAS-IP-Address = 187.19.96.40 (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (0) authorize { (0) sql: EXPAND %{User-Name} (0) sql: --> teste-sql (0) sql: SQL-User-Name set to 'teste-sql' rlm_sql (sql): Reserved connection (1) (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (0) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (0) sql: User found in radcheck table (0) sql: Conditional check items matched, merging assignment check items (0) sql: Crypt-Password := "w54qGtgpcqSaw" (0) sql: Pool-Name := "main_pool" (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (0) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (0) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (0) sql: --> SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (0) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (0) sql: User found in the group table (0) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id (0) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (0) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (0) sql: Group "grupo-teste-sql": Conditional check items matched (0) sql: Group "grupo-teste-sql": Merging assignment check items (0) sql: Simultaneous-Use := 1 (0) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id (0) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (0) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (0) sql: Group "grupo-teste-sql": Merging reply items (0) sql: Mikrotik-Rate-Limit := "32k" rlm_sql (sql): Released connection (1) rlm_sql (sql): Closing connection (2), from 10 unused connections rlm_sql_mysql: Socket destructor called, closing socket (0) [sql] = ok (0) [pap] = updated (0) } # authorize = updated (0) Found Auth-Type = PAP (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Auth-Type PAP { (0) pap: Login attempt with password (0) pap: Comparing with "known-good" Crypt-password (0) pap: User authenticated successfully (0) [pap] = ok (0) } # Auth-Type PAP = ok (0) # Executing section session from file /usr/local/etc/raddb/sites-enabled/default (0) session { (0) sql: EXPAND %{User-Name} (0) sql: --> teste-sql (0) sql: SQL-User-Name set to 'teste-sql' (0) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL (0) sql: --> SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Reserved connection (3) (0) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Released connection (3) (0) [sql] = ok (0) } # session = ok (0) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728647 cli E4:8D:8C:EC:90:A2) (0) Sent Access-Accept Id 17 from 172.31.255.188:1812 to 187.19.96.40:35728 length 0 (0) Mikrotik-Rate-Limit = "32k" (0) Finished request Waking up in 1.9 seconds. (0) Cleaning up request packet ID 17 with timestamp +47 Ready to process requests (1) Received Access-Request Id 17 from 187.19.96.40:35728 to 172.31.255.188:1812 length 136 (1) Service-Type = Framed-User (1) Framed-Protocol = PPP (1) NAS-Port = 15728647 (1) NAS-Port-Type = Ethernet (1) User-Name = "teste-sql" (1) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (1) Called-Station-Id = "CSC-755-rt-01" (1) NAS-Port-Id = "vlan14" (1) User-Password = "senha34" (1) NAS-Identifier = "CSC-755-rt-01" (1) NAS-IP-Address = 187.19.96.40 (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (1) authorize { (1) sql: EXPAND %{User-Name} (1) sql: --> teste-sql (1) sql: SQL-User-Name set to 'teste-sql' rlm_sql (sql): Reserved connection (4) (1) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (1) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (1) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (1) sql: User found in radcheck table (1) sql: Conditional check items matched, merging assignment check items (1) sql: Crypt-Password := "w54qGtgpcqSaw" (1) sql: Pool-Name := "main_pool" (1) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (1) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (1) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (1) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (1) sql: --> SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (1) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (1) sql: User found in the group table (1) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id (1) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (1) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (1) sql: Group "grupo-teste-sql": Conditional check items matched (1) sql: Group "grupo-teste-sql": Merging assignment check items (1) sql: Simultaneous-Use := 1 (1) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id (1) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (1) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (1) sql: Group "grupo-teste-sql": Merging reply items (1) sql: Mikrotik-Rate-Limit := "32k" rlm_sql (sql): Released connection (4) rlm_sql (sql): Closing connection (5), from 9 unused connections rlm_sql_mysql: Socket destructor called, closing socket (1) [sql] = ok (1) [pap] = updated (1) } # authorize = updated (1) Found Auth-Type = PAP (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (1) Auth-Type PAP { (1) pap: Login attempt with password (1) pap: Comparing with "known-good" Crypt-password (1) pap: User authenticated successfully (1) [pap] = ok (1) } # Auth-Type PAP = ok (1) # Executing section session from file /usr/local/etc/raddb/sites-enabled/default (1) session { (1) sql: EXPAND %{User-Name} (1) sql: --> teste-sql (1) sql: SQL-User-Name set to 'teste-sql' (1) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL (1) sql: --> SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Reserved connection (6) (1) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Released connection (6) (1) [sql] = ok (1) } # session = ok (1) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728647 cli E4:8D:8C:EC:90:A2) (1) Sent Access-Accept Id 17 from 172.31.255.188:1812 to 187.19.96.40:35728 length 0 (1) Mikrotik-Rate-Limit = "32k" (1) Finished request Waking up in 1.9 seconds. (1) Cleaning up request packet ID 17 with timestamp +50 Ready to process requests (2) Received Access-Request Id 17 from 187.19.96.40:35728 to 172.31.255.188:1812 length 136 (2) Service-Type = Framed-User (2) Framed-Protocol = PPP (2) NAS-Port = 15728647 (2) NAS-Port-Type = Ethernet (2) User-Name = "teste-sql" (2) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (2) Called-Station-Id = "CSC-755-rt-01" (2) NAS-Port-Id = "vlan14" (2) User-Password = "senha34" (2) NAS-Identifier = "CSC-755-rt-01" (2) NAS-IP-Address = 187.19.96.40 (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (2) authorize { (2) sql: EXPAND %{User-Name} (2) sql: --> teste-sql (2) sql: SQL-User-Name set to 'teste-sql' rlm_sql (sql): Reserved connection (7) (2) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (2) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (2) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (2) sql: User found in radcheck table (2) sql: Conditional check items matched, merging assignment check items (2) sql: Crypt-Password := "w54qGtgpcqSaw" (2) sql: Pool-Name := "main_pool" (2) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (2) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (2) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (2) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (2) sql: --> SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (2) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (2) sql: User found in the group table (2) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id (2) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (2) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (2) sql: Group "grupo-teste-sql": Conditional check items matched (2) sql: Group "grupo-teste-sql": Merging assignment check items (2) sql: Simultaneous-Use := 1 (2) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id (2) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (2) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (2) sql: Group "grupo-teste-sql": Merging reply items (2) sql: Mikrotik-Rate-Limit := "32k" rlm_sql (sql): Released connection (7) rlm_sql (sql): Closing connection (8), from 8 unused connections rlm_sql_mysql: Socket destructor called, closing socket (2) [sql] = ok (2) [pap] = updated (2) } # authorize = updated (2) Found Auth-Type = PAP (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (2) Auth-Type PAP { (2) pap: Login attempt with password (2) pap: Comparing with "known-good" Crypt-password (2) pap: User authenticated successfully (2) [pap] = ok (2) } # Auth-Type PAP = ok (2) # Executing section session from file /usr/local/etc/raddb/sites-enabled/default (2) session { (2) sql: EXPAND %{User-Name} (2) sql: --> teste-sql (2) sql: SQL-User-Name set to 'teste-sql' (2) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL (2) sql: --> SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Reserved connection (9) (2) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Released connection (9) (2) [sql] = ok (2) } # session = ok (2) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728647 cli E4:8D:8C:EC:90:A2) (2) Sent Access-Accept Id 17 from 172.31.255.188:1812 to 187.19.96.40:35728 length 0 (2) Mikrotik-Rate-Limit = "32k" (2) Finished request Waking up in 1.9 seconds. (2) Cleaning up request packet ID 17 with timestamp +53 Ready to process requests (3) Received Access-Request Id 18 from 187.19.96.40:36982 to 172.31.255.188:1812 length 136 (3) Service-Type = Framed-User (3) Framed-Protocol = PPP (3) NAS-Port = 15728648 (3) NAS-Port-Type = Ethernet (3) User-Name = "teste-sql" (3) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (3) Called-Station-Id = "CSC-755-rt-01" (3) NAS-Port-Id = "vlan14" (3) User-Password = "senha34" (3) NAS-Identifier = "CSC-755-rt-01" (3) NAS-IP-Address = 187.19.96.40 (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (3) authorize { (3) sql: EXPAND %{User-Name} (3) sql: --> teste-sql (3) sql: SQL-User-Name set to 'teste-sql' rlm_sql (sql): Reserved connection (10) (3) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (3) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (3) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'teste-sql' ORDER BY id (3) sql: User found in radcheck table (3) sql: Conditional check items matched, merging assignment check items (3) sql: Crypt-Password := "w54qGtgpcqSaw" (3) sql: Pool-Name := "main_pool" (3) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id (3) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (3) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'teste-sql' ORDER BY id (3) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (3) sql: --> SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (3) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'teste-sql' ORDER BY priority (3) sql: User found in the group table (3) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id (3) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (3) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'grupo-teste-sql' ORDER BY id (3) sql: Group "grupo-teste-sql": Conditional check items matched (3) sql: Group "grupo-teste-sql": Merging assignment check items (3) sql: Simultaneous-Use := 1 (3) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id (3) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (3) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'grupo-teste-sql' ORDER BY id (3) sql: Group "grupo-teste-sql": Merging reply items (3) sql: Mikrotik-Rate-Limit := "32k" rlm_sql (sql): Released connection (10) rlm_sql (sql): Closing connection (11), from 7 unused connections rlm_sql_mysql: Socket destructor called, closing socket (3) [sql] = ok (3) [pap] = updated (3) } # authorize = updated (3) Found Auth-Type = PAP (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) Auth-Type PAP { (3) pap: Login attempt with password (3) pap: Comparing with "known-good" Crypt-password (3) pap: User authenticated successfully (3) [pap] = ok (3) } # Auth-Type PAP = ok (3) # Executing section session from file /usr/local/etc/raddb/sites-enabled/default (3) session { (3) sql: EXPAND %{User-Name} (3) sql: --> teste-sql (3) sql: SQL-User-Name set to 'teste-sql' (3) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL (3) sql: --> SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Reserved connection (12) (3) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = 'teste-sql' AND acctstoptime IS NULL rlm_sql (sql): Released connection (12) (3) [sql] = ok (3) } # session = ok (3) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728648 cli E4:8D:8C:EC:90:A2) (3) Sent Access-Accept Id 18 from 172.31.255.188:1812 to 187.19.96.40:36982 length 0 (3) Mikrotik-Rate-Limit = "32k" (3) Finished request Waking up in 1.9 seconds. (4) Received Accounting-Request Id 19 from 187.19.96.40:39970 to 172.31.255.188:1813 length 158 (4) Service-Type = Framed-User (4) Framed-Protocol = PPP (4) NAS-Port = 15728648 (4) NAS-Port-Type = Ethernet (4) User-Name = "teste-sql" (4) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (4) Called-Station-Id = "CSC-755-rt-01" (4) NAS-Port-Id = "vlan14" (4) Acct-Session-Id = "81800003" (4) Framed-IP-Address = 0.0.0.0 (4) Acct-Authentic = RADIUS (4) Event-Timestamp = "Oct 18 2016 08:28:53 BRST" (4) Acct-Status-Type = Start (4) NAS-Identifier = "CSC-755-rt-01" (4) Acct-Delay-Time = 0 (4) NAS-IP-Address = 187.19.96.40 (4) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (4) preacct { (4) policy acct_unique { (4) update request { (4) Tmp-String-9 := "ai:" (4) } # update request = noop (4) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (4) EXPAND %{hex:&Class} (4) --> (4) EXPAND ^%{hex:&Tmp-String-9} (4) --> ^61693a (4) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (4) else { (4) update request { (4) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (4) --> 747ce123cf0bf502dfc1fb210db060a6 (4) &Acct-Unique-Session-Id := 747ce123cf0bf502dfc1fb210db060a6 (4) } # update request = noop (4) } # else = noop (4) } # policy acct_unique = noop (4) } # preacct = noop (4) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (4) accounting { (4) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (4) sql: --> type.start.query (4) sql: Using query template 'query' rlm_sql (sql): Reserved connection (13) (4) sql: EXPAND %{User-Name} (4) sql: --> teste-sql (4) sql: SQL-User-Name set to 'teste-sql' (4) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}') (4) sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('81800003', '747ce123cf0bf502dfc1fb210db060a6', 'teste-sql', '', '187.19.96.40', 'vlan14', 'Ethernet', FROM_UNIXTIME(1476786533), FROM_UNIXTIME(1476786533), NULL, '0', 'RADIUS', '', '', '0', '0', 'CSC-755-rt-01', 'E4:8D:8C:EC:90:A2', '', 'Framed-User', 'PPP', '0.0.0.0') (4) sql: EXPAND /usr/local/var/log/radius/sqllog.sql (4) sql: --> /usr/local/var/log/radius/sqllog.sql (4) sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('81800003', '747ce123cf0bf502dfc1fb210db060a6', 'teste-sql', '', '187.19.96.40', 'vlan14', 'Ethernet', FROM_UNIXTIME(1476786533), FROM_UNIXTIME(1476786533), NULL, '0', 'RADIUS', '', '', '0', '0', 'CSC-755-rt-01', 'E4:8D:8C:EC:90:A2', '', 'Framed-User', 'PPP', '0.0.0.0') (4) sql: SQL query returned: success (4) sql: 1 record(s) updated rlm_sql (sql): Released connection (13) (4) [sql] = ok (4) attr_filter.accounting_response: EXPAND %{User-Name} (4) attr_filter.accounting_response: --> teste-sql (4) attr_filter.accounting_response: Matched entry DEFAULT at line 12 (4) [attr_filter.accounting_response] = updated (4) } # accounting = updated (4) Sent Accounting-Response Id 19 from 172.31.255.188:1813 to 187.19.96.40:39970 length 0 (4) Finished request (4) Cleaning up request packet ID 19 with timestamp +56 Waking up in 1.9 seconds. (3) Cleaning up request packet ID 18 with timestamp +56 Ready to process requests (5) Received Accounting-Request Id 19 from 187.19.96.40:1073 to 172.31.255.188:1813 length 158 (5) Service-Type = Framed-User (5) Framed-Protocol = PPP (5) NAS-Port = 15728648 (5) NAS-Port-Type = Ethernet (5) User-Name = "teste-sql" (5) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (5) Called-Station-Id = "CSC-755-rt-01" (5) NAS-Port-Id = "vlan14" (5) Acct-Session-Id = "81800003" (5) Framed-IP-Address = 0.0.0.0 (5) Acct-Authentic = RADIUS (5) Event-Timestamp = "Oct 18 2016 08:28:53 BRST" (5) Acct-Status-Type = Start (5) NAS-Identifier = "CSC-755-rt-01" (5) Acct-Delay-Time = 3 (5) NAS-IP-Address = 187.19.96.40 (5) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (5) preacct { (5) policy acct_unique { (5) update request { (5) Tmp-String-9 := "ai:" (5) } # update request = noop (5) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (5) EXPAND %{hex:&Class} (5) --> (5) EXPAND ^%{hex:&Tmp-String-9} (5) --> ^61693a (5) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (5) 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) --> 747ce123cf0bf502dfc1fb210db060a6 (5) &Acct-Unique-Session-Id := 747ce123cf0bf502dfc1fb210db060a6 (5) } # update request = noop (5) } # else = noop (5) } # policy acct_unique = noop (5) } # preacct = noop (5) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (5) accounting { (5) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (5) sql: --> type.start.query (5) sql: Using query template 'query' rlm_sql (sql): Reserved connection (14) (5) sql: EXPAND %{User-Name} (5) sql: --> teste-sql (5) sql: SQL-User-Name set to 'teste-sql' (5) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}') (5) sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('81800003', '747ce123cf0bf502dfc1fb210db060a6', 'teste-sql', '', '187.19.96.40', 'vlan14', 'Ethernet', FROM_UNIXTIME(1476786533), FROM_UNIXTIME(1476786533), NULL, '0', 'RADIUS', '', '', '0', '0', 'CSC-755-rt-01', 'E4:8D:8C:EC:90:A2', '', 'Framed-User', 'PPP', '0.0.0.0') (5) sql: EXPAND /usr/local/var/log/radius/sqllog.sql (5) sql: --> /usr/local/var/log/radius/sqllog.sql (5) sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('81800003', '747ce123cf0bf502dfc1fb210db060a6', 'teste-sql', '', '187.19.96.40', 'vlan14', 'Ethernet', FROM_UNIXTIME(1476786533), FROM_UNIXTIME(1476786533), NULL, '0', 'RADIUS', '', '', '0', '0', 'CSC-755-rt-01', 'E4:8D:8C:EC:90:A2', '', 'Framed-User', 'PPP', '0.0.0.0') (5) sql: rlm_sql_mysql: ERROR 1062 (Duplicate entry '747ce123cf0bf502dfc1fb210db060a6' for key 'acctuniqueid'): 23000 (5) sql: SQL query returned: need alt query (5) sql: Trying next query... (5) sql: EXPAND UPDATE radacct SET acctstarttime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), connectinfo_start = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' (5) sql: --> UPDATE radacct SET acctstarttime = FROM_UNIXTIME(1476786533), acctupdatetime = FROM_UNIXTIME(1476786533), connectinfo_start = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' (5) sql: EXPAND /usr/local/var/log/radius/sqllog.sql (5) sql: --> /usr/local/var/log/radius/sqllog.sql (5) sql: Executing query: UPDATE radacct SET acctstarttime = FROM_UNIXTIME(1476786533), acctupdatetime = FROM_UNIXTIME(1476786533), connectinfo_start = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' rlm_sql_mysql: Rows matched: 1 Changed: 0 Warnings: 0 (5) sql: SQL query returned: success (5) sql: 1 record(s) updated rlm_sql (sql): Released connection (14) rlm_sql (sql): Closing connection (15), from 6 unused connections rlm_sql_mysql: Socket destructor called, closing socket (5) [sql] = ok (5) attr_filter.accounting_response: EXPAND %{User-Name} (5) attr_filter.accounting_response: --> teste-sql (5) attr_filter.accounting_response: Matched entry DEFAULT at line 12 (5) [attr_filter.accounting_response] = updated (5) } # accounting = updated (5) Sent Accounting-Response Id 19 from 172.31.255.188:1813 to 187.19.96.40:1073 length 0 (5) Finished request (5) Cleaning up request packet ID 19 with timestamp +59 Ready to process requests (6) Received Accounting-Request Id 20 from 187.19.96.40:35154 to 172.31.255.188:1813 length 206 (6) Service-Type = Framed-User (6) Framed-Protocol = PPP (6) NAS-Port = 15728648 (6) NAS-Port-Type = Ethernet (6) User-Name = "teste-sql" (6) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (6) Called-Station-Id = "CSC-755-rt-01" (6) NAS-Port-Id = "vlan14" (6) Acct-Session-Id = "81800003" (6) Framed-IP-Address = 0.0.0.0 (6) Acct-Authentic = RADIUS (6) Event-Timestamp = "Oct 18 2016 08:29:07 BRST" (6) Acct-Session-Time = 14 (6) Acct-Input-Octets = 65 (6) Acct-Input-Gigawords = 0 (6) Acct-Input-Packets = 6 (6) Acct-Output-Octets = 50 (6) Acct-Output-Gigawords = 0 (6) Acct-Output-Packets = 7 (6) Acct-Status-Type = Stop (6) Acct-Terminate-Cause = User-Request (6) NAS-Identifier = "CSC-755-rt-01" (6) Acct-Delay-Time = 0 (6) NAS-IP-Address = 187.19.96.40 (6) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (6) preacct { (6) policy acct_unique { (6) update request { (6) Tmp-String-9 := "ai:" (6) } # update request = noop (6) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (6) EXPAND %{hex:&Class} (6) --> (6) EXPAND ^%{hex:&Tmp-String-9} (6) --> ^61693a (6) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (6) 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) --> 747ce123cf0bf502dfc1fb210db060a6 (6) &Acct-Unique-Session-Id := 747ce123cf0bf502dfc1fb210db060a6 (6) } # update request = noop (6) } # else = noop (6) } # policy acct_unique = noop (6) } # preacct = noop (6) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (6) accounting { (6) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (6) sql: --> type.stop.query (6) sql: Using query template 'query' rlm_sql (sql): Closing connection (16): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (17): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (18): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (19): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (20): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (21): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (22): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (23): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (24): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (25): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (26): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (27): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (28): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (29): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (0): Hit idle_timeout, was idle for 70 seconds rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Reserved connection (1) (6) sql: EXPAND %{User-Name} (6) sql: --> teste-sql (6) sql: SQL-User-Name set to 'teste-sql' (6) sql: EXPAND UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = %{%{Acct-Session-Time}:-NULL}, 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 AcctUniqueId = '%{Acct-Unique-Session-Id}' (6) sql: --> UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1476786547), acctsessiontime = 14, acctinputoctets = '0' << 32 | '65', acctoutputoctets = '0' << 32 | '50', acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' (6) sql: EXPAND /usr/local/var/log/radius/sqllog.sql (6) sql: --> /usr/local/var/log/radius/sqllog.sql (6) sql: Executing query: UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1476786547), acctsessiontime = 14, acctinputoctets = '0' << 32 | '65', acctoutputoctets = '0' << 32 | '50', acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 (6) sql: SQL query returned: success (6) sql: 1 record(s) updated rlm_sql (sql): Released connection (1) (6) [sql] = ok (6) attr_filter.accounting_response: EXPAND %{User-Name} (6) attr_filter.accounting_response: --> teste-sql (6) attr_filter.accounting_response: Matched entry DEFAULT at line 12 (6) [attr_filter.accounting_response] = updated (6) } # accounting = updated (6) Sent Accounting-Response Id 20 from 172.31.255.188:1813 to 187.19.96.40:35154 length 0 (6) Finished request (6) Cleaning up request packet ID 20 with timestamp +70 Ready to process requests (7) Received Accounting-Request Id 20 from 187.19.96.40:35154 to 172.31.255.188:1813 length 206 (7) Service-Type = Framed-User (7) Framed-Protocol = PPP (7) NAS-Port = 15728648 (7) NAS-Port-Type = Ethernet (7) User-Name = "teste-sql" (7) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (7) Called-Station-Id = "CSC-755-rt-01" (7) NAS-Port-Id = "vlan14" (7) Acct-Session-Id = "81800003" (7) Framed-IP-Address = 0.0.0.0 (7) Acct-Authentic = RADIUS (7) Event-Timestamp = "Oct 18 2016 08:29:07 BRST" (7) Acct-Session-Time = 14 (7) Acct-Input-Octets = 65 (7) Acct-Input-Gigawords = 0 (7) Acct-Input-Packets = 6 (7) Acct-Output-Octets = 50 (7) Acct-Output-Gigawords = 0 (7) Acct-Output-Packets = 7 (7) Acct-Status-Type = Stop (7) Acct-Terminate-Cause = User-Request (7) NAS-Identifier = "CSC-755-rt-01" (7) Acct-Delay-Time = 3 (7) NAS-IP-Address = 187.19.96.40 (7) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (7) preacct { (7) policy acct_unique { (7) update request { (7) Tmp-String-9 := "ai:" (7) } # update request = noop (7) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (7) EXPAND %{hex:&Class} (7) --> (7) EXPAND ^%{hex:&Tmp-String-9} (7) --> ^61693a (7) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (7) 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) --> 747ce123cf0bf502dfc1fb210db060a6 (7) &Acct-Unique-Session-Id := 747ce123cf0bf502dfc1fb210db060a6 (7) } # update request = noop (7) } # else = noop (7) } # policy acct_unique = noop (7) } # preacct = noop (7) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (7) accounting { (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 (3) (7) sql: EXPAND %{User-Name} (7) sql: --> teste-sql (7) sql: SQL-User-Name set to 'teste-sql' (7) sql: EXPAND UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = %{%{Acct-Session-Time}:-NULL}, 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 AcctUniqueId = '%{Acct-Unique-Session-Id}' (7) sql: --> UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1476786547), acctsessiontime = 14, acctinputoctets = '0' << 32 | '65', acctoutputoctets = '0' << 32 | '50', acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' (7) sql: EXPAND /usr/local/var/log/radius/sqllog.sql (7) sql: --> /usr/local/var/log/radius/sqllog.sql (7) sql: Executing query: UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1476786547), acctsessiontime = 14, acctinputoctets = '0' << 32 | '65', acctoutputoctets = '0' << 32 | '50', acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' rlm_sql_mysql: Rows matched: 1 Changed: 0 Warnings: 0 (7) sql: SQL query returned: success (7) sql: 1 record(s) updated rlm_sql (sql): Released connection (3) (7) [sql] = ok (7) attr_filter.accounting_response: EXPAND %{User-Name} (7) attr_filter.accounting_response: --> teste-sql (7) attr_filter.accounting_response: Matched entry DEFAULT at line 12 (7) [attr_filter.accounting_response] = updated (7) } # accounting = updated (7) Sent Accounting-Response Id 20 from 172.31.255.188:1813 to 187.19.96.40:35154 length 0 (7) Finished request (7) Cleaning up request packet ID 20 with timestamp +73 Ready to process requests (8) Received Accounting-Request Id 20 from 187.19.96.40:35154 to 172.31.255.188:1813 length 206 (8) Service-Type = Framed-User (8) Framed-Protocol = PPP (8) NAS-Port = 15728648 (8) NAS-Port-Type = Ethernet (8) User-Name = "teste-sql" (8) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (8) Called-Station-Id = "CSC-755-rt-01" (8) NAS-Port-Id = "vlan14" (8) Acct-Session-Id = "81800003" (8) Framed-IP-Address = 0.0.0.0 (8) Acct-Authentic = RADIUS (8) Event-Timestamp = "Oct 18 2016 08:29:07 BRST" (8) Acct-Session-Time = 14 (8) Acct-Input-Octets = 65 (8) Acct-Input-Gigawords = 0 (8) Acct-Input-Packets = 6 (8) Acct-Output-Octets = 50 (8) Acct-Output-Gigawords = 0 (8) Acct-Output-Packets = 7 (8) Acct-Status-Type = Stop (8) Acct-Terminate-Cause = User-Request (8) NAS-Identifier = "CSC-755-rt-01" (8) Acct-Delay-Time = 6 (8) NAS-IP-Address = 187.19.96.40 (8) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (8) preacct { (8) policy acct_unique { (8) update request { (8) Tmp-String-9 := "ai:" (8) } # update request = noop (8) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (8) EXPAND %{hex:&Class} (8) --> (8) EXPAND ^%{hex:&Tmp-String-9} (8) --> ^61693a (8) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (8) else { (8) update request { (8) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (8) --> 747ce123cf0bf502dfc1fb210db060a6 (8) &Acct-Unique-Session-Id := 747ce123cf0bf502dfc1fb210db060a6 (8) } # update request = noop (8) } # else = noop (8) } # policy acct_unique = noop (8) } # preacct = noop (8) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (8) accounting { (8) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (8) sql: --> type.stop.query (8) sql: Using query template 'query' rlm_sql (sql): Reserved connection (4) (8) sql: EXPAND %{User-Name} (8) sql: --> teste-sql (8) sql: SQL-User-Name set to 'teste-sql' (8) sql: EXPAND UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = %{%{Acct-Session-Time}:-NULL}, 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 AcctUniqueId = '%{Acct-Unique-Session-Id}' (8) sql: --> UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1476786547), acctsessiontime = 14, acctinputoctets = '0' << 32 | '65', acctoutputoctets = '0' << 32 | '50', acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' (8) sql: EXPAND /usr/local/var/log/radius/sqllog.sql (8) sql: --> /usr/local/var/log/radius/sqllog.sql (8) sql: Executing query: UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1476786547), acctsessiontime = 14, acctinputoctets = '0' << 32 | '65', acctoutputoctets = '0' << 32 | '50', acctterminatecause = 'User-Request', connectinfo_stop = '' WHERE AcctUniqueId = '747ce123cf0bf502dfc1fb210db060a6' rlm_sql_mysql: Rows matched: 1 Changed: 0 Warnings: 0 (8) sql: SQL query returned: success (8) sql: 1 record(s) updated rlm_sql (sql): Released connection (4) (8) [sql] = ok (8) attr_filter.accounting_response: EXPAND %{User-Name} (8) attr_filter.accounting_response: --> teste-sql (8) attr_filter.accounting_response: Matched entry DEFAULT at line 12 (8) [attr_filter.accounting_response] = updated (8) } # accounting = updated (8) Sent Accounting-Response Id 20 from 172.31.255.188:1813 to 187.19.96.40:35154 length 0 (8) Finished request (8) Cleaning up request packet ID 20 with timestamp +76 Ready to process requests This is just one connection running and I saw that 0, 1, 2 and 3 are all Access-Request: (0) Received Access-Request Id 17 from 187.19.96.40:35728 to 172.31.255.188:1812 length 136 (0) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728647 cli E4:8D:8C:EC:90:A2) (1) Received Access-Request Id 17 from 187.19.96.40:35728 to 172.31.255.188:1812 length 136 (1) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728647 cli E4:8D:8C:EC:90:A2) (2) Received Access-Request Id 17 from 187.19.96.40:35728 to 172.31.255.188:1812 length 136 (2) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728647 cli E4:8D:8C:EC:90:A2) (3) Received Access-Request Id 18 from 187.19.96.40:36982 to 172.31.255.188:1812 length 136 (3) Login OK: [teste-sql] (from client CSC-755-rt-01 port 15728648 cli E4:8D:8C:EC:90:A2) But for some reasons I can't find the only Accounting-Request is made to connection number 3 (NAS-Port = 15728648): (4) Received Accounting-Request Id 19 from 187.19.96.40:39970 to 172.31.255.188:1813 length 158 (4) Service-Type = Framed-User (4) Framed-Protocol = PPP (4) NAS-Port = 15728648 (4) NAS-Port-Type = Ethernet (4) User-Name = "teste-sql" (4) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (4) Called-Station-Id = "CSC-755-rt-01" (4) NAS-Port-Id = "vlan14" (4) Acct-Session-Id = "81800003" (4) Framed-IP-Address = 0.0.0.0 (4) Acct-Authentic = RADIUS (4) Event-Timestamp = "Oct 18 2016 08:28:53 BRST" (4) Acct-Status-Type = Start (4) NAS-Identifier = "CSC-755-rt-01" (4) Acct-Delay-Time = 0 (4) NAS-IP-Address = 187.19.96.40 Them, again I have a repeated Accounting-Request that I can't explain on number 5: (5) Received Accounting-Request Id 19 from 187.19.96.40:1073 to 172.31.255.188:1813 length 158 (5) Service-Type = Framed-User (5) Framed-Protocol = PPP (5) NAS-Port = 15728648 (5) NAS-Port-Type = Ethernet (5) User-Name = "teste-sql" (5) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (5) Called-Station-Id = "CSC-755-rt-01" (5) NAS-Port-Id = "vlan14" (5) Acct-Session-Id = "81800003" (5) Framed-IP-Address = 0.0.0.0 (5) Acct-Authentic = RADIUS (5) Event-Timestamp = "Oct 18 2016 08:28:53 BRST" (5) Acct-Status-Type = Start (5) NAS-Identifier = "CSC-755-rt-01" (5) Acct-Delay-Time = 3 (5) NAS-IP-Address = 187.19.96.40 the Acct-Delay-Time is set to 3 (seconds) which is the exact time set to PPPoE NAS Server as a Radius Timeout: [admin@CSC-755-rt-01] > radius print detail Flags: X - disabled 0 service=ppp called-id="" domain="" address=172.31.255.188 secret="testing123" authentication-port=1812 accounting-port=1813 timeout=3s accounting-backup=no realm="" src-address=187.19.96.40 Then the Radius register an Accounting-Request as stop when I stop the test connection: (6) Received Accounting-Request Id 20 from 187.19.96.40:35154 to 172.31.255.188:1813 length 206 (6) Service-Type = Framed-User (6) Framed-Protocol = PPP (6) NAS-Port = 15728648 (6) NAS-Port-Type = Ethernet (6) User-Name = "teste-sql" (6) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (6) Called-Station-Id = "CSC-755-rt-01" (6) NAS-Port-Id = "vlan14" (6) Acct-Session-Id = "81800003" (6) Framed-IP-Address = 0.0.0.0 (6) Acct-Authentic = RADIUS (6) Event-Timestamp = "Oct 18 2016 08:29:07 BRST" (6) Acct-Session-Time = 14 (6) Acct-Input-Octets = 65 (6) Acct-Input-Gigawords = 0 (6) Acct-Input-Packets = 6 (6) Acct-Output-Octets = 50 (6) Acct-Output-Gigawords = 0 (6) Acct-Output-Packets = 7 (6) Acct-Status-Type = Stop (6) Acct-Terminate-Cause = User-Request (6) NAS-Identifier = "CSC-755-rt-01" (6) Acct-Delay-Time = 0 (6) NAS-IP-Address = 187.19.96.40 And again, exact 3 seconds later, a new request as number 7: (7) Received Accounting-Request Id 20 from 187.19.96.40:35154 to 172.31.255.188:1813 length 206 (7) Service-Type = Framed-User (7) Framed-Protocol = PPP (7) NAS-Port = 15728648 (7) NAS-Port-Type = Ethernet (7) User-Name = "teste-sql" (7) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (7) Called-Station-Id = "CSC-755-rt-01" (7) NAS-Port-Id = "vlan14" (7) Acct-Session-Id = "81800003" (7) Framed-IP-Address = 0.0.0.0 (7) Acct-Authentic = RADIUS (7) Event-Timestamp = "Oct 18 2016 08:29:07 BRST" (7) Acct-Session-Time = 14 (7) Acct-Input-Octets = 65 (7) Acct-Input-Gigawords = 0 (7) Acct-Input-Packets = 6 (7) Acct-Output-Octets = 50 (7) Acct-Output-Gigawords = 0 (7) Acct-Output-Packets = 7 (7) Acct-Status-Type = Stop (7) Acct-Terminate-Cause = User-Request (7) NAS-Identifier = "CSC-755-rt-01" (7) Acct-Delay-Time = 3 (7) NAS-IP-Address = 187.19.96.40 And in this I have a third try with 6 seconds as request 8: (8) Received Accounting-Request Id 20 from 187.19.96.40:35154 to 172.31.255.188:1813 length 206 (8) Service-Type = Framed-User (8) Framed-Protocol = PPP (8) NAS-Port = 15728648 (8) NAS-Port-Type = Ethernet (8) User-Name = "teste-sql" (8) Calling-Station-Id = "E4:8D:8C:EC:90:A2" (8) Called-Station-Id = "CSC-755-rt-01" (8) NAS-Port-Id = "vlan14" (8) Acct-Session-Id = "81800003" (8) Framed-IP-Address = 0.0.0.0 (8) Acct-Authentic = RADIUS (8) Event-Timestamp = "Oct 18 2016 08:29:07 BRST" (8) Acct-Session-Time = 14 (8) Acct-Input-Octets = 65 (8) Acct-Input-Gigawords = 0 (8) Acct-Input-Packets = 6 (8) Acct-Output-Octets = 50 (8) Acct-Output-Gigawords = 0 (8) Acct-Output-Packets = 7 (8) Acct-Status-Type = Stop (8) Acct-Terminate-Cause = User-Request (8) NAS-Identifier = "CSC-755-rt-01" (8) Acct-Delay-Time = 6 (8) NAS-IP-Address = 187.19.96.40 I know there is something I am missing in FreeRadius but I am not being able to find out what. I hope someone can help me something I didn't see. The NAS configuration is the same I use on older FreeRadius version (and it's working fine). Atenciosamente, *Nataniel Klug* | nataniel.klug@gmail.com