Checkrad problem with Acct-Unique-Session-Id
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
On Nov 14, 2015, at 8:30 AM, SC SCx <kredaxx@gmail.com> wrote:
The access request received has a different Acct-Session-Id: 7427566-L_pppoe1-1 (the previous one was: 7427542-L_pppoe1-1)
Which is allowed. BUT if you need to delete the old session, you need to use the old Acct-Session-Id.
Since this Access-Request has a different Acct-Session-Id, the hash value of Acct-Unique-Session-Id is different.
Yes. Use the old Acct-Session-Id for the "delete old session". Or, don't use an Acct-Session-Id. Just key off of the old session information.
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'
Which uses the old Acct-Session-Id...
Then a queued? (Says 'trying next query...') query is called which inserts a new session entry to radacct table:
It can't do an update, so it fails over to insert. Which it shouldn't do for the "delete old session" functionality. If the old session doesn't exist, it shouldn't do anything. The underlying problem here is that the server assumes Access-Request packets don't contain Acct-Session-Id. On top of that, the "session" functionality has code to create a fake Accounting-Request "stop" packet, and you can't manually edit the contents of that packet. And, it runs the accounting packet through the normal accounting section... instead of a specific "stop session" section. What you *can* do is check for this fake packet in the accounting section. accounting { if (outer.request:User-Name) { # it's a fake accounting packet # do special things to delete old sessions return } ... existing accounting stuff... } Arran and I are re-doing the server architecture for 3.1. That should make all of this much easier and more consistent. Alan DeKok.
Hi, Since I cant control the session id beween Access-Requests: * user connects * 1) Access-Request ( acct-session-id: 7427542-L_pppoe1-1 ) 2) Accounting-Request * ... nas gets killed at this point and reboots ... * * user connects again * 3) Access-Request (acct-session-id: 7427566-L_pppoe1-1) 4) Accounting-Request I will most likely resort to a combination of a cronjob (to set acctstop time to a non null value) for entries that had not been updated for some time interval + checkrad. Cronjob will remove those stale entries created by the "fake accounting stop" packets. While checkrad will prevent being locked out in presence of such stale entry until cronjob cleans it up. Not as pretty as checkrad taking care of both, but I think it will be the easiest compromise. Thank you !!! 2015-11-14 15:15 GMT+01:00 Alan DeKok <aland@deployingradius.com>:
On Nov 14, 2015, at 8:30 AM, SC SCx <kredaxx@gmail.com> wrote:
The access request received has a different Acct-Session-Id: 7427566-L_pppoe1-1 (the previous one was: 7427542-L_pppoe1-1)
Which is allowed. BUT if you need to delete the old session, you need to use the old Acct-Session-Id.
Since this Access-Request has a different Acct-Session-Id, the hash value of Acct-Unique-Session-Id is different.
Yes. Use the old Acct-Session-Id for the "delete old session". Or, don't use an Acct-Session-Id. Just key off of the old session information.
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'
Which uses the old Acct-Session-Id...
Then a queued? (Says 'trying next query...') query is called which inserts a new session entry to radacct table:
It can't do an update, so it fails over to insert.
Which it shouldn't do for the "delete old session" functionality. If the old session doesn't exist, it shouldn't do anything.
The underlying problem here is that the server assumes Access-Request packets don't contain Acct-Session-Id. On top of that, the "session" functionality has code to create a fake Accounting-Request "stop" packet, and you can't manually edit the contents of that packet. And, it runs the accounting packet through the normal accounting section... instead of a specific "stop session" section.
What you *can* do is check for this fake packet in the accounting section.
accounting { if (outer.request:User-Name) { # it's a fake accounting packet # do special things to delete old sessions
return }
... existing accounting stuff...
}
Arran and I are re-doing the server architecture for 3.1. That should make all of this much easier and more consistent.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (2)
-
Alan DeKok -
SC SCx