RES: RES: RES: Incorrect username being registered by freeradius

25 Jun 2020

      Thanks Dekok and Buxey for helping me. 

As I used Dekok's suggestion of updating outer.session-state from the other topic (CUI thing), I discovered that I was NOT setting Stripped-User-Name just because that policy was NOT mentioned anywhere of VS default and inner-tunnel.

Reading that code, it was clear to me that I could "fix" MAC addr in user name of broken NAS (you see, only a few packets of these few NASes was arriving wrong)
So, I enabled splitting username from realm and used code of MAC canonicalization to fix MAC user problem:

user-as-mac-regexp = '([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})'

rewrite_username {
        if (&User-name && (&User-Name =~ /^${policy.user-as-mac-regexp}$/i)) {
                update request {
                        &User-Name := "%{sql:SELECT username from radacct \
                                WHERE CallingStationId = '%{toupper:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}}' \
                                ORDER BY radacctid limit 1}"
                }
                updated
        }
        else {
                noop
        }
}

Did some copy and paste with a little substitution...
Then, inserted rewrite_username before split_username_nai filter at preacct section and that is it.
From, 9417 packets, only one, for now, had the problem and was fixed (server running for 48min until this moment)

(8907) Thu Jun 25 14:43:59 2020: Debug: Received Accounting-Request Id 192 from 10.34.5.223:1829 to 10.34.242.3:1813 length 151
(8907) Thu Jun 25 14:43:59 2020: Debug:   Acct-Session-Id = "386D9BFB-0000015C"
(8907) Thu Jun 25 14:43:59 2020: Debug:   Acct-Status-Type = Start
(8907) Thu Jun 25 14:43:59 2020: Debug:   Acct-Authentic = RADIUS
(8907) Thu Jun 25 14:43:59 2020: Debug:   User-Name = "a8b86e23fca1"
(8907) Thu Jun 25 14:43:59 2020: Debug:   NAS-IP-Address = 10.34.5.223
(8907) Thu Jun 25 14:43:59 2020: Debug:   NAS-Port = 2
(8907) Thu Jun 25 14:43:59 2020: Debug:   Called-Station-Id = "5C-D9-98-14-14-78:MPDFT"
(8907) Thu Jun 25 14:43:59 2020: Debug:   Calling-Station-Id = "A8-B8-6E-23-FC-A1"
(8907) Thu Jun 25 14:43:59 2020: Debug:   NAS-Port-Type = Wireless-802.11
(8907) Thu Jun 25 14:43:59 2020: Debug:   Connect-Info = "CONNECT 54Mbps 802.11g"
(8907) Thu Jun 25 14:43:59 2020: Debug: # Executing section preacct from file /etc/freeradius/3.0/sites-enabled/default
(8907) Thu Jun 25 14:43:59 2020: Debug:   preacct {
(8907) Thu Jun 25 14:43:59 2020: Debug:     [preprocess] = ok
(8907) Thu Jun 25 14:43:59 2020: Debug:     policy rewrite_username {
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (&User-name && (&User-Name =~ /^([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})$/i)) {
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (&User-name && (&User-Name =~ /^([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})$/i))  -> TRUE
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (&User-name && (&User-Name =~ /^([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})$/i))  {
(8907) Thu Jun 25 14:43:59 2020: Debug:         update request {
(8907) Thu Jun 25 14:43:59 2020: Debug:           EXPAND %{tolower:%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}}
(8907) Thu Jun 25 14:43:59 2020: Debug:              --> a8b86e23fca1
(8907) Thu Jun 25 14:43:59 2020: Debug:           SQL-User-Name set to 'a8b86e23fca1'
(8907) Thu Jun 25 14:43:59 2020: Debug:           Executing select query: SELECT username from radacct                          WHERE CallingStationId = 'A8-B8-6E-23-FC-A1'                            ORDER BY radacctid limit 1
(8907) Thu Jun 25 14:43:59 2020: Debug:           EXPAND %{sql:SELECT username from radacct                             WHERE CallingStationId = '%{toupper:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}}'                             ORDER BY radacctid limit 1}
(8907) Thu Jun 25 14:43:59 2020: Debug:              --> alex.dalton
(8907) Thu Jun 25 14:43:59 2020: Debug:         } # update request = noop
(8907) Thu Jun 25 14:43:59 2020: Debug:         [updated] = updated
(8907) Thu Jun 25 14:43:59 2020: Debug:       } # if (&User-name && (&User-Name =~ /^([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})([0-9a-f]{2})$/i))  = updated
(8907) Thu Jun 25 14:43:59 2020: Debug:       ... skipping else: Preceding "if" was taken
(8907) Thu Jun 25 14:43:59 2020: Debug:     } # policy rewrite_username = updated
(8907) Thu Jun 25 14:43:59 2020: Debug:     policy split_username_nai {
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) {
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  -> TRUE
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  {
(8907) Thu Jun 25 14:43:59 2020: Debug:         update request {
(8907) Thu Jun 25 14:43:59 2020: Debug:           EXPAND %{1}
(8907) Thu Jun 25 14:43:59 2020: Debug:              --> alex.dalton
(8907) Thu Jun 25 14:43:59 2020: Debug:           EXPAND %{3}
(8907) Thu Jun 25 14:43:59 2020: Debug:              -->
(8907) Thu Jun 25 14:43:59 2020: Debug:         } # update request = noop
(8907) Thu Jun 25 14:43:59 2020: Debug:         [updated] = updated
(8907) Thu Jun 25 14:43:59 2020: Debug:       } # if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  = updated
(8907) Thu Jun 25 14:43:59 2020: Debug:       ... skipping else: Preceding "if" was taken
(8907) Thu Jun 25 14:43:59 2020: Debug:     } # policy split_username_nai = updated
(8907) Thu Jun 25 14:43:59 2020: Debug:     update request {
(8907) Thu Jun 25 14:43:59 2020: Debug:       EXPAND %{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}}
(8907) Thu Jun 25 14:43:59 2020: Debug:          --> 1593107039
(8907) Thu Jun 25 14:43:59 2020: Debug:     } # update request = noop
(8907) Thu Jun 25 14:43:59 2020: Debug:     policy acct_unique {
(8907) Thu Jun 25 14:43:59 2020: Debug:       update request {
(8907) Thu Jun 25 14:43:59 2020: Debug:       } # update request = noop
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) &&           ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
(8907) Thu Jun 25 14:43:59 2020: Debug:       EXPAND %{hex:&Class}
(8907) Thu Jun 25 14:43:59 2020: Debug:          -->
(8907) Thu Jun 25 14:43:59 2020: Debug:       EXPAND ^%{hex:&Tmp-String-9}
(8907) Thu Jun 25 14:43:59 2020: Debug:          --> ^61693a
(8907) Thu Jun 25 14:43:59 2020: Debug:       if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) &&           ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE
(8907) Thu Jun 25 14:43:59 2020: Debug:       else {
(8907) Thu Jun 25 14:43:59 2020: Debug:         update request {
(8907) Thu Jun 25 14:43:59 2020: Debug:           EXPAND %{Acct-Session-ID}
(8907) Thu Jun 25 14:43:59 2020: Debug:              --> 386D9BFB-0000015C
(8907) Thu Jun 25 14:43:59 2020: Debug:           EXPAND %{%{Stripped-User-Name}:-%{User-Name}}
(8907) Thu Jun 25 14:43:59 2020: Debug:              --> alex.dalton
(8907) Thu Jun 25 14:43:59 2020: Debug:           EXPAND %{md5:%{%{Stripped-User-Name}:-%{User-Name}},%{Acct-Session-ID},%{Calling-Station-Id}}
(8907) Thu Jun 25 14:43:59 2020: Debug:              --> d07a1728ff39147a452a960d300c989e
(8907) Thu Jun 25 14:43:59 2020: Debug:         } # update request = noop
(8907) Thu Jun 25 14:43:59 2020: Debug:       } # else = noop
(8907) Thu Jun 25 14:43:59 2020: Debug:     } # policy acct_unique = noop
(8907) Thu Jun 25 14:43:59 2020: Debug: suffix: Checking for suffix after "@"
(8907) Thu Jun 25 14:43:59 2020: Debug: suffix: No '@' in User-Name = "alex.dalton", looking up realm NULL
(8907) Thu Jun 25 14:43:59 2020: Debug: suffix: No such realm "NULL"
(8907) Thu Jun 25 14:43:59 2020: Debug:     [suffix] = noop
(8907) Thu Jun 25 14:43:59 2020: Debug: files: acct_users: Matched entry DEFAULT at line 22
(8907) Thu Jun 25 14:43:59 2020: Debug: files: EXPAND %{%{Stripped-User-Name}:-%{User-Name}}
(8907) Thu Jun 25 14:43:59 2020: Debug: files:    --> alex.dalton
(8907) Thu Jun 25 14:43:59 2020: Debug:     [files] = ok
(8907) Thu Jun 25 14:43:59 2020: Debug:   } # preacct = updated
(8907) Thu Jun 25 14:43:59 2020: Debug: # Executing section accounting from file /etc/freeradius/3.0/sites-enabled/default
(8907) Thu Jun 25 14:43:59 2020: Debug:   accounting {
(8907) Thu Jun 25 14:43:59 2020: Debug: log_accounting: EXPAND Accounting-Request.%{%{Acct-Status-Type}:-unknown}
(8907) Thu Jun 25 14:43:59 2020: Debug: log_accounting:    --> Accounting-Request.Start
(8907) Thu Jun 25 14:43:59 2020: Debug: log_accounting: EXPAND %{date:Event-Timestamp} Connect: [%{User-Name}] (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} ip %{Framed-IP-Address})
(8907) Thu Jun 25 14:43:59 2020: Debug: log_accounting:    --> Thu, 25-06-2020 14:43:59 Connect: [alex.dalton] (did 5C-D9-98-14-14-78:MPDFT cli A8-B8-6E-23-FC-A1 port 2 ip )
(8907) Thu Jun 25 14:43:59 2020: Debug: log_accounting: EXPAND /var/log/freeradius/linelog-accounting
(8907) Thu Jun 25 14:43:59 2020: Debug: log_accounting:    --> /var/log/freeradius/linelog-accounting
(8907) Thu Jun 25 14:43:59 2020: Debug:     [log_accounting] = ok
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-none}.query}
(8907) Thu Jun 25 14:43:59 2020: Debug: sql:    --> type.start.query
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: Using query template 'query'
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: EXPAND %{tolower:%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}}
(8907) Thu Jun 25 14:43:59 2020: Debug: sql:    --> alex.dalton
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: SQL-User-Name set to 'alex.dalton'
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: EXPAND INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Realm}', ''), '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}', NULLIF('%{%{NAS-Port-ID}:-%{NAS-Port}}', ''), '%{NAS-Port-Type}', TO_TIMESTAMP(%{integer:Event-Timestamp}), TO_TIMESTAMP(%{integer:Event-Timestamp}), NULL, 0, '%{Acct-Authentic}', '%{Connect-Info}', NULL, 0, 0, '%{Called-Station-Id}', '%{Calling-Station-Id}', NULL, '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', '')::inet)
(8907) Thu Jun 25 14:43:59 2020: Debug: sql:    --> INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('386D9BFB-0000015C', 'd07a1728ff39147a452a960d300c989e', 'alex.dalton', NULLIF('', ''), '10.34.5.223', NULLIF('2', ''), 'Wireless-802.11', TO_TIMESTAMP(1593107039), TO_TIMESTAMP(1593107039), NULL, 0, 'RADIUS', 'CONNECT 54Mbps 802.11g', NULL, 0, 0, '5C-D9-98-14-14-78:MPDFT', 'A8-B8-6E-23-FC-A1', NULL, '', '', NULLIF('', '')::inet)
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: Executing query: INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('386D9BFB-0000015C', 'd07a1728ff39147a452a960d300c989e', 'alex.dalton', NULLIF('', ''), '10.34.5.223', NULLIF('2', ''), 'Wireless-802.11', TO_TIMESTAMP(1593107039), TO_TIMESTAMP(1593107039), NULL, 0, 'RADIUS', 'CONNECT 54Mbps 802.11g', NULL, 0, 0, '5C-D9-98-14-14-78:MPDFT', 'A8-B8-6E-23-FC-A1', NULL, '', '', NULLIF('', '')::inet)
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: SQL query returned: success
(8907) Thu Jun 25 14:43:59 2020: Debug: sql: 1 record(s) updated
(8907) Thu Jun 25 14:43:59 2020: Debug:     [sql] = ok
(8907) Thu Jun 25 14:43:59 2020: Debug:     if (&request:Acct-Status-Type == start) {
(8907) Thu Jun 25 14:43:59 2020: Debug:     if (&request:Acct-Status-Type == start)  -> TRUE
(8907) Thu Jun 25 14:43:59 2020: Debug:     if (&request:Acct-Status-Type == start)  {
(8907) Thu Jun 25 14:43:59 2020: Debug:       EXPAND %{tolower:%{%{Stripped-User-Name}:-%{%{User-Name}:-none}}}
(8907) Thu Jun 25 14:43:59 2020: Debug:          --> alex.dalton
(8907) Thu Jun 25 14:43:59 2020: Debug:       SQL-User-Name set to 'alex.dalton'
(8907) Thu Jun 25 14:43:59 2020: Debug:       Executing query: UPDATE radacct                   SET                             AcctStopTime = TO_TIMESTAMP(1593107039),                                AcctUpdateTime = TO_TIMESTAMP(1593107039),                           AcctTerminateCause = 'Stalled-session',                                 ConnectInfo_stop = 'CONNECT 54Mbps 802.11g'                     WHERE UserName = 'alex.dalton'                  AND AcctUniqueId <> 'd07a1728ff39147a452a960d300c989e'                       AND CallingStationId = 'A8-B8-6E-23-FC-A1'                      AND AcctStopTime IS NULL
(8907) Thu Jun 25 14:43:59 2020: Debug:       SQL query affected no rows
(8907) Thu Jun 25 14:43:59 2020: Debug:       EXPAND %{sql:UPDATE radacct                       SET                             AcctStopTime = TO_TIMESTAMP(%{integer:Event-Timestamp}),                                AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}),                           AcctTerminateCause = 'Stalled-session',                                 ConnectInfo_stop = '%{Connect-Info}'                    WHERE UserName = '%{tolower:%{%{Stripped-User-Name}:-%{User-Name}}}'                         AND AcctUniqueId <> '%{Acct-Unique-Session-Id}'                         AND CallingStationId = '%{Calling-Station-Id}'                  AND AcctStopTime IS NULL}
(8907) Thu Jun 25 14:43:59 2020: Debug:          -->
(8907) Thu Jun 25 14:43:59 2020: Debug:     } # if (&request:Acct-Status-Type == start)  = ok
(8907) Thu Jun 25 14:43:59 2020: Debug:     [exec] = noop
(8907) Thu Jun 25 14:43:59 2020: Debug: attr_filter.accounting_response: EXPAND %{User-Name}
(8907) Thu Jun 25 14:43:59 2020: Debug: attr_filter.accounting_response:    --> alex.dalton
(8907) Thu Jun 25 14:43:59 2020: Debug: attr_filter.accounting_response: Matched entry DEFAULT at line 12
(8907) Thu Jun 25 14:43:59 2020: Debug:     [attr_filter.accounting_response] = updated
(8907) Thu Jun 25 14:43:59 2020: Debug:   } # accounting = updated
(8907) Thu Jun 25 14:43:59 2020: Debug: Sent Accounting-Response Id 192 from 10.34.242.3:1813 to 10.34.5.223:1829 length 0
(8907) Thu Jun 25 14:43:59 2020: Debug: Finished request
(8907) Thu Jun 25 14:43:59 2020: Debug: Cleaning up request packet ID 192 with timestamp +2160

RES: RES: RES: Incorrect username being registered by freeradius

Daniel Guimaraes Pena