Multiple accounting requests crash the server

[Mother]

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 at 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