Long delay on response to PPPoE NAS (Mikrotik) on FreeRadius 3.0.12 + MySQL
Nataniel Klug
nataniel.klug at gmail.com
Tue Oct 18 14:14:44 CEST 2016
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 at 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 at gmail.com
More information about the Freeradius-Users
mailing list