ERROR: eap: We expected EAP type PEAP, but received type MD5
Alan Buxey
alan.buxey at gmail.com
Fri Jan 12 20:24:11 CET 2018
The switches are sending EAP MD5 and are getting a NAK, presumably because
freeradius is configured for PEAP but not MD5 ... And so fix is either
configure MD5 EAP on freeradius so that those devices work, or configure
the devices to do PEAP so they work with FR as it is.
alan
On 12 Jan 2018 6:46 pm, "Truax, Peter" <PTruax at stmartin.edu> wrote:
> 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 0x020100220410ee3ae909f6d578cb
> a5049bf774ee2360373832626362653133353062=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
>
>
>
>
>
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/
> list/users.html
More information about the Freeradius-Users
mailing list