Hi, 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. So following is the flow - 1. Use login on hotspot, accounting starts2. After sometime (5-7 minutes), acctstoptime populates with a datetime value, while user is surfing3. user keep surfing and accounting keep happening.4. I have run radius in debug mode and captured log, NAS did not send any accounting stop packet.5. I have also observed around 26 records out of 110 current logged in users have same acctstoptime timestamp value and acctterminatecause value as either NULL or 0. Looks like a query is making incorrect updates. I am using FR 2x an can't update to 3 right now. Have observed following query in logs, which might be an issue - UPDATE radacct SET acctstoptime = '2016-12-08 12:13:26', acctsessiontime = unix_timestamp('2016-12-08 12:13:26') - unix_timestamp(acctstarttime), acctterminatecause = '', acctstopdelay = 0 WHERE acctstoptime IS NULL AND nasipaddress = '192.168.182.1' AND acctstarttime <= '2016-12-08 12:13:26' Or there may be some mis-configuration as our end. Kindly let me know.
On 10/12/2016 07:22, Sachin Yadav 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.
What you should do is look at the raw incoming packets and see what is actually happening. There are several ways to do this: e.g. you can configure the "detail" module to log the accounting packets as they come in to a text file, or at worst use tcpdump (e.g. tcpdump -i eth0 -nn -s0 -v udp port 1813) As a guess: maybe the NAS is sending an Interim-Update but your SQL configuration treats it as Stop? An Interim-Update packet gives usage so far on a still-active session.
On Sat, Dec 10, 2016 at 04:07:56PM +0000, Brian Candler wrote:
or at worst use tcpdump
radsniff :) Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
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.
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.
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.
On 11/12/2016 04:38, Sachin Yadav wrote:
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
That is correct behaviour by the NAS. When it reboots it sends an accounting packet with Acct-Status-Type = Accounting-On But if the NAS has rebooted, does this not also imply that all of the previously-active sessions on that NAS must have terminated?
It should terminate but only its own sessions and not write acctstoptime for session of other nas. If you look at the query i found and mentioned in last response FR is blindly updating all records based on few generic parameters in where condition which is incorrect IMHO. Is there a way so that i can switch off this process/query update on nas reboot?
On 11-Dec-2016, at 1:12 pm, Brian Candler <b.candler@pobox.com> wrote:
On 11/12/2016 04:38, Sachin Yadav wrote: 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
That is correct behaviour by the NAS. When it reboots it sends an accounting packet with Acct-Status-Type = Accounting-On
But if the NAS has rebooted, does this not also imply that all of the previously-active sessions on that NAS must have terminated?
On Sun, Dec 11, 2016 at 6:26 PM, Sachin via Freeradius-Users < freeradius-users@lists.freeradius.org> wrote:
It should terminate but only its own sessions and not write acctstoptime for session of other nas.
.. which is why teh query has "AND nasipaddress = '192.168.182.1'"
If you look at the query i found and mentioned in last response FR is blindly updating all records based on few generic parameters in where condition which is incorrect IMHO.
FR made the assumption that each client (i.e. NAS) IP address belongs to a unique NAS. Thus the query above. If that's not the case (i.e. you have a masquerade NAT where many NAS appears as a single IP address to FR), then you either need to change your network setup, or find a unique parameter for each NAS from their sent attributes. Is there a way so that i can switch off this process/query update on nas
reboot?
https://github.com/FreeRADIUS/freeradius-server/blob/v2.x.x/raddb/sql/mysql/... (or if you're not using mysql, find the appropriate dialup.conf). That file should be on /etc/raddb/sql/... (or /etc/freeradius on ubuntu/debian). Try commenting out accounting_onoff_query, or change it to something suitable for your case. -- Fajar
Change the Accounting-On query to check the MAC address of the NAS El dom., 11 dic. 2016 11:30, Sachin via Freeradius-Users < freeradius-users@lists.freeradius.org> escribió:
It should terminate but only its own sessions and not write acctstoptime for session of other nas.
If you look at the query i found and mentioned in last response FR is blindly updating all records based on few generic parameters in where condition which is incorrect IMHO.
Is there a way so that i can switch off this process/query update on nas reboot?
On 11-Dec-2016, at 1:12 pm, Brian Candler <b.candler@pobox.com> wrote:
On 11/12/2016 04:38, Sachin Yadav wrote: 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
That is correct behaviour by the NAS. When it reboots it sends an accounting packet with Acct-Status-Type = Accounting-On
But if the NAS has rebooted, does this not also imply that all of the previously-active sessions on that NAS must have terminated?
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Dec 10, 2016, at 11:38 PM, Sachin Yadav <sachin0235@yahoo.com> wrote:
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
That's mostly what's supposed to happen. The issue is that the default configuration assumes your NASes have different IP addresses. If they all have the same IP, then things will go wrong. You will need to check that each NAS is sending a unique value in Called-Station-Id. You may have to split off the SSID from that field. Then, update the SQL accounting ON/OFF statements to key off of Called-Station-Id, instead of NAS-IP-Address. Also ensure that the accounting ON/OFF packets contain a Called-Station-Id. It might not be there... Or, you could use NAS-Identifier, if that is sent in every packet. But it might not be. And it would involve updating the SQL schema and queries to use NAS-Identifier. In short, you need SOME way to uniquely identity each NAS. Most people do it by IP address. When you gave each NAS the same IP address, you broke the assumptions in the default configuration. Alan DeKok.
Thank you everyone for the help. I have updated accounting on/off query to check for called-station-id value while updating the records. For now everything seems to be working fine on NAS running openwrt. Have to test with different NAS. I hope mikrotik do send called-station-id value on accounting on/off packets. Thanks again!! On Sunday, December 11, 2016 8:06 PM, Alan DeKok <aland@deployingradius.com> wrote: On Dec 10, 2016, at 11:38 PM, Sachin Yadav <sachin0235@yahoo.com> wrote:
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
That's mostly what's supposed to happen. The issue is that the default configuration assumes your NASes have different IP addresses. If they all have the same IP, then things will go wrong. You will need to check that each NAS is sending a unique value in Called-Station-Id. You may have to split off the SSID from that field. Then, update the SQL accounting ON/OFF statements to key off of Called-Station-Id, instead of NAS-IP-Address. Also ensure that the accounting ON/OFF packets contain a Called-Station-Id. It might not be there... Or, you could use NAS-Identifier, if that is sent in every packet. But it might not be. And it would involve updating the SQL schema and queries to use NAS-Identifier. In short, you need SOME way to uniquely identity each NAS. Most people do it by IP address. When you gave each NAS the same IP address, you broke the assumptions in the default configuration. Alan DeKok.
participants (7)
-
Alan DeKok -
Brian Candler -
Fajar A. Nugraha -
Javier Morán -
Matthew Newton -
Sachin -
Sachin Yadav