Accommodating miss behaving NAS?
Hi, We have a legacy ADSL system whereby the Telco handles PPPoE termination of the circuits, proxying authentication and accounting records through to us. We have several instances where the NASs appear to be miss-behaving and looking for recommendations around this. Authorization and authentication appears to be working as intended, accounting is also initially as expected in that we receive accounting start, interim updates and then an accounting stop. We however then continue to receive interim update accounting records where the utilisation is not added to the radacct table. We do have a request logged with the Telco regarding this behaviour, but our legacy FR v1 system would continue to associate accounting data and my understanding of the mods-config/sql/main/mysql/queries.conf file is that the following query should still continue to update the closed session as well (pretty sure the following is unmodified): # # Update an existing session and calculate the interval # between the last data we received for the session and this # update. This can be used to find stale sessions. # query = "\ UPDATE ${....acct_table1} \ SET \ acctupdatetime = (@acctupdatetime_old:=acctupdatetime), \ acctupdatetime = FROM_UNIXTIME(\ %{integer:Event-Timestamp}), \ acctinterval = %{integer:Event-Timestamp} - \ UNIX_TIMESTAMP(@acctupdatetime_old), \ framedipaddress = '%{Framed-IP-Address}', \ acctsessiontime = %{%{Acct-Session-Time}:-NULL}, \ acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' \ << 32 | '%{%{Acct-Input-Octets}:-0}', \ acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' \ << 32 | '%{%{Acct-Output-Octets}:-0}' \ WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'" FR 3.0.17+dfsg-1.1 appears to only update accounting up until the stop being received, ignoring subsequent updates: [admin@unix-01 ~]# mysql -u root -p**************** radius -e 'SELECT username,acctstarttime,acctstoptime,framedipaddress,callingstationid,acctinputoctets,acctoutputoctets FROM radacct WHERE acctuniqueid="50decbeb537ebe5860a8fdf11221017f"'; +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+ | username | acctstarttime | acctstoptime | framedipaddress | callingstationid | acctinputoctets | acctoutputoctets | +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+ | user60d1@realm.company.co.za<mailto:user60d1@realm.company.co.za> | 2021-07-24 11:11:08 | 2021-07-25 18:50:23 | 41.247.86.6 | 0112223333 | 199564666 | 321290299 | +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+ [admin@unix-01 ~]# grep '50decbeb537ebe5860a8fdf11221017f' /var/log/freeradius/radacct/*/*; /var/log/freeradius/radacct/196.43.3.76/detail-20210724: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # start /var/log/freeradius/radacct/196.43.3.76/detail-20210724: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.76/detail-20210724: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.76/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.76/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # stop /var/log/freeradius/radacct/196.43.3.77/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.77/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update Herewith the relevant accounting packets for Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f". Green entries above are the 'start', 'interim-updates' and then a 'stop'. The red entries above are interim-updates we receive after the stop and the purple is the in/out counters as per the stop packet having been received: Sat Jul 24 11:11:13 2021 X-Ascend-Xmit-Rate = 20480000 Acct-Authentic = RADIUS NAS-IP-Address = 196.43.47.51 Attr-26.1431.7 = 0x4144534c Framed-Protocol = PPP Attr-26.1431.3 = 0x494e5445524e4554 NAS-Port-Type = PPPoEoQinQ Acct-Status-Type = Start Calling-Station-Id = "0112223333" NAS-Port = 2686963842 User-Name = "user60d1@realm.company.co.za" Class = 0x4e31 X-Ascend-Data-Rate = 20480000 Acct-Delay-Time = 0 Framed-IP-Address = 41.247.86.6 NAS-Port-Id = "10/2/1:125.130" Acct-Session-Time = 5 Attr-26.1431.4 = 0x00005000 Acct-Session-Id = "B74D8B03E91BB460FBD922" Service-Type = Framed-User Telkom-Access-Type = "DSL" Proxy-State = 0x3739 Event-Timestamp = "Jul 24 2021 11:11:13 SAST" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" Timestamp = 1627117873 Sat Jul 24 17:10:26 2021 NAS-Port = 2686963842 Attr-26.1431.7 = 0x4144534c X-Ascend-Xmit-Rate = 20480000 Calling-Station-Id = "0112223333" Class = 0x4e31 NAS-Port-Type = PPPoEoQinQ Framed-IP-Address = 41.247.86.6 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port-Id = "10/2/1:125.130" Acct-Input-Gigawords = 0 NAS-IP-Address = 196.43.47.51 Acct-Output-Octets = 65339784 Acct-Output-Packets = 138132 Acct-Input-Packets = 145488 User-Name = "user60d1@realm.company.co.za" Acct-Authentic = RADIUS Acct-Session-Time = 21558 Attr-26.1431.3 = 0x494e5445524e4554 Acct-Status-Type = Interim-Update Acct-Input-Octets = 33612675 Acct-Session-Id = "B74D8B03E91BB460FBD922" Acct-Delay-Time = 0 Acct-Output-Gigawords = 0 Attr-26.1431.4 = 0x00005000 X-Ascend-Data-Rate = 20480000 Telkom-Access-Type = "DSL" Proxy-State = 0x313936 Event-Timestamp = "Jul 24 2021 17:10:26 SAST" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" Timestamp = 1627139426 Sat Jul 24 23:13:24 2021 Acct-Input-Gigawords = 0 NAS-Port-Id = "10/2/1:125.130" Acct-Output-Octets = 124192829 Attr-26.1431.7 = 0x4144534c Acct-Delay-Time = 0 X-Ascend-Xmit-Rate = 20480000 X-Ascend-Data-Rate = 20480000 Attr-26.1431.4 = 0x00005000 Acct-Input-Packets = 295296 NAS-Port = 2686963842 Acct-Input-Octets = 86715171 User-Name = "user60d1@realm.company.co.za" Acct-Status-Type = Interim-Update NAS-IP-Address = 196.43.47.51 Acct-Output-Packets = 271352 Attr-26.1431.3 = 0x494e5445524e4554 Framed-Protocol = PPP Class = 0x4e31 Framed-IP-Address = 41.247.86.6 Service-Type = Framed-User Acct-Output-Gigawords = 0 Calling-Station-Id = "0112223333" Acct-Authentic = RADIUS NAS-Port-Type = PPPoEoQinQ Acct-Session-Time = 43336 Acct-Session-Id = "B74D8B03E91BB460FBD922" Telkom-Access-Type = "DSL" Proxy-State = 0x3634 Event-Timestamp = "Jul 24 2021 23:13:24 SAST" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" Timestamp = 1627161204 Sun Jul 25 05:15:19 2021 Acct-Input-Octets = 118004756 Attr-26.1431.4 = 0x00005000 Acct-Status-Type = Interim-Update Acct-Input-Packets = 425898 X-Ascend-Xmit-Rate = 20480000 User-Name = "user60d1@realm.company.co.za" Framed-Protocol = PPP NAS-Port = 2686963842 Attr-26.1431.7 = 0x4144534c Class = 0x4e31 NAS-Port-Type = PPPoEoQinQ Acct-Output-Octets = 179007110 Framed-IP-Address = 41.247.86.6 Acct-Output-Packets = 390444 Service-Type = Framed-User X-Ascend-Data-Rate = 20480000 Acct-Session-Id = "B74D8B03E91BB460FBD922" Acct-Session-Time = 65052 Acct-Output-Gigawords = 0 NAS-IP-Address = 196.43.47.51 Calling-Station-Id = "0112223333" Acct-Delay-Time = 0 Attr-26.1431.3 = 0x494e5445524e4554 Acct-Input-Gigawords = 0 Acct-Authentic = RADIUS NAS-Port-Id = "10/2/1:125.130" Telkom-Access-Type = "DSL" Proxy-State = 0x323432 Event-Timestamp = "Jul 25 2021 05:15:19 SAST" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" Timestamp = 1627182919 Sun Jul 25 18:50:23 2021 Calling-Station-Id = "0112223333" Acct-Terminate-Cause = Lost-Carrier Acct-Output-Octets = 321290299 NAS-Port-Type = PPPoEoQinQ Acct-Authentic = RADIUS Acct-Input-Packets = 798410 Attr-26.1431.3 = 0x494e5445524e4554 Acct-Status-Type = Stop Acct-Input-Gigawords = 0 Framed-Protocol = PPP NAS-Port = 2686963842 X-Ascend-Data-Rate = 20480000 Attr-26.1431.7 = 0x4144534c Acct-Delay-Time = 0 User-Name = "user60d1@realm.company.co.za" Attr-26.1431.4 = 0x00005000 Class = 0x4e31 NAS-Port-Id = "10/2/1:125.130" Service-Type = Framed-User Acct-Session-Id = "B74D8B03E91BB460FBD922" NAS-IP-Address = 196.43.47.51 Acct-Input-Octets = 199564666 Acct-Session-Time = 113955 Acct-Output-Gigawords = 0 Framed-IP-Address = 41.247.86.6 X-Ascend-Xmit-Rate = 20480000 Acct-Output-Packets = 742386 Telkom-Access-Type = "DSL" Proxy-State = 0x323235 Event-Timestamp = "Jul 25 2021 18:50:23 SAST" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" Timestamp = 1627231823 Sun Jul 25 11:16:58 2021 NAS-Port-Id = "10/2/1:125.130" Acct-Status-Type = Interim-Update NAS-IP-Address = 196.43.47.51 Class = 0x4e31 X-Ascend-Data-Rate = 20480000 Acct-Input-Packets = 600825 Attr-26.1431.4 = 0x00005000 X-Ascend-Xmit-Rate = 20480000 Framed-IP-Address = 41.247.86.6 Acct-Session-Id = "B74D8B03E91BB460FBD922" Acct-Input-Gigawords = 0 Acct-Output-Gigawords = 0 Acct-Delay-Time = 0 User-Name = "user60d1@realm.company.co.za" Framed-Protocol = PPP Acct-Session-Time = 86751 Attr-26.1431.7 = 0x4144534c Service-Type = Framed-User Calling-Station-Id = "0112223333" Attr-26.1431.3 = 0x494e5445524e4554 Acct-Input-Octets = 155655292 Acct-Output-Octets = 243066595 NAS-Port-Type = PPPoEoQinQ NAS-Port = 2686963842 Acct-Output-Packets = 557229 Acct-Authentic = RADIUS Telkom-Access-Type = "DSL" Proxy-State = 0x3439 Event-Timestamp = "Jul 25 2021 11:16:58 SAST" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" Timestamp = 1627204618 Sun Jul 25 17:14:09 2021 Acct-Delay-Time = 0 NAS-Port-Id = "10/2/1:125.130" Acct-Output-Packets = 708535 Service-Type = Framed-User Calling-Station-Id = "0112223333" Acct-Session-Id = "B74D8B03E91BB460FBD922" X-Ascend-Data-Rate = 20480000 Class = 0x4e31 Acct-Authentic = RADIUS Framed-IP-Address = 41.247.86.6 NAS-Port = 2686963842 User-Name = "user60d1@realm.company.co.za" Acct-Output-Octets = 305092740 Acct-Session-Time = 108182 Acct-Input-Gigawords = 0 Acct-Output-Gigawords = 0 Attr-26.1431.4 = 0x00005000 Framed-Protocol = PPP Acct-Status-Type = Interim-Update Acct-Input-Packets = 761669 Attr-26.1431.7 = 0x4144534c Attr-26.1431.3 = 0x494e5445524e4554 NAS-Port-Type = PPPoEoQinQ Acct-Input-Octets = 190814584 NAS-IP-Address = 196.43.47.51 X-Ascend-Xmit-Rate = 20480000 Telkom-Access-Type = "DSL" Proxy-State = 0x3133 Event-Timestamp = "Jul 25 2021 17:14:09 SAST" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" Timestamp = 1627226049 Regards David Herselman
On 28/07/2021 08:39, David Herselman via Freeradius-Users wrote:
FR 3.0.17+dfsg-1.1 appears to only update accounting up until the stop being received, ignoring subsequent updates: [admin@unix-01 ~]# mysql -u root -p**************** radius -e 'SELECT username,acctstarttime,acctstoptime,framedipaddress,callingstationid,acctinputoctets,acctoutputoctets FROM radacct WHERE acctuniqueid="50decbeb537ebe5860a8fdf11221017f"'; +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+ | username | acctstarttime | acctstoptime | framedipaddress | callingstationid | acctinputoctets | acctoutputoctets | +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+ | user60d1@realm.company.co.za<mailto:user60d1@realm.company.co.za> | 2021-07-24 11:11:08 | 2021-07-25 18:50:23 | 41.247.86.6 | 0112223333 | 199564666 | 321290299 | +------------------------------+---------------------+---------------------+-----------------+------------------+-----------------+------------------+
What does acctupdatetime contain? The Interm-Update query doesn't touch acctstoptime.
[admin@unix-01 ~]# grep '50decbeb537ebe5860a8fdf11221017f' /var/log/freeradius/radacct/*/*; /var/log/freeradius/radacct/196.43.3.76/detail-20210724: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # start /var/log/freeradius/radacct/196.43.3.76/detail-20210724: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.76/detail-20210724: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.76/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.76/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # stop /var/log/freeradius/radacct/196.43.3.77/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update /var/log/freeradius/radacct/196.43.3.77/detail-20210725: Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f" # interim-update
Herewith the relevant accounting packets for Acct-Unique-Session-Id = "50decbeb537ebe5860a8fdf11221017f". Green entries above are the 'start', 'interim-updates' and then a 'stop'. The red entries above are interim-updates we receive after the stop and the purple is the in/out counters as per the stop packet having been received:
The Event-Timestamp of the last two Interim-Updates show they happened before the Stop, and the Acct-{Input,Output}-Octets are lower values than the final Stop, too, so looks like they were just logged out of order, rather than being received out of order? The SQL data is correct from what I can see. Not sure what the problem is here. The debug output will show what is actually happening. Most anything else is guesswork.
Sat Jul 24 11:11:13 2021 Acct-Status-Type = Start
Sat Jul 24 17:10:26 2021
Sat Jul 24 23:13:24 2021
Sun Jul 25 05:15:19 2021
5am
Sun Jul 25 18:50:23 2021 Acct-Terminate-Cause = Lost-Carrier Acct-Status-Type = Stop
7pm
Sun Jul 25 11:16:58 2021
11am (earlier than stop)
Sun Jul 25 17:14:09 2021
5pm (earlier than stop) -- Matthew
participants (2)
-
David Herselman -
Matthew Newton