Freeradius incorrect acctstoptime

Sachin Yadav sachin0235 at
Sun Dec 11 05:38:00 CET 2016

Here are some more details, From the logs i found that 1 NAS reboots and it updates radacct. This query cause a mass update of acctstoptime value for almost 26 records out of 319 currently active, all updates happen for openwrt NAS only. Below is the log

rad_recv: Accounting-Request packet from host 45.xx.1xx.1xx port 58986, id=0, length=189 ChilliSpot-Version = "1.3.1-svn" ChilliSpot-Attr-10 = 0x00000002 Event-Timestamp = "Nov 23 2016 15:30:09 IST" Acct-Status-Type = Accounting-On NAS-Port-Type = Wireless-802.11 Calling-Station-Id = "00-00-00-00-00-00" Called-Station-Id = "14-xx-xx-xx-98-xx" NAS-IP-Address = NAS-Identifier = "xx_001_1" WISPr-Location-ID = "isocc=,cc=,ac=,network=xxxxx_com," WISPr-Location-Name = "Ht_xxxxxx"
# Executing section preacct from file /etc/freeradius/sites-enabled/default+- entering group preacct {...}++[preprocess] returns ok[acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent[acct_unique] WARNING: Attribute Acct-Session-Id was not found in request, unique ID MAY be inconsistent[acct_unique] WARNING: Attribute User-Name was not found in request, unique ID MAY be inconsistent[acct_unique] Hashing ',Client-IP-Address = 45.xx.1xx.1xx,NAS-IP-Address =,,'[acct_unique] Acct-Unique-Session-ID = "c3bc8721f1fa62cf".++[acct_unique] returns ok[suffix] Proxy reply, or no User-Name.  Ignoring.++[suffix] returns ok++[files] returns noop# Executing section accounting from file /etc/freeradius/sites-enabled/default+- entering group accounting {...}[detail]  expand: %{Packet-Src-IP-Address} -> 45.xx.1xx.1xx[detail]  expand: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /var/log/freeradius/radacct/45.xx.1xx.1xx/detail-20161210[detail] /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/45.xx.1xx.1xx/detail-20161210[detail]  expand: %t -> Sat Dec 10 12:13:26 2016++[detail] returns ok
[sql] Received Acct On/Off packet[sql]  expand: %{Acct-Delay-Time} -> [sql]  ... expanding second conditional
[sql]  expand:           UPDATE radacct           SET              acctstoptime       =  '%S',              acctsessiontime    =  unix_timestamp('%S') -                                    unix_timestamp(acctstarttime),              acctterminatecause =  '%{Acct-Terminate-Cause}',              acctstopdelay      =  %{%{Acct-Delay-Time}:-0}           WHERE acctstoptime IS NULL           AND nasipaddress      =  '%{NAS-IP-Address}'           AND acctstarttime     <= '%S' ->           UPDATE radacct           SET              acctstoptime       =  '2016-12-10 12:13:26',              acctsessiontime    =  unix_timestamp('2016-12-10 12:13:26') -                                    unix_timestamp(acctstarttime),              acctterminatecause =  '',              acctstopdelay      =  0           WHERE acctstoptime IS NULL           AND nasipaddress      =  ''           AND acctstarttime     <= '2016-12-10 12:13:26'rlm_sql (sql): Reserving sql socket id: 6rlm_sql (sql): Released sql socket id: 6++[sql] returns ok++[exec] returns noop
[attr_filter.accounting_response]  expand: %{User-Name} -> ++[attr_filter.accounting_response] returns noop
Sending Accounting-Response of id 0 to 45.xx.1xx.1xx port 58986Finished request 4995.Cleaning up request 4995 ID 0 with timestamp +477Going to the next requestReady to process requests.


    On Sunday, December 11, 2016 9:31 AM, Sachin Yadav <sachin0235 at> wrote:

 Hi Alan,
Thank you for your reply. I have ran freeradius in debug mode and closely inspected each packet. No NAS is sending accounting stop packet incorrectly (At least it is not getting printed in logs).<br/>
We do not have simultaneous user check or any SQL counter active. I will check for option C, mentioned by you. What i have observed(and mentioned earlier) there is an update query which may be the culprit. 
It is updating acctstop time for all records where nasipaddress   =  '' and acctstoptime is null. This results in mass update of all such records. All openwrt nas have nasipaddress as and hence the incorrect result.<br/>
Could you please tell me what executes this query? In the mean time i will try and log all SQL queries.
Thanks a lot!! 

    On Sunday, December 11, 2016 8:15 AM, Alan DeKok <aland at> wrote:

 On Dec 10, 2016, at 2:22 AM, Sachin Yadav via Freeradius-Users <freeradius-users at> wrote:
> We have a large deployment of about 600 NAS (mixed openwrt/mikrotik/others). I have noticed that for some records, incorrect acctstoptime was marked while user session was still going on and accounting was happening.

  FreeRADIUS doesn't invent accounting packets.  You have a few choices:

a) your NAS is incorrectly sending accounting "stop" packets for sessions which are ongoing

  - rare, but not impossible.

b) something else is writing to the DB and setting acctstoptime

  - maybe you have Simultaneous-Use checking configured, and it's going wrong?

c) you've configured the server to write stop times for non-stop packets

  - possible, but not common.

> Or there may be some mis-configuration as our end. Kindly let me know.

  Log all SQL queries, and all accounting packets.  Then, see which ones update acctstoptime.  And find out why...

  Alan DeKok.



More information about the Freeradius-Users mailing list