ERROR: eap: We expected EAP type PEAP, but received type MD5

Truax, Peter PTruax at stmartin.edu
Fri Jan 12 19:44:59 CET 2018


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 at netreg:~
[?1034h[root at 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









More information about the Freeradius-Users mailing list