Active Directory AUTHENTICATION with LDAP AUTHORIZATION

16 Aug 2017

      Hi everybody, I have implemented a Freeradius server that works perfectly
because the users are authenticated ok for wifi, with this features:

* Active Directory authentication in accordance with Alan Dekok's tutorial
step-by-step
* No group authorization
* Client machines and phones configured with WPA-WPA2 enterprise AES /
802.1X
* Freeradius debug OK where I can see eap/peap/mschap lines

After seeing a question in this mailing list about group authorization,
this morning I've tried to implement LDAP support in order to use the
"Ldap_Group" attribute to search users in some groups of our Active
Directory service and let them to access certains SSID. I've installed
freeradius-ldap package, and configured the ldap module and modify the
default and inner-tunnel files adding ldap to authorize sections. At time
of testing the new implementation, it fails because the users can't
authenticate. So here is my debug output in order to get your help please:

THIS DEBUG IS THE ONE CORRESPONDING TO JUST ONE ATTEMPT OF AUTHENTICATION,
IT'S SO LONG...I APOLOGIZE FOR THIS

rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=185,
length=280
        User-Name = "host/host44.d-holomit.com"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message =
0x0202002001686f73742f4d4954574e2d343337362e672d626170726f2e6e6574
        Message-Authenticator = 0xc68ef06d5cef7815308c7211f38bd153
Wed Aug 16 12:32:25 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authorize {
Wed Aug 16 12:32:25 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:25 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:25 2017 : Info: [suffix] No '@' in User-Name = "host/
host44.d-holomit.com", looking up realm NULL
Wed Aug 16 12:32:25 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:25 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP packet type response id 2 length
32
Wed Aug 16 12:32:25 2017 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = updated
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] Entering ldap_groupcmp()
Wed Aug 16 12:32:25 2017 : Info: [files]        expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:25 2017 : Info: [files]        expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:25 2017 : Info: [files]        ... expanding second
conditional
Wed Aug 16 12:32:25 2017 : Info: [files]        expand: %{User-Name} ->
host/host44.d-holomit.com
Wed Aug 16 12:32:25 2017 : Info: [files]        expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=host/host44.d-holomit.com)
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=host/
host44.d-holomit.com)
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] object not found
Wed Aug 16 12:32:25 2017 : Debug: rlm_ldap::ldap_groupcmp: search failed
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:25 2017 : Info: ++[files] = noop
Wed Aug 16 12:32:25 2017 : Info: [ldap] performing user authorization for
host/host44.d-holomit.com
Wed Aug 16 12:32:25 2017 : Info: [ldap]         expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:25 2017 : Info: [ldap]         ... expanding second
conditional
Wed Aug 16 12:32:25 2017 : Info: [ldap]         expand: %{User-Name} ->
host/host44.d-holomit.com
Wed Aug 16 12:32:25 2017 : Info: [ldap]         expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=host/host44.d-holomit.com)
Wed Aug 16 12:32:25 2017 : Info: [ldap]         expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=host/
host44.d-holomit.com)
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] object not found
Wed Aug 16 12:32:25 2017 : Info: [ldap] search failed
Wed Aug 16 12:32:25 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:25 2017 : Info: ++[ldap] = notfound
Wed Aug 16 12:32:25 2017 : Info: ++[expiration] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[logintime] = noop
Wed Aug 16 12:32:25 2017 : Info: [pap] WARNING! No "known good" password
found for the user.  Authentication may fail because of this.
Wed Aug 16 12:32:25 2017 : Info: ++[pap] = noop
Wed Aug 16 12:32:25 2017 : Info: +} # group authorize = updated
Wed Aug 16 12:32:25 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:25 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authenticate {
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP Identity
Wed Aug 16 12:32:25 2017 : Info: [eap] processing type tls
Wed Aug 16 12:32:25 2017 : Info: [tls] Initiate
Wed Aug 16 12:32:25 2017 : Info: [tls] Start returned 1
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:25 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 185 to 172.22.88.223 port 32769
        EAP-Message = 0x010300061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x59eb8f4659e89632250362e94c0380f2
Wed Aug 16 12:32:25 2017 : Info: Finished request 8.
Wed Aug 16 12:32:25 2017 : Debug: Going to the next request
Wed Aug 16 12:32:25 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=186,
length=450
        User-Name = "host/host44.d-holomit.com"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message =
0x020300b81980000000ae16030300a9010000a50303599465891f49dba4ac7f9e56b534972a7fb86e01bcef0692bfb18cff05fb1eae00003cc02cc02bc030c02f009f009ec024c023c028c027c00ac009c014c01300390033009d009c003d003c0035002f000a006a00400038003200130005000401000040000500050100000000000a00080006001d00170018000b00020100000d001400120401050102010403050302030202060106030023000000170000ff01000100
        State = 0x59eb8f4659e89632250362e94c0380f2
        Message-Authenticator = 0xf4f8492d3761f56f917b46a845f8df4c
Wed Aug 16 12:32:25 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authorize {
Wed Aug 16 12:32:25 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:25 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:25 2017 : Info: [suffix] No '@' in User-Name = "host/
host44.d-holomit.com", looking up realm NULL
Wed Aug 16 12:32:25 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:25 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP packet type response id 3 length
184
Wed Aug 16 12:32:25 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:25 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:25 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:25 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authenticate {
Wed Aug 16 12:32:25 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:25 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:25 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:25 2017 : Debug:   TLS Length 174
Wed Aug 16 12:32:25 2017 : Info: [peap] Length Included
Wed Aug 16 12:32:25 2017 : Info: [peap] eaptls_verify returned 11
Wed Aug 16 12:32:25 2017 : Info: [peap]     (other): before/accept
initialization
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: before/accept
initialization
Wed Aug 16 12:32:25 2017 : Info: [peap] <<< TLS 1.0 Handshake [length
00a9], ClientHello
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:25 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
0039], ServerHello
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:25 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
02ea], Certificate
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:25 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
014b], ServerKeyExchange
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:25 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
0004], ServerHelloDone
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:25 2017 : Info: [peap]     TLS_accept: Need to read more
data: unknown state
Wed Aug 16 12:32:25 2017 : Debug: In SSL Handshake Phase
Wed Aug 16 12:32:25 2017 : Debug: In SSL Accept mode
Wed Aug 16 12:32:25 2017 : Info: [peap] eaptls_process returned 13
Wed Aug 16 12:32:25 2017 : Info: [peap] EAPTLS_HANDLED
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:25 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 186 to 172.22.88.223 port 32769
        EAP-Message =
0x0104040019c0000004861603010039020000350301e149eb2e18e64c91101fb756d0721d324079c23427c47d1be5c80b8cf7db0b8400c01400000dff01000100000b00040300010216030102ea0b0002e60002e30002e0308202dc308201c4a003020102020900d7c4dc55dfef2499300d06092a864886f70d01010b050030263124302206035504030c1b44656269616e382e70726f76696e6369616e65742e636f6d2e6172301e170d3135303630323136323934355a170d3235303533303136323934355a30263124302206035504030c1b44656269616e382e70726f76696e6369616e65742e636f6d2e617230820122300d06092a864886f70d01
        EAP-Message =
0x010105000382010f003082010a0282010100ce2407532c44ee6b97291153b8f3acc2bb95063610866225f9a42ee5a3e03625e3fc2d861bf1bc6aba40b16950019ab955c365b12b5442056a3873d8636f10a2f963b869aa39f99216455561afa8429a07e3b10bc2a2a4bf2d3699687685ea74e6640537d790ce44ac359b9f1b8a2db50ac16948973d7704db0a84a35c33ed823836ecdd75159ec70be01f6b81fcbed10aeebfaf2197d2f74ea337db67b14076316613c9e95e4014682b85e9b89973e21f4ab6dce002e01e1464421e39bb83e083c25492bfa4c0fdca03267cf2d619e5636746ffca069f808ca768a61c0ad709a15206e86cb2ad7ec175fe
        EAP-Message =
0x20cdf42366910672c50beefc04ff74a9b6e0d0e38f0203010001a30d300b30090603551d1304023000300d06092a864886f70d01010b0500038201010081fcbbf1b939721ad72c4df2bb6b3807d190aa189d6f0b4ce2ad4b849ab087ef18a16f66abf10e8fadb33e0f595bae0a21bcd2c3515f080ed09ba5f35bb4cd437877d0b79b6b3edcc907940465b1689c6c3045dd38628dc8ffbc2bf8ea1a25ae9d2794bc42c36276e66b96270db6dfae1a45fbde4394c0265d74c38f4d1d9d286cee8a30f0b3be33bf22e57ad7590756fd44641e64a9796b34cd842ddac2403401e49c87c411f316c0936ada58bc873b7fae1a5cf5e24961c692d9fe40262569
        EAP-Message =
0xc8b81b521cd4cb64c771b0e44ee2a3c15b744451841e11bb4ed0e28e4e3c40ff854e32162814348b2460b630a77f5a1bbb51d02534337ea8b06a65b4604611c3160301014b0c0001470300174104a384a762c854efc2801da643eab3ae5c2ec35d92b88ee57a18c2e92eba98f63bd6620f8e3c83753e0bb48fc7cdfa0f35130bf5992f54984ed231489e72cdf349010062d018d01e2bd473fb10f924eddbdc9f65e501df31412f45fe3b083c2cc8621e0f1d00df55161cb56f4e8592ce4a5abde810ad0002953c8e1a92a04828b1339722fd78fa8640df9fe2322ee3e9bba1b4a7ed82782e90f7e60511a37443e1314447ca6daebc15f78869a3517df2
        EAP-Message = 0x6ab3b860fb42a908b695b8de
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x59eb8f4658ef9632250362e94c0380f2
Wed Aug 16 12:32:25 2017 : Info: Finished request 9.
Wed Aug 16 12:32:25 2017 : Debug: Going to the next request
Wed Aug 16 12:32:25 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=187,
length=272
        User-Name = "host/host44.d-holomit.com"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message = 0x020400061900
        State = 0x59eb8f4658ef9632250362e94c0380f2
        Message-Authenticator = 0x10cd0a2d319de6c0c07fb4c887dfa404
Wed Aug 16 12:32:25 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authorize {
Wed Aug 16 12:32:25 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:25 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:25 2017 : Info: [suffix] No '@' in User-Name = "host/
host44.d-holomit.com", looking up realm NULL
Wed Aug 16 12:32:25 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:25 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP packet type response id 4 length
6
Wed Aug 16 12:32:25 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:25 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:25 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:25 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authenticate {
Wed Aug 16 12:32:25 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:25 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:25 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:25 2017 : Info: [peap] Received TLS ACK
Wed Aug 16 12:32:25 2017 : Info: [peap] ACK handshake fragment handler
Wed Aug 16 12:32:25 2017 : Info: [peap] eaptls_verify returned 1
Wed Aug 16 12:32:25 2017 : Info: [peap] eaptls_process returned 13
Wed Aug 16 12:32:25 2017 : Info: [peap] EAPTLS_HANDLED
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:25 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 187 to 172.22.88.223 port 32769
        EAP-Message =
0x0105009619000c768a5f5291e3e20b3518c60a8bd43dc75406d8a71ef311749e16dcc8b0e4cf6164c19c0524d8a8652c6fb10c238da09eaca5c13d45456385ea2ff9ddc236d5f91c712bd15f3a7626702048a997195c88521b5e93e5b0354c40f42f1c03c1e16d512dd474010a728ecb92046efb44a1c82fb9c8b57f92f37938c3269889387b7af7c93ce5d88b16030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x59eb8f465bee9632250362e94c0380f2
Wed Aug 16 12:32:25 2017 : Info: Finished request 10.
Wed Aug 16 12:32:25 2017 : Debug: Going to the next request
Wed Aug 16 12:32:25 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=188,
length=283
        User-Name = "host/host44.d-holomit.com"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message = 0x0205001119800000000715030100020230
        State = 0x59eb8f465bee9632250362e94c0380f2
        Message-Authenticator = 0xa94148f0545f37a6b509de767abdcdac
Wed Aug 16 12:32:25 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authorize {
Wed Aug 16 12:32:25 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:25 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:25 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:25 2017 : Info: [suffix] No '@' in User-Name = "host/
host44.d-holomit.com", looking up realm NULL
Wed Aug 16 12:32:25 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:25 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP packet type response id 5 length
17
Wed Aug 16 12:32:25 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:25 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:25 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:25 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group authenticate {
Wed Aug 16 12:32:25 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:25 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:25 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:25 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:25 2017 : Debug:   TLS Length 7
Wed Aug 16 12:32:25 2017 : Info: [peap] Length Included
Wed Aug 16 12:32:25 2017 : Info: [peap] eaptls_verify returned 11
Wed Aug 16 12:32:25 2017 : Info: [peap] <<< TLS 1.0 Alert [length 0002],
fatal unknown_ca
Wed Aug 16 12:32:25 2017 : Error: TLS Alert read:fatal:unknown CA
Wed Aug 16 12:32:25 2017 : Error:     TLS_accept: failed in unknown state
Wed Aug 16 12:32:25 2017 : Error: rlm_eap: SSL error error:14094418:SSL
routines:SSL3_READ_BYTES:tlsv1 alert unknown ca
Wed Aug 16 12:32:25 2017 : Error: SSL: SSL_read failed inside of TLS (-1),
TLS session fails.
Wed Aug 16 12:32:25 2017 : Debug: TLS receive handshake failed during
operation
Wed Aug 16 12:32:25 2017 : Info: [peap] eaptls_process returned 4
Wed Aug 16 12:32:25 2017 : Info: [peap] EAPTLS_OTHERS
Wed Aug 16 12:32:25 2017 : Info: [eap] Handler failed in EAP/peap
Wed Aug 16 12:32:25 2017 : Info: [eap] Failed in EAP select
Wed Aug 16 12:32:25 2017 : Info: ++[eap] = invalid
Wed Aug 16 12:32:25 2017 : Info: +} # group authenticate = invalid
Wed Aug 16 12:32:25 2017 : Info: Failed to authenticate the user.
Wed Aug 16 12:32:25 2017 : Info: Using Post-Auth-Type REJECT
Wed Aug 16 12:32:25 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:25 2017 : Info: +group REJECT {
Wed Aug 16 12:32:25 2017 : Info: [attr_filter.access_reject]    expand:
%{User-Name} -> host/host44.d-holomit.com
Wed Aug 16 12:32:25 2017 : Debug: attr_filter: Matched entry DEFAULT at
line 11
Wed Aug 16 12:32:25 2017 : Info: ++[attr_filter.access_reject] = updated
Wed Aug 16 12:32:25 2017 : Info: +} # group REJECT = updated
Wed Aug 16 12:32:25 2017 : Info: Delaying reject of request 11 for 1 seconds
Wed Aug 16 12:32:25 2017 : Debug: Going to the next request
Wed Aug 16 12:32:25 2017 : Debug: Waking up in 0.9 seconds.
Wed Aug 16 12:32:26 2017 : Info: Sending delayed reject for request 11
Sending Access-Reject of id 188 to 172.22.88.223 port 32769
        EAP-Message = 0x04050004
        Message-Authenticator = 0x00000000000000000000000000000000
Wed Aug 16 12:32:26 2017 : Debug: Waking up in 3.9 seconds.
Wed Aug 16 12:32:30 2017 : Info: Cleaning up request 8 ID 185 with
timestamp +77
Wed Aug 16 12:32:30 2017 : Info: Cleaning up request 9 ID 186 with
timestamp +77
Wed Aug 16 12:32:30 2017 : Info: Cleaning up request 10 ID 187 with
timestamp +77
Wed Aug 16 12:32:30 2017 : Debug: Waking up in 1.0 seconds.
Wed Aug 16 12:32:31 2017 : Info: Cleaning up request 11 ID 188 with
timestamp +77
Wed Aug 16 12:32:31 2017 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=189,
length=246
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message = 0x0202000f0165616c6d6f6e61636964
        Message-Authenticator = 0x6820d0499f28cf30ff01359789853ba9
Wed Aug 16 12:32:37 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authorize {
Wed Aug 16 12:32:37 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:37 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:37 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:37 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:37 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP packet type response id 2 length
15
Wed Aug 16 12:32:37 2017 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = updated
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] Entering ldap_groupcmp()
Wed Aug 16 12:32:37 2017 : Info: [files]        expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:37 2017 : Info: [files]        expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:37 2017 : Info: [files]        ... expanding second
conditional
Wed Aug 16 12:32:37 2017 : Info: [files]        expand: %{User-Name} ->
tyard
Wed Aug 16 12:32:37 2017 : Info: [files]        expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=tyard)
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=tyard)
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:37 2017 : Info: [files]        expand:
(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))) ->
(|(&(objectClass=group)(member=CN\3dTom Yard\2cOU\3dIT\2cOU\3dG.
IT\2cOU\3dDir.
tech\2cOU\3dusers\2cOU\3dholomit\2cDC\3dd-holomit\2cDC\3dcom)))
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] performing search in
cn=wifi,ou=WI-FI,ou=in,ou=services,ou=holomit,dc=d-holomit,dc=com, with
filter (|(&(objectClass=group)(member=CN\3dTom Yard\2cOU\3dIT\2cOU\3dG.
IT\2cOU\3dDir.
tech\2cOU\3dusers\2cOU\3dholomit\2cDC\3dd-holomit\2cDC\3dcom)))
Wed Aug 16 12:32:37 2017 : Debug: rlm_ldap::ldap_groupcmp: User found in
group cn=wifi,ou=WI-FI,ou=in,ou=services,ou=holomit,dc=d-holomit,dc=com
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:37 2017 : Info: [files] users: Matched entry DEFAULT at
line 207
Wed Aug 16 12:32:37 2017 : Info: ++[files] = ok
Wed Aug 16 12:32:37 2017 : Info: [ldap] performing user authorization for
tyard
Wed Aug 16 12:32:37 2017 : Info: [ldap]         expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:37 2017 : Info: [ldap]         ... expanding second
conditional
Wed Aug 16 12:32:37 2017 : Info: [ldap]         expand: %{User-Name} ->
tyard
Wed Aug 16 12:32:37 2017 : Info: [ldap]         expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=tyard)
Wed Aug 16 12:32:37 2017 : Info: [ldap]         expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=tyard)
Wed Aug 16 12:32:37 2017 : Info: [ldap] No default NMAS login sequence
Wed Aug 16 12:32:37 2017 : Info: [ldap] looking for check items in
directory...
Wed Aug 16 12:32:37 2017 : Info: [ldap] looking for reply items in
directory...
Wed Aug 16 12:32:37 2017 : Debug: WARNING: No "known good" password was
found in LDAP.  Are you sure that the user is configured correctly?
Wed Aug 16 12:32:37 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:37 2017 : Info: ++[ldap] = ok
Wed Aug 16 12:32:37 2017 : Info: ++[expiration] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[logintime] = noop
Wed Aug 16 12:32:37 2017 : Info: [pap] WARNING! No "known good" password
found for the user.  Authentication may fail because of this.
Wed Aug 16 12:32:37 2017 : Info: ++[pap] = noop
Wed Aug 16 12:32:37 2017 : Info: +} # group authorize = updated
Wed Aug 16 12:32:37 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:37 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authenticate {
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP Identity
Wed Aug 16 12:32:37 2017 : Info: [eap] processing type tls
Wed Aug 16 12:32:37 2017 : Info: [tls] Initiate
Wed Aug 16 12:32:37 2017 : Info: [tls] Start returned 1
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:37 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 189 to 172.22.88.223 port 32769
        EAP-Message = 0x010300061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x840fb4a2840cad03cf3fb9b167c12725
Wed Aug 16 12:32:37 2017 : Info: Finished request 12.
Wed Aug 16 12:32:37 2017 : Debug: Going to the next request
Wed Aug 16 12:32:37 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=190,
length=433
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message =
0x020300b81980000000ae16030300a9010000a5030359946595b76976f7f5e431aa67870fa4214f82d3c4412d0e5c9eb4fe9d475a4600003cc02cc02bc030c02f009f009ec024c023c028c027c00ac009c014c01300390033009d009c003d003c0035002f000a006a00400038003200130005000401000040000500050100000000000a00080006001d00170018000b00020100000d001400120401050102010403050302030202060106030023000000170000ff01000100
        State = 0x840fb4a2840cad03cf3fb9b167c12725
        Message-Authenticator = 0x6d2c8564416b9951a9a06e943dadacaa
Wed Aug 16 12:32:37 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authorize {
Wed Aug 16 12:32:37 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:37 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:37 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:37 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:37 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP packet type response id 3 length
184
Wed Aug 16 12:32:37 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:37 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:37 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:37 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authenticate {
Wed Aug 16 12:32:37 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:37 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:37 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:37 2017 : Debug:   TLS Length 174
Wed Aug 16 12:32:37 2017 : Info: [peap] Length Included
Wed Aug 16 12:32:37 2017 : Info: [peap] eaptls_verify returned 11
Wed Aug 16 12:32:37 2017 : Info: [peap]     (other): before/accept
initialization
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: before/accept
initialization
Wed Aug 16 12:32:37 2017 : Info: [peap] <<< TLS 1.0 Handshake [length
00a9], ClientHello
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
0039], ServerHello
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
02ea], Certificate
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
014b], ServerKeyExchange
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
0004], ServerHelloDone
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: Need to read more
data: unknown state
Wed Aug 16 12:32:37 2017 : Debug: In SSL Handshake Phase
Wed Aug 16 12:32:37 2017 : Debug: In SSL Accept mode
Wed Aug 16 12:32:37 2017 : Info: [peap] eaptls_process returned 13
Wed Aug 16 12:32:37 2017 : Info: [peap] EAPTLS_HANDLED
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:37 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 190 to 172.22.88.223 port 32769
        EAP-Message =
0x0104040019c0000004861603010039020000350301c693c768221406eb53b9b17a7a06c18359606282457f802631e848edd43f4ec300c01400000dff01000100000b00040300010216030102ea0b0002e60002e30002e0308202dc308201c4a003020102020900d7c4dc55dfef2499300d06092a864886f70d01010b050030263124302206035504030c1b44656269616e382e70726f76696e6369616e65742e636f6d2e6172301e170d3135303630323136323934355a170d3235303533303136323934355a30263124302206035504030c1b44656269616e382e70726f76696e6369616e65742e636f6d2e617230820122300d06092a864886f70d01
        EAP-Message =
0x010105000382010f003082010a0282010100ce2407532c44ee6b97291153b8f3acc2bb95063610866225f9a42ee5a3e03625e3fc2d861bf1bc6aba40b16950019ab955c365b12b5442056a3873d8636f10a2f963b869aa39f99216455561afa8429a07e3b10bc2a2a4bf2d3699687685ea74e6640537d790ce44ac359b9f1b8a2db50ac16948973d7704db0a84a35c33ed823836ecdd75159ec70be01f6b81fcbed10aeebfaf2197d2f74ea337db67b14076316613c9e95e4014682b85e9b89973e21f4ab6dce002e01e1464421e39bb83e083c25492bfa4c0fdca03267cf2d619e5636746ffca069f808ca768a61c0ad709a15206e86cb2ad7ec175fe
        EAP-Message =
0x20cdf42366910672c50beefc04ff74a9b6e0d0e38f0203010001a30d300b30090603551d1304023000300d06092a864886f70d01010b0500038201010081fcbbf1b939721ad72c4df2bb6b3807d190aa189d6f0b4ce2ad4b849ab087ef18a16f66abf10e8fadb33e0f595bae0a21bcd2c3515f080ed09ba5f35bb4cd437877d0b79b6b3edcc907940465b1689c6c3045dd38628dc8ffbc2bf8ea1a25ae9d2794bc42c36276e66b96270db6dfae1a45fbde4394c0265d74c38f4d1d9d286cee8a30f0b3be33bf22e57ad7590756fd44641e64a9796b34cd842ddac2403401e49c87c411f316c0936ada58bc873b7fae1a5cf5e24961c692d9fe40262569
        EAP-Message =
0xc8b81b521cd4cb64c771b0e44ee2a3c15b744451841e11bb4ed0e28e4e3c40ff854e32162814348b2460b630a77f5a1bbb51d02534337ea8b06a65b4604611c3160301014b0c0001470300174104e0fd0dfd3fa67966e2a6caff90c0cf6c3b768a5788b0be70a1f0dc945ec5fbce883b71b8d583eb02a9914cf8df86b562e6a6ac1835fad0e19a02b5a2060e277c01006fed0cc484aff40f1a30905d82b661c0dff0fb5da253c288cf80cedad0bed0b8e2e46440071fc3a840409b1990a4aa7b782a74472d6810961fc1ecb7fa96decc9be7f3e0a11e4928d2237c4341ca051c2561d9d29972340093639d3d43e1872caeb309c56dd0ebbd8bd37fbf24
        EAP-Message = 0x63cdd0235c2ae2350eaa5f20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x840fb4a2850bad03cf3fb9b167c12725
Wed Aug 16 12:32:37 2017 : Info: Finished request 13.
Wed Aug 16 12:32:37 2017 : Debug: Going to the next request
Wed Aug 16 12:32:37 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=191,
length=255
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message = 0x020400061900
        State = 0x840fb4a2850bad03cf3fb9b167c12725
        Message-Authenticator = 0xbfad3c3064ff4a4e80270b8dfa4f0b19
Wed Aug 16 12:32:37 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authorize {
Wed Aug 16 12:32:37 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:37 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:37 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:37 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:37 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP packet type response id 4 length
6
Wed Aug 16 12:32:37 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:37 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:37 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:37 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authenticate {
Wed Aug 16 12:32:37 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:37 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:37 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:37 2017 : Info: [peap] Received TLS ACK
Wed Aug 16 12:32:37 2017 : Info: [peap] ACK handshake fragment handler
Wed Aug 16 12:32:37 2017 : Info: [peap] eaptls_verify returned 1
Wed Aug 16 12:32:37 2017 : Info: [peap] eaptls_process returned 13
Wed Aug 16 12:32:37 2017 : Info: [peap] EAPTLS_HANDLED
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:37 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 191 to 172.22.88.223 port 32769
        EAP-Message =
0x010500961900cb6f0053a470b8d79aeddf756ef80c1b1625ddf8674ac8cfa52694e16a59b505d189be051d57396b1df310daaf81c70cc8ac4309047ac91477416fed9ce366966f662ee218b68497c6d3482731d118efc334b35a03d91c71f171bfca2e1cb20525eca8b2d2975e0a91c54edd68c8c26e4b7033a19247163ff68d48dd20625a984558eab46bd5d516030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x840fb4a2860aad03cf3fb9b167c12725
Wed Aug 16 12:32:37 2017 : Info: Finished request 14.
Wed Aug 16 12:32:37 2017 : Debug: Going to the next request
Wed Aug 16 12:32:37 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=192,
length=393
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message =
0x020500901980000000861603010046100000424104365857e925f26d3a813dccc4f24c1a4247f666a08f26d3c4f6423f4ebe1043ac692aff1b9da2818e7e5468eacc1afe30137ec1f751f7ba0763e4255bc7dc358914030100010116030100308f1b3cfc54b5620d4467ad8de34ea3c848a68776301942e85991761759f86ebbf1a17d6c537414c7dd8be83476be36e5
        State = 0x840fb4a2860aad03cf3fb9b167c12725
        Message-Authenticator = 0x585024fb1c17c198e93e558106c5b24a
Wed Aug 16 12:32:37 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authorize {
Wed Aug 16 12:32:37 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:37 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:37 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:37 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:37 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:37 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP packet type response id 5 length
144
Wed Aug 16 12:32:37 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:37 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:37 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:37 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:37 2017 : Info: +group authenticate {
Wed Aug 16 12:32:37 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:37 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:37 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:37 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:37 2017 : Debug:   TLS Length 134
Wed Aug 16 12:32:37 2017 : Info: [peap] Length Included
Wed Aug 16 12:32:37 2017 : Info: [peap] eaptls_verify returned 11
Wed Aug 16 12:32:37 2017 : Info: [peap] <<< TLS 1.0 Handshake [length
0046], ClientKeyExchange
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap] <<< TLS 1.0 ChangeCipherSpec
[length 0001]
Wed Aug 16 12:32:37 2017 : Info: [peap] <<< TLS 1.0 Handshake [length
0010], Finished
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap] >>> TLS 1.0 ChangeCipherSpec
[length 0001]
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap] >>> TLS 1.0 Handshake [length
0010], Finished
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap]     TLS_accept: unknown state
Wed Aug 16 12:32:37 2017 : Info: [peap]     (other): SSL negotiation
finished successfully
Wed Aug 16 12:32:37 2017 : Debug: SSL Connection Established
Wed Aug 16 12:32:37 2017 : Info: [peap] eaptls_process returned 13
Wed Aug 16 12:32:37 2017 : Info: [peap] EAPTLS_HANDLED
Wed Aug 16 12:32:37 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:37 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 192 to 172.22.88.223 port 32769
        EAP-Message =
0x0106004119001403010001011603010030613aab7ab5b0909d983984f216497fc9171a157c56cc96fb34852fcb30d821b2dccbd766db2ce70bad285a42eb3d85e3
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x840fb4a28709ad03cf3fb9b167c12725
Wed Aug 16 12:32:37 2017 : Info: Finished request 15.
Wed Aug 16 12:32:37 2017 : Debug: Going to the next request
Wed Aug 16 12:32:37 2017 : Debug: Waking up in 4.9 seconds.
Wed Aug 16 12:32:42 2017 : Info: Cleaning up request 12 ID 189 with
timestamp +89
Wed Aug 16 12:32:42 2017 : Info: Cleaning up request 13 ID 190 with
timestamp +89
Wed Aug 16 12:32:42 2017 : Info: Cleaning up request 14 ID 191 with
timestamp +89
Wed Aug 16 12:32:42 2017 : Info: Cleaning up request 15 ID 192 with
timestamp +89
Wed Aug 16 12:32:42 2017 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Wed Aug 16 12:32:42 2017 : Debug: WARNING: !! EAP session for state
0x840fb4a28709ad03 did not finish!
Wed Aug 16 12:32:42 2017 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/guide/Certificate_Compatibility
Wed Aug 16 12:32:42 2017 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Wed Aug 16 12:32:42 2017 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=193,
length=255
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message = 0x020600061900
        State = 0x840fb4a28709ad03cf3fb9b167c12725
        Message-Authenticator = 0x66460b98c5614772bbf59585253fef1b
Wed Aug 16 12:32:43 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authorize {
Wed Aug 16 12:32:43 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:43 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:43 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:43 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:43 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP packet type response id 6 length
6
Wed Aug 16 12:32:43 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:43 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:43 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authenticate {
Wed Aug 16 12:32:43 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:43 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:43 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:43 2017 : Info: [peap] Received TLS ACK
Wed Aug 16 12:32:43 2017 : Info: [peap] ACK handshake is finished
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_verify returned 3
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_process returned 3
Wed Aug 16 12:32:43 2017 : Info: [peap] EAPTLS_SUCCESS
Wed Aug 16 12:32:43 2017 : Info: [peap] Session established.  Decoding
tunneled attributes.
Wed Aug 16 12:32:43 2017 : Info: [peap] Peap state TUNNEL ESTABLISHED
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:43 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 193 to 172.22.88.223 port 32769
        EAP-Message =
0x0107002b190017030100201088099661e7d2a1b6c0da4ad13486200099e7c8f15f2ae5c71d5dde7b0e8ce1
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x840fb4a28008ad03cf3fb9b167c12725
Wed Aug 16 12:32:43 2017 : Info: Finished request 16.
Wed Aug 16 12:32:43 2017 : Debug: Going to the next request
Wed Aug 16 12:32:43 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=194,
length=292
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message =
0x0207002b190017030100205a4ef58ecd71029ca8c30dc3a10383ffec01b65ccecac827644d9892cc243969
        State = 0x840fb4a28008ad03cf3fb9b167c12725
        Message-Authenticator = 0x959d8110e38c88ee2599d725d8750b02
Wed Aug 16 12:32:43 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authorize {
Wed Aug 16 12:32:43 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:43 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:43 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:43 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:43 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP packet type response id 7 length
43
Wed Aug 16 12:32:43 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:43 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:43 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authenticate {
Wed Aug 16 12:32:43 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:43 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:43 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_verify returned 7
Wed Aug 16 12:32:43 2017 : Info: [peap] Done initial handshake
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_process returned 7
Wed Aug 16 12:32:43 2017 : Info: [peap] EAPTLS_OK
Wed Aug 16 12:32:43 2017 : Info: [peap] Session established.  Decoding
tunneled attributes.
Wed Aug 16 12:32:43 2017 : Info: [peap] Peap state WAITING FOR INNER
IDENTITY
Wed Aug 16 12:32:43 2017 : Info: [peap] Identity - tyard
Wed Aug 16 12:32:43 2017 : Info: [peap] Got inner identity 'tyard'
Wed Aug 16 12:32:43 2017 : Info: [peap] Setting default EAP type for
tunneled EAP session.
Wed Aug 16 12:32:43 2017 : Info: [peap] Got tunneled request
        EAP-Message = 0x0207000f0165616c6d6f6e61636964
server  {
Wed Aug 16 12:32:43 2017 : Info: [peap] Setting User-Name to tyard
Sending tunneled request
        EAP-Message = 0x0207000f0165616c6d6f6e61636964
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "tyard"
server inner-tunnel {
Wed Aug 16 12:32:43 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: +group authorize {
Wed Aug 16 12:32:43 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:43 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:43 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:43 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:43 2017 : Info: ++update control {
Wed Aug 16 12:32:43 2017 : Info: ++} # update control = noop
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP packet type response id 7 length
15
Wed Aug 16 12:32:43 2017 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = updated
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] Entering ldap_groupcmp()
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:43 2017 : Info: [files]        ... expanding second
conditional
Wed Aug 16 12:32:43 2017 : Info: [files]        expand: %{User-Name} ->
tyard
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))) ->
(|(&(objectClass=group)(member=CN\3dTom Yard\2cOU\3dIT\2cOU\3dG.
IT\2cOU\3dDir.
tech\2cOU\3dusers\2cOU\3dholomit\2cDC\3dd-holomit\2cDC\3dcom)))
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] performing search in
cn=wifi,ou=WI-FI,ou=in,ou=services,ou=holomit,dc=d-holomit,dc=com, with
filter (|(&(objectClass=group)(member=CN\3dTom Yard\2cOU\3dIT\2cOU\3dG.
IT\2cOU\3dDir.
tech\2cOU\3dusers\2cOU\3dholomit\2cDC\3dd-holomit\2cDC\3dcom)))
Wed Aug 16 12:32:43 2017 : Debug: rlm_ldap::ldap_groupcmp: User found in
group cn=wifi,ou=WI-FI,ou=in,ou=services,ou=holomit,dc=d-holomit,dc=com
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:43 2017 : Info: [files] users: Matched entry DEFAULT at
line 207
Wed Aug 16 12:32:43 2017 : Info: ++[files] = ok
Wed Aug 16 12:32:43 2017 : Info: [ldap] performing user authorization for
tyard
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:43 2017 : Info: [ldap]         ... expanding second
conditional
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand: %{User-Name} ->
tyard
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Info: [ldap] No default NMAS login sequence
Wed Aug 16 12:32:43 2017 : Info: [ldap] looking for check items in
directory...
Wed Aug 16 12:32:43 2017 : Info: [ldap] looking for reply items in
directory...
Wed Aug 16 12:32:43 2017 : Debug: WARNING: No "known good" password was
found in LDAP.  Are you sure that the user is configured correctly?
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:43 2017 : Info: ++[ldap] = ok
Wed Aug 16 12:32:43 2017 : Info: ++[expiration] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[logintime] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[pap] = noop
Wed Aug 16 12:32:43 2017 : Info: +} # group authorize = updated
Wed Aug 16 12:32:43 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: +group authenticate {
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP Identity
Wed Aug 16 12:32:43 2017 : Info: [eap] processing type mschapv2
Wed Aug 16 12:32:43 2017 : Debug: rlm_eap_mschapv2: Issuing Challenge
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:43 2017 : Info: +} # group authenticate = handled
} # server inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: [peap] Got tunneled reply code 11
        EAP-Message =
0x010800241a0108001f1013ecab12c8d0da668bb565eb0e16e89e65616c6d6f6e61636964
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x13d849c113d05325705c1d91b22c8dc5
Wed Aug 16 12:32:43 2017 : Info: [peap] Got tunneled reply RADIUS code 11
        EAP-Message =
0x010800241a0108001f1013ecab12c8d0da668bb565eb0e16e89e65616c6d6f6e61636964
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x13d849c113d05325705c1d91b22c8dc5
Wed Aug 16 12:32:43 2017 : Info: [peap] Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 01 08 00 1f 10 13 ec ab 12 c8 d0 da 66 8b
b5
  PEAP tunnel data out 0010: 65 eb 0e 16 e8 9e 65 61 6c 6d 6f 6e 61 63 69
64
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:43 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 194 to 172.22.88.223 port 32769
        EAP-Message =
0x0108004b190017030100408f5c8be7955f46253220ac946e20643c2db06e426fbe1d81c14889ee809d5aad6e55bcc054dd0f28eb8d7af2b7a2609333dfe5cdfa59d713edd34ec8b850d573
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x840fb4a28107ad03cf3fb9b167c12725
Wed Aug 16 12:32:43 2017 : Info: Finished request 17.
Wed Aug 16 12:32:43 2017 : Debug: Going to the next request
Wed Aug 16 12:32:43 2017 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=195,
length=356
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message =
0x0208006b190017030100602bd484175477a9a35f3c1042a628d500311969a3520dce194cba98def75c7943da13af729559760d7796ce0be5da4089d03a3fd056b5baa96eca181feb4b17def338120a029fd96e5b8d0ac5356a840ffd78f9ed90ceb5c38eba6471387ccc68
        State = 0x840fb4a28107ad03cf3fb9b167c12725
        Message-Authenticator = 0x09953ef1ad5cbcba93de44d2b74155d9
Wed Aug 16 12:32:43 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authorize {
Wed Aug 16 12:32:43 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:43 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:43 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:43 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:43 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP packet type response id 8 length
107
Wed Aug 16 12:32:43 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:43 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:43 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authenticate {
Wed Aug 16 12:32:43 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:43 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:43 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_verify returned 7
Wed Aug 16 12:32:43 2017 : Info: [peap] Done initial handshake
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_process returned 7
Wed Aug 16 12:32:43 2017 : Info: [peap] EAPTLS_OK
Wed Aug 16 12:32:43 2017 : Info: [peap] Session established.  Decoding
tunneled attributes.
Wed Aug 16 12:32:43 2017 : Info: [peap] Peap state phase2
Wed Aug 16 12:32:43 2017 : Info: [peap] EAP type mschapv2
Wed Aug 16 12:32:43 2017 : Info: [peap] Got tunneled request
        EAP-Message =
0x020800451a0208004031bcc11cd717735cf85643d6363baa72ff00000000000000001d818e8388886074e15547872eddf3f58cd2da004dcc58170065616c6d6f6e61636964
server  {
Wed Aug 16 12:32:43 2017 : Info: [peap] Setting User-Name to tyard
Sending tunneled request
        EAP-Message =
0x020800451a0208004031bcc11cd717735cf85643d6363baa72ff00000000000000001d818e8388886074e15547872eddf3f58cd2da004dcc58170065616c6d6f6e61636964
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "tyard"
        State = 0x13d849c113d05325705c1d91b22c8dc5
server inner-tunnel {
Wed Aug 16 12:32:43 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: +group authorize {
Wed Aug 16 12:32:43 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:43 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:43 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:43 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:43 2017 : Info: ++update control {
Wed Aug 16 12:32:43 2017 : Info: ++} # update control = noop
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP packet type response id 8 length
69
Wed Aug 16 12:32:43 2017 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = updated
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] Entering ldap_groupcmp()
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:43 2017 : Info: [files]        ... expanding second
conditional
Wed Aug 16 12:32:43 2017 : Info: [files]        expand: %{User-Name} ->
tyard
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:43 2017 : Info: [files]        expand:
(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))) ->
(|(&(objectClass=group)(member=CN\3dTom Yard\2cOU\3dIT\2cOU\3dG.
IT\2cOU\3dDir.
tech\2cOU\3dusers\2cOU\3dholomit\2cDC\3dd-holomit\2cDC\3dcom)))
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] performing search in
cn=wifi,ou=WI-FI,ou=in,ou=servicese,ou=holomit,dc=d-holomit,dc=com, with
filter (|(&(objectClass=group)(member=CN\3dTom Yard\2cOU\3dIT\2cOU\3dG.
IT\2cOU\3dDir.
tech\2cOU\3dusers\2cOU\3dholomit\2cDC\3dd-holomit\2cDC\3dcom)))
Wed Aug 16 12:32:43 2017 : Debug: rlm_ldap::ldap_groupcmp: User found in
group cn=wifi,ou=WI-FI,ou=in,ou=services,ou=holomit,dc=d-holomit,dc=com
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:43 2017 : Info: [files] users: Matched entry DEFAULT at
line 207
Wed Aug 16 12:32:43 2017 : Info: ++[files] = ok
Wed Aug 16 12:32:43 2017 : Info: [ldap] performing user authorization for
tyard
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand:
%{Stripped-User-Name} ->
Wed Aug 16 12:32:43 2017 : Info: [ldap]         ... expanding second
conditional
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand: %{User-Name} ->
tyard
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) ->
(sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Info: [ldap]         expand:
OU=holomit,DC=d-holomit,DC=com -> OU=holomit,DC=d-holomit,DC=com
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] performing search in
OU=holomit,DC=d-holomit,DC=com, with filter (sAMAccountName=tyard)
Wed Aug 16 12:32:43 2017 : Info: [ldap] No default NMAS login sequence
Wed Aug 16 12:32:43 2017 : Info: [ldap] looking for check items in
directory...
Wed Aug 16 12:32:43 2017 : Info: [ldap] looking for reply items in
directory...
Wed Aug 16 12:32:43 2017 : Debug: WARNING: No "known good" password was
found in LDAP.  Are you sure that the user is configured correctly?
Wed Aug 16 12:32:43 2017 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Wed Aug 16 12:32:43 2017 : Info: ++[ldap] = ok
Wed Aug 16 12:32:43 2017 : Info: ++[expiration] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[logintime] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[pap] = noop
Wed Aug 16 12:32:43 2017 : Info: +} # group authorize = updated
Wed Aug 16 12:32:43 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: +group authenticate {
Wed Aug 16 12:32:43 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP/mschapv2
Wed Aug 16 12:32:43 2017 : Info: [eap] processing type mschapv2
Wed Aug 16 12:32:43 2017 : Info: [mschapv2] # Executing group from file
/etc/freeradius/sites-enabled/inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: [mschapv2] +group MS-CHAP {
Wed Aug 16 12:32:43 2017 : Info: [mschap] Creating challenge hash with
username: tyard
Wed Aug 16 12:32:43 2017 : Info: [mschap] Client is using MS-CHAPv2 for
tyard, we need NT-Password
Wed Aug 16 12:32:43 2017 : Info: [mschap]       expand:
--username=%{mschap:User-Name:-None} -> --username=tyard
Wed Aug 16 12:32:43 2017 : Info: [mschap] No NT-Domain was found in the
User-Name.
Wed Aug 16 12:32:43 2017 : Info: [mschap]       expand: %{mschap:NT-Domain}
->
Wed Aug 16 12:32:43 2017 : Info: [mschap]       ... expanding second
conditional
Wed Aug 16 12:32:43 2017 : Info: [mschap]       expand:
--domain=%{%{mschap:NT-Domain}:-d-holomit} -> --domain=d-holomit
Wed Aug 16 12:32:43 2017 : Info: [mschap] Creating challenge hash with
username: tyard
Wed Aug 16 12:32:43 2017 : Info: [mschap]       expand:
--challenge=%{mschap:Challenge:-00} -> --challenge=c7e9749f9a9488cc
Wed Aug 16 12:32:43 2017 : Info: [mschap]       expand:
--nt-response=%{mschap:NT-Response:-00} ->
--nt-response=1d818e8388886074e15547872eddf3f58cd2da004dcc5817
Wed Aug 16 12:32:43 2017 : Debug: Exec output: No trusted SAM account
(0xc000018b)
Wed Aug 16 12:32:43 2017 : Debug: Exec plaintext: No trusted SAM account
(0xc000018b)
Wed Aug 16 12:32:43 2017 : Info: [mschap] Exec: program returned: 1
Wed Aug 16 12:32:43 2017 : Info: [mschap] External script failed.
Wed Aug 16 12:32:43 2017 : Info: [mschap] FAILED: MS-CHAP2-Response is
incorrect
Wed Aug 16 12:32:43 2017 : Info: ++[mschap] = reject
Wed Aug 16 12:32:43 2017 : Info: +} # = rejectgroup MS-CHAP
Wed Aug 16 12:32:43 2017 : Info: [eap] Freeing handler
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = reject
Wed Aug 16 12:32:43 2017 : Info: +} # group authenticate = reject
Wed Aug 16 12:32:43 2017 : Info: Failed to authenticate the user.
Wed Aug 16 12:32:43 2017 : Info: Using Post-Auth-Type REJECT
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: +group REJECT {
Wed Aug 16 12:32:43 2017 : Info: [attr_filter.access_reject]    expand:
%{User-Name} -> tyard
Wed Aug 16 12:32:43 2017 : Debug: attr_filter: Matched entry DEFAULT at
line 11
Wed Aug 16 12:32:43 2017 : Info: ++[attr_filter.access_reject] = updated
Wed Aug 16 12:32:43 2017 : Info: +} # group REJECT = updated
} # server inner-tunnel
Wed Aug 16 12:32:43 2017 : Info: [peap] Got tunneled reply code 3
        MS-CHAP-Error = "\010E=691 R=1"
        EAP-Message = 0x04080004
        Message-Authenticator = 0x00000000000000000000000000000000
Wed Aug 16 12:32:43 2017 : Info: [peap] Got tunneled reply RADIUS code 3
        MS-CHAP-Error = "\010E=691 R=1"
        EAP-Message = 0x04080004
        Message-Authenticator = 0x00000000000000000000000000000000
Wed Aug 16 12:32:43 2017 : Info: [peap] Tunneled authentication was
rejected.
Wed Aug 16 12:32:43 2017 : Info: [peap] FAILURE
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = handled
Wed Aug 16 12:32:43 2017 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 195 to 172.22.88.223 port 32769
        EAP-Message =
0x0109002b190017030100205c769298d305cb8efb64174de3ed2ad1dfaab7273ca01b4cd4d95e6a27e2b8a5
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x840fb4a28206ad03cf3fb9b167c12725
Wed Aug 16 12:32:43 2017 : Info: Finished request 18.
Wed Aug 16 12:32:43 2017 : Debug: Going to the next request
Wed Aug 16 12:32:43 2017 : Debug: Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 172.22.88.223 port 32769, id=196,
length=292
        User-Name = "tyard"
        Calling-Station-Id = "54:27:1e:0c:0b:fc"
        Called-Station-Id = "44:ad:d9:0e:dd:40:Test-radius"
        NAS-Port = 13
        Cisco-AVPair = "audit-session-id=ac1f0c620000019b599464c7"
        NAS-IP-Address = 172.22.88.223
        NAS-Identifier = "WLC1"
        Airespace-Wlan-Id = 2
        Service-Type = Framed-User
        Framed-MTU = 1300
        NAS-Port-Type = Wireless-802.11
        Tunnel-Type:0 = VLAN
        Tunnel-Medium-Type:0 = IEEE-802
        Tunnel-Private-Group-Id:0 = "5"
        EAP-Message =
0x0209002b1900170301002030c59a1b02051b475f48edea4ac129971ffed1682eef63fd870b88ae1c2dc32a
        State = 0x840fb4a28206ad03cf3fb9b167c12725
        Message-Authenticator = 0xfc6cb60e6db2999b5ed447417650829f
Wed Aug 16 12:32:43 2017 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authorize {
Wed Aug 16 12:32:43 2017 : Info: ++[preprocess] = ok
Wed Aug 16 12:32:43 2017 : Info: ++[chap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[mschap] = noop
Wed Aug 16 12:32:43 2017 : Info: ++[digest] = noop
Wed Aug 16 12:32:43 2017 : Info: [suffix] No '@' in User-Name = "tyard",
looking up realm NULL
Wed Aug 16 12:32:43 2017 : Info: [suffix] No such realm "NULL"
Wed Aug 16 12:32:43 2017 : Info: ++[suffix] = noop
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP packet type response id 9 length
43
Wed Aug 16 12:32:43 2017 : Info: [eap] Continuing tunnel setup.
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = ok
Wed Aug 16 12:32:43 2017 : Info: +} # group authorize = ok
Wed Aug 16 12:32:43 2017 : Info: Found Auth-Type = EAP
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group authenticate {
Wed Aug 16 12:32:43 2017 : Info: [eap] Request found, released from the list
Wed Aug 16 12:32:43 2017 : Info: [eap] EAP/peap
Wed Aug 16 12:32:43 2017 : Info: [eap] processing type peap
Wed Aug 16 12:32:43 2017 : Info: [peap] processing EAP-TLS
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_verify returned 7
Wed Aug 16 12:32:43 2017 : Info: [peap] Done initial handshake
Wed Aug 16 12:32:43 2017 : Info: [peap] eaptls_process returned 7
Wed Aug 16 12:32:43 2017 : Info: [peap] EAPTLS_OK
Wed Aug 16 12:32:43 2017 : Info: [peap] Session established.  Decoding
tunneled attributes.
Wed Aug 16 12:32:43 2017 : Info: [peap] Peap state send tlv failure
Wed Aug 16 12:32:43 2017 : Info: [peap] Received EAP-TLV response.
Wed Aug 16 12:32:43 2017 : Info: [peap]  The users session was previously
rejected: returning reject (again.)
Wed Aug 16 12:32:43 2017 : Info: [peap]  *** This means you need to read
the PREVIOUS messages in the debug output
Wed Aug 16 12:32:43 2017 : Info: [peap]  *** to find out the reason why the
user was rejected.
Wed Aug 16 12:32:43 2017 : Info: [peap]  *** Look for "reject" or "fail".
Those earlier messages will tell you.
Wed Aug 16 12:32:43 2017 : Info: [peap]  *** what went wrong, and how to
fix the problem.
Wed Aug 16 12:32:43 2017 : Info: [eap] Handler failed in EAP/peap
Wed Aug 16 12:32:43 2017 : Info: [eap] Failed in EAP select
Wed Aug 16 12:32:43 2017 : Info: ++[eap] = invalid
Wed Aug 16 12:32:43 2017 : Info: +} # group authenticate = invalid
Wed Aug 16 12:32:43 2017 : Info: Failed to authenticate the user.
Wed Aug 16 12:32:43 2017 : Info: Using Post-Auth-Type REJECT
Wed Aug 16 12:32:43 2017 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Aug 16 12:32:43 2017 : Info: +group REJECT {
Wed Aug 16 12:32:43 2017 : Info: [attr_filter.access_reject]    expand:
%{User-Name} -> tyard
Wed Aug 16 12:32:43 2017 : Debug: attr_filter: Matched entry DEFAULT at
line 11
Wed Aug 16 12:32:43 2017 : Info: ++[attr_filter.access_reject] = updated
Wed Aug 16 12:32:43 2017 : Info: +} # group REJECT = updated
Wed Aug 16 12:32:43 2017 : Info: Delaying reject of request 19 for 1 seconds
Wed Aug 16 12:32:43 2017 : Debug: Going to the next request
Wed Aug 16 12:32:43 2017 : Debug: Waking up in 0.9 seconds.
Wed Aug 16 12:32:44 2017 : Info: Sending delayed reject for request 19
Sending Access-Reject of id 196 to 172.22.88.223 port 32769
        EAP-Message = 0x04090004
        Message-Authenticator = 0x00000000000000000000000000000000
Wed Aug 16 12:32:44 2017 : Debug: Waking up in 3.8 seconds.
Wed Aug 16 12:32:48 2017 : Info: Cleaning up request 16 ID 193 with
timestamp +95
Wed Aug 16 12:32:48 2017 : Info: Cleaning up request 17 ID 194 with
timestamp +95
Wed Aug 16 12:32:48 2017 : Debug: Waking up in 0.1 seconds.
Wed Aug 16 12:32:48 2017 : Info: Cleaning up request 18 ID 195 with
timestamp +95
Wed Aug 16 12:32:48 2017 : Debug: Waking up in 1.0 seconds.

Special thanks to all of you.

Tomy Yard