Accounting-Packets from Huawei NAS randomly not being written to the database
Hello everyone, I have some radius servers configured to use decoupled-accounting to avoid overwhelming the database with real-time writes. In all of them I am having the same problem. Some accounting packets sent from Huawei devices are not being written to the database. I have set up a second detail log file to check if the packets were being sent by the NAS. For example: Packet received from the NAS, stored in the second detail file: Fri Aug 7 08:54:43 2020 User-Name = "andersonoliveira" NAS-Port = 3162917 NAS-IP-Address = X.X.X.X Framed-IP-Address = 100.64.218.153 NAS-Identifier = "TI5-BRAS01" Acct-Status-Type = Stop Acct-Delay-Time = 0 Acct-Input-Octets = 0 Acct-Output-Octets = 0 Acct-Session-Id = "TI5-BRA00304080500000a598ccAAADbA" Acct-Authentic = RADIUS Acct-Session-Time = 200 Acct-Input-Packets = 0 Acct-Output-Packets = 0 Acct-Terminate-Cause = Lost-Carrier Acct-Input-Gigawords = 0 Acct-Output-Gigawords = 0 Event-Timestamp = "Aug 7 2020 08:54:43 -03" NAS-Port-Type = Ethernet Calling-Station-Id = "58:10:8c:07:48:8f" NAS-Port-Id = "slot=0;subslot=3;port=4;vlanid=805;" Service-Type = Framed-User Framed-Protocol = PPP Connect-Info = "1300000/1000000" Idle-Timeout = 0 Session-Timeout = 0 Huawei-IPHost-Addr = "100.64.218.153 58:10:8c:07:48:8f" Huawei-Input-Peak-Rate = 1000000 Huawei-Input-Peak-Rate = 1000000 Huawei-Input-Average-Rate = 1000000 Huawei-Output-Peak-Rate = 1300000 Huawei-Output-Average-Rate = 1300000 Huawei-Priority = 15 Huawei-Connect-ID = 13206 Huawei-Domain-Name = "provedor_pppoe" Huawei-Accounting-Level = 0 Huawei-Up-Priority = 15 Huawei-Down-Priority = 15 Huawei-Acct-IPv6-Input-Octets = 0 Huawei-Acct-IPv6-Output-Octets = 0 Huawei-Acct-IPv6-Input-Packets = 0 Huawei-Acct-IPv6-Output-Packets = 0 Huawei-Acct-IPv6-Input-Gigawords = 0 Huawei-Acct-IPv6-Output-Gigawords = 0 Huawei-User-Mac = "58:10:8c:07:48:8f" Huawei-Acct-Update-Address = 0 Huawei-Input-Burst-Size = 625000 Huawei-Output-Burst-Size = 812504 Huawei-Input-Peak-Burst-Size = 625000 Huawei-Output-Peak-Burst-Size = 812504 Timestamp = 1596801283 Record in the redacct table: -[ RECORD 5 ]-------+---------------------------------- username | andersonoliveira acctsessionid | TI5-BRA00304080500000a598ccAAADbA acctstarttime | 2020-08-07 08:51:23-03 acctlocalupdatetime | 2020-08-07 08:51:23-03 acctstoptime | As you can see, neither acctlocalupdatetime or acctstoptime were updated with the correct timestamps from the packet received by the NAS. I checked the logs and I couldn’t find any error message related to this. As the server is in production, enabling the debug creates a lot of output. The only thing I think could be causing this is this condition I have in my accounting section: if (noop) { ok } What do you guys suggest? Thanks in advance.
On Aug 7, 2020, at 8:26 AM, Antônio Modesto <modesto@hubsoft.com.br> wrote:
I have some radius servers configured to use decoupled-accounting to avoid overwhelming the database with real-time writes.
Databases should be able to keep up, with some DB tweaking. But decoupled-accounting does make it simpler.
In all of them I am having the same problem. Some accounting packets sent from Huawei devices are not being written to the database. I have set up a second detail log file to check if the packets were being sent by the NAS. For example:
Look at the debug output to see why. Look at the logic you have around using the SQL module.
As you can see, neither acctlocalupdatetime or acctstoptime were updated with the correct timestamps from the packet received by the NAS. I checked the logs and I couldn’t find any error message related to this. As the server is in production, enabling the debug creates a lot of output.
You can set up a test server, and use "radclient". Take a copy of the detail file entry, and use radclient to send it to the test server.
The only thing I think could be causing this is this condition I have in my accounting section:
if (noop) { ok }
That doesn't say "skip writing to the SQL module"
What do you guys suggest?
Set up a test server and run it in debug mode. Alan DeKok.
On 7 Aug 2020, at 09:33, Alan DeKok <aland@deployingradius.com> wrote:
You can set up a test server, and use "radclient". Take a copy of the detail file entry, and use radclient to send it to the test server.
Hi Alan, thanks for your response. I tried to resend the same packet using radclient as you suggested (on the same server) and it worked. The record in the database was updated. I will try to store some compressed debug output for a longer period to see if I can find something that explains this behaviour. radclient -x -f /tmp/record.txt 127.1.1.2 acct testing123 Sent Accounting-Request Id 22 from 127.1.1.2:21530 to 127.1.1.2:1813 length 617 User-Name = "andersonoliveira" NAS-Port = 3162917 NAS-IP-Address = 177.66.167.254 Framed-IP-Address = 100.64.218.153 NAS-Identifier = "TI5-BRAS01" Acct-Status-Type = Stop Acct-Delay-Time = 0 Acct-Input-Octets = 0 Acct-Output-Octets = 0 Acct-Session-Id = "TI5-BRA00304080500000a598ccAAADbA" Acct-Authentic = RADIUS Acct-Session-Time = 200 Acct-Input-Packets = 0 Acct-Output-Packets = 0 Acct-Terminate-Cause = Lost-Carrier Acct-Input-Gigawords = 0 Acct-Output-Gigawords = 0 Event-Timestamp = "Aug 7 2020 08:54:43 -03" NAS-Port-Type = Ethernet Calling-Station-Id = "58:10:8c:07:48:8f" NAS-Port-Id = "slot=0;subslot=3;port=4;vlanid=805;" Service-Type = Framed-User Framed-Protocol = PPP Connect-Info = "1300000/1000000" Idle-Timeout = 0 Session-Timeout = 0 Huawei-IPHost-Addr = "100.64.218.153 58:10:8c:07:48:8f" Huawei-Input-Peak-Rate = 1000000 Huawei-Input-Peak-Rate = 1000000 Huawei-Input-Average-Rate = 1000000 Huawei-Output-Peak-Rate = 1300000 Huawei-Output-Average-Rate = 1300000 Huawei-Priority = 15 Huawei-Connect-ID = 13206 Huawei-Domain-Name = "provedor_pppoe" Huawei-Accounting-Level = 0 Huawei-Up-Priority = 15 Huawei-Down-Priority = 15 Huawei-Acct-IPv6-Input-Octets = 0 Huawei-Acct-IPv6-Output-Octets = 0 Huawei-Acct-IPv6-Input-Packets = 0 Huawei-Acct-IPv6-Output-Packets = 0 Huawei-Acct-IPv6-Input-Gigawords = 0 Huawei-Acct-IPv6-Output-Gigawords = 0 Huawei-User-Mac = "58:10:8c:07:48:8f" Huawei-Acct-Update-Address = 0 Huawei-Input-Burst-Size = 625000 Huawei-Output-Burst-Size = 812504 Huawei-Input-Peak-Burst-Size = 625000 Huawei-Output-Peak-Burst-Size = 812504 Received Accounting-Response Id 22 from 127.1.1.2:1813 to 127.1.1.2:21530 length 20 Acctstoptime and acctlocalupdatetime were correctly updated: radius=# select username, acctsessionid, acctstarttime, acctstoptime, acctlocalupdatetime from radacct where acctsessionid = 'TI5-BRA00304080500000a598ccAAADbA'; -[ RECORD 1 ]-------+---------------------------------- username | andersonoliveira acctsessionid | TI5-BRA00304080500000a598ccAAADbA acctstarttime | 2020-08-07 08:51:23-03 acctstoptime | 2020-08-07 08:54:43-03 acctlocalupdatetime | 2020-08-07 10:20:35-03 Thanks.
Hi folks, I tried to run the server in debug mode for the whole afternoon to see if I could find something, but not even a single packet was lost during this time. The most intriguing is that I started the server in debug mode at 02:00 PM (GMT -3), the last packet lost was at 01:56 (GMT -3). I also noticed that these warnings stopped just after I started the server in debug mode: Aug 7 13:59:27 radius-server radiusd[34270]: detail (/var/log/radacct/detail/detail-*:*): Read empty packet from file /var/log/radacct/detail/detail.work I find this really weird, because this problem happens quite frequently. I didn’t mention this before but I am running FreeRADIUS Version 3.0.17.
On Aug 7, 2020, at 4:50 PM, Antônio Modesto <modesto@hubsoft.com.br> wrote:
I tried to run the server in debug mode for the whole afternoon to see if I could find something, but not even a single packet was lost during this time. The most intriguing is that I started the server in debug mode at 02:00 PM (GMT -3), the last packet lost was at 01:56 (GMT -3). I also noticed that these warnings stopped just after I started the server in debug mode:
Aug 7 13:59:27 radius-server radiusd[34270]: detail (/var/log/radacct/detail/detail-*:*): Read empty packet from file /var/log/radacct/detail/detail.work
I find this really weird, because this problem happens quite frequently. I didn’t mention this before but I am running FreeRADIUS Version 3.0.17.
Try v3.0.x from Github: https://github.com/FreeRADIUS/freeradius-server/archive/v3.0.x.zip It has many fixes over 3.0.17. One of these may be affecting you. Alan DeKok.
Try v3.0.x from Github: https://github.com/FreeRADIUS/freeradius-server/archive/v3.0.x.zip
It has many fixes over 3.0.17. One of these may be affecting you.
Alan DeKok.
Thanks, I’ll check that out later, I changed our config to realtime accounting and it is working well so far, let’s see what happens. Thanks again for the willingness to help.
participants (2)
-
Alan DeKok -
Antônio Modesto