Good Evening I am seeing something slightly odd here with FreeRadius in some situations. for some (not not all) session closes on RadAcct we are seeing: (142) sql1: SQL-User-Name set to 'myusername@myrealm' (142) sql1: EXPAND EXECUTE radius.[dbo].[proc_RadacctUpdate_1] '%S', '%{Acct-Session-Time}', '%{Acct-Input-Gigawords}', '%{Acct-Input-Octets}', '%{Acct-Output-Gigawords}', '%{Acct-Output-Octets}', '%{Acct-Terminate-Cause}', '%{Acct-Delay-Time}', '%{Connect-Info}', '%{Acct-Session-Id}', '%{NAS-IP-Address}' (142) sql1: --> EXECUTE radius.[dbo].[proc_RadacctUpdate_1] '2021-11-03 19:54:22', '2835', '0', '361059', '0', '357416', 'Lost-Carrier', '', '287000/396000', 'S600000269717108F60302', '1.2.3.4' (142) sql1: EXPAND /usr/local/var/log/radius/accounting.sql (142) sql1: --> /usr/local/var/log/radius/accounting.sql (142) sql1: Executing query: EXECUTE radius.[dbo].[proc_RadacctUpdate_1] '2021-11-03 19:54:22', '2835', '0', '361059', '0', '357416', 'Lost-Carrier', '', '287000/396000', 'S600000269717108F60302', '1.2.3.4' (142) sql1: SQL query returned: success (142) sql1: -1 record(s) updated (142) sql1: No additional queries configured rlm_sql (sql1): Released connection (21) (142) [sql1] = noop (142) [handled] = handled (142) } # redundant = handled (142) } # accounting = handled (142) Not sending reply to client. Note this is using MS SQL via TDS As this is not seeing a positive return from the numbers of records updated - then it does not reply to the NAS and so the NAS tries again and again Running the Query on the MS SQL server I see: --- (1 row affected) (1 row affected) --- So it is correctly updating records - the stored procedure is safe as long as it returns success. 1) Can you think why FreeRadius is getting -1 as a return. 2) Given the stored procedure will return an error IF it can't update the data - is there anyway for us to tell FreeRadius to accept and process OK as long as the Query works. We are not seeing this for all queries - but just some - happy to add as many details as needed here - and it's not pointing the blame at Radius - just trying to understand the oddity for the future Thanks in advance Richard
On Nov 3, 2021, at 4:03 PM, Richard J Palmer <richard@merula.net> wrote:
for some (not not all) session closes on RadAcct we are seeing:
(142) sql1: SQL-User-Name set to 'myusername@myrealm' (142) sql1: EXPAND EXECUTE radius.[dbo].[proc_RadacctUpdate_1] '%S', '%{Acct-Session-Time}', '%{Acct-Input-Gigawords}', '%{Acct-Input-Octets}', '%{Acct-Output-Gigawords}', '%{Acct-Output-Octets}', '%{Acct-Terminate-Cause}', '%{Acct-Delay-Time}', '%{Connect-Info}', '%{Acct-Session-Id}', '%{NAS-IP-Address}' (142) sql1: --> EXECUTE radius.[dbo].[proc_RadacctUpdate_1] '2021-11-03 19:54:22', '2835', '0', '361059', '0', '357416', 'Lost-Carrier', '', '287000/396000', 'S600000269717108F60302', '1.2.3.4' (142) sql1: EXPAND /usr/local/var/log/radius/accounting.sql (142) sql1: --> /usr/local/var/log/radius/accounting.sql (142) sql1: Executing query: EXECUTE radius.[dbo].[proc_RadacctUpdate_1] '2021-11-03 19:54:22', '2835', '0', '361059', '0', '357416', 'Lost-Carrier', '', '287000/396000', 'S600000269717108F60302', '1.2.3.4' (142) sql1: SQL query returned: success (142) sql1: -1 record(s) updated
If that's what MS-SQL returns, then it's what FreeRADIUS gets. It's hard to fix something in another library / server.
Note this is using MS SQL via TDS
As this is not seeing a positive return from the numbers of records updated - then it does not reply to the NAS and so the NAS tries again and again
Yes. :(
Running the Query on the MS SQL server I see:
--- (1 row affected)
(1 row affected)
---
So it is correctly updating records - the stored procedure is safe as long as it returns success.
Well, RADIUS does all kind of asynchronous updates to sessions. So there's no guarantee that the session database is the same when you run the query, and when FreeRADIUS runs the query.
1) Can you think why FreeRadius is getting -1 as a return.
The TDS / MS-SQL client library is returning that.
2) Given the stored procedure will return an error IF it can't update the data - is there anyway for us to tell FreeRadius to accept and process OK as long as the Query works.
Except that the SQL library says the query *didn't* work.
We are not seeing this for all queries - but just some - happy to add as many details as needed here - and it's not pointing the blame at Radius - just trying to understand the oddity for the future
Which version of FreeRADIUS are you using? Alan DeKok.
Good Evening Alan This is currently a slightly old install - FreeRADIUS Version 3.0.19. I have however just upgraded to 3.0.25 and I'm still seeing the same. I also upgraded unixODBC/FreeTDS to the latest release too - just in case Just chap from an LNS and data to/from a MS SQL Server.
Running the Query on the MS SQL server I see:
--- (1 row affected)
(1 row affected)
---
So it is correctly updating records - the stored procedure is safe as long as it returns success.
Well, RADIUS does all kind of asynchronous updates to sessions. So there's no guarantee that the session database is the same when you run the query, and when FreeRADIUS runs the query.
This is actually a session that's ended - the SQL table before the query shows the data for this session all correct and ended - In this case it's trying time and time again to update the session to finished - so radacct (for this session at least) won't be changing - I'm wondering if this is a result of the update effectively not affecting the data because it's updating the recored to exacly as it is already?
1) Can you think why FreeRadius is getting -1 as a return.
The TDS / MS-SQL client library is returning that.
Indeed :)
2) Given the stored procedure will return an error IF it can't update the data - is there anyway for us to tell FreeRadius to accept and process OK as long as the Query works.
Except that the SQL library says the query *didn't* work.
Agree - badly worded - I meant the Stored procedure is written so it's virtually impossible for the data we need not to be saved - and I know there can always be edge cases... As long as we get (142) sql1: SQL query returned: success It's processed the update OK - I'm happy to share the Stored procedure if it helps - I'd just prefer it not to be totally in the public. I know in some cases this may not be acceptable - but in this particular use case at the end of a session - worse case the process that cllses zombie sessions will close the session in the background a bit later on. Richard
On Wed, 3 Nov 2021 at 22:09, Richard J Palmer <richard@merula.net> wrote:
This is actually a session that's ended - the SQL table before the query shows the data for this session all correct and ended - In this case it's trying time and time again to update the session to finished - so radacct (for this session at least) won't be changing - I'm wondering if this is a result of the update effectively not affecting the data because it's updating the recored to exacly as it is already?
Yes, it is likely a "rows updated" vs "rows matched" issue. Some engines/drivers differentiate the two, others do not. You can test your hypothesis by writing CURRENT_TIMESTAMP (with some reasonable degree of resolution) into an unused field causing the record to be modified. If your issue goes away then you have identified the culprit and can likely fix it by modifying the schema/query in a way that feels less hackish.
participants (3)
-
Alan DeKok -
Richard J Palmer -
Terry Burton