Unexpected Accounting Response
Giuseppe
gaaw at interfree.it
Thu Sep 29 09:20:47 CEST 2005
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>
More information about the Freeradius-Users
mailing list