[Help-gnu-radius] mysql accounting entries sent out-of-order

[Lai Zit Seng]

I have this problem with radius accounting entries being logged 
out-of-order, i.e., the STOP record is logged _before_ its corresponding 
START record.

This happens when my NAS sends START and STOP records at almost the same
time (happens with failed logins). The NAS' syslog shows it sending the
START first then the STOP. The gnu-radius' logs also show START then STOP:

Jan 17 23:47:06: [10121]: Acct.debug: acct.c:387:rad_acct_system: start: 
User #7760540 at NAS shiva5 port 20127 session c46f4f3ca6a1f10 
... some stuffs inbetween ...
Jan 17 23:47:06: [10122]: Acct.debug: acct.c:387:rad_acct_system: stop: 
User #7760540 at NAS shiva5 port 20127 session c46f4f3ca6a1f10 

The account detail file in /var/log/radacct/*/detail also shows the Start 
entry then the corresponding Stop entry.

But, the sql log /var/log/radacct/sql.log shows the SQL statement for the 
STOP coming first:

UPDATE calls SET 
status=2,acct_session_time=69,acct_input_octets=641,acct_output_octets=79,connect_term_reason=1,framed_ip_address='0'
 
WHERE user_name='' AND status = 1 AND 
acct_session_id='000000463c46f4f3ca6a1f10';
INSERT INTO calls VALUES(1,'','2002-01-17 
15:47:06','137.132.95.5',20127,'000000463c46f4f3ca6a1f10',0,0,0,0,'0','8737906','7760540');

Obviously it matters that the 'insert' statement comes before the 'update' 
statement... otherwise the accounting entry never gets "closed".

I guess this would count as a bug?

Regards,

.lzs