Freeradius 3.0.9 Hi, I have a simple setup using Simultaneous-Use=1 and checkrad with sql as the session backend. [freeradius] ------------ [nas] ------------- [user] server default { listen { type = auth ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = acct ipaddr = * port = 0 } authorize { filter_username preprocess chap suffix custom_python expiration logintime } authenticate { Auth-Type CHAP { chap } } preacct { preprocess acct_unique suffix } accounting { custom_python -sql attr_filter.accounting_response } session { sql } post-auth { -sql Post-Auth-Type REJECT { attr_filter.access_reject } } } I got excited that I can use checkrad to immediately remove stale sessions from radacct table by simply querying the nas. So I tested a situation where I connect a client to the NAS. radacct table looks now like this: id:1 acctsessionid:7427542-L_pppoe1-1 acctuniqueid:ef4c9a0535776f8a2a8f6de0f7afad48 username:user nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet acctstarttime:2015-11-13 16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:NULL I then proceed to reboot the nas (non-gracefully) to simulate the effect of nas hardware failure. Once the nas is up, a connection attempt is made by the client. The access request received has a different Acct-Session-Id: 7427566-L_pppoe1-1 (the previous one was: 7427542-L_pppoe1-1) During the request radius checks for an existing session in radacct SELECT COUNT(*) FROM radacct WHERE username = 'user' AND acctstoptime IS NULL It returns 1, so it queries for additional data to invoke checkrad with SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = 'user' AND acctstoptime IS NULL Checkrad is invoked with params: ( nas_ip: 10.2.2.14, nas_port: 0, session_id: 7427542-L_pppoe1-1, login: user ). Return code is 0 (no logged user) so it's time to cleanup a stale session. (And this is where problems start) Since this Access-Request has a different Acct-Session-Id, the hash value of Acct-Unique-Session-Id is different. An update query is called to remove the stale session, but because of the different Acct-Unique-Session-Id it doesn't match the previous session entry. UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1447427566), acctsessiontime = 192, acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = '', connectinfo_stop = '' WHERE AcctUniqueId = '9785b846930595ba6d83f5955a13fa1d' Then a queued? (Says 'trying next query...') query is called which inserts a new session entry to radacct table: 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 ('7427542-L_pppoe1-1', '9785b846930595ba6d83f5955a13fa1d', 'user', '', '10.2.2.14', '0', '', FROM_UNIXTIME(1447427566 - 192), FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), 192, '', '', '', '0' << 32 | '0', '0' << 32 | '0', '', '', '', 'Framed-User', 'PPP', '10.10.11.42') At this point radacct table looks like this: id:1 acctsessionid:7427542-L_pppoe1-1 acctuniqueid:ef4c9a0535776f8a2a8f6de0f7afad48 username:user nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet acctstarttime:2015-11-13 16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:NULL id:2 acctsessionid:7427542-L_pppoe1-1 acctuniqueid:9785b846930595ba6d83f5955a13fa1d username:user nasipaddress:10.2.2.14 nasportid:0 nasporttype:Ethernet acctstarttime:2015-11-13 16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:2015-11-13 16:12:46 Now an Accounting-Request comes in and anoher radacct table insert is made: 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 ('7427566-L_pppoe1-1', '502963895dc1d5a8f1d967d6f1e3db04', 'user', '', '10.2.2.14', 'em1', 'Ethernet', FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), NULL, '0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '', 'Framed-User', 'PPP', '10.10.11.42') At this point radacct table looks like this: id:1 acctsessionid:7427542-L_pppoe1-1 acctuniqueid:ef4c9a0535776f8a2a8f6de0f7afad48 username:user nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet acctstarttime:2015-11-13 16:12:21 acctupdatetime:2015-11-13 16:12:21 acctstoptime:NULL id:2 acctsessionid:7427542-L_pppoe1-1 acctuniqueid:9785b846930595ba6d83f5955a13fa1d username:user nasipaddress:10.2.2.14 nasportid:0 nasporttype:Ethernet acctstarttime:2015-11-13 16:09:34 acctupdatetime:2015-11-13 16:12:46 acctstoptime:2015-11-13 16:12:46 id:3 acctsessionid:7427542-L_pppoe1-1 acctuniqueid:502963895dc1d5a8f1d967d6f1e3db04 username:user nasipaddress:10.2.2.14 nasportid:em1 nasporttype:Ethernet acctstarttime:2015-11-13 16:12:46 acctupdatetime:2015-11-13 16:12:46 acctstoptime:NULL So there's a total 3 records when I would expect to see just 2. Bad news is that whenever "user" connects it will force checkrad to be called always (since there always will be a stale session). Good news is that the "user" will be allowed because checkrad will correctly report that there's no such user logged in the nas. One solution I see would be to use a cronjob to periodically remove such stale entries. However I thought that the whole point of checkrad was to close such entries in the first place. Checkrad is supplied with parameters from this query: SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = 'user' AND acctstoptime IS NULL Among them is 'AcctSessionId' which I would expect to be used to close a stale session, but instead in the update query 'AcctUniqueId' from the current request is used which will never match. Leaving a stale entry behind. Anything I can do to fix it? Or is a cronjob the only solution (but then it means that checkrad is a little bit wonky) Thank you. Below I supplied a debug log of: 1)Access-Request 2)Accounting-Request [nas gets killed at this point and reboots] 3)Access-Request 4)Accounting-Request Listening on proxy address * port 22303 Ready to process requests (0) Received Access-Request Id 66 from 10.2.2.14:30089 to 10.2.2.13:1812 length 237 (0) NAS-Identifier = "ppoe" (0) Message-Authenticator = 0x6d2402b5a07673ab6e60fe1a5f36cc52 (0) Acct-Session-Id = "7427542-L_pppoe1-1" (0) NAS-Port = 1 (0) NAS-Port-Type = Ethernet (0) Service-Type = Framed-User (0) Framed-Protocol = PPP (0) Calling-Station-Id = "6a:61:0a:7f:37:27" (0) Called-Station-Id = "service1" (0) NAS-Port-Id = "em1" (0) Attr-26.12341.12 = 0x4c5f7070706f65312d31 (0) Attr-26 = 0x000030351302 (0) Tunnel-Medium-Type:0 = IEEE-802 (0) Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27" (0) User-Name = "user" (0) CHAP-Challenge = 0xbb1e687466a51fdc396ecbd5c48e2bafbf72350a8f492cc599e7b446dbbb3ab320f0288695 (0) CHAP-Password = 0x01c71a4709e5ae36393254df5afe44adf3 (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (0) authorize { (0) policy filter_username { (0) if (!&User-Name) { (0) if (!&User-Name) -> FALSE (0) if (&User-Name =~ / /) { (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@.*@/ ) { (0) if (&User-Name =~ /@.*@/ ) -> FALSE (0) if (&User-Name =~ /\.\./ ) { (0) if (&User-Name =~ /\.\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\.$/) { (0) if (&User-Name =~ /\.$/) -> FALSE (0) if (&User-Name =~ /@\./) { (0) if (&User-Name =~ /@\./) -> FALSE (0) } # policy filter_username = notfound (0) [preprocess] = ok (0) chap: &control:Auth-Type := CHAP (0) [chap] = ok (0) suffix: Checking for suffix after "@" (0) suffix: No '@' in User-Name = "user", looking up realm NULL (0) suffix: No such realm "NULL" (0) [suffix] = noop rlm_python:authorize: 'MS-Primary-DNS-Server' = '10.10.11.1' rlm_python:authorize: 'MS-Secondary-DNS-Server' = '8.8.8.8' rlm_python:authorize: 'Framed-Ip-Address' = '10.10.11.42' rlm_python:authorize: 'Simultaneous-Use' = '1' rlm_python:authorize: 'Cleartext-Password' = 'pass123' (0) [custom_python] = updated (0) [expiration] = noop (0) [logintime] = noop (0) } # authorize = updated (0) Found Auth-Type = CHAP (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Auth-Type CHAP { (0) chap: Comparing with "known good" Cleartext-Password (0) chap: CHAP user "user" authenticated successfully (0) [chap] = ok (0) } # Auth-Type CHAP = ok (0) # Executing section session from file /usr/local/etc/raddb/sites-enabled/default (0) session { (0) sql: EXPAND %{User-Name} (0) sql: --> user (0) sql: SQL-User-Name set to 'user' (0) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL (0) sql: --> SELECT COUNT(*) FROM radacct WHERE username = 'user' AND acctstoptime IS NULL rlm_sql (sql): Reserved connection (0) (0) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = 'user' AND acctstoptime IS NULL rlm_sql (sql): Released connection (0) rlm_sql (sql): 0 of 5 connections in use. Need more spares rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'lms' on Localhost via UNIX socket, server version 10.0.21-MariaDB, protocol version 10 (0) [sql] = ok (0) } # session = ok (0) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default (0) post-auth { (0) sql: EXPAND .query (0) sql: --> .query (0) sql: Using query template 'query' rlm_sql (sql): Reserved connection (1) (0) sql: EXPAND %{User-Name} (0) sql: --> user (0) sql: SQL-User-Name set to 'user' (0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (0) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '0x01c71a4709e5ae36393254df5afe44adf3', 'Access-Accept', '2015-11-13 16:12:21') (0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '0x01c71a4709e5ae36393254df5afe44adf3', 'Access-Accept', '2015-11-13 16:12:21') (0) sql: SQL query returned: success (0) sql: 1 record(s) updated rlm_sql (sql): Released connection (1) (0) [sql] = ok (0) } # post-auth = ok (0) Sent Access-Accept Id 66 from 10.2.2.13:1812 to 10.2.2.14:30089 length 0 (0) MS-Primary-DNS-Server = 10.10.11.1 (0) MS-Secondary-DNS-Server = 8.8.8.8 (0) Framed-IP-Address = 10.10.11.42 (0) Finished request Waking up in 4.9 seconds. (1) Received Accounting-Request Id 6 from 10.2.2.14:21504 to 10.2.2.13:1813 length 254 (1) NAS-Identifier = "ppoe" (1) Acct-Session-Id = "7427542-L_pppoe1-1" (1) NAS-Port = 1 (1) NAS-Port-Type = Ethernet (1) Service-Type = Framed-User (1) Framed-Protocol = PPP (1) Calling-Station-Id = "6a:61:0a:7f:37:27" (1) Called-Station-Id = "service1" (1) NAS-Port-Id = "em1" (1) Attr-26.12341.12 = 0x4c5f7070706f65312d31 (1) Attr-26 = 0x000030351302 (1) Tunnel-Medium-Type:0 = IEEE-802 (1) Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27" (1) Acct-Status-Type = Start (1) Framed-IP-Address = 10.10.11.42 (1) User-Name = "user" (1) Acct-Multi-Session-Id = "7427542-B_pppoe1-1" (1) Attr-26.12341.13 = 0x425f7070706f65312d31 (1) Attr-26.12341.14 = 0x6e6730 (1) Attr-26.12341.15 = 0x00000004 (1) Attr-26 = 0x000030351302 (1) Acct-Link-Count = 1 (1) Acct-Authentic = RADIUS (1) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (1) preacct { (1) [preprocess] = ok (1) policy acct_unique { (1) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { (1) EXPAND %{string:Class} (1) --> (1) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (1) else { (1) update request { (1) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (1) --> ef4c9a0535776f8a2a8f6de0f7afad48 (1) &Acct-Unique-Session-Id := ef4c9a0535776f8a2a8f6de0f7afad48 (1) } # update request = noop (1) } # else = noop (1) } # policy acct_unique = noop (1) suffix: Checking for suffix after "@" (1) suffix: No '@' in User-Name = "user", looking up realm NULL (1) suffix: No such realm "NULL" (1) [suffix] = noop (1) } # preacct = ok (1) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (1) accounting { (1) [custom_python] = noop (1) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (1) sql: --> type.start.query (1) sql: Using query template 'query' rlm_sql (sql): Reserved connection (2) (1) sql: EXPAND %{User-Name} (1) sql: --> user (1) sql: SQL-User-Name set to 'user' (1) 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}') (1) 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 ('7427542-L_pppoe1-1', 'ef4c9a0535776f8a2a8f6de0f7afad48', 'user', '', '10.2.2.14', 'em1', 'Ethernet', FROM_UNIXTIME(1447427541), FROM_UNIXTIME(1447427541), NULL, '0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '', 'Framed-User', 'PPP', '10.10.11.42') (1) 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 ('7427542-L_pppoe1-1', 'ef4c9a0535776f8a2a8f6de0f7afad48', 'user', '', '10.2.2.14', 'em1', 'Ethernet', FROM_UNIXTIME(1447427541), FROM_UNIXTIME(1447427541), NULL, '0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '', 'Framed-User', 'PPP', '10.10.11.42') (1) sql: SQL query returned: success (1) sql: 1 record(s) updated rlm_sql (sql): Released connection (2) (1) [sql] = ok (1) attr_filter.accounting_response: EXPAND %{User-Name} (1) attr_filter.accounting_response: --> user (1) attr_filter.accounting_response: Matched entry DEFAULT at line 15 (1) [attr_filter.accounting_response] = updated (1) } # accounting = updated (1) Sent Accounting-Response Id 6 from 10.2.2.13:1813 to 10.2.2.14:21504 length 0 (1) Finished request (1) <done>: Cleaning up request packet ID 6 with timestamp +28 Waking up in 4.9 seconds. (0) <done>: Cleaning up request packet ID 66 with timestamp +28 Ready to process requests (3) Received Access-Request Id 228 from 10.2.2.14:19182 to 10.2.2.13:1812 length 234 (3) NAS-Identifier = "ppoe" (3) Message-Authenticator = 0x8635f9c9047b7a815f56ac7539937a50 (3) Acct-Session-Id = "7427566-L_pppoe1-1" (3) NAS-Port = 1 (3) NAS-Port-Type = Ethernet (3) Service-Type = Framed-User (3) Framed-Protocol = PPP (3) Calling-Station-Id = "6a:61:0a:7f:37:27" (3) Called-Station-Id = "service1" (3) NAS-Port-Id = "em1" (3) Attr-26.12341.12 = 0x4c5f7070706f65312d31 (3) Attr-26 = 0x000030351302 (3) Tunnel-Medium-Type:0 = IEEE-802 (3) Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27" (3) User-Name = "user" (3) CHAP-Challenge = 0xbb1e6800688010c3ef4cada327bf23a1f8bc2e4cf15e765693eb03a6eb1a0af5da9c (3) CHAP-Password = 0x01f29750c6827e6ff5e45baa625d131275 (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (3) authorize { (3) policy filter_username { (3) if (!&User-Name) { (3) if (!&User-Name) -> FALSE (3) if (&User-Name =~ / /) { (3) if (&User-Name =~ / /) -> FALSE (3) if (&User-Name =~ /@.*@/ ) { (3) if (&User-Name =~ /@.*@/ ) -> FALSE (3) if (&User-Name =~ /\.\./ ) { (3) if (&User-Name =~ /\.\./ ) -> FALSE (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (3) if (&User-Name =~ /\.$/) { (3) if (&User-Name =~ /\.$/) -> FALSE (3) if (&User-Name =~ /@\./) { (3) if (&User-Name =~ /@\./) -> FALSE (3) } # policy filter_username = notfound (3) [preprocess] = ok (3) chap: &control:Auth-Type := CHAP (3) [chap] = ok (3) suffix: Checking for suffix after "@" (3) suffix: No '@' in User-Name = "user", looking up realm NULL (3) suffix: No such realm "NULL" (3) [suffix] = noop rlm_python:authorize: 'MS-Primary-DNS-Server' = '10.10.11.1' rlm_python:authorize: 'MS-Secondary-DNS-Server' = '8.8.8.8' rlm_python:authorize: 'Framed-Ip-Address' = '10.10.11.42' rlm_python:authorize: 'Simultaneous-Use' = '1' rlm_python:authorize: 'Cleartext-Password' = 'pass123' (3) [custom_python] = updated (3) [expiration] = noop (3) [logintime] = noop (3) } # authorize = updated (3) Found Auth-Type = CHAP (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) Auth-Type CHAP { (3) chap: Comparing with "known good" Cleartext-Password (3) chap: CHAP user "user" authenticated successfully (3) [chap] = ok (3) } # Auth-Type CHAP = ok (3) # Executing section session from file /usr/local/etc/raddb/sites-enabled/default (3) session { (3) sql: EXPAND %{User-Name} (3) sql: --> user (3) sql: SQL-User-Name set to 'user' (3) sql: EXPAND SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL (3) sql: --> SELECT COUNT(*) FROM radacct WHERE username = 'user' AND acctstoptime IS NULL rlm_sql (sql): Reserved connection (3) (3) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = 'user' AND acctstoptime IS NULL (3) sql: EXPAND SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL (3) sql: --> SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = 'user' AND acctstoptime IS NULL (3) sql: Executing select query: SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = 'user' AND acctstoptime IS NULL CHECKRAD CALLED !!! retcode was: 0, nas_ip: 10.2.2.14, nas_port: 0, session_id: 7427542-L_pppoe1-1, login: user (3) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (3) preacct { (3) [preprocess] = ok (3) policy acct_unique { (3) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { (3) EXPAND %{string:Class} (3) --> (3) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (3) else { (3) update request { (3) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (3) --> 9785b846930595ba6d83f5955a13fa1d (3) &Acct-Unique-Session-Id := 9785b846930595ba6d83f5955a13fa1d (3) } # update request = noop (3) } # else = noop (3) } # policy acct_unique = noop (3) suffix: Checking for suffix after "@" (3) suffix: No '@' in User-Name = "user", looking up realm NULL (3) suffix: No such realm "NULL" (3) [suffix] = noop (3) } # preacct = ok (3) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (3) accounting { (3) [custom_python] = noop (3) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (3) sql: --> type.stop.query (3) sql: Using query template 'query' rlm_sql (sql): Reserved connection (4) (3) sql: EXPAND %{User-Name} (3) sql: --> user (3) sql: SQL-User-Name set to 'user' (3) 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}' (3) sql: --> UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1447427566), acctsessiontime = 192, acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = '', connectinfo_stop = '' WHERE AcctUniqueId = '9785b846930595ba6d83f5955a13fa1d' (3) sql: Executing query: UPDATE radacct SET acctstoptime = FROM_UNIXTIME(1447427566), acctsessiontime = 192, acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = '', connectinfo_stop = '' WHERE AcctUniqueId = '9785b846930595ba6d83f5955a13fa1d' rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 (3) sql: SQL query returned: success (3) sql: 0 record(s) updated (3) sql: Trying next query... (3) 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} - %{%{Acct-Session-Time}:-0}), FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), %{%{Acct-Session-Time}:-NULL}, '%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}') (3) 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 ('7427542-L_pppoe1-1', '9785b846930595ba6d83f5955a13fa1d', 'user', '', '10.2.2.14', '0', '', FROM_UNIXTIME(1447427566 - 192), FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), 192, '', '', '', '0' << 32 | '0', '0' << 32 | '0', '', '', '', 'Framed-User', 'PPP', '10.10.11.42') (3) 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 ('7427542-L_pppoe1-1', '9785b846930595ba6d83f5955a13fa1d', 'user', '', '10.2.2.14', '0', '', FROM_UNIXTIME(1447427566 - 192), FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), 192, '', '', '', '0' << 32 | '0', '0' << 32 | '0', '', '', '', 'Framed-User', 'PPP', '10.10.11.42') (3) sql: SQL query returned: success (3) sql: 1 record(s) updated rlm_sql (sql): Released connection (4) rlm_sql (sql): 1 of 6 connections in use. Need more spares rlm_sql (sql): Opening additional connection (6), 1 of 26 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'lms' on Localhost via UNIX socket, server version 10.0.21-MariaDB, protocol version 10 (3) [sql] = ok (3) attr_filter.accounting_response: EXPAND %{User-Name} (3) attr_filter.accounting_response: --> user (3) attr_filter.accounting_response: Matched entry DEFAULT at line 15 (3) [attr_filter.accounting_response] = updated (3) } # accounting = updated rlm_sql (sql): Released connection (3) (3) [sql] = ok (3) } # session = ok (3) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default (3) post-auth { (3) sql: EXPAND .query (3) sql: --> .query (3) sql: Using query template 'query' rlm_sql (sql): Reserved connection (0) (3) sql: EXPAND %{User-Name} (3) sql: --> user (3) sql: SQL-User-Name set to 'user' (3) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (3) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '0x01f29750c6827e6ff5e45baa625d131275', 'Access-Accept', '2015-11-13 16:12:46') (3) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '0x01f29750c6827e6ff5e45baa625d131275', 'Access-Accept', '2015-11-13 16:12:46') (3) sql: SQL query returned: success (3) sql: 1 record(s) updated rlm_sql (sql): Released connection (0) (3) [sql] = ok (3) } # post-auth = ok (3) Sent Access-Accept Id 228 from 10.2.2.13:1812 to 10.2.2.14:19182 length 0 (3) MS-Primary-DNS-Server = 10.10.11.1 (3) MS-Secondary-DNS-Server = 8.8.8.8 (3) Framed-IP-Address = 10.10.11.42 (3) Finished request Waking up in 4.9 seconds. (4) Received Accounting-Request Id 31 from 10.2.2.14:16585 to 10.2.2.13:1813 length 254 (4) NAS-Identifier = "ppoe" (4) Acct-Session-Id = "7427566-L_pppoe1-1" (4) NAS-Port = 1 (4) NAS-Port-Type = Ethernet (4) Service-Type = Framed-User (4) Framed-Protocol = PPP (4) Calling-Station-Id = "6a:61:0a:7f:37:27" (4) Called-Station-Id = "service1" (4) NAS-Port-Id = "em1" (4) Attr-26.12341.12 = 0x4c5f7070706f65312d31 (4) Attr-26 = 0x000030351302 (4) Tunnel-Medium-Type:0 = IEEE-802 (4) Tunnel-Client-Endpoint:0 = "6a:61:0a:7f:37:27" (4) Acct-Status-Type = Start (4) Framed-IP-Address = 10.10.11.42 (4) User-Name = "user" (4) Acct-Multi-Session-Id = "7427567-B_pppoe1-1" (4) Attr-26.12341.13 = 0x425f7070706f65312d31 (4) Attr-26.12341.14 = 0x6e6730 (4) Attr-26.12341.15 = 0x00000004 (4) Attr-26 = 0x000030351302 (4) Acct-Link-Count = 1i (4) Acct-Authentic = RADIUS (4) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (4) preacct { (4) [preprocess] = ok (4) policy acct_unique { (4) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { (4) EXPAND %{string:Class} (4) --> (4) if ("%{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) --> 502963895dc1d5a8f1d967d6f1e3db04 (4) &Acct-Unique-Session-Id := 502963895dc1d5a8f1d967d6f1e3db04 (4) } # update request = noop (4) } # else = noop (4) } # policy acct_unique = noop (4) suffix: Checking for suffix after "@" (4) suffix: No '@' in User-Name = "user", looking up realm NULL (4) suffix: No such realm "NULL" (4) [suffix] = noop (4) } # preacct = ok (4) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (4) accounting { (4) [custom_python] = noop (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 (5) (4) sql: EXPAND %{User-Name} (4) sql: --> user (4) sql: SQL-User-Name set to 'user' (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 ('7427566-L_pppoe1-1', '502963895dc1d5a8f1d967d6f1e3db04', 'user', '', '10.2.2.14', 'em1', 'Ethernet', FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), NULL, '0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '', 'Framed-User', 'PPP', '10.10.11.42') (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 ('7427566-L_pppoe1-1', '502963895dc1d5a8f1d967d6f1e3db04', 'user', '', '10.2.2.14', 'em1', 'Ethernet', FROM_UNIXTIME(1447427566), FROM_UNIXTIME(1447427566), NULL, '0', 'RADIUS', '', '', '0', '0', 'service1', '6a:61:0a:7f:37:27', '', 'Framed-User', 'PPP', '10.10.11.42') (4) sql: SQL query returned: success (4) sql: 1 record(s) updated rlm_sql (sql): Released connection (5) (4) [sql] = ok (4) attr_filter.accounting_response: EXPAND %{User-Name} (4) attr_filter.accounting_response: --> user (4) attr_filter.accounting_response: Matched entry DEFAULT at line 15 (4) [attr_filter.accounting_response] = updated (4) } # accounting = updated (4) Sent Accounting-Response Id 31 from 10.2.2.13:1813 to 10.2.2.14:16585 length 0 (4) Finished request (4) <done>: Cleaning up request packet ID 31 with timestamp +53 Waking up in 4.9 seconds. (3) <done>: Cleaning up request packet ID 228 with timestamp +53