Hello all, I'm trying to get a Cumulus Linux switch to CLI authenticate to PacketFence, and unable to figure out the root cause of the username auth failure.
I've got switches defined in PacketFence, and they successfully work for 802.1x RADIUS authentication. I've defined them as Cisco 2960s, though I've tried other switch types just to test. I've made sure to toggle the flag `CLI Access Enabled`. I'm using a local database of users only. This is a simple lab test. I've got a user `test-radius` defined, with Access Level to ALL. I'm using plaintext passwords. Supported EAP Authentication Methods are MD5, MSCHAPv2 and PEAP. I've searched through archives, and not been able to figure out what's the key line in the debugging info below that I should focus on. Any suggestions would be very helpful! Config and debugging info below: Config of RADIUS on the Cumulus switch done as per docs: https://docs.cumulusnetworks.com/cumulus-linux-41/System-Configuration/Authentication-Authorization-and-Accounting/RADIUS-AAA/ There's little config on the cumulus side: /etc/pam_radius_auth.conf mapped_priv_user radius_priv_user # server[:port] shared_secret timeout (secs) src_ip 192.168.200.252 cumulus # when mgmt vrf is in use vrf-name mgmt Tcpdump from switch showing outgoing RADIUS auth request: 15:28:15.340201 IP (tos 0x0, ttl 64, id 14880, offset 0, flags [DF], proto UDP (17), length 124) closet04.57381 > packetfence.radius: [udp sum ok] RADIUS, length: 96 Access-Request (1), id: 0x61, Authenticator: f226ecd0bb0321d52e139756c9ba1366 User-Name Attribute (1), length: 13, Value: test-radius 0x0000: 7465 7374 2d72 6164 6975 73 User-Password Attribute (2), length: 18, Value: 0x0000: 5bf5 b7a5 18e1 89f5 362c cf53 3205 92a1 NAS-IP-Address Attribute (4), length: 6, Value: closet04 0x0000: 7f00 0101 NAS-Identifier Attribute (32), length: 6, Value: sshd 0x0000: 7373 6864 NAS-Port Attribute (5), length: 6, Value: 10130 0x0000: 0000 2792 NAS-Port-Type Attribute (61), length: 6, Value: Virtual 0x0000: 0000 0005 Service-Type Attribute (6), length: 6, Value: Authenticate Only 0x0000: 0000 0008 Calling-Station-Id Attribute (31), length: 15, Value: 192.168.200.1 0x0000: 3139 322e 3136 382e 3230 302e 31 15:28:16.472830 IP (tos 0x0, ttl 64, id 146, offset 0, flags [none], proto UDP (17), length 48) packetfence.radius > closet04.57381: [udp sum ok] RADIUS, length: 20 Access-Reject (3), id: 0x61, Authenticator: 53558faff1296f5f2531b72e4be237bd PacketFence RADIUS Debugging Info: root@packetfence:/usr/local/pf# raddebug -f var/run/radiusd.sock -t 300 (4) Mon Apr 20 15:28:15 2020: Debug: Received Status-Server Id 166 from 127.0.0.1:60738 to 127.0.0.1:18121 length 50 (4) Mon Apr 20 15:28:15 2020: Debug: Message-Authenticator = 0xd61e4bf3e9ef1fe37b8bd6833281f4ff (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Statistics-Type = 15 (4) Mon Apr 20 15:28:15 2020: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/status (4) Mon Apr 20 15:28:15 2020: Debug: Autz-Type Status-Server { (4) Mon Apr 20 15:28:15 2020: Debug: [ok] = ok (4) Mon Apr 20 15:28:15 2020: Debug: } # Autz-Type Status-Server = ok (4) Mon Apr 20 15:28:15 2020: Debug: Sent Access-Accept Id 166 from 127.0.0.1:18121 to 127.0.0.1:60738 length 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Access-Requests = 5 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Access-Accepts = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Access-Rejects = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Access-Challenges = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Auth-Responses = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Auth-Duplicate-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Auth-Malformed-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Auth-Invalid-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Auth-Dropped-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Auth-Unknown-Types = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Accounting-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Accounting-Responses = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Acct-Duplicate-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Acct-Malformed-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Acct-Invalid-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Acct-Dropped-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Acct-Unknown-Types = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Access-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Access-Accepts = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Access-Rejects = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Access-Challenges = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Auth-Responses = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Accounting-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Accounting-Responses = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0 (4) Mon Apr 20 15:28:15 2020: Debug: FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0 (4) Mon Apr 20 15:28:15 2020: Debug: Finished request (5) Mon Apr 20 15:28:15 2020: Debug: Received Access-Request Id 97 from 192.168.200.34:57381 to 192.168.200.252:1812 length 96 (5) Mon Apr 20 15:28:15 2020: Debug: User-Name = "test-radius" (5) Mon Apr 20 15:28:15 2020: Debug: User-Password = "cumulus" (5) Mon Apr 20 15:28:15 2020: Debug: NAS-IP-Address = 127.0.1.1 (5) Mon Apr 20 15:28:15 2020: Debug: NAS-Identifier = "sshd" (5) Mon Apr 20 15:28:15 2020: Debug: NAS-Port = 10130 (5) Mon Apr 20 15:28:15 2020: Debug: NAS-Port-Type = Virtual (5) Mon Apr 20 15:28:15 2020: Debug: Service-Type = Authenticate-Only (5) Mon Apr 20 15:28:15 2020: Debug: Calling-Station-Id = "192.168.200.1" (5) Mon Apr 20 15:28:15 2020: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (5) Mon Apr 20 15:28:15 2020: Debug: authorize { (5) Mon Apr 20 15:28:15 2020: Debug: update { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{Packet-Src-IP-Address} (5) Mon Apr 20 15:28:15 2020: Debug: --> 192.168.200.34 (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{Packet-Dst-IP-Address} (5) Mon Apr 20 15:28:15 2020: Debug: --> 192.168.200.252 (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %l (5) Mon Apr 20 15:28:15 2020: Debug: --> 1587396495 (5) Mon Apr 20 15:28:15 2020: Debug: } # update = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy packetfence-set-realm-if-machine { (5) Mon Apr 20 15:28:15 2020: Debug: if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) { (5) Mon Apr 20 15:28:15 2020: Debug: if (User-Name =~ /host\/([a-z0-9_-]*)[\.](.*)/i) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: } # policy packetfence-set-realm-if-machine = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy packetfence-balanced-key-policy { (5) Mon Apr 20 15:28:15 2020: Debug: if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i)) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&PacketFence-KeyBalanced && (&PacketFence-KeyBalanced =~ /^(.*)(.)$/i)) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: else { (5) Mon Apr 20 15:28:15 2020: Debug: update { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{md5:%{Calling-Station-Id}%{User-Name}} (5) Mon Apr 20 15:28:15 2020: Debug: --> fb4172cb9cf644e1d3d9f75872bdf56d (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{md5:%{Calling-Station-Id}%{User-Name}} (5) Mon Apr 20 15:28:15 2020: Debug: --> fb4172cb9cf644e1d3d9f75872bdf56d (5) Mon Apr 20 15:28:15 2020: Debug: } # update = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # else = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # policy packetfence-balanced-key-policy = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy packetfence-set-tenant-id { (5) Mon Apr 20 15:28:15 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){ (5) Mon Apr 20 15:28:15 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0} (5) Mon Apr 20 15:28:15 2020: Debug: --> 0 (5) Mon Apr 20 15:28:15 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE (5) Mon Apr 20 15:28:15 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (5) Mon Apr 20 15:28:15 2020: Debug: update control { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{User-Name} (5) Mon Apr 20 15:28:15 2020: Debug: --> test-radius (5) Mon Apr 20 15:28:15 2020: Debug: SQL-User-Name set to 'test-radius' (5) Mon Apr 20 15:28:15 2020: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '127.0.1.1'), 0) (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname = '%{NAS-IP-Address}'), 0)} (5) Mon Apr 20 15:28:15 2020: Debug: --> 0 (5) Mon Apr 20 15:28:15 2020: Debug: } # update control = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop (5) Mon Apr 20 15:28:15 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (5) Mon Apr 20 15:28:15 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> TRUE (5) Mon Apr 20 15:28:15 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (5) Mon Apr 20 15:28:15 2020: Debug: update control { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{User-Name} (5) Mon Apr 20 15:28:15 2020: Debug: --> test-radius (5) Mon Apr 20 15:28:15 2020: Debug: SQL-User-Name set to 'test-radius' (5) Mon Apr 20 15:28:15 2020: Debug: Executing select query: SELECT IFNULL((SELECT tenant_id from radius_nas WHERE start_ip <= INET_ATON('127.0.1.1') and INET_ATON('127.0.1.1') <= end_ip order by range_length limit 1), 1) (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{sql: SELECT IFNULL((SELECT tenant_id from radius_nas WHERE start_ip <= INET_ATON('%{NAS-IP-Address}') and INET_ATON('%{NAS-IP-Address}') <= end_ip order by range_length limit 1), 1)} (5) Mon Apr 20 15:28:15 2020: Debug: --> 1 (5) Mon Apr 20 15:28:15 2020: Debug: } # update control = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # if ( &control:PacketFence-Tenant-Id == 0 ) = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # policy packetfence-set-tenant-id = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy rewrite_calling_station_id { (5) Mon Apr 20 15:28:15 2020: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: else { (5) Mon Apr 20 15:28:15 2020: Debug: [noop] = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # else = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # policy rewrite_calling_station_id = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy rewrite_called_station_id { (5) Mon Apr 20 15:28:15 2020: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) { (5) Mon Apr 20 15:28:15 2020: Debug: if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: else { (5) Mon Apr 20 15:28:15 2020: Debug: [noop] = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # else = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # policy rewrite_called_station_id = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy filter_username { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name) -> TRUE (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ / /) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ / /) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /@[^@]*@/ ) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /\.\./ ) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (5) Mon Apr 20 15:28:15 2020: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /\.$/) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /\.$/) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /@\./) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name =~ /@\./) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: } # if (&User-Name) = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # policy filter_username = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy filter_password { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{string:User-Password} (5) Mon Apr 20 15:28:15 2020: Debug: --> cumulus (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: } # policy filter_password = noop (5) Mon Apr 20 15:28:15 2020: Debug: [preprocess] = ok (5) Mon Apr 20 15:28:15 2020: Debug: suffix: Checking for suffix after "@" (5) Mon Apr 20 15:28:15 2020: Debug: suffix: No '@' in User-Name = "test-radius", skipping NULL due to config. (5) Mon Apr 20 15:28:15 2020: Debug: [suffix] = noop (5) Mon Apr 20 15:28:15 2020: Debug: ntdomain: Checking for prefix before "\" (5) Mon Apr 20 15:28:15 2020: Debug: ntdomain: No '\' in User-Name = "test-radius", looking up realm NULL (5) Mon Apr 20 15:28:15 2020: Debug: ntdomain: Found realm "null" (5) Mon Apr 20 15:28:15 2020: Debug: ntdomain: Adding Stripped-User-Name = "test-radius" (5) Mon Apr 20 15:28:15 2020: Debug: ntdomain: Adding Realm = "null" (5) Mon Apr 20 15:28:15 2020: Debug: ntdomain: Authentication realm is LOCAL (5) Mon Apr 20 15:28:15 2020: Debug: [ntdomain] = ok (5) Mon Apr 20 15:28:15 2020: Debug: eap: No EAP-Message, not doing EAP (5) Mon Apr 20 15:28:15 2020: Debug: [eap] = noop (5) Mon Apr 20 15:28:15 2020: Debug: if ( !EAP-Message ) { (5) Mon Apr 20 15:28:15 2020: Debug: if ( !EAP-Message ) -> TRUE (5) Mon Apr 20 15:28:15 2020: Debug: if ( !EAP-Message ) { (5) Mon Apr 20 15:28:15 2020: Debug: update { (5) Mon Apr 20 15:28:15 2020: Debug: } # update = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # if ( !EAP-Message ) = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy packetfence-eap-mac-policy { (5) Mon Apr 20 15:28:15 2020: Debug: if ( &EAP-Type ) { (5) Mon Apr 20 15:28:15 2020: Debug: if ( &EAP-Type ) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: [noop] = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # policy packetfence-eap-mac-policy = noop (5) Mon Apr 20 15:28:15 2020: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (5) Mon Apr 20 15:28:15 2020: WARNING: pap: !!! Ignoring control:User-Password. Update your !!! (5) Mon Apr 20 15:28:15 2020: WARNING: pap: !!! configuration so that the "known good" clear text !!! (5) Mon Apr 20 15:28:15 2020: WARNING: pap: !!! password is in Cleartext-Password and NOT in !!! (5) Mon Apr 20 15:28:15 2020: WARNING: pap: !!! User-Password. !!! (5) Mon Apr 20 15:28:15 2020: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (5) Mon Apr 20 15:28:15 2020: WARNING: pap: Auth-Type already set. Not setting to PAP (5) Mon Apr 20 15:28:15 2020: Debug: [pap] = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # authorize = ok (5) Mon Apr 20 15:28:15 2020: Debug: Found Auth-Type = Accept (5) Mon Apr 20 15:28:15 2020: Debug: Auth-Type = Accept, accepting the user (5) Mon Apr 20 15:28:15 2020: Debug: # Executing section post-auth from file /usr/local/pf/raddb/sites-enabled/packetfence (5) Mon Apr 20 15:28:15 2020: Debug: post-auth { (5) Mon Apr 20 15:28:15 2020: Debug: update { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{Packet-Src-IP-Address} (5) Mon Apr 20 15:28:15 2020: Debug: --> 192.168.200.34 (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{Packet-Dst-IP-Address} (5) Mon Apr 20 15:28:15 2020: Debug: --> 192.168.200.252 (5) Mon Apr 20 15:28:15 2020: Debug: } # update = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy packetfence-set-tenant-id { (5) Mon Apr 20 15:28:15 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){ (5) Mon Apr 20 15:28:15 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0} (5) Mon Apr 20 15:28:15 2020: Debug: --> 1 (5) Mon Apr 20 15:28:15 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (5) Mon Apr 20 15:28:15 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: } # policy packetfence-set-tenant-id = noop (5) Mon Apr 20 15:28:15 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{%{control:PacketFence-Proxied-From}:-False} (5) Mon Apr 20 15:28:15 2020: Debug: --> False (5) Mon Apr 20 15:28:15 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (5) Mon Apr 20 15:28:15 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> TRUE (5) Mon Apr 20 15:28:15 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (5) Mon Apr 20 15:28:15 2020: Debug: rest: Expanding URI components (5) Mon Apr 20 15:28:15 2020: Debug: rest: EXPAND http://127.0.0.1:7070 (5) Mon Apr 20 15:28:15 2020: Debug: rest: --> http://127.0.0.1:7070 (5) Mon Apr 20 15:28:15 2020: Debug: rest: EXPAND //radius/rest/authorize (5) Mon Apr 20 15:28:15 2020: Debug: rest: --> //radius/rest/authorize (5) Mon Apr 20 15:28:15 2020: Debug: rest: Sending HTTP POST to "http://127.0.0.1:7070//radius/rest/authorize";; (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "User-Name" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "User-Password" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "NAS-IP-Address" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "NAS-Port" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "Service-Type" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "Calling-Station-Id" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "NAS-Identifier" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "NAS-Port-Type" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "Event-Timestamp" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "Stripped-User-Name" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "Realm" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "SQL-User-Name" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "FreeRADIUS-Client-IP-Address" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "PacketFence-KeyBalanced" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Encoding attribute "PacketFence-Radius-Ip" (5) Mon Apr 20 15:28:15 2020: Debug: rest: Processing response header (5) Mon Apr 20 15:28:15 2020: Debug: rest: Status : 401 (Unauthorized) (5) Mon Apr 20 15:28:15 2020: Debug: rest: Type : json (application/json) (5) Mon Apr 20 15:28:15 2020: ERROR: rest: Server returned: (5) Mon Apr 20 15:28:15 2020: ERROR: rest: {"control:PacketFence-Authorization-Status":"allow"} (5) Mon Apr 20 15:28:15 2020: Debug: [rest] = invalid (5) Mon Apr 20 15:28:15 2020: Debug: } # if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) = invalid (5) Mon Apr 20 15:28:15 2020: Debug: } # post-auth = invalid (5) Mon Apr 20 15:28:15 2020: Debug: Using Post-Auth-Type Reject (5) Mon Apr 20 15:28:15 2020: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (5) Mon Apr 20 15:28:15 2020: Debug: Post-Auth-Type REJECT { (5) Mon Apr 20 15:28:15 2020: Debug: policy packetfence-set-tenant-id { (5) Mon Apr 20 15:28:15 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0"){ (5) Mon Apr 20 15:28:15 2020: Debug: if (!NAS-IP-Address || NAS-IP-Address == "0.0.0.0") -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{%{control:PacketFence-Tenant-Id}:-0} (5) Mon Apr 20 15:28:15 2020: Debug: --> 1 (5) Mon Apr 20 15:28:15 2020: Debug: if ( "%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) { (5) Mon Apr 20 15:28:15 2020: Debug: if ( &control:PacketFence-Tenant-Id == 0 ) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: } # policy packetfence-set-tenant-id = noop (5) Mon Apr 20 15:28:15 2020: Debug: update { (5) Mon Apr 20 15:28:15 2020: Debug: } # update = noop (5) Mon Apr 20 15:28:15 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (5) Mon Apr 20 15:28:15 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> TRUE (5) Mon Apr 20 15:28:15 2020: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (5) Mon Apr 20 15:28:15 2020: Debug: policy packetfence-audit-log-reject { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name && (&User-Name == "dummy")) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&User-Name && (&User-Name == "dummy")) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: else { (5) Mon Apr 20 15:28:15 2020: Debug: policy request-timing { (5) Mon Apr 20 15:28:15 2020: Debug: if ("%{%{control:PacketFence-Request-Time}:-0}" != 0) { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{%{control:PacketFence-Request-Time}:-0} (5) Mon Apr 20 15:28:15 2020: Debug: --> 0 (5) Mon Apr 20 15:28:15 2020: Debug: if ("%{%{control:PacketFence-Request-Time}:-0}" != 0) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: } # policy request-timing = noop (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: EXPAND type.reject.query (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: --> type.reject.query (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: Using query template 'query' (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: EXPAND %{User-Name} (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: --> test-radius (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: SQL-User-Name set to 'test-radius' (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: EXPAND INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}', '%{%{control:PacketFence-Computer-Name}:-N/A}', '%{request:User-Name}', '%{request:Stripped-User-Name}', '%{request:Realm}', 'Radius-Access-Request', '%{%{control:PacketFence-Switch-Id}:-N/A}', '%{%{control:PacketFence-Switch-Mac}:-N/A}', '%{%{control:PacketFence-Switch-Ip-Address}:-N/A}', '%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}', '%{request:Calling-Sta tion-Id}', '%{request:NAS-Port-Type}', '%{request:Called-Station-SSID}', '%{request:NAS-Port-Id}', '%{%{control:PacketFence-IfIndex}:-N/A}', '%{request:NAS-Port}', '%{%{control:PacketFence-Connection-Type}:-N/A}', '%{request:NAS-IP-Address}', '%{request:NAS-Identifier}', 'Reject', '%{request:Module-Failure-Message}', '%{control:Auth-Type}', '%{request:EAP-Type}', '%{%{control:PacketFence-Role}:-N/A}', '%{%{control:PacketFence-Status}:-N/A}', '%{%{control:PacketFence-Profile}:-N/A}', '%{%{control:PacketFence-Source}:-N/A}', '%{%{control:PacketFence-AutoReg}:-0}', '%{%{control:PacketFence-IsPhone}:-0}', '%{request:PacketFence-Domain}', '', '%{pairs:&request:[*]}','%{pairs:&reply:[*]}', '%{%{control:PacketFence-Request-Time}:-N/A}', '%{control:PacketFence-Tenant-Id}', '%{request:PacketFence-Radius-Ip}') (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: --> INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '192.168.200.1', '', 'N/A', 'test-radius', 'test-radius', 'null', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '192.168.200.34', '', '192.168.200.1', 'Virtual', '', '', 'N/A', '10130', 'N/A', '127.0.1.1', 'sshd', 'Reject', 'rest: Server returned:', 'Accept', '', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'User-Name =3D =22test-radius=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C NAS-IP-Address =3D 127.0.1.1=2C NAS-Port =3D 1013 0=2C Service-Type =3D Authenticate-Only=2C Calling-Station-Id =3D =22192.168.200.1=22=2C NAS-Identifier =3D =22sshd=22=2C NAS-Port-Type =3D Virtual=2C Event-Timestamp =3D =22Apr 20 2020 15:28:15 UTC=22=2C Stripped-User-Name =3D =22test-radius=22=2C Realm =3D =22null=22=2C FreeRADIUS-Client-IP-Address =3D 192.168.200.34=2C PacketFence-KeyBalanced =3D =22fb4172cb9cf644e1d3d9f75872bdf56d=22=2C PacketFence-Radius-Ip =3D =22192.168.200.252=22=2C Module-Failure-Message =3D =22rest: Server returned:=22=2C Module-Failure-Message =3D =22rest: =7B=5C=22control:PacketFence-Authorization-Status=5C=22:=5C=22allow=5C=22=7D=22=2C SQL-User-Name =3D =22test-radius=22','', '0', '1', '192.168.200.252') (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: Executing query: INSERT INTO radius_audit_log ( mac, ip, computer_name, user_name, stripped_user_name, realm, event_type, switch_id, switch_mac, switch_ip_address, radius_source_ip_address, called_station_id, calling_station_id, nas_port_type, ssid, nas_port_id, ifindex, nas_port, connection_type, nas_ip_address, nas_identifier, auth_status, reason, auth_type, eap_type, role, node_status, profile, source, auto_reg, is_phone, pf_domain, uuid, radius_request, radius_reply, request_time, tenant_id, radius_ip) VALUES ( '192.168.200.1', '', 'N/A', 'test-radius', 'test-radius', 'null', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '192.168.200.34', '', '192.168.200.1', 'Virtual', '', '', 'N/A', '10130', 'N/A', '127.0.1.1', 'sshd', 'Reject', 'rest: Server returned:', 'Accept', '', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0', '', '', 'User-Name =3D =22test-radius=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C NAS-IP-Address =3D 127.0.1.1=2C NAS- Port =3D 10130=2C Service-Type =3D Authenticate-Only=2C Calling-Station-Id =3D =22192.168.200.1=22=2C NAS-Identifier =3D =22sshd=22=2C NAS-Port-Type =3D Virtual=2C Event-Timestamp =3D =22Apr 20 2020 15:28:15 UTC=22=2C Stripped-User-Name =3D =22test-radius=22=2C Realm =3D =22null=22=2C FreeRADIUS-Client-IP-Address =3D 192.168.200.34=2C PacketFence-KeyBalanced =3D =22fb4172cb9cf644e1d3d9f75872bdf56d=22=2C PacketFence-Radius-Ip =3D =22192.168.200.252=22=2C Module-Failure-Message =3D =22rest: Server returned:=22=2C Module-Failure-Message =3D =22rest: =7B=5C=22control:PacketFence-Authorization-Status=5C=22:=5C=22allow=5C=22=7D=22=2C SQL-User-Name =3D =22test-radius=22','', '0', '1', '192.168.200.252') (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: SQL query returned: success (5) Mon Apr 20 15:28:15 2020: Debug: sql_reject: 1 record(s) updated (5) Mon Apr 20 15:28:15 2020: Debug: [sql_reject] = ok (5) Mon Apr 20 15:28:15 2020: Debug: } # else = ok (5) Mon Apr 20 15:28:15 2020: Debug: } # policy packetfence-audit-log-reject = ok (5) Mon Apr 20 15:28:15 2020: Debug: } # if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) = ok (5) Mon Apr 20 15:28:15 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") { (5) Mon Apr 20 15:28:15 2020: Debug: EXPAND %{%{control:PacketFence-Proxied-From}:-False} (5) Mon Apr 20 15:28:15 2020: Debug: --> False (5) Mon Apr 20 15:28:15 2020: Debug: if ("%{%{control:PacketFence-Proxied-From}:-False}" == "True") -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: attr_filter.access_reject: EXPAND %{User-Name} (5) Mon Apr 20 15:28:15 2020: Debug: attr_filter.access_reject: --> test-radius (5) Mon Apr 20 15:28:15 2020: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11 (5) Mon Apr 20 15:28:15 2020: Debug: [attr_filter.access_reject] = updated (5) Mon Apr 20 15:28:15 2020: Debug: attr_filter.packetfence_post_auth: EXPAND %{User-Name} (5) Mon Apr 20 15:28:15 2020: Debug: attr_filter.packetfence_post_auth: --> test-radius (5) Mon Apr 20 15:28:15 2020: Debug: attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10 (5) Mon Apr 20 15:28:15 2020: Debug: [attr_filter.packetfence_post_auth] = updated (5) Mon Apr 20 15:28:15 2020: Debug: [eap] = noop (5) Mon Apr 20 15:28:15 2020: Debug: policy remove_reply_message_if_eap { (5) Mon Apr 20 15:28:15 2020: Debug: if (&reply:EAP-Message && &reply:Reply-Message) { (5) Mon Apr 20 15:28:15 2020: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (5) Mon Apr 20 15:28:15 2020: Debug: else { (5) Mon Apr 20 15:28:15 2020: Debug: [noop] = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # else = noop (5) Mon Apr 20 15:28:15 2020: Debug: } # policy remove_reply_message_if_eap = noop (5) Mon Apr 20 15:28:15 2020: Debug: linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (5) Mon Apr 20 15:28:15 2020: Debug: linelog: --> messages.Access-Reject (5) Mon Apr 20 15:28:15 2020: Debug: linelog: EXPAND [mac:%{Calling-Station-Id}] Rejected user: %{User-Name} (5) Mon Apr 20 15:28:15 2020: Debug: linelog: --> [mac:192.168.200.1] Rejected user: test-radius (5) Mon Apr 20 15:28:15 2020: Debug: [linelog] = ok (5) Mon Apr 20 15:28:15 2020: Debug: } # Post-Auth-Type REJECT = updated (5) Mon Apr 20 15:28:15 2020: Debug: Delaying response for 1.000000 seconds (5) Mon Apr 20 15:28:16 2020: Debug: Sending delayed response (5) Mon Apr 20 15:28:16 2020: Debug: Sent Access-Reject Id 97 from 192.168.200.252:1812 to 192.168.200.34:57381 length 20 (4) Mon Apr 20 15:28:20 2020: Debug: Cleaning up request packet ID 166 with timestamp +52 (5) Mon Apr 20 15:28:20 2020: Debug: Cleaning up request packet ID 97 with timestamp +52 (6) Mon Apr 20 15:28:30 2020: Debug: Received Status-Server Id 70 from 127.0.0.1:35436 to 127.0.0.1:18121 length 50 (6) Mon Apr 20 15:28:30 2020: Debug: Message-Authenticator = 0x394df86ebc609547b45a800d00ec2a89 (6) Mon Apr 20 15:28:30 2020: Debug: FreeRADIUS-Statistics-Type = 15 (6) Mon Apr 20 15:28:30 2020: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/status (6) Mon Apr 20 15:28:30 2020: Debug: Autz-Type Status-Server { (6) Mon Apr 20 15:28:30 2020: Debug: [ok] = ok (6) Mon Apr 20 15:28:30 2020: Debug: } # Autz-Type Status-Server = ok
_______________________________________________ PacketFence-users mailing list PacketFence-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/packetfence-users
