Hello everyone, I have a Packet Fence install running FreeRadius version freeradius-3.0.15-4.1.x86_64 on a CentOs VM. We are trying to authenticate using Mac-Auth-Bypass with a Dell 3500 switch. Below is the raddebug output when we attempt it. The significant portion of the debug output seems to be: 268) Mon Jan 8 14:04:01 2018: Debug: Found Auth-Type = eap (268) Mon Jan 8 14:04:01 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (268) Mon Jan 8 14:04:01 2018: Debug: authenticate { (268) Mon Jan 8 14:04:01 2018: Debug: eap: Expiring EAP session with state 0x4dc5b0bd4dc4a935 (268) Mon Jan 8 14:04:01 2018: Debug: eap: Finished EAP session with state 0x4dc5b0bd4dc4a935 (268) Mon Jan 8 14:04:01 2018: Debug: eap: Previous EAP request found for state 0x4dc5b0bd4dc4a935, released from the list (268) Mon Jan 8 14:04:01 2018: ERROR: eap: Response appears to match a previous request, but the EAP type is wrong (268) Mon Jan 8 14:04:01 2018: ERROR: eap: We expected EAP type PEAP, but received type MD5 (268) Mon Jan 8 14:04:01 2018: ERROR: eap: Your Supplicant or NAS is probably broken (268) Mon Jan 8 14:04:01 2018: Debug: eap: Failed in handler (268) Mon Jan 8 14:04:01 2018: Debug: [eap] = invalid (268) Mon Jan 8 14:04:01 2018: Debug: } # authenticate = invalid (268) Mon Jan 8 14:04:01 2018: Debug: Failed to authenticate the user (268) Mon Jan 8 14:04:01 2018: Debug: Using Post-Auth-Type Reject The debug messages go to rejected from there. We have successfully authenticated with a different Dell switch (N1500), but cannot get the 3500s to work. The point where the 2 outputs deviates is the section: 265) Mon Jan 8 14:01:26 2018: Debug: Found Auth-Type = eap (265) Mon Jan 8 14:01:26 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (265) Mon Jan 8 14:01:26 2018: Debug: authenticate { (265) Mon Jan 8 14:01:26 2018: Debug: eap: Expiring EAP session with state 0x26e9466f26e85fde (265) Mon Jan 8 14:01:26 2018: Debug: eap: Finished EAP session with state 0x26e9466f26e85fde (265) Mon Jan 8 14:01:26 2018: Debug: eap: Previous EAP request found for state 0x26e9466f26e85fde, released from the list (265) Mon Jan 8 14:01:26 2018: Debug: eap: Peer sent packet with method EAP NAK (3) (265) Mon Jan 8 14:01:26 2018: Debug: eap: Found mutually acceptable type MD5 (4) (265) Mon Jan 8 14:01:26 2018: Debug: eap: Calling submodule eap_md5 to process data Looking at the freeradius source code, I found that the " We expected EAP type PEAP, but received type MD5" error comes from FreeRadius. My question is what would cause this? And what configuration of either freeradius or the switch could I use to fix the issue? It seems that the switch isn't sending an EAP NAK packet that the server is expecting. Peter Truax Network Administrator (360) 688-2240 St. Martin's University 5000 Abbey Way E Lacey, WA 98503 P.S. Full Debug output for both switch types: **** Debug Output for Dell 3500 ***** (267) Mon Jan 8 14:04:01 2018: Debug: Received Access-Request Id 0 from 10.10.0.130:49154 to 10.0.1.44:1812 length 108 (267) Mon Jan 8 14:04:01 2018: Debug: NAS-IP-Address = 10.10.0.130 (267) Mon Jan 8 14:04:01 2018: Debug: NAS-Port-Type = Ethernet (267) Mon Jan 8 14:04:01 2018: Debug: NAS-Port = 7 (267) Mon Jan 8 14:04:01 2018: Debug: User-Name = "782bcbe1350b" (267) Mon Jan 8 14:04:01 2018: Debug: Calling-Station-Id = "78-2B-CB-E1-35-0B" (267) Mon Jan 8 14:04:01 2018: Debug: EAP-Message = 0x0200001101373832626362653133353062 (267) Mon Jan 8 14:04:01 2018: Debug: Message-Authenticator = 0x25c7983dccfc4d321955ff943818eb86 (267) Mon Jan 8 14:04:01 2018: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (267) Mon Jan 8 14:04:01 2018: Debug: authorize { (267) Mon Jan 8 14:04:01 2018: Debug: update { (267) Mon Jan 8 14:04:01 2018: Debug: EXPAND %{Packet-Src-IP-Address} (267) Mon Jan 8 14:04:01 2018: Debug: --> 10.10.0.130 (267) Mon Jan 8 14:04:01 2018: Debug: EXPAND %l (267) Mon Jan 8 14:04:01 2018: Debug: --> 1515449041 (267) Mon Jan 8 14:04:01 2018: Debug: } # update = noop (267) Mon Jan 8 14:04:01 2018: Debug: policy rewrite_calling_station_id { (267) Mon Jan 8 14:04:01 2018: 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)) { (267) Mon Jan 8 14:04:01 2018: 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)) -> TRUE (267) Mon Jan 8 14:04:01 2018: 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)) { (267) Mon Jan 8 14:04:01 2018: Debug: update request { (267) Mon Jan 8 14:04:01 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (267) Mon Jan 8 14:04:01 2018: Debug: --> 78:2b:cb:e1:35:0b (267) Mon Jan 8 14:04:01 2018: Debug: } # update request = noop (267) Mon Jan 8 14:04:01 2018: Debug: [updated] = updated (267) Mon Jan 8 14:04:01 2018: 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)) = updated (267) Mon Jan 8 14:04:01 2018: Debug: ... skipping else: Preceding "if" was taken (267) Mon Jan 8 14:04:01 2018: Debug: } # policy rewrite_calling_station_id = updated (267) Mon Jan 8 14:04:01 2018: Debug: policy rewrite_called_station_id { (267) Mon Jan 8 14:04:01 2018: 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)) { (267) Mon Jan 8 14:04:01 2018: 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 (267) Mon Jan 8 14:04:01 2018: Debug: else { (267) Mon Jan 8 14:04:01 2018: Debug: [noop] = noop (267) Mon Jan 8 14:04:01 2018: Debug: } # else = noop (267) Mon Jan 8 14:04:01 2018: Debug: } # policy rewrite_called_station_id = noop (267) Mon Jan 8 14:04:01 2018: Debug: policy filter_username { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name) -> TRUE (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ / /) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ / /) -> FALSE (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.\./ ) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (267) Mon Jan 8 14:04:01 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (267) Mon Jan 8 14:04:01 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.$/) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@\./) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@\./) -> FALSE (267) Mon Jan 8 14:04:01 2018: Debug: } # if (&User-Name) = updated (267) Mon Jan 8 14:04:01 2018: Debug: } # policy filter_username = updated (267) Mon Jan 8 14:04:01 2018: Debug: policy filter_password { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (267) Mon Jan 8 14:04:01 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (267) Mon Jan 8 14:04:01 2018: Debug: } # policy filter_password = updated (267) Mon Jan 8 14:04:01 2018: Debug: [preprocess] = ok (267) Mon Jan 8 14:04:01 2018: Debug: suffix: Checking for suffix after "@" (267) Mon Jan 8 14:04:01 2018: Debug: suffix: No '@' in User-Name = "782bcbe1350b", skipping NULL due to config. (267) Mon Jan 8 14:04:01 2018: Debug: [suffix] = noop (267) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Checking for prefix before "\" (267) Mon Jan 8 14:04:01 2018: Debug: ntdomain: No '\' in User-Name = "782bcbe1350b", looking up realm NULL (267) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Found realm "null" (267) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Adding Stripped-User-Name = "782bcbe1350b" (267) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Adding Realm = "null" (267) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Authentication realm is LOCAL (267) Mon Jan 8 14:04:01 2018: Debug: [ntdomain] = ok (267) Mon Jan 8 14:04:01 2018: Debug: eap: Peer sent EAP Response (code 2) ID 0 length 17 (267) Mon Jan 8 14:04:01 2018: Debug: eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (267) Mon Jan 8 14:04:01 2018: Debug: [eap] = ok (267) Mon Jan 8 14:04:01 2018: Debug: } # authorize = ok (267) Mon Jan 8 14:04:01 2018: Debug: Found Auth-Type = eap (267) Mon Jan 8 14:04:01 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (267) Mon Jan 8 14:04:01 2018: Debug: authenticate { (267) Mon Jan 8 14:04:01 2018: Debug: eap: Peer sent packet with method EAP Identity (1) (267) Mon Jan 8 14:04:01 2018: Debug: eap: Calling submodule eap_peap to process data (267) Mon Jan 8 14:04:01 2018: Debug: eap_peap: Initiating new EAP-TLS session (267) Mon Jan 8 14:04:01 2018: Debug: eap_peap: [eaptls start] = request (267) Mon Jan 8 14:04:01 2018: Debug: eap: Sending EAP Request (code 1) ID 1 length 6 (267) Mon Jan 8 14:04:01 2018: Debug: eap: EAP session adding &reply:State = 0x4dc5b0bd4dc4a935 (267) Mon Jan 8 14:04:01 2018: Debug: [eap] = handled (267) Mon Jan 8 14:04:01 2018: Debug: } # authenticate = handled (267) Mon Jan 8 14:04:01 2018: Debug: Using Post-Auth-Type Challenge (267) Mon Jan 8 14:04:01 2018: Debug: Post-Auth-Type sub-section not found. Ignoring. (267) Mon Jan 8 14:04:01 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (267) Mon Jan 8 14:04:01 2018: Debug: Sent Access-Challenge Id 0 from 10.0.1.44:1812 to 10.10.0.130:49154 length 0 (267) Mon Jan 8 14:04:01 2018: Debug: EAP-Message = 0x010100061920 (267) Mon Jan 8 14:04:01 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (267) Mon Jan 8 14:04:01 2018: Debug: State = 0x4dc5b0bd4dc4a935c0d86b7ff0b369b0 (267) Mon Jan 8 14:04:01 2018: Debug: Finished request (267) Mon Jan 8 14:04:01 2018: Debug: Cleaning up request packet ID 0 with timestamp +254115 (268) Mon Jan 8 14:04:01 2018: Debug: Received Access-Request Id 0 from 10.10.0.130:49154 to 10.0.1.44:1812 length 143 (268) Mon Jan 8 14:04:01 2018: Debug: NAS-IP-Address = 10.10.0.130 (268) Mon Jan 8 14:04:01 2018: Debug: NAS-Port-Type = Ethernet (268) Mon Jan 8 14:04:01 2018: Debug: NAS-Port = 7 (268) Mon Jan 8 14:04:01 2018: Debug: User-Name = "782bcbe1350b" (268) Mon Jan 8 14:04:01 2018: Debug: State = 0x4dc5b0bd4dc4a935c0d86b7ff0b369b0 (268) Mon Jan 8 14:04:01 2018: Debug: Calling-Station-Id = "78-2B-CB-E1-35-0B" (268) Mon Jan 8 14:04:01 2018: Debug: EAP-Message = 0x020100220410ee3ae909f6d578cba5049bf774ee2360373832626362653133353062 (268) Mon Jan 8 14:04:01 2018: Debug: Message-Authenticator = 0x8e93ade61a0f14ee8d6cb48b8c5aaf41 (268) Mon Jan 8 14:04:01 2018: Debug: session-state: No cached attributes (268) Mon Jan 8 14:04:01 2018: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (268) Mon Jan 8 14:04:01 2018: Debug: authorize { (268) Mon Jan 8 14:04:01 2018: Debug: update { (268) Mon Jan 8 14:04:01 2018: Debug: EXPAND %{Packet-Src-IP-Address} (268) Mon Jan 8 14:04:01 2018: Debug: --> 10.10.0.130 (268) Mon Jan 8 14:04:01 2018: Debug: EXPAND %l (268) Mon Jan 8 14:04:01 2018: Debug: --> 1515449041 (268) Mon Jan 8 14:04:01 2018: Debug: } # update = noop (268) Mon Jan 8 14:04:01 2018: Debug: policy rewrite_calling_station_id { (268) Mon Jan 8 14:04:01 2018: 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)) { (268) Mon Jan 8 14:04:01 2018: 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)) -> TRUE (268) Mon Jan 8 14:04:01 2018: 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)) { (268) Mon Jan 8 14:04:01 2018: Debug: update request { (268) Mon Jan 8 14:04:01 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (268) Mon Jan 8 14:04:01 2018: Debug: --> 78:2b:cb:e1:35:0b (268) Mon Jan 8 14:04:01 2018: Debug: } # update request = noop (268) Mon Jan 8 14:04:01 2018: Debug: [updated] = updated (268) Mon Jan 8 14:04:01 2018: 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)) = updated (268) Mon Jan 8 14:04:01 2018: Debug: ... skipping else: Preceding "if" was taken (268) Mon Jan 8 14:04:01 2018: Debug: } # policy rewrite_calling_station_id = updated (268) Mon Jan 8 14:04:01 2018: Debug: policy rewrite_called_station_id { (268) Mon Jan 8 14:04:01 2018: 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)) { (268) Mon Jan 8 14:04:01 2018: 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 (268) Mon Jan 8 14:04:01 2018: Debug: else { (268) Mon Jan 8 14:04:01 2018: Debug: [noop] = noop (268) Mon Jan 8 14:04:01 2018: Debug: } # else = noop (268) Mon Jan 8 14:04:01 2018: Debug: } # policy rewrite_called_station_id = noop (268) Mon Jan 8 14:04:01 2018: Debug: policy filter_username { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name) -> TRUE (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ / /) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ / /) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.\./ ) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (268) Mon Jan 8 14:04:01 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.$/) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@\./) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name =~ /@\./) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: } # if (&User-Name) = updated (268) Mon Jan 8 14:04:01 2018: Debug: } # policy filter_username = updated (268) Mon Jan 8 14:04:01 2018: Debug: policy filter_password { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: } # policy filter_password = updated (268) Mon Jan 8 14:04:01 2018: Debug: [preprocess] = ok (268) Mon Jan 8 14:04:01 2018: Debug: suffix: Checking for suffix after "@" (268) Mon Jan 8 14:04:01 2018: Debug: suffix: No '@' in User-Name = "782bcbe1350b", skipping NULL due to config. (268) Mon Jan 8 14:04:01 2018: Debug: [suffix] = noop (268) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Checking for prefix before "\" (268) Mon Jan 8 14:04:01 2018: Debug: ntdomain: No '\' in User-Name = "782bcbe1350b", looking up realm NULL (268) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Found realm "null" (268) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Adding Stripped-User-Name = "782bcbe1350b" (268) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Adding Realm = "null" (268) Mon Jan 8 14:04:01 2018: Debug: ntdomain: Authentication realm is LOCAL (268) Mon Jan 8 14:04:01 2018: Debug: [ntdomain] = ok (268) Mon Jan 8 14:04:01 2018: Debug: eap: Peer sent EAP Response (code 2) ID 1 length 34 (268) Mon Jan 8 14:04:01 2018: Debug: eap: No EAP Start, assuming it's an on-going EAP conversation (268) Mon Jan 8 14:04:01 2018: Debug: [eap] = updated (268) Mon Jan 8 14:04:01 2018: Debug: if ( !EAP-Message ) { (268) Mon Jan 8 14:04:01 2018: Debug: if ( !EAP-Message ) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: policy packetfence-eap-mac-policy { (268) Mon Jan 8 14:04:01 2018: Debug: if ( &EAP-Type ) { (268) Mon Jan 8 14:04:01 2018: Debug: if ( &EAP-Type ) -> TRUE (268) Mon Jan 8 14:04:01 2018: Debug: if ( &EAP-Type ) { (268) Mon Jan 8 14:04:01 2018: 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)) { (268) Mon Jan 8 14:04:01 2018: 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)) -> TRUE (268) Mon Jan 8 14:04:01 2018: 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)) { (268) Mon Jan 8 14:04:01 2018: Debug: update { (268) Mon Jan 8 14:04:01 2018: Debug: EXPAND %{tolower:%{1}%{2}%{3}%{4}%{5}%{6}} (268) Mon Jan 8 14:04:01 2018: Debug: --> 782bcbe1350b (268) Mon Jan 8 14:04:01 2018: Debug: } # update = noop (268) Mon Jan 8 14:04:01 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) { (268) Mon Jan 8 14:04:01 2018: Debug: EXPAND %{tolower:%{User-Name}} (268) Mon Jan 8 14:04:01 2018: Debug: --> 782bcbe1350b (268) Mon Jan 8 14:04:01 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) -> TRUE (268) Mon Jan 8 14:04:01 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) { (268) Mon Jan 8 14:04:01 2018: Debug: update { (268) Mon Jan 8 14:04:01 2018: Debug: } # update = noop (268) Mon Jan 8 14:04:01 2018: Debug: [updated] = updated (268) Mon Jan 8 14:04:01 2018: Debug: } # if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) = updated (268) Mon Jan 8 14:04:01 2018: 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)) = updated (268) Mon Jan 8 14:04:01 2018: Debug: } # if ( &EAP-Type ) = updated (268) Mon Jan 8 14:04:01 2018: Debug: [noop] = noop (268) Mon Jan 8 14:04:01 2018: Debug: } # policy packetfence-eap-mac-policy = updated (268) Mon Jan 8 14:04:01 2018: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (268) Mon Jan 8 14:04:01 2018: WARNING: pap: !!! Ignoring control:User-Password. Update your !!! (268) Mon Jan 8 14:04:01 2018: WARNING: pap: !!! configuration so that the "known good" clear text !!! (268) Mon Jan 8 14:04:01 2018: WARNING: pap: !!! password is in Cleartext-Password and NOT in !!! (268) Mon Jan 8 14:04:01 2018: WARNING: pap: !!! User-Password. !!! (268) Mon Jan 8 14:04:01 2018: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (268) Mon Jan 8 14:04:01 2018: WARNING: pap: Auth-Type already set. Not setting to PAP (268) Mon Jan 8 14:04:01 2018: Debug: [pap] = noop (268) Mon Jan 8 14:04:01 2018: Debug: } # authorize = updated (268) Mon Jan 8 14:04:01 2018: Debug: Found Auth-Type = eap (268) Mon Jan 8 14:04:01 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (268) Mon Jan 8 14:04:01 2018: Debug: authenticate { (268) Mon Jan 8 14:04:01 2018: Debug: eap: Expiring EAP session with state 0x4dc5b0bd4dc4a935 (268) Mon Jan 8 14:04:01 2018: Debug: eap: Finished EAP session with state 0x4dc5b0bd4dc4a935 (268) Mon Jan 8 14:04:01 2018: Debug: eap: Previous EAP request found for state 0x4dc5b0bd4dc4a935, released from the list (268) Mon Jan 8 14:04:01 2018: ERROR: eap: Response appears to match a previous request, but the EAP type is wrong (268) Mon Jan 8 14:04:01 2018: ERROR: eap: We expected EAP type PEAP, but received type MD5 (268) Mon Jan 8 14:04:01 2018: ERROR: eap: Your Supplicant or NAS is probably broken (268) Mon Jan 8 14:04:01 2018: Debug: eap: Failed in handler (268) Mon Jan 8 14:04:01 2018: Debug: [eap] = invalid (268) Mon Jan 8 14:04:01 2018: Debug: } # authenticate = invalid (268) Mon Jan 8 14:04:01 2018: Debug: Failed to authenticate the user (268) Mon Jan 8 14:04:01 2018: Debug: Using Post-Auth-Type Reject (268) Mon Jan 8 14:04:01 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (268) Mon Jan 8 14:04:01 2018: Debug: Post-Auth-Type REJECT { (268) Mon Jan 8 14:04:01 2018: Debug: update { (268) Mon Jan 8 14:04:01 2018: Debug: } # update = noop (268) Mon Jan 8 14:04:01 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (268) Mon Jan 8 14:04:01 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> TRUE (268) Mon Jan 8 14:04:01 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (268) Mon Jan 8 14:04:01 2018: Debug: policy packetfence-audit-log-reject { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name != "dummy") { (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name != "dummy") -> TRUE (268) Mon Jan 8 14:04:01 2018: Debug: if (&User-Name != "dummy") { (268) Mon Jan 8 14:04:01 2018: Debug: policy request-timing { (268) Mon Jan 8 14:04:01 2018: Debug: if (control:PacketFence-Request-Time != 0) { (268) Mon Jan 8 14:04:01 2018: Debug: if (control:PacketFence-Request-Time != 0) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: } # policy request-timing = noop (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: EXPAND type.reject.query (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: --> type.reject.query (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: Using query template 'query' (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: EXPAND %{User-Name} (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: --> 782bcbe1350b (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: SQL-User-Name set to '782bcbe1350b' (268) Mon Jan 8 14:04:01 2018: 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) 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-Station-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}:-N/A}', '%{%{control:PacketFence-IsPhone}:-N/A}', '%{request:PacketFence-Domain}', '', '%{pairs:&request:[*]}','%{pairs:&reply:[*]}', '%{%{control:PacketFence-Request-Time}:-N/A}') (268) Mon Jan 8 14:04:01 2018: 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) VALUES ( '78:2b:cb:e1:35:0b', '', 'N/A', '782bcbe1350b', '782bcbe1350b', 'null', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '10.10.0.130', '', '78:2b:cb:e1:35:0b', 'Ethernet', '', '', 'N/A', '7', 'N/A', '10.10.0.130', '', 'Reject', 'eap: Response appears to match a previous request=2C but the EAP type is wrong', 'eap', 'MD5', 'N/A', 'N/A', 'N/A', 'N/A', 'N/A', 'N/A', '', '', 'NAS-IP-Address =3D 10.10.0.130=2C NAS-Port-Type =3D Ethernet=2C NAS-Port =3D 7=2C User-Name =3D =22782bcbe1350b=22=2C State =3D 0x4dc5b0bd4dc4a935c0d86b7ff0b369b0=2C Calling-Station-Id =3D =2278:2b:cb:e1:35:0b=22=2C EAP-Message =3D 0x020100220410ee3ae909f6d578cba5049bf774ee2360373832626362653133353062=2C Message-Authenticator =3D 0x8e93ade61a0f14ee8d6cb48b8c5aaf41=2C FreeRADIUS-Client-IP-Address =3D 10.10.0.130=2C Event-Timestamp =3D =22Jan 8 2018 14:04:01 PST=22=2C Stripped-User-Name =3D =22782bcbe1350b=22=2C Realm =3D =22null=22=2C EAP-Type =3D MD5=2C Tmp-String-1 =3D =22782bcbe1350b=22=2C Module-Failure-Message =3D =22eap: Response appears to match a previous request=2C but the EAP type is wrong=22=2C Module-Failure-Message =3D =22eap: We expected EAP type PEAP=2C but received type MD5=22=2C Module-Failure-Message =3D =22eap: Your Supplicant or NAS is probably broken=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22782bcbe1350b=22','', '0') (268) Mon Jan 8 14:04:01 2018: 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) VALUES ( '78:2b:cb:e1:35:0b', '', 'N/A', '782bcbe1350b', '782bcbe1350b', 'null', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A', '10.10.0.130', '', '78:2b:cb:e1:35:0b', 'Ethernet', '', '', 'N/A', '7', 'N/A', '10.10.0.130', '', 'Reject', 'eap: Response appears to match a previous request=2C but the EAP type is wrong', 'eap', 'MD5', 'N/A', 'N/A', 'N/A', 'N/A', 'N/A', 'N/A', '', '', 'NAS-IP-Address =3D 10.10.0.130=2C NAS-Port-Type =3D Ethernet=2C NAS-Port =3D 7=2C User-Name =3D =22782bcbe1350b=22=2C State =3D 0x4dc5b0bd4dc4a935c0d86b7ff0b369b0=2C Calling-Station-Id =3D =2278:2b:cb:e1:35:0b=22=2C EAP-Message =3D 0x020100220410ee3ae909f6d578cba5049bf774ee2360373832626362653133353062=2C Message-Authenticator =3D 0x8e93ade61a0f14ee8d6cb48b8c5aaf41=2C FreeRADIUS-Client-IP-Address =3D 10.10.0.130=2C Event-Timestamp =3D =22Jan 8 2018 14:04:01 PST=22=2C Stripped-User-Name =3D =22782bcbe1350b=22=2C Realm =3D =22null=22=2C EAP-Type =3D MD5=2C Tmp-String-1 =3D =22782bcbe1350b=22=2C Module-Failure-Message =3D =22eap: Response appears to match a previous request=2C but the EAP type is wrong=22=2C Module-Failure-Message =3D =22eap: We expected EAP type PEAP=2C but received type MD5=22=2C Module-Failure-Message =3D =22eap: Your Supplicant or NAS is probably broken=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22782bcbe1350b=22','', '0') (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: SQL query returned: success (268) Mon Jan 8 14:04:01 2018: Debug: sql_reject: 1 record(s) updated (268) Mon Jan 8 14:04:01 2018: Debug: [sql_reject] = ok (268) Mon Jan 8 14:04:01 2018: Debug: } # if (&User-Name != "dummy") = ok (268) Mon Jan 8 14:04:01 2018: Debug: } # policy packetfence-audit-log-reject = ok (268) Mon Jan 8 14:04:01 2018: Debug: } # if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) = ok (268) Mon Jan 8 14:04:01 2018: Debug: attr_filter.access_reject: EXPAND %{User-Name} (268) Mon Jan 8 14:04:01 2018: Debug: attr_filter.access_reject: --> 782bcbe1350b (268) Mon Jan 8 14:04:01 2018: Debug: attr_filter.access_reject: Matched entry DEFAULT at line 11 (268) Mon Jan 8 14:04:01 2018: Debug: [attr_filter.access_reject] = updated (268) Mon Jan 8 14:04:01 2018: Debug: attr_filter.packetfence_post_auth: EXPAND %{User-Name} (268) Mon Jan 8 14:04:01 2018: Debug: attr_filter.packetfence_post_auth: --> 782bcbe1350b (268) Mon Jan 8 14:04:01 2018: Debug: attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10 (268) Mon Jan 8 14:04:01 2018: Debug: [attr_filter.packetfence_post_auth] = updated (268) Mon Jan 8 14:04:01 2018: ERROR: eap: rlm_eap (EAP): No EAP session matching state 0x4dc5b0bd4dc4a935 (268) Mon Jan 8 14:04:01 2018: Debug: eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request (268) Mon Jan 8 14:04:01 2018: Debug: eap: Failed to get handler, probably already removed, not inserting EAP-Failure (268) Mon Jan 8 14:04:01 2018: Debug: [eap] = noop (268) Mon Jan 8 14:04:01 2018: Debug: policy remove_reply_message_if_eap { (268) Mon Jan 8 14:04:01 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) { (268) Mon Jan 8 14:04:01 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (268) Mon Jan 8 14:04:01 2018: Debug: else { (268) Mon Jan 8 14:04:01 2018: Debug: [noop] = noop (268) Mon Jan 8 14:04:01 2018: Debug: } # else = noop (268) Mon Jan 8 14:04:01 2018: Debug: } # policy remove_reply_message_if_eap = noop (268) Mon Jan 8 14:04:01 2018: Debug: linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (268) Mon Jan 8 14:04:01 2018: Debug: linelog: --> messages.Access-Reject (268) Mon Jan 8 14:04:01 2018: Debug: linelog: EXPAND [mac:%{Calling-Station-Id}] Rejected user: %{User-Name} (268) Mon Jan 8 14:04:01 2018: Debug: linelog: --> [mac:78:2b:cb:e1:35:0b] Rejected user: 782bcbe1350b (268) Mon Jan 8 14:04:01 2018: Debug: [linelog] = ok (268) Mon Jan 8 14:04:01 2018: Debug: } # Post-Auth-Type REJECT = updated (268) Mon Jan 8 14:04:01 2018: Debug: Delaying response for 1.000000 seconds (268) Mon Jan 8 14:04:02 2018: Debug: Sending delayed response (268) Mon Jan 8 14:04:02 2018: Debug: Sent Access-Reject Id 0 from 10.0.1.44:1812 to 10.10.0.130:49154 length 20 (268) Mon Jan 8 14:04:06 2018: Debug: Cleaning up request packet ID 0 with timestamp +254115 ***** Debug Output For Dell N1500 ***** ]0;root@netreg:~ [?1034h[root@netreg ~]# raddebug -f /usr/local/pf/var/run/radiusd.sock -t 3600 (264) Mon Jan 8 14:01:26 2018: Debug: Received Access-Request Id 44 from 10.10.0.133:55190 to 10.0.1.44:1812 length 152 (264) Mon Jan 8 14:01:26 2018: Debug: User-Name = "782BCBE1350B" (264) Mon Jan 8 14:01:26 2018: Debug: Called-Station-Id = "f8-b1-56-31-90-5c" (264) Mon Jan 8 14:01:26 2018: Debug: Calling-Station-Id = "78:2b:cb:e1:35:0b" (264) Mon Jan 8 14:01:26 2018: Debug: NAS-Identifier = "f8-b1-56-31-90-5a" (264) Mon Jan 8 14:01:26 2018: Debug: NAS-IP-Address = 10.10.0.133 (264) Mon Jan 8 14:01:26 2018: Debug: NAS-Port = 1 (264) Mon Jan 8 14:01:26 2018: Debug: Framed-MTU = 1500 (264) Mon Jan 8 14:01:26 2018: Debug: NAS-Port-Type = Ethernet (264) Mon Jan 8 14:01:26 2018: Debug: EAP-Message = 0x0200001101373832424342453133353042 (264) Mon Jan 8 14:01:26 2018: Debug: Message-Authenticator = 0xf16efd118e4bc7f99777c0c9a0692c48 (264) Mon Jan 8 14:01:26 2018: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (264) Mon Jan 8 14:01:26 2018: Debug: authorize { (264) Mon Jan 8 14:01:26 2018: Debug: update { (264) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{Packet-Src-IP-Address} (264) Mon Jan 8 14:01:26 2018: Debug: --> 10.10.0.133 (264) Mon Jan 8 14:01:26 2018: Debug: EXPAND %l (264) Mon Jan 8 14:01:26 2018: Debug: --> 1515448886 (264) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (264) Mon Jan 8 14:01:26 2018: Debug: policy rewrite_calling_station_id { (264) Mon Jan 8 14:01:26 2018: 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)) { (264) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (264) Mon Jan 8 14:01:26 2018: 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)) { (264) Mon Jan 8 14:01:26 2018: Debug: update request { (264) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (264) Mon Jan 8 14:01:26 2018: Debug: --> 78:2b:cb:e1:35:0b (264) Mon Jan 8 14:01:26 2018: Debug: } # update request = noop (264) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (264) Mon Jan 8 14:01:26 2018: 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)) = updated (264) Mon Jan 8 14:01:26 2018: Debug: ... skipping else: Preceding "if" was taken (264) Mon Jan 8 14:01:26 2018: Debug: } # policy rewrite_calling_station_id = updated (264) Mon Jan 8 14:01:26 2018: Debug: policy rewrite_called_station_id { (264) Mon Jan 8 14:01:26 2018: 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)) { (264) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (264) Mon Jan 8 14:01:26 2018: 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)) { (264) Mon Jan 8 14:01:26 2018: Debug: update request { (264) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (264) Mon Jan 8 14:01:26 2018: Debug: --> f8:b1:56:31:90:5c (264) Mon Jan 8 14:01:26 2018: Debug: } # update request = noop (264) Mon Jan 8 14:01:26 2018: Debug: if ("%{8}") { (264) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{8} (264) Mon Jan 8 14:01:26 2018: Debug: --> (264) Mon Jan 8 14:01:26 2018: Debug: if ("%{8}") -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) { (264) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: elsif (Aruba-Essid-Name) { (264) Mon Jan 8 14:01:26 2018: Debug: elsif (Aruba-Essid-Name) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) { (264) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (264) Mon Jan 8 14:01:26 2018: 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)) = updated (264) Mon Jan 8 14:01:26 2018: Debug: ... skipping else: Preceding "if" was taken (264) Mon Jan 8 14:01:26 2018: Debug: } # policy rewrite_called_station_id = updated (264) Mon Jan 8 14:01:26 2018: Debug: policy filter_username { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) -> TRUE (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ / /) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ / /) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.\./ ) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (264) Mon Jan 8 14:01:26 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.$/) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@\./) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@\./) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: } # if (&User-Name) = updated (264) Mon Jan 8 14:01:26 2018: Debug: } # policy filter_username = updated (264) Mon Jan 8 14:01:26 2018: Debug: policy filter_password { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (264) Mon Jan 8 14:01:26 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (264) Mon Jan 8 14:01:26 2018: Debug: } # policy filter_password = updated (264) Mon Jan 8 14:01:26 2018: Debug: [preprocess] = ok (264) Mon Jan 8 14:01:26 2018: Debug: suffix: Checking for suffix after "@" (264) Mon Jan 8 14:01:26 2018: Debug: suffix: No '@' in User-Name = "782BCBE1350B", skipping NULL due to config. (264) Mon Jan 8 14:01:26 2018: Debug: [suffix] = noop (264) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Checking for prefix before "\" (264) Mon Jan 8 14:01:26 2018: Debug: ntdomain: No '\' in User-Name = "782BCBE1350B", looking up realm NULL (264) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Found realm "null" (264) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Adding Stripped-User-Name = "782BCBE1350B" (264) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Adding Realm = "null" (264) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Authentication realm is LOCAL (264) Mon Jan 8 14:01:26 2018: Debug: [ntdomain] = ok (264) Mon Jan 8 14:01:26 2018: Debug: eap: Peer sent EAP Response (code 2) ID 0 length 17 (264) Mon Jan 8 14:01:26 2018: Debug: eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (264) Mon Jan 8 14:01:26 2018: Debug: [eap] = ok (264) Mon Jan 8 14:01:26 2018: Debug: } # authorize = ok (264) Mon Jan 8 14:01:26 2018: Debug: Found Auth-Type = eap (264) Mon Jan 8 14:01:26 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (264) Mon Jan 8 14:01:26 2018: Debug: authenticate { (264) Mon Jan 8 14:01:26 2018: Debug: eap: Peer sent packet with method EAP Identity (1) (264) Mon Jan 8 14:01:26 2018: Debug: eap: Calling submodule eap_peap to process data (264) Mon Jan 8 14:01:26 2018: Debug: eap_peap: Initiating new EAP-TLS session (264) Mon Jan 8 14:01:26 2018: Debug: eap_peap: [eaptls start] = request (264) Mon Jan 8 14:01:26 2018: Debug: eap: Sending EAP Request (code 1) ID 1 length 6 (264) Mon Jan 8 14:01:26 2018: Debug: eap: EAP session adding &reply:State = 0x26e9466f26e85fde (264) Mon Jan 8 14:01:26 2018: Debug: [eap] = handled (264) Mon Jan 8 14:01:26 2018: Debug: } # authenticate = handled (264) Mon Jan 8 14:01:26 2018: Debug: Using Post-Auth-Type Challenge (264) Mon Jan 8 14:01:26 2018: Debug: Post-Auth-Type sub-section not found. Ignoring. (264) Mon Jan 8 14:01:26 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (264) Mon Jan 8 14:01:26 2018: Debug: Sent Access-Challenge Id 44 from 10.0.1.44:1812 to 10.10.0.133:55190 length 0 (264) Mon Jan 8 14:01:26 2018: Debug: EAP-Message = 0x010100061920 (264) Mon Jan 8 14:01:26 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (264) Mon Jan 8 14:01:26 2018: Debug: State = 0x26e9466f26e85fde8319bfa4a63b805d (264) Mon Jan 8 14:01:26 2018: Debug: Finished request (265) Mon Jan 8 14:01:26 2018: Debug: Received Access-Request Id 45 from 10.10.0.133:55190 to 10.0.1.44:1812 length 159 (265) Mon Jan 8 14:01:26 2018: Debug: User-Name = "782BCBE1350B" (265) Mon Jan 8 14:01:26 2018: Debug: Called-Station-Id = "f8-b1-56-31-90-5c" (265) Mon Jan 8 14:01:26 2018: Debug: Calling-Station-Id = "78:2b:cb:e1:35:0b" (265) Mon Jan 8 14:01:26 2018: Debug: NAS-Identifier = "f8-b1-56-31-90-5a" (265) Mon Jan 8 14:01:26 2018: Debug: NAS-IP-Address = 10.10.0.133 (265) Mon Jan 8 14:01:26 2018: Debug: NAS-Port = 1 (265) Mon Jan 8 14:01:26 2018: Debug: Framed-MTU = 1500 (265) Mon Jan 8 14:01:26 2018: Debug: NAS-Port-Type = Ethernet (265) Mon Jan 8 14:01:26 2018: Debug: State = 0x26e9466f26e85fde8319bfa4a63b805d (265) Mon Jan 8 14:01:26 2018: Debug: EAP-Message = 0x020100060304 (265) Mon Jan 8 14:01:26 2018: Debug: Message-Authenticator = 0x59b370e46568fb6f4813f958483d8036 (265) Mon Jan 8 14:01:26 2018: Debug: session-state: No cached attributes (265) Mon Jan 8 14:01:26 2018: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (265) Mon Jan 8 14:01:26 2018: Debug: authorize { (265) Mon Jan 8 14:01:26 2018: Debug: update { (265) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{Packet-Src-IP-Address} (265) Mon Jan 8 14:01:26 2018: Debug: --> 10.10.0.133 (265) Mon Jan 8 14:01:26 2018: Debug: EXPAND %l (265) Mon Jan 8 14:01:26 2018: Debug: --> 1515448886 (265) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (265) Mon Jan 8 14:01:26 2018: Debug: policy rewrite_calling_station_id { (265) Mon Jan 8 14:01:26 2018: 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)) { (265) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (265) Mon Jan 8 14:01:26 2018: 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)) { (265) Mon Jan 8 14:01:26 2018: Debug: update request { (265) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (265) Mon Jan 8 14:01:26 2018: Debug: --> 78:2b:cb:e1:35:0b (265) Mon Jan 8 14:01:26 2018: Debug: } # update request = noop (265) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (265) Mon Jan 8 14:01:26 2018: 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)) = updated (265) Mon Jan 8 14:01:26 2018: Debug: ... skipping else: Preceding "if" was taken (265) Mon Jan 8 14:01:26 2018: Debug: } # policy rewrite_calling_station_id = updated (265) Mon Jan 8 14:01:26 2018: Debug: policy rewrite_called_station_id { (265) Mon Jan 8 14:01:26 2018: 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)) { (265) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (265) Mon Jan 8 14:01:26 2018: 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)) { (265) Mon Jan 8 14:01:26 2018: Debug: update request { (265) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (265) Mon Jan 8 14:01:26 2018: Debug: --> f8:b1:56:31:90:5c (265) Mon Jan 8 14:01:26 2018: Debug: } # update request = noop (265) Mon Jan 8 14:01:26 2018: Debug: if ("%{8}") { (265) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{8} (265) Mon Jan 8 14:01:26 2018: Debug: --> (265) Mon Jan 8 14:01:26 2018: Debug: if ("%{8}") -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) { (265) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: elsif (Aruba-Essid-Name) { (265) Mon Jan 8 14:01:26 2018: Debug: elsif (Aruba-Essid-Name) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) { (265) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (265) Mon Jan 8 14:01:26 2018: 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)) = updated (265) Mon Jan 8 14:01:26 2018: Debug: ... skipping else: Preceding "if" was taken (265) Mon Jan 8 14:01:26 2018: Debug: } # policy rewrite_called_station_id = updated (265) Mon Jan 8 14:01:26 2018: Debug: policy filter_username { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) -> TRUE (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ / /) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ / /) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.\./ ) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (265) Mon Jan 8 14:01:26 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.$/) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@\./) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@\./) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: } # if (&User-Name) = updated (265) Mon Jan 8 14:01:26 2018: Debug: } # policy filter_username = updated (265) Mon Jan 8 14:01:26 2018: Debug: policy filter_password { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (265) Mon Jan 8 14:01:26 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: } # policy filter_password = updated (265) Mon Jan 8 14:01:26 2018: Debug: [preprocess] = ok (265) Mon Jan 8 14:01:26 2018: Debug: suffix: Checking for suffix after "@" (265) Mon Jan 8 14:01:26 2018: Debug: suffix: No '@' in User-Name = "782BCBE1350B", skipping NULL due to config. (265) Mon Jan 8 14:01:26 2018: Debug: [suffix] = noop (265) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Checking for prefix before "\" (265) Mon Jan 8 14:01:26 2018: Debug: ntdomain: No '\' in User-Name = "782BCBE1350B", looking up realm NULL (265) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Found realm "null" (265) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Adding Stripped-User-Name = "782BCBE1350B" (265) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Adding Realm = "null" (265) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Authentication realm is LOCAL (265) Mon Jan 8 14:01:26 2018: Debug: [ntdomain] = ok (265) Mon Jan 8 14:01:26 2018: Debug: eap: Peer sent EAP Response (code 2) ID 1 length 6 (265) Mon Jan 8 14:01:26 2018: Debug: eap: No EAP Start, assuming it's an on-going EAP conversation (265) Mon Jan 8 14:01:26 2018: Debug: [eap] = updated (265) Mon Jan 8 14:01:26 2018: Debug: if ( !EAP-Message ) { (265) Mon Jan 8 14:01:26 2018: Debug: if ( !EAP-Message ) -> FALSE (265) Mon Jan 8 14:01:26 2018: Debug: policy packetfence-eap-mac-policy { (265) Mon Jan 8 14:01:26 2018: Debug: if ( &EAP-Type ) { (265) Mon Jan 8 14:01:26 2018: Debug: if ( &EAP-Type ) -> TRUE (265) Mon Jan 8 14:01:26 2018: Debug: if ( &EAP-Type ) { (265) Mon Jan 8 14:01:26 2018: 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)) { (265) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (265) Mon Jan 8 14:01:26 2018: 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)) { (265) Mon Jan 8 14:01:26 2018: Debug: update { (265) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}%{2}%{3}%{4}%{5}%{6}} (265) Mon Jan 8 14:01:26 2018: Debug: --> 782bcbe1350b (265) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (265) Mon Jan 8 14:01:26 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) { (265) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{User-Name}} (265) Mon Jan 8 14:01:26 2018: Debug: --> 782bcbe1350b (265) Mon Jan 8 14:01:26 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) -> TRUE (265) Mon Jan 8 14:01:26 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) { (265) Mon Jan 8 14:01:26 2018: Debug: update { (265) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (265) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (265) Mon Jan 8 14:01:26 2018: Debug: } # if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) = updated (265) Mon Jan 8 14:01:26 2018: 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)) = updated (265) Mon Jan 8 14:01:26 2018: Debug: } # if ( &EAP-Type ) = updated (265) Mon Jan 8 14:01:26 2018: Debug: [noop] = noop (265) Mon Jan 8 14:01:26 2018: Debug: } # policy packetfence-eap-mac-policy = updated (265) Mon Jan 8 14:01:26 2018: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (265) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! Ignoring control:User-Password. Update your !!! (265) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! configuration so that the "known good" clear text !!! (265) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! password is in Cleartext-Password and NOT in !!! (265) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! User-Password. !!! (265) Mon Jan 8 14:01:26 2018: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (265) Mon Jan 8 14:01:26 2018: WARNING: pap: Auth-Type already set. Not setting to PAP (265) Mon Jan 8 14:01:26 2018: Debug: [pap] = noop (265) Mon Jan 8 14:01:26 2018: Debug: } # authorize = updated (265) Mon Jan 8 14:01:26 2018: Debug: Found Auth-Type = eap (265) Mon Jan 8 14:01:26 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (265) Mon Jan 8 14:01:26 2018: Debug: authenticate { (265) Mon Jan 8 14:01:26 2018: Debug: eap: Expiring EAP session with state 0x26e9466f26e85fde (265) Mon Jan 8 14:01:26 2018: Debug: eap: Finished EAP session with state 0x26e9466f26e85fde (265) Mon Jan 8 14:01:26 2018: Debug: eap: Previous EAP request found for state 0x26e9466f26e85fde, released from the list (265) Mon Jan 8 14:01:26 2018: Debug: eap: Peer sent packet with method EAP NAK (3) (265) Mon Jan 8 14:01:26 2018: Debug: eap: Found mutually acceptable type MD5 (4) (265) Mon Jan 8 14:01:26 2018: Debug: eap: Calling submodule eap_md5 to process data (265) Mon Jan 8 14:01:26 2018: Debug: eap_md5: Issuing MD5 Challenge (265) Mon Jan 8 14:01:26 2018: Debug: eap: Sending EAP Request (code 1) ID 2 length 22 (265) Mon Jan 8 14:01:26 2018: Debug: eap: EAP session adding &reply:State = 0x26e9466f27eb42de (265) Mon Jan 8 14:01:26 2018: Debug: [eap] = handled (265) Mon Jan 8 14:01:26 2018: Debug: } # authenticate = handled (265) Mon Jan 8 14:01:26 2018: Debug: Using Post-Auth-Type Challenge (265) Mon Jan 8 14:01:26 2018: Debug: Post-Auth-Type sub-section not found. Ignoring. (265) Mon Jan 8 14:01:26 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (265) Mon Jan 8 14:01:26 2018: Debug: Sent Access-Challenge Id 45 from 10.0.1.44:1812 to 10.10.0.133:55190 length 0 (265) Mon Jan 8 14:01:26 2018: Debug: EAP-Message = 0x0102001604108fcf9a3173c4a7d510712ad043ded2ea (265) Mon Jan 8 14:01:26 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (265) Mon Jan 8 14:01:26 2018: Debug: State = 0x26e9466f27eb42de8319bfa4a63b805d (265) Mon Jan 8 14:01:26 2018: Debug: Finished request (266) Mon Jan 8 14:01:26 2018: Debug: Received Access-Request Id 46 from 10.10.0.133:55190 to 10.0.1.44:1812 length 175 (266) Mon Jan 8 14:01:26 2018: Debug: User-Name = "782BCBE1350B" (266) Mon Jan 8 14:01:26 2018: Debug: Called-Station-Id = "f8-b1-56-31-90-5c" (266) Mon Jan 8 14:01:26 2018: Debug: Calling-Station-Id = "78:2b:cb:e1:35:0b" (266) Mon Jan 8 14:01:26 2018: Debug: NAS-Identifier = "f8-b1-56-31-90-5a" (266) Mon Jan 8 14:01:26 2018: Debug: NAS-IP-Address = 10.10.0.133 (266) Mon Jan 8 14:01:26 2018: Debug: NAS-Port = 1 (266) Mon Jan 8 14:01:26 2018: Debug: Framed-MTU = 1500 (266) Mon Jan 8 14:01:26 2018: Debug: NAS-Port-Type = Ethernet (266) Mon Jan 8 14:01:26 2018: Debug: State = 0x26e9466f27eb42de8319bfa4a63b805d (266) Mon Jan 8 14:01:26 2018: Debug: EAP-Message = 0x020200160410780dd2fb773db3731d527467949bc4ba (266) Mon Jan 8 14:01:26 2018: Debug: Message-Authenticator = 0x646cc2548777b3f79b3eea2988367a9a (266) Mon Jan 8 14:01:26 2018: Debug: session-state: No cached attributes (266) Mon Jan 8 14:01:26 2018: Debug: # Executing section authorize from file /usr/local/pf/raddb/sites-enabled/packetfence (266) Mon Jan 8 14:01:26 2018: Debug: authorize { (266) Mon Jan 8 14:01:26 2018: Debug: update { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{Packet-Src-IP-Address} (266) Mon Jan 8 14:01:26 2018: Debug: --> 10.10.0.133 (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %l (266) Mon Jan 8 14:01:26 2018: Debug: --> 1515448886 (266) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (266) Mon Jan 8 14:01:26 2018: Debug: policy rewrite_calling_station_id { (266) Mon Jan 8 14:01:26 2018: 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)) { (266) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (266) Mon Jan 8 14:01:26 2018: 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)) { (266) Mon Jan 8 14:01:26 2018: Debug: update request { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (266) Mon Jan 8 14:01:26 2018: Debug: --> 78:2b:cb:e1:35:0b (266) Mon Jan 8 14:01:26 2018: Debug: } # update request = noop (266) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (266) Mon Jan 8 14:01:26 2018: 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)) = updated (266) Mon Jan 8 14:01:26 2018: Debug: ... skipping else: Preceding "if" was taken (266) Mon Jan 8 14:01:26 2018: Debug: } # policy rewrite_calling_station_id = updated (266) Mon Jan 8 14:01:26 2018: Debug: policy rewrite_called_station_id { (266) Mon Jan 8 14:01:26 2018: 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)) { (266) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (266) Mon Jan 8 14:01:26 2018: 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)) { (266) Mon Jan 8 14:01:26 2018: Debug: update request { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} (266) Mon Jan 8 14:01:26 2018: Debug: --> f8:b1:56:31:90:5c (266) Mon Jan 8 14:01:26 2018: Debug: } # update request = noop (266) Mon Jan 8 14:01:26 2018: Debug: if ("%{8}") { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{8} (266) Mon Jan 8 14:01:26 2018: Debug: --> (266) Mon Jan 8 14:01:26 2018: Debug: if ("%{8}") -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) { (266) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: elsif (Aruba-Essid-Name) { (266) Mon Jan 8 14:01:26 2018: Debug: elsif (Aruba-Essid-Name) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) { (266) Mon Jan 8 14:01:26 2018: Debug: elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (266) Mon Jan 8 14:01:26 2018: 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)) = updated (266) Mon Jan 8 14:01:26 2018: Debug: ... skipping else: Preceding "if" was taken (266) Mon Jan 8 14:01:26 2018: Debug: } # policy rewrite_called_station_id = updated (266) Mon Jan 8 14:01:26 2018: Debug: policy filter_username { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) -> TRUE (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ / /) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ / /) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.\./ ) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (266) Mon Jan 8 14:01:26 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.$/) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@\./) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name =~ /@\./) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: } # if (&User-Name) = updated (266) Mon Jan 8 14:01:26 2018: Debug: } # policy filter_username = updated (266) Mon Jan 8 14:01:26 2018: Debug: policy filter_password { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Password && (&User-Password != "%{string:User-Password}")) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: } # policy filter_password = updated (266) Mon Jan 8 14:01:26 2018: Debug: [preprocess] = ok (266) Mon Jan 8 14:01:26 2018: Debug: suffix: Checking for suffix after "@" (266) Mon Jan 8 14:01:26 2018: Debug: suffix: No '@' in User-Name = "782BCBE1350B", skipping NULL due to config. (266) Mon Jan 8 14:01:26 2018: Debug: [suffix] = noop (266) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Checking for prefix before "\" (266) Mon Jan 8 14:01:26 2018: Debug: ntdomain: No '\' in User-Name = "782BCBE1350B", looking up realm NULL (266) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Found realm "null" (266) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Adding Stripped-User-Name = "782BCBE1350B" (266) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Adding Realm = "null" (266) Mon Jan 8 14:01:26 2018: Debug: ntdomain: Authentication realm is LOCAL (266) Mon Jan 8 14:01:26 2018: Debug: [ntdomain] = ok (266) Mon Jan 8 14:01:26 2018: Debug: eap: Peer sent EAP Response (code 2) ID 2 length 22 (266) Mon Jan 8 14:01:26 2018: Debug: eap: No EAP Start, assuming it's an on-going EAP conversation (266) Mon Jan 8 14:01:26 2018: Debug: [eap] = updated (266) Mon Jan 8 14:01:26 2018: Debug: if ( !EAP-Message ) { (266) Mon Jan 8 14:01:26 2018: Debug: if ( !EAP-Message ) -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: policy packetfence-eap-mac-policy { (266) Mon Jan 8 14:01:26 2018: Debug: if ( &EAP-Type ) { (266) Mon Jan 8 14:01:26 2018: Debug: if ( &EAP-Type ) -> TRUE (266) Mon Jan 8 14:01:26 2018: Debug: if ( &EAP-Type ) { (266) Mon Jan 8 14:01:26 2018: 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)) { (266) Mon Jan 8 14:01:26 2018: 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)) -> TRUE (266) Mon Jan 8 14:01:26 2018: 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)) { (266) Mon Jan 8 14:01:26 2018: Debug: update { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{1}%{2}%{3}%{4}%{5}%{6}} (266) Mon Jan 8 14:01:26 2018: Debug: --> 782bcbe1350b (266) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (266) Mon Jan 8 14:01:26 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{tolower:%{User-Name}} (266) Mon Jan 8 14:01:26 2018: Debug: --> 782bcbe1350b (266) Mon Jan 8 14:01:26 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) -> TRUE (266) Mon Jan 8 14:01:26 2018: Debug: if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) { (266) Mon Jan 8 14:01:26 2018: Debug: update { (266) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (266) Mon Jan 8 14:01:26 2018: Debug: [updated] = updated (266) Mon Jan 8 14:01:26 2018: Debug: } # if ( &Tmp-String-1 == "%{tolower:%{User-Name}}" ) = updated (266) Mon Jan 8 14:01:26 2018: 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)) = updated (266) Mon Jan 8 14:01:26 2018: Debug: } # if ( &EAP-Type ) = updated (266) Mon Jan 8 14:01:26 2018: Debug: [noop] = noop (266) Mon Jan 8 14:01:26 2018: Debug: } # policy packetfence-eap-mac-policy = updated (266) Mon Jan 8 14:01:26 2018: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (266) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! Ignoring control:User-Password. Update your !!! (266) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! configuration so that the "known good" clear text !!! (266) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! password is in Cleartext-Password and NOT in !!! (266) Mon Jan 8 14:01:26 2018: WARNING: pap: !!! User-Password. !!! (266) Mon Jan 8 14:01:26 2018: WARNING: pap: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! (266) Mon Jan 8 14:01:26 2018: WARNING: pap: Auth-Type already set. Not setting to PAP (266) Mon Jan 8 14:01:26 2018: Debug: [pap] = noop (266) Mon Jan 8 14:01:26 2018: Debug: } # authorize = updated (266) Mon Jan 8 14:01:26 2018: Debug: Found Auth-Type = eap (266) Mon Jan 8 14:01:26 2018: Debug: # Executing group from file /usr/local/pf/raddb/sites-enabled/packetfence (266) Mon Jan 8 14:01:26 2018: Debug: authenticate { (266) Mon Jan 8 14:01:26 2018: Debug: eap: Expiring EAP session with state 0x26e9466f27eb42de (266) Mon Jan 8 14:01:26 2018: Debug: eap: Finished EAP session with state 0x26e9466f27eb42de (266) Mon Jan 8 14:01:26 2018: Debug: eap: Previous EAP request found for state 0x26e9466f27eb42de, released from the list (266) Mon Jan 8 14:01:26 2018: Debug: eap: Peer sent packet with method EAP MD5 (4) (266) Mon Jan 8 14:01:26 2018: Debug: eap: Calling submodule eap_md5 to process data (266) Mon Jan 8 14:01:26 2018: Debug: eap: Sending EAP Success (code 3) ID 2 length 4 (266) Mon Jan 8 14:01:26 2018: Debug: eap: Freeing handler (266) Mon Jan 8 14:01:26 2018: Debug: [eap] = ok (266) Mon Jan 8 14:01:26 2018: Debug: } # authenticate = ok (266) Mon Jan 8 14:01:26 2018: Debug: # Executing section post-auth from file /usr/local/pf/raddb/sites-enabled/packetfence (266) Mon Jan 8 14:01:26 2018: Debug: post-auth { (266) Mon Jan 8 14:01:26 2018: Debug: update { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{Packet-Src-IP-Address} (266) Mon Jan 8 14:01:26 2018: Debug: --> 10.10.0.133 (266) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (266) Mon Jan 8 14:01:26 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (266) Mon Jan 8 14:01:26 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) -> TRUE (266) Mon Jan 8 14:01:26 2018: Debug: if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) { (266) Mon Jan 8 14:01:26 2018: Debug: rest: Expanding URI components (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND http://127.0.0.1:7070 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> http://127.0.0.1:7070 (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND //radius/rest/authorize (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> //radius/rest/authorize (266) Mon Jan 8 14:01:26 2018: Debug: rest: Sending HTTP POST to "http://127.0.0.1:7070//radius/rest/authorize" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "User-Name" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "NAS-IP-Address" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "NAS-Port" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Framed-MTU" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "State" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Called-Station-Id" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Calling-Station-Id" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "NAS-Identifier" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "NAS-Port-Type" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Event-Timestamp" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "EAP-Message" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Message-Authenticator" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "EAP-Type" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Stripped-User-Name" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Realm" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "FreeRADIUS-Client-IP-Address" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Tmp-String-1" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Returning 1000 bytes of JSON data (buffer full or chunk exceeded) (266) Mon Jan 8 14:01:26 2018: Debug: rest: Encoding attribute "Tmp-String-1" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Processing response header (266) Mon Jan 8 14:01:26 2018: Debug: rest: Status : 100 (Continue) (266) Mon Jan 8 14:01:26 2018: Debug: rest: Continuing... (266) Mon Jan 8 14:01:26 2018: Debug: rest: Processing response header (266) Mon Jan 8 14:01:26 2018: Debug: rest: Status : 200 (OK) (266) Mon Jan 8 14:01:26 2018: Debug: rest: Type : json (application/json) (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Role" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND Employees (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> Employees (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Role := "Employees" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Eap-Type" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 4 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 4 (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Eap-Type := "4" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "Tunnel-Type" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 13 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 13 (266) Mon Jan 8 14:01:26 2018: Debug: rest: Tunnel-Type := VLAN (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-AutoReg" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 0 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 0 (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-AutoReg := "0" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Authorization-Status" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND allow (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> allow (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Authorization-Status := "allow" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "Tunnel-Private-Group-ID" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 300 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 300 (266) Mon Jan 8 14:01:26 2018: Debug: rest: Tunnel-Private-Group-Id := "300" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Switch-Ip-Address" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 10.10.0.133 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 10.10.0.133 (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Switch-Ip-Address := "10.10.0.133" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Request-Time" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 1515448886 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 1515448886 (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Request-Time := 1515448886 (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-UserName" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 782BCBE1350B (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 782BCBE1350B (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-UserName := "782BCBE1350B" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-IsPhone" (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-IsPhone := "" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Switch-Id" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 10.10.0.133 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 10.10.0.133 (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Switch-Id := "10.10.0.133" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Switch-Mac" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND f8:b1:56:31:90:5c (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> f8:b1:56:31:90:5c (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Switch-Mac := "f8:b1:56:31:90:5c" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "Tunnel-Medium-Type" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 6 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 6 (266) Mon Jan 8 14:01:26 2018: Debug: rest: Tunnel-Medium-Type := IEEE-802 (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Computer-Name" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND adele3 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> adele3 (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Computer-Name := "adele3" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Mac" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 78:2b:cb:e1:35:0b (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 78:2b:cb:e1:35:0b (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Mac := "78:2b:cb:e1:35:0b" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-IfIndex" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND 1 (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> 1 (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-IfIndex := "1" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Connection-Type" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND WIRED_MAC_AUTH (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> WIRED_MAC_AUTH (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Connection-Type := "WIRED_MAC_AUTH" (266) Mon Jan 8 14:01:26 2018: Debug: rest: Parsing attribute "control:PacketFence-Status" (266) Mon Jan 8 14:01:26 2018: Debug: rest: EXPAND reg (266) Mon Jan 8 14:01:26 2018: Debug: rest: --> reg (266) Mon Jan 8 14:01:26 2018: Debug: rest: PacketFence-Status := "reg" (266) Mon Jan 8 14:01:26 2018: Debug: [rest] = updated (266) Mon Jan 8 14:01:26 2018: Debug: update { (266) Mon Jan 8 14:01:26 2018: Debug: } # update = noop (266) Mon Jan 8 14:01:26 2018: Debug: if (&control:PacketFence-Authorization-Status == "deny") { (266) Mon Jan 8 14:01:26 2018: Debug: if (&control:PacketFence-Authorization-Status == "deny") -> FALSE (266) Mon Jan 8 14:01:26 2018: Debug: else { (266) Mon Jan 8 14:01:26 2018: Debug: policy packetfence-audit-log-accept { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name != "dummy") { (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name != "dummy") -> TRUE (266) Mon Jan 8 14:01:26 2018: Debug: if (&User-Name != "dummy") { (266) Mon Jan 8 14:01:26 2018: Debug: policy request-timing { (266) Mon Jan 8 14:01:26 2018: Debug: if (control:PacketFence-Request-Time != 0) { (266) Mon Jan 8 14:01:26 2018: Debug: if (control:PacketFence-Request-Time != 0) -> TRUE (266) Mon Jan 8 14:01:26 2018: Debug: if (control:PacketFence-Request-Time != 0) { (266) Mon Jan 8 14:01:26 2018: Debug: update control { (266) Mon Jan 8 14:01:26 2018: Debug: EXPAND %{expr: %{control:PacketFence-Request-Time} - %{control:Tmp-Integer-0}} (266) Mon Jan 8 14:01:26 2018: Debug: --> 0 (266) Mon Jan 8 14:01:26 2018: Debug: } # update control = noop (266) Mon Jan 8 14:01:26 2018: Debug: } # if (control:PacketFence-Request-Time != 0) = noop (266) Mon Jan 8 14:01:26 2018: Debug: } # policy request-timing = noop (266) Mon Jan 8 14:01:26 2018: Debug: sql: EXPAND type.accept.query (266) Mon Jan 8 14:01:26 2018: Debug: sql: --> type.accept.query (266) Mon Jan 8 14:01:26 2018: Debug: sql: Using query template 'query' (266) Mon Jan 8 14:01:26 2018: Debug: sql: EXPAND %{User-Name} (266) Mon Jan 8 14:01:26 2018: Debug: sql: --> 782BCBE1350B (266) Mon Jan 8 14:01:26 2018: Debug: sql: SQL-User-Name set to '782BCBE1350B' (266) Mon Jan 8 14:01:26 2018: Debug: sql: 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) 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-Station-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}', 'Accept', '%{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}:-N/A}', '%{%{control:PacketFence-IsPhone}:-N/A}', '%{request:PacketFence-Domain}', '', '%{pairs:&request:[*]}','%{pairs:&reply:[*]}', '%{control:PacketFence-Request-Time}') (266) Mon Jan 8 14:01:26 2018: Debug: sql: --> 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) VALUES ( '78:2b:cb:e1:35:0b', '', 'adele3', '782BCBE1350B', '782BCBE1350B', 'null', 'Radius-Access-Request', '10.10.0.133', 'f8:b1:56:31:90:5c', '10.10.0.133', '10.10.0.133', 'f8:b1:56:31:90:5c', '78:2b:cb:e1:35:0b', 'Ethernet', '', '', '1', '1', 'WIRED_MAC_AUTH', '10.10.0.133', 'f8-b1-56-31-90-5a', 'Accept', '', 'eap', 'MD5', 'Employees', 'reg', 'N/A', 'N/A', '0', 'N/A', '', '', 'User-Name =3D =22782BCBE1350B=22=2C NAS-IP-Address =3D 10.10.0.133=2C NAS-Port =3D 1=2C Framed-MTU =3D 1500=2C State =3D 0x26e9466f27eb42de8319bfa4a63b805d=2C Called-Station-Id =3D =22f8:b1:56:31:90:5c=22=2C Calling-Station-Id =3D =2278:2b:cb:e1:35:0b=22=2C NAS-Identifier =3D =22f8-b1-56-31-90-5a=22=2C NAS-Port-Type =3D Ethernet=2C Event-Timestamp =3D =22Jan 8 2018 14:01:26 PST=22=2C EAP-Message =3D 0x020200160410780dd2fb773db3731d527467949bc4ba=2C Message-Authenticator =3D 0x646cc2548777b3f79b3eea2988367a9a=2C EAP-Type =3D MD5=2C Stripped-User-Name =3D =22782BCBE1350B=22=2C Realm =3D =22null=22=2C FreeRADIUS-Client-IP-Address =3D 10.10.0.133=2C Tmp-String-1 =3D =22782bcbe1350b=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22782BCBE1350B=22','EAP-Message =3D 0x03020004=2C Message-Authenticator =3D 0x00000000000000000000000000000000=2C Stripped-User-Name =3D =22782BCBE1350B=22=2C Tunnel-Type =3D VLAN=2C Tunnel-Private-Group-Id =3D =22300=22=2C Tunnel-Medium-Type =3D IEEE-802', '0') (266) Mon Jan 8 14:01:26 2018: Debug: sql: 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) VALUES ( '78:2b:cb:e1:35:0b', '', 'adele3', '782BCBE1350B', '782BCBE1350B', 'null', 'Radius-Access-Request', '10.10.0.133', 'f8:b1:56:31:90:5c', '10.10.0.133', '10.10.0.133', 'f8:b1:56:31:90:5c', '78:2b:cb:e1:35:0b', 'Ethernet', '', '', '1', '1', 'WIRED_MAC_AUTH', '10.10.0.133', 'f8-b1-56-31-90-5a', 'Accept', '', 'eap', 'MD5', 'Employees', 'reg', 'N/A', 'N/A', '0', 'N/A', '', '', 'User-Name =3D =22782BCBE1350B=22=2C NAS-IP-Address =3D 10.10.0.133=2C NAS-Port =3D 1=2C Framed-MTU =3D 1500=2C State =3D 0x26e9466f27eb42de8319bfa4a63b805d=2C Called-Station-Id =3D =22f8:b1:56:31:90:5c=22=2C Calling-Station-Id =3D =2278:2b:cb:e1:35:0b=22=2C NAS-Identifier =3D =22f8-b1-56-31-90-5a=22=2C NAS-Port-Type =3D Ethernet=2C Event-Timestamp =3D =22Jan 8 2018 14:01:26 PST=22=2C EAP-Message =3D 0x020200160410780dd2fb773db3731d527467949bc4ba=2C Message-Authenticator =3D 0x646cc2548777b3f79b3eea2988367a9a=2C EAP-Type =3D MD5=2C Stripped-User-Name =3D =22782BCBE1350B=22=2C Realm =3D =22null=22=2C FreeRADIUS-Client-IP-Address =3D 10.10.0.133=2C Tmp-String-1 =3D =22782bcbe1350b=22=2C User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C SQL-User-Name =3D =22782BCBE1350B=22','EAP-Message =3D 0x03020004=2C Message-Authenticator =3D 0x00000000000000000000000000000000=2C Stripped-User-Name =3D =22782BCBE1350B=22=2C Tunnel-Type =3D VLAN=2C Tunnel-Private-Group-Id =3D =22300=22=2C Tunnel-Medium-Type =3D IEEE-802', '0') (266) Mon Jan 8 14:01:26 2018: Debug: sql: SQL query returned: success (266) Mon Jan 8 14:01:26 2018: Debug: sql: 1 record(s) updated (266) Mon Jan 8 14:01:26 2018: Debug: [sql] = ok (266) Mon Jan 8 14:01:26 2018: Debug: } # if (&User-Name != "dummy") = ok (266) Mon Jan 8 14:01:26 2018: Debug: } # policy packetfence-audit-log-accept = ok (266) Mon Jan 8 14:01:26 2018: Debug: } # else = ok (266) Mon Jan 8 14:01:26 2018: Debug: } # if (! EAP-Type || (EAP-Type != TTLS && EAP-Type != PEAP) ) = updated (266) Mon Jan 8 14:01:26 2018: Debug: attr_filter.packetfence_post_auth: EXPAND %{User-Name} (266) Mon Jan 8 14:01:26 2018: Debug: attr_filter.packetfence_post_auth: --> 782BCBE1350B (266) Mon Jan 8 14:01:26 2018: Debug: attr_filter.packetfence_post_auth: Matched entry DEFAULT at line 10 (266) Mon Jan 8 14:01:26 2018: Debug: [attr_filter.packetfence_post_auth] = updated (266) Mon Jan 8 14:01:26 2018: Debug: linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (266) Mon Jan 8 14:01:26 2018: Debug: linelog: --> messages.Access-Accept (266) Mon Jan 8 14:01:26 2018: Debug: linelog: EXPAND [mac:%{Calling-Station-Id}] Accepted user: %{reply:User-Name} and returned VLAN %{reply:Tunnel-Private-Group-ID} (266) Mon Jan 8 14:01:26 2018: Debug: linelog: --> [mac:78:2b:cb:e1:35:0b] Accepted user: and returned VLAN 300 (266) Mon Jan 8 14:01:26 2018: Debug: [linelog] = ok (266) Mon Jan 8 14:01:26 2018: Debug: } # post-auth = updated (266) Mon Jan 8 14:01:26 2018: Debug: Sent Access-Accept Id 46 from 10.0.1.44:1812 to 10.10.0.133:55190 length 0 (266) Mon Jan 8 14:01:26 2018: Debug: EAP-Message = 0x03020004 (266) Mon Jan 8 14:01:26 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (266) Mon Jan 8 14:01:26 2018: Debug: Tunnel-Type = VLAN (266) Mon Jan 8 14:01:26 2018: Debug: Tunnel-Private-Group-Id = "300" (266) Mon Jan 8 14:01:26 2018: Debug: Tunnel-Medium-Type = IEEE-802 (266) Mon Jan 8 14:01:26 2018: Debug: Finished request (264) Mon Jan 8 14:01:31 2018: Debug: Cleaning up request packet ID 44 with timestamp +253960 (265) Mon Jan 8 14:01:31 2018: Debug: Cleaning up request packet ID 45 with timestamp +253960 (266) Mon Jan 8 14:01:31 2018: Debug: Cleaning up request packet ID 46 with timestamp +253960