Accommodating miss behaving NAS?

[Matthew Newton]

On 28/07/2021 08:39, David Herselman via Freeradius-Users wrote:
> FR 3.0.17+dfsg-1.1 appears to only update accounting up until the stop being received, ignoring subsequent updates:
> [admin at unix-01 ~]# mysql -u root -p**************** radius -e 'SELECT username,acctstarttime,acctstoptime,framedipaddress,callingstationid,acctinputoctets,acctoutputoctets FROM radacct WHERE acctuniqueid="50decbeb537ebe5860a8fdf11221017f"';
> +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+
> | username                     | acctstarttime       | acctstoptime        | framedipaddress | callingstationid | acctinputoctets | acctoutputoctets |
> +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+
> | user60d1 at realm.company.co.za<mailto:user60d1 at realm.company.co.za> | 2021-07-24 11:11:08 | 2021-07-25 18:50:23 | 41.247.86.6     | 0112223333       |       199564666 |        321290299 |
> +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+


What does acctupdatetime contain? The Interm-Update query doesn't touch 
acctstoptime.


> [admin at unix-01 ~]# grep '50decbeb537ebe5860a8fdf11221017f' /var/log/freeradius/radacct/*/*;
> /var/log/freeradius/radacct/196.43.3.76/detail-20210724:        Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f"   # start
> /var/log/freeradius/radacct/196.43.3.76/detail-20210724:        Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f"   # interim-update
> /var/log/freeradius/radacct/196.43.3.76/detail-20210724:        Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f"   # interim-update
> /var/log/freeradius/radacct/196.43.3.76/detail-20210725:        Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f"   # interim-update
> /var/log/freeradius/radacct/196.43.3.76/detail-20210725:        Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f"   # stop
> /var/log/freeradius/radacct/196.43.3.77/detail-20210725:        Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f"   # interim-update
> /var/log/freeradius/radacct/196.43.3.77/detail-20210725:        Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f"   # interim-update



> Herewith the relevant accounting packets for Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f". Green entries above are the 'start', 'interim-updates' and then a 'stop'. The red entries above are interim-updates we receive after the stop and the purple is the in/out counters as per the stop packet having been received:

The Event-Timestamp of the last two Interim-Updates show they happened 
before the Stop, and the Acct-{Input,Output}-Octets are lower values 
than the final Stop, too, so looks like they were just logged out of 
order, rather than being received out of order? The SQL data is correct 
from what I can see.

Not sure what the problem is here. The debug output will show what is 
actually happening. Most anything else is guesswork.


> Sat Jul 24 11:11:13 2021
>          Acct-Status-Type = Start

> 
> Sat Jul 24 17:10:26 2021

> 
> Sat Jul 24 23:13:24 2021

> 
> Sun Jul 25 05:15:19 2021

5am

> 
> Sun Jul 25 18:50:23 2021
>          Acct-Terminate-Cause = Lost-Carrier
>          Acct-Status-Type = Stop

7pm

> 
> Sun Jul 25 11:16:58 2021

11am (earlier than stop)

> 
> Sun Jul 25 17:14:09 2021

5pm (earlier than stop)



-- 
Matthew