Freeradius incorrect acctstoptime

[Sachin Yadav]

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 = 192.168.182.1 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 = 192.168.182.1,,'[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      =  '192.168.182.1'           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 yahoo.com> 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   =  '192.168.182.1' and acctstoptime is null. This results in mass update of all such records. All openwrt nas have nasipaddress as 192.168.182.1 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 deployingradius.com> wrote:
 

 On Dec 10, 2016, at 2:22 AM, Sachin Yadav via Freeradius-Users <freeradius-users at lists.freeradius.org> 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.