Hi Alan, Thanks for your answers, mine inline below: Alan DeKok wrote:
Mother wrote:
I am seeing a strange situation. I receive an accounting-stop request from a NAS, and FreeRADIUS (1.1.7 against Oracle) updates the corresponding radacct record. However, the NAS is not receiving the ack, and thus re-sends the stop request. On the second request, FreeRADIUS tries to do an update query again, and then, an insert query, with the stop message details (i.e. only a stop time, reason idle-timeout, etc.), which fails.
Why?
As I mention in my update, an accounting-stop that uses the alternate default query will attempt an insert, not an update (I have a few new records in radacct with only stop time after this episode, all with the same session ID). The reason the NAS was resending was that it was not receiving the confirmation back from FreeRADIUS, most likely due to a temporary network failure on a segment along the way.
After the third request from the NAS (and corresponding update followed by insert), Oracle throws a unique constraint violation error, and the server freezes.
Weird.
Indeed - why it throws this after the third query is what gets me, as the unique constraint should have been hit right after the first update was done. I will investigate the timeline of events with more detail.
Questions:
1. Why is FreeRADIUS failing to see that this request was already acknowledged, i.e. it has been updated on the database, and just sends an ACK, rather than trying to insert a new record?
Because RADIUS doesn't work like that. Accounting requests are never re-sent, so *all* accounting requests are "brand new", and have to be treated that way.
They are never re-sent? Then please tell one of the major European wireless ISP about this, as they were hammering my server :) This is what they saw: Fri Jan 25 10:31:10 2008: INFO: AuthRADIUS: No reply after 2 retransmissions to 80.33.137.68:1813 for mother@whisher (25). Now have 1 consecutive failures over 0 seconds. Backing off for 30 seconds Note that they are *not* using FreeRADIUS. In any case, I will adapt the queries as needed so that they don't hit a brick wall if I find conditions like this.
2. Why does FreeRADIUS freeze on an SQL error from Oracle? Should it not just log the error and carry on about its business? I am finding my server freezing every few days due to these issues, for example, if a query takes too long to run, or a trigger fails to execute. Is FreeRADIUS against Oracle more fragile than say MySQL?
I think that fewer people are using it that way.
Yes, I understand Oracle penetration in FreeRADIUS is tiny, but still.
Perhaps you could try posting the error message, or run it under "gdb" to see why it's freezing.
These are the sanitized logs, with irrelevant crud cut out: #1: rad_recv: Accounting-Request packet from host X.X.X.X:46641, id=184, length=302 User-Name = "blah" NAS-Port = 2 NAS-Port-Type = Wireless-802.11 NAS-Identifier = "XXXXXX" NAS-IP-Address = X.X.X.X Acct-Status-Type = Stop Calling-Station-Id = "MAC" Called-Station-Id = "MAC" Event-Timestamp = "Jan 25 2008 10:49:13 CET" Acct-Delay-Time = 955 Acct-Session-Id = "59fdb3fd" Acct-Authentic = RADIUS Acct-Session-Time = 343 Acct-Input-Octets = 48365 Acct-Input-Gigawords = 0 Acct-Input-Packets = 199 Acct-Output-Octets = 42343 Acct-Output-Gigawords = 0 Acct-Output-Packets = 248 Acct-Terminate-Cause = Idle-Timeout Framed-IP-Address = 192.168.51.186 WISPr-Location-Name = "Address" Vendor-18529-Attr-42 = 0x484553363333373131 Attr-103 = 0x4799b09a Attr-103 = 0x4799b09a WISPr-Location-ID = "isocc=es,cc=34,ac=08080,network=SSID" UPDATE query (fails) INSERT query (seems to take place) rlm_sql (sql): Released sql socket id: 3 modcall[accounting]: module "sql" returns ok for request 0 modcall: leaving group accounting (returns ok) for request 0 Sending Accounting-Response of id 184 to X.X.X.X port 46641 Finished request 0 #2: rad_recv: Accounting-Request packet from host X.X.X.X:46641, id=185, length=302 User-Name = "blah" NAS-Port = 2 NAS-Port-Type = Wireless-802.11 NAS-Identifier = "XXXXXXX" NAS-IP-Address = X.X.X.X Acct-Status-Type = Stop Calling-Station-Id = "MAC" Called-Station-Id = "MAC" Event-Timestamp = "Jan 25 2008 10:49:13 CET" Acct-Delay-Time = 955 Acct-Session-Id = "59fdb3fd" Acct-Authentic = RADIUS Acct-Session-Time = 343 Acct-Input-Octets = 48365 Acct-Input-Gigawords = 0 Acct-Input-Packets = 199 Acct-Output-Octets = 42343 Acct-Output-Gigawords = 0 Acct-Output-Packets = 248 Acct-Terminate-Cause = Idle-Timeout Framed-IP-Address = 192.168.51.186 WISPr-Location-Name = "Address" Vendor-18529-Attr-42 = 0x484553363333373131 Attr-103 = 0x4799b05a Attr-103 = 0x4799b09b WISPr-Location-ID = "isocc=es,cc=34,ac=08080,network=SSID" UPDATE query (fails) INSERT query (seems to take place) rlm_sql (sql): Released sql socket id: 1 modcall[accounting]: module "sql" returns ok for request 2 modcall: leaving group accounting (returns ok) for request 2 Sending Accounting-Response of id 185 to X.X.X.X port 46641 #3: rad_recv: Accounting-Request packet from host X.X.X.X:46641, id=186, length=302 User-Name = "blah" NAS-Port = 2 NAS-Port-Type = Wireless-802.11 NAS-Identifier = "XXXXXXX" NAS-IP-Address = X.X.X.X Acct-Status-Type = Stop Calling-Station-Id = "MAC" Called-Station-Id = "MAC" Event-Timestamp = "Jan 25 2008 10:49:13 CET" Acct-Delay-Time = 960 Acct-Session-Id = "59fdb3fd" Acct-Authentic = RADIUS Acct-Session-Time = 343 Acct-Input-Octets = 48365 Acct-Input-Gigawords = 0 Acct-Input-Packets = 199 Acct-Output-Octets = 42343 Acct-Output-Gigawords = 0 Acct-Output-Packets = 248 Acct-Terminate-Cause = Idle-Timeout Framed-IP-Address = 192.168.51.186 WISPr-Location-Name = "Address" Vendor-18529-Attr-42 = 0x484553363333373131 Attr-103 = 0x4799b09a Attr-103 = 0x4799b09a WISPr-Location-ID = "isocc=es,cc=34,ac=08080,network=SSID" UPDATE query (fails) INSERT query (Oracle throws a unique constraint violation, FreeRADIUS freezes). Any ideas? Best regards, and thanks for your input, Mike