Hi, As per config files it’s enough to enable sql_session_start in default server and toggle set of queries - start section in queries.conf (freeradius 3.0.20): # When using "sql_session_start", you should comment out # the previous query, and enable this one. Mainly changing sql query INSERT to UPDATE in queries.conf. Is this all or I’m missing something? Description in policy.d/accounting doesn’t say anything more. The reason I’m asking is accounting became useless as lots of data is missing (like acctupdatetime, acctstoptime and acctinterval and so on) when this feature is enabled… Accounting request debug with sql_session_start on: Ready to process requests (8) Received Accounting-Request Id 217 from 172.16.0.4:60220 to 172.16.0.12:1813 length 264 (8) Acct-Status-Type = Interim-Update (8) Acct-Authentic = RADIUS (8) User-Name = "Mark" (8) Framed-IP-Address = 172.16.4.6 (8) NAS-Identifier = "fdecea88ef4d" (8) Called-Station-Id = "FD-EC-EA-88-EF-4D:Site" (8) NAS-Port-Type = Wireless-802.11 (8) Service-Type = Framed-User (8) Calling-Station-Id = „A8-63-C7-20-A6-BC" (8) Connect-Info = "CONNECT 0Mbps 802.11b" (8) Acct-Session-Id = "4989DEE1E63DA03B" (8) WLAN-Pairwise-Cipher = 1027076 (8) WLAN-Group-Cipher = 1027076 (8) WLAN-AKM-Suite = 1027073 (8) Class = 0x61693a6135626131326534323930313730623036636231383032303437383138313738 (8) Event-Timestamp = "Sep 12 2019 22:45:48 CEST" (8) Acct-Delay-Time = 0 (8) Acct-Session-Time = 3985 (8) Acct-Input-Packets = 982894 (8) Acct-Output-Packets = 988539 (8) Acct-Input-Octets = 86555066 (8) Acct-Input-Gigawords = 0 (8) Acct-Output-Octets = 1008668910 (8) Acct-Output-Gigawords = 0 (8) # Executing section preacct from file /etc/freeradius/sites-enabled/default (8) preacct { (8) [preprocess] = ok (8) policy acct_counters64.preacct { (8) update request { (8) EXPAND %{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets} (8) --> 86555066 (8) &Acct-Input-Octets64 = 86555066 (8) EXPAND %{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets} (8) --> 1008668910 (8) &Acct-Output-Octets64 = 1008668910 (8) } # update request = noop (8) } # policy acct_counters64.preacct = noop (8) update request { (8) EXPAND %{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}} (8) --> 1568317163 (8) &FreeRADIUS-Acct-Session-Start-Time = Sep 12 2019 21:39:23 CEST (8) } # update request = noop (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) --> 61693a6135626131326534323930313730623036636231383032303437383138313738 (8) EXPAND ^%{hex:&Tmp-String-9} (8) --> ^61693a (8) EXPAND %{string:&Class} (8) --> ai:a5ba12e4290170b06cb1802047818178 (8) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> TRUE (8) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (8) update request { (8) EXPAND %{md5:%{1},%{Acct-Session-ID}} (8) --> 6d2b000d2e24857d10699c46ad662bff (8) &Acct-Unique-Session-Id := 6d2b000d2e24857d10699c46ad662bff (8) } # update request = noop (8) } # if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) = noop (8) ... skipping else: Preceding "if" was taken (8) } # policy acct_unique = noop (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "Mark", looking up realm NULL (8) suffix: No such realm "NULL" (8) [suffix] = noop (8) } # preacct = ok (8) # Executing section accounting from file /etc/freeradius/sites-enabled/default (8) accounting { (8) detail: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d (8) detail: --> /var/log/freeradius/radacct/172.16.0.4/detail-20190912 (8) detail: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/172.16.0.4/detail-20190912 (8) detail: EXPAND %t (8) detail: --> Thu Sep 12 22:45:48 2019 (8) [detail] = ok (8) sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query} (8) sql: --> type.interim-update.query (8) sql: Using query template 'query' rlm_sql (sql): Closing connection (14): Hit idle_timeout, was idle for 224 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): Closing connection (15): Hit idle_timeout, was idle for 224 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare" rlm_sql (sql): Opening additional connection (16), 1 of 32 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'radius' on 172.16.0.13 via TCP/IP, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 rlm_sql (sql): Reserved connection (16) (8) sql: EXPAND %{User-Name} (8) sql: --> Mark (8) sql: SQL-User-Name set to 'Mark' (8) sql: EXPAND UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctinterval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '%{Framed-IP-Address}', framedipv6address = '%{Framed-IPv6-Address}', framedipv6prefix = '%{Framed-IPv6-Prefix}', framedinterfaceid = '%{Framed-Interface-Id}', delegatedipv6prefix = '%{Delegated-IPv6-Prefix}', 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}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' (8) sql: --> UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1568321148), acctinterval = 1568321148 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', acctsessiontime = 3985, acctinputoctets = '0' << 32 | '86555066', acctoutputoctets = '0' << 32 | '1008668910' WHERE AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff' (8) sql: Executing query: UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1568321148), acctinterval = 1568321148 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', acctsessiontime = 3985, acctinputoctets = '0' << 32 | '86555066', acctoutputoctets = '0' << 32 | '1008668910' WHERE AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff' rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 (8) sql: SQL query returned: success (8) sql: 0 record(s) updated (8) sql: Trying next query... (8) sql: EXPAND UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', framedipaddress = '%{Framed-IP-Address}', framedipv6address = '%{Framed-IPv6-Address}', framedipv6prefix = '%{Framed-IPv6-Prefix}', framedinterfaceid = '%{Framed-Interface-Id}', delegatedipv6prefix = '%{Delegated-IPv6-Prefix}', AcctUpdateTime = 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}' WHERE UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}' AND NASPortId = '%{%{NAS-Port-ID}:-%{NAS-Port}}' AND NASPortType = '%{NAS-Port-Type}' AND AcctStopTime IS NULL (8) sql: --> UPDATE radacct SET AcctSessionId = '4989DEE1E63DA03B', AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff', AcctAuthentic = 'RADIUS', ConnectInfo_start = 'CONNECT 0Mbps 802.11b', ServiceType = 'Framed-User', FramedProtocol = '', framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', AcctUpdateTime = FROM_UNIXTIME(1568321148), AcctSessionTime = 3985, AcctInputOctets = '0' << 32 | '86555066', AcctOutputOctets = '0' << 32 | '1008668910' WHERE UserName = 'Mark' AND NASIPAddress = '172.16.0.4' AND NASPortId = '' AND NASPortType = 'Wireless-802.11' AND AcctStopTime IS NULL (8) sql: Executing query: UPDATE radacct SET AcctSessionId = '4989DEE1E63DA03B', AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff', AcctAuthentic = 'RADIUS', ConnectInfo_start = 'CONNECT 0Mbps 802.11b', ServiceType = 'Framed-User', FramedProtocol = '', framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', AcctUpdateTime = FROM_UNIXTIME(1568321148), AcctSessionTime = 3985, AcctInputOctets = '0' << 32 | '86555066', AcctOutputOctets = '0' << 32 | '1008668910' WHERE UserName = 'Mark' AND NASIPAddress = '172.16.0.4' AND NASPortId = '' AND NASPortType = 'Wireless-802.11' AND AcctStopTime IS NULL rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 (8) sql: SQL query returned: success (8) sql: 0 record(s) updated (8) sql: No additional queries configured rlm_sql (sql): Released connection (16) Need 2 more connections to reach min connections (3) rlm_sql (sql): Opening additional connection (17), 1 of 31 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'radius' on 172.16.0.13 via TCP/IP, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10 (8) [sql] = noop (8) [exec] = noop (8) attr_filter.accounting_response: EXPAND %{User-Name} (8) attr_filter.accounting_response: --> Mark (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 217 from 172.16.0.12:1813 to 172.16.0.4:60220 length 0 (8) Finished request (8) Cleaning up request packet ID 217 with timestamp +613 Regards Martin
On Sep 12, 2019, at 5:25 PM, Marcin Marszałkowski <m.marszal@wp.pl> wrote:
As per config files it’s enough to enable sql_session_start in default server and toggle set of queries - start section in queries.conf (freeradius 3.0.20): # When using "sql_session_start", you should comment out # the previous query, and enable this one. Mainly changing sql query INSERT to UPDATE in queries.conf. Is this all or I’m missing something? Description in policy.d/accounting doesn’t say anything more.
It should work.
The reason I’m asking is accounting became useless as lots of data is missing (like acctupdatetime, acctstoptime and acctinterval and so on) when this feature is enabled…
Accounting request debug with sql_session_start on:
(8) sql: EXPAND UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctinterval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '%{Framed-IP-Address}', framedipv6address = '%{Framed-IPv6-Address}', framedipv6prefix = '%{Framed-IPv6-Prefix}', framedinterfaceid = '%{Framed-Interface-Id}', delegatedipv6prefix = '%{Delegated-IPv6-Prefix}', 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}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' (8) sql: --> UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1568321148), acctinterval = 1568321148 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', acctsessiontime = 3985, acctinputoctets = '0' << 32 | '86555066', acctoutputoctets = '0' << 32 | '1008668910' WHERE AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff' (8) sql: Executing query: UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1568321148), acctinterval = 1568321148 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', acctsessiontime = 3985, acctinputoctets = '0' << 32 | '86555066', acctoutputoctets = '0' << 32 | '1008668910' WHERE AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff'
So what's in SQL? Does the AcctUniqueId match?
(8) sql: EXPAND UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', framedipaddress = '%{Framed-IP-Address}', framedipv6address = '%{Framed-IPv6-Address}', framedipv6prefix = '%{Framed-IPv6-Prefix}', framedinterfaceid = '%{Framed-Interface-Id}', delegatedipv6prefix = '%{Delegated-IPv6-Prefix}', AcctUpdateTime = 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}' WHERE UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}' AND NASPortId = '%{%{NAS-Port-ID}:-%{NAS-Port}}' AND NASPortType = '%{NAS-Port-Type}' AND AcctStopTime IS NULL (8) sql: --> UPDATE radacct SET AcctSessionId = '4989DEE1E63DA03B', AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff', AcctAuthentic = 'RADIUS', ConnectInfo_start = 'CONNECT 0Mbps 802.11b', ServiceType = 'Framed-User', FramedProtocol = '', framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', AcctUpdateTime = FROM_UNIXTIME(1568321148), AcctSessionTime = 3985, AcctInputOctets = '0' << 32 | '86555066', AcctOutputOctets = '0' << 32 | '1008668910' WHERE UserName = 'Mark' AND NASIPAddress = '172.16.0.4' AND NASPortId = '' AND NASPortType = 'Wireless-802.11' AND AcctStopTime IS NULL (8) sql: Executing query: UPDATE radacct SET AcctSessionId = '4989DEE1E63DA03B', AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff', AcctAuthentic = 'RADIUS', ConnectInfo_start = 'CONNECT 0Mbps 802.11b', ServiceType = 'Framed-User', FramedProtocol = '', framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', AcctUpdateTime = FROM_UNIXTIME(1568321148), AcctSessionTime = 3985, AcctInputOctets = '0' << 32 | '86555066', AcctOutputOctets = '0' << 32 | '1008668910' WHERE UserName = 'Mark' AND NASIPAddress = '172.16.0.4' AND NASPortId = '' AND NASPortType = 'Wireless-802.11' AND AcctStopTime IS NULL
Again, what's in SQL? If the WHERE clause doesn't find any matching rows, then it won't do the UPDATE. What was inserted into SQL when the Access-Accept was sent? You're giving us 1/3 of the information, and asking us to solve it. That's bad. You're likely doing this because *you're* not looking at the rest of the information. The way to fix this is simple. READ the debug output to see what is inserted during the "post-auth" phase. CHECK the SQL database to see what data is there for the user. COMPARE that data to what happens when an accounting packet is received. We don't know *any* of that. So it's impossible for us to help you, just by looking at an accounting packet. Alan DeKok.
Alan DeKok <aland@deployingradius.com> w dniu 13.09.2019, o godz. 15:02:
So what's in SQL? Does the AcctUniqueId match?
Yes it does and no, it doesn’t. Most often, AcctUniqueId is inserted but sometimes not. And if it’s in table, sometimes not all columns in radacct table are updated. Affected are: acctupdatetime acctstoptime acctinterval acctsessiontime connectinfo_stop acctinputoctets acctoutputoctets framedipaddress
What was inserted into SQL when the Access-Accept was sent?
Inserted values are either NULL or „0” (in acctsessiontime, acctinputoctets and acctoutputoctets) - which reflects initial - postauth entry. So, I guess it’s right. i.e. missing data in entry, which is not updated: mysql> SELECT * FROM `radacct` WHERE `acctuniqueid` = 'fd2ad124f5dafc712c9865a3bb8b95af'; +-----------+------------------+----------------------------------+----------+-------+--------------+-----------+-----------------+---------------------+----------------+--------------+--------------+-----------------+---------------+-----------------------+------------------+-----------------+------------------+-----------------------+-------------------+--------------------+-------------+----------------+-----------------+-------------------+------------------+-------------------+---------------------+ | radacctid | acctsessionid | acctuniqueid | username | realm | nasipaddress | nasportid | nasporttype | acctstarttime | acctupdatetime | acctstoptime | acctinterval | acctsessiontime | acctauthentic | connectinfo_start | connectinfo_stop | acctinputoctets | acctoutputoctets | calledstationid | callingstationid | acctterminatecause | servicetype | framedprotocol | framedipaddress | framedipv6address | framedipv6prefix | framedinterfaceid | delegatedipv6prefix | +-----------+------------------+----------------------------------+----------+-------+--------------+-----------+-----------------+---------------------+----------------+--------------+--------------+-----------------+---------------+-----------------------+------------------+-----------------+------------------+-----------------------+-------------------+--------------------+-------------+----------------+-----------------+-------------------+------------------+-------------------+---------------------+ | 2275 | 8FC4A77CA2F41209 | fd2ad124f5dafc712c9865a3bb8b95af | Kito | | 172.16.0.4 | NULL | Wireless-802.11 | 2019-09-13 13:44:50 | NULL | NULL | NULL | 0 | | CONNECT 0Mbps 802.11b | NULL | 0 | 0 | FK-EC-CA-88-FF-4D:Site | 10-87-35-81-FC-65 | NULL | Framed-User | NULL | | | | | | +-----------+------------------+----------------------------------+----------+-------+--------------+-----------+-----------------+---------------------+----------------+--------------+--------------+-----------------+---------------+-----------------------+------------------+-----------------+------------------+-----------------------+-------------------+--------------------+-------------+----------------+-----------------+-------------------+------------------+-------------------+---------------------+ 1 row in set (0.00 sec) Updated data: mysql> SELECT * FROM `radacct` WHERE `acctuniqueid` = '549a0425b38d30407db45aa8ae9b0c35'; +-----------+------------------+----------------------------------+----------+-------+--------------+-----------+-----------------+---------------------+---------------------+---------------------+--------------+-----------------+---------------+-----------------------+-----------------------+-----------------+------------------+-----------------------+-------------------+--------------------+-------------+----------------+-----------------+-------------------+------------------+-------------------+---------------------+ | radacctid | acctsessionid | acctuniqueid | username | realm | nasipaddress | nasportid | nasporttype | acctstarttime | acctupdatetime | acctstoptime | acctinterval | acctsessiontime | acctauthentic | connectinfo_start | connectinfo_stop | acctinputoctets | acctoutputoctets | calledstationid | callingstationid | acctterminatecause | servicetype | framedprotocol | framedipaddress | framedipv6address | framedipv6prefix | framedinterfaceid | delegatedipv6prefix | +-----------+------------------+----------------------------------+----------+-------+--------------+-----------+-----------------+---------------------+---------------------+---------------------+--------------+-----------------+---------------+-----------------------+-----------------------+-----------------+------------------+-----------------------+-------------------+--------------------+-------------+----------------+-----------------+-------------------+------------------+-------------------+---------------------+ | 2281 | C0A8033AB1FB6258 | 549a0425b38d30407db45aa8ae9b0c35 | Mark | | 172.16.0.5 | NULL | Wireless-802.11 | 2019-09-13 16:03:34 | 2019-09-13 16:03:34 | 2019-09-13 16:02:47 | 300 | 416 | | CONNECT 0Mbps 802.11b | CONNECT 0Mbps 802.11b | 4294967296 | 4294967296 | FK-EC-CA-88-FF-4D:Site | 78-FG-C7-99-D1-A6 | | Framed-User | NULL | 172.16.4.10 | | | | | +-----------+------------------+----------------------------------+----------+-------+--------------+-----------+-----------------+---------------------+---------------------+---------------------+--------------+-----------------+---------------+-----------------------+-----------------------+-----------------+------------------+-----------------------+-------------------+--------------------+-------------+----------------+-----------------+-------------------+------------------+-------------------+---------------------+ 1 row in set (0.00 sec) Or empty: mysql> SELECT * FROM `radacct` WHERE `acctuniqueid` = '6d2b000d2e24857d10699c46ad662bff'; Empty set (0.00 sec) mysql> In general, it seems like table is updated inconsistently. Since there are no any accounting errors when sql_session_start is disabled, I think it's must be related to that particular feature or maybe to mysql database itself?
On Sep 13, 2019, at 12:25 PM, Marcin <m.marszal@wp.pl> wrote:
So what's in SQL? Does the AcctUniqueId match?
Yes it does and no, it doesn’t. Most often, AcctUniqueId is inserted but sometimes not.
So... read the debug output to see what's different between the two cases. The debug output shows you which attributes are being used to calculate AcctUniqueId. If the input attributes are different, then the output hash is different. Maybe your NAS sends *different information* in the Access-Request and Accounting-Request packet. Again, go read the debug output to see the differences. Then if you can't fix the NAS to be consistent, edit the Acct-Unique-Session-Id calculation. Make it use the attributes which exist in both packets.
And if it’s in table, sometimes not all columns in radacct table are updated. Affected are: acctupdatetime acctstoptime acctinterval acctsessiontime connectinfo_stop acctinputoctets acctoutputoctets framedipaddress
Again, if you READ the debug output, it will SHOW YOU which attributes are in the packet. This isn't rocket science. The server doesn't magically invent things to put into the DB. FreeRADIUS can log ONLY what the NAS sends. So if the NAS sends different attributes in different packets, then blame the NAS. Don't look at SQL and go "gosh, I don't know what's going on".
What was inserted into SQL when the Access-Accept was sent?
Inserted values are either NULL or „0” (in acctsessiontime, acctinputoctets and acctoutputoctets) - which reflects initial - postauth entry. So, I guess it’s right.
That is entirely missing my point.
In general, it seems like table is updated inconsistently.
Blame the NAS. This isn't magic. FreeRADIUS doesn't magically skip certain fields at random.
Since there are no any accounting errors when sql_session_start is disabled, I think it's must be related to that particular feature or maybe to mysql database itself?
Think about it. Is the database really magically causing data to disappear? Or is FreeRADIUS randomly deciding to *not* insert certain fields? Or maybe, if you READ THE DEBUG OUTPUT, you will see that the NAS sends different information in different packets. And when information is "missing" from SQL, it's because that information is ALSO missing from the accounting packet. The information you need to understand this problem is in the debug output. All you need to do is read it. Looking at the SQL database means that you're 3 steps removed from the actual problem. Alan DeKok.
Alan DeKok <aland@deployingradius.com> w dniu 13.09.2019, o godz. 18:36: Think about it. Is the database really magically causing data to disappear? Or is FreeRADIUS randomly deciding to *not* insert certain fields?
I don’t know what to think about it. Why accounting works when sql_session_start is disabled? NAS has no idea about that - keeps sending same accounting data...
So... read the debug output to see what's different between the two cases. The debug output shows you which attributes are being used to calculate AcctUniqueId. That’s what I’m going to do but since they do not happen on regular basis - it’s hard to spot and it will take some time..
On Sep 13, 2019, at 1:40 PM, Marcin <m.marszal@wp.pl> wrote:
Alan DeKok <aland@deployingradius.com> w dniu 13.09.2019, o godz. 18:36: Think about it. Is the database really magically causing data to disappear? Or is FreeRADIUS randomly deciding to *not* insert certain fields?
I don’t know what to think about it. Why accounting works when sql_session_start is disabled? NAS has no idea about that - keeps sending same accounting data...
And sql_session_start creates a record in the SQL database from the *Access-Request* packet. Which, as I already said, contains *different* information than what's in the Accounting-Request packet. Since the AcctUniqueId is different, the next packet doesn't match the session. Again, this is all in the debug output. It's not magic. It tells you exactly what it's doing and why. Alan DeKok.
participants (3)
-
Alan DeKok -
Marcin -
Marcin Marszałkowski