Accommodating miss behaving NAS?

28 Jul 2021

      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