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