Unexpected Accounting Response

[Giuseppe]

Hi.

I'm configuring the radius server so that no duplicate 
Calling-Station-Id values are found in the DB I'm logging to (Oracle), 
which is the only destination I'm logging onto (not even "detail").
The quickest way I thought of was to add a unique index to the RADACCT 
table so that any Accounting Start for a Calling-Station-Id already 
present in the DB would fail.

Indeed I can see through the server log (started with -X) that the 
INSERT statement fails because it attempts to violate the unique constraint:

------
rlm_sql (sql): Couldn't insert SQL accounting START record - ORA-00001: 
unique constraint (RADUSER.RADACCT_IDX2) violated
------

However, just a few lines below I see:

------
modcall[accounting]: module "sql" returns ok for request 0
------

which probably is the root cause of unexpected (to me):

------
Sending Accounting-Response of id 241 to XXX.XXX.XXX.XXX:33863
------

This Accounting Response is unexpected to me because RFC 2866 says:
"If the RADIUS accounting server is unable to successfully record the 
accounting packet it MUST NOT send an Accounting-Response acknowledgment 
to the client".

Any help ?

Thanks in advance
Giuseppe

P.S. Here there's the whole log section related to the request 
processing that raises the above issue:

---------
rad_recv: Accounting-Request packet from host XXX.XXX.XXX.XX:33863, 
id=241, length=92
        User-Name = "testuser"
        User-Password = "\001\272O\257UN\214\307\245\333%\261 <\020d"
        Acct-Status-Type = Start
        Calling-Station-Id = "393480000000"
        Framed-IP-Address = XXX.XXX.XXX.XX
        Acct-Session-Id = "c16a444a16927797"
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 0
  modcall[preacct]: module "preprocess" returns noop for request 0
rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request, 
unique ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address = 
XXX.XXX.XXX.XXX,NAS-IP-Address = XXX.XXX.XXX.XXX,Acct-Session-Id = 
"c16a444a16927797",User-Name = "testuser"'
rlm_acct_unique: Acct-Unique-Session-ID = "aecc66663df0011c".
  modcall[preacct]: module "acct_unique" returns ok for request 0
    rlm_realm: No '@' in User-Name = "testuser", looking up realm NULL
    rlm_realm: No such realm "NULL"
  modcall[preacct]: module "suffix" returns noop for request 0
  modcall[preacct]: module "files" returns noop for request 0
modcall: group preacct returns ok for request 0
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 0
radius_xlat:  'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat:  'INSERT into radacct (RadAcctId, AcctSessionId, 
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, 
AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, 
ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, 
CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, 
FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) 
values('', 'c16a444a16927797', 'aecc66663df0011c', 'testuser', '', 
'XXX.XXX.XXX.XXX', '', '', TO_DATE('2005-09-28 19:46:43','yyyy-mm-dd 
hh24:mi:ss'), NULL, '0', '', '', '', '0', '0', '', '393480000000', '', 
'', '', 'XXX.XXX.XXX.XXX', '', '0')'
radius_xlat:  '/usr/local/var/log/radius/sqltrace.sql'
rlm_sql (sql): Reserving sql socket id: 4
INSERT into radacct (RadAcctId, AcctSessionId, AcctUniqueId, UserName, 
Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, 
AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, 
ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, 
CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, 
FramedIPAddress, AcctStartDelay, AcctStopDelay) values('', 
'c16a444a16927797', 'aecc66663df0011c', 'testuser', '', 
'XXX.XXX.XXX.XXX', '', '', TO_DATE('2005-09-28 19:46:43','yyyy-mm-dd 
hh24:mi:ss'), NULL, '0', '', '', '', '0', '0', '', '393480000000', '', 
'', '', 'XXX.XXX.XXX.XXX', '', '0')
rlm_sql_oracle: execute query failed in sql_query: ORA-00001: unique 
constraint (RADUSER.RADACCT_IDX2) violated
rlm_sql (sql): Attempting to connect rlm_sql_oracle #4
rlm_sql (sql): Connected new DB handle, #4
INSERT into radacct (RadAcctId, AcctSessionId, AcctUniqueId, UserName, 
Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, 
AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, 
ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, 
CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, 
FramedIPAddress, AcctStartDelay, AcctStopDelay) values('', 
'c16a444a16927797', 'aecc66663df0011c', 'testuser', '', 
'XXX.XXX.XXX.XXX', '', '', TO_DATE('2005-09-28 19:46:43','yyyy-mm-dd 
hh24:mi:ss'), NULL, '0', '', '', '', '0', '0', '', '393480000000', '', 
'', '', 'XXX.XXX.XXX.XX', '', '0')
rlm_sql_oracle: execute query failed in sql_query: ORA-00001: unique 
constraint (RADUSER.RADACCT_IDX2) violated
rlm_sql (sql): failed after re-connect
rlm_sql (sql): Couldn't insert SQL accounting START record - ORA-00001: 
unique constraint (RADUSER.RADACCT_IDX2) violated
radius_xlat:  ''
radius_xlat:  '/usr/local/var/log/radius/sqltrace.sql'
rlm_sql (sql): Released sql socket id: 4
  modcall[accounting]: module "sql" returns ok for request 0
modcall: group accounting returns ok for request 0
Sending Accounting-Response of id 241 to XXX.XXX.XXX.XX:33863
Finished request 0
Going to the next request
--- Walking the entire request list ---
Cleaning up request 0 ID 241 with timestamp 433b0133
Nothing to do.  Sleeping until we see a request.
-------------

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20050929/3802c8d6/attachment.html>