Active Directory AUTHENTICATION with LDAP AUTHORIZATION
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
On Aug 16, 2017, at 6:22 PM, Tom Yard <tomyyard@gmail.com> wrote:
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
That's good...
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:
The general approach is to test each piece in isolation. i.e. if you add "ldap" to the inner-tunnel virtual server, then test *just* the inner-tunnel server until you get an Access-Accept. That has the nice side-effect of giving you much smaller debug logs, which are therefore easier to read.
THIS DEBUG IS THE ONE CORRESPONDING TO JUST ONE ATTEMPT OF AUTHENTICATION, IT'S SO LONG...I APOLOGIZE FOR THIS
It's fine to have a long debug output. It's *much* better than posting 3 lines and asking "What's wrong?"
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
This message means that the client doesn't know about the CA which is configured on the server. Follow the guide, and add the CA certificate to the client.
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)
And that's not a FreeRADIUS message. That's from AD. Alan DeKok.
hi,
THIS DEBUG IS THE ONE CORRESPONDING TO JUST ONE ATTEMPT OF AUTHENTICATION,
no its not. you have a machine auth there followed by a user auth - ensure your client is configured to only do user authentication
IT'S SO LONG...I APOLOGIZE FOR THIS
thats fine - this is fine - the debug may be long but a lot of it can be scanned over quickly once you understand what is going on - visit some sites about PEAP to see the flow - then look at the conversation that is going on with FreeRADIUS...each packet request/reply being part of the conversation....little hello, then EAP to construct secure tunnel (then lots of those EAP-Message attributes appear, then the MSCHAPv2 inside the PEAP (a few more packets) then end of session, access accept etc.
User-Name = "host/host44.d-holomit.com"
machine auth attempt
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
machine not in AD (well, not in THAT location anyway ;-) )
Sending Access-Reject of id 188 to 172.22.88.223 port 32769 EAP-Message = 0x04050004 Message-Authenticator = 0x00000000000000000000000000000000
end of that one.... now the user auth
User-Name = "tyard"
user auth
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
this user was found - but why are you running ldap in the outer phase? anyone can spoof the outer packet....you only trust the inner-tunnel for EAP... ...and onwards
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
okay PEAP being started some delays to responses....did you get a cert prompt? you really need to configure your client with correct CA and RADIUS server cert.. there are plenty of 802.1X configuration tools now the MSCHAPv2 in the inner-tunnel
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
..and from now on its a fail/reject. cause? the user with the doamin of "d-holmit" did not have a trusted account in this AD...is that domain correct? i'd advise against using %{mschap:NT-Domain} - the domain provided by the user in the MSCHAP - and just hardcode it in the ntlm_auth however. the easiest part here is to just use radtst directly against the inner-tunnel on the server itself... in inner-tunnel, by default, you have a listener directive localhost on port 18120 or such. so all you do is use that as your server target with radtest or such....meaning your mschap request hits inner-tunnel directly (as if EAP had been set up nicely by the client).. and thus you can test your policies and inner-tunnel very easily. at that point, mschapv2 will be working and you can look at ldap and what policies/unlang you need there. one bit at a time alan
Dear both Alans, thanks for your advice. Before planning the tests, I need your help on these topics: 1) In the first implementation for authentication like Alan Dekok's guide, I setup default and inner-tunnel servers. Now if I enable ldap for authorization, do I have to enable ldap in the default virtual server and also in the inner-tunnel virtual server ??? Or just in default file ??? 2) I can't understand this comment from you: "but why are you running ldap in the outer phase?" Can you explain to me in more detail please ??? Thanks again!!! 2017-08-16 15:23 GMT-03:00 Alan Buxey <alan.buxey@gmail.com>:
hi,
THIS DEBUG IS THE ONE CORRESPONDING TO JUST ONE ATTEMPT OF AUTHENTICATION,
no its not. you have a machine auth there followed by a user auth - ensure your client is configured to only do user authentication
IT'S SO LONG...I APOLOGIZE FOR THIS
thats fine - this is fine - the debug may be long but a lot of it can be scanned over quickly once you understand what is going on - visit some sites about PEAP to see the flow - then look at the conversation that is going on with FreeRADIUS...each packet request/reply being part of the conversation....little hello, then EAP to construct secure tunnel (then lots of those EAP-Message attributes appear, then the MSCHAPv2 inside the PEAP (a few more packets) then end of session, access accept etc.
User-Name = "host/host44.d-holomit.com"
machine auth attempt
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
machine not in AD (well, not in THAT location anyway ;-) )
Sending Access-Reject of id 188 to 172.22.88.223 port 32769 EAP-Message = 0x04050004 Message-Authenticator = 0x00000000000000000000000000000000
end of that one.... now the user auth
User-Name = "tyard"
user auth
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
this user was found - but why are you running ldap in the outer phase? anyone can spoof the outer packet....you only trust the inner-tunnel for EAP...
...and onwards
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
okay PEAP being started
some delays to responses....did you get a cert prompt? you really need to configure your client with correct CA and RADIUS server cert.. there are plenty of 802.1X configuration tools
now the MSCHAPv2 in the inner-tunnel
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
..and from now on its a fail/reject. cause? the user with the doamin of "d-holmit" did not have a trusted account in this AD...is that domain correct? i'd advise against using %{mschap:NT-Domain} - the domain provided by the user in the MSCHAP - and just hardcode it in the ntlm_auth
however. the easiest part here is to just use radtst directly against the inner-tunnel on the server itself... in inner-tunnel, by default, you have a listener directive localhost on port 18120 or such. so all you do is use that as your server target with radtest or such....meaning your mschap request hits inner-tunnel directly (as if EAP had been set up nicely by the client).. and thus you can test your policies and inner-tunnel very easily. at that point, mschapv2 will be working and you can look at ldap and what policies/unlang you need there. one bit at a time
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
Tom Yard <tomyyard@gmail.com> wrote:
2) I can't understand this comment from you: "but why are you running ldap in the outer phase?" Can you explain to me in more detail please ???
The inner tunnel server happens inside the TLS crypto tunnel. You should do LDAP there. User-Name in the outer (default) server is untrustworthy data which should only be used for routing requests around relays. For example, people can lie about their usernames, putting one username in the outer envelope and a different username inside the TLS tunnel. Only trust the one that you get in inner-tunnel. To be more exact, you can trust most fields in the outer server ("default")... anything that your NAS adds to the RADIUS packet can be trusted, assuming your backbone is secure of course. But the NAS just passes User-Name along untouched. If you are just using LDAP to accept/reject then this is easy. If you are using it to choose VLANs, then you have to leak the VLAN choice out of the inner tunnel server to the outer server, so it can tell the NAS in cleartext.
participants (4)
-
Alan Buxey -
Alan DeKok -
Brian Julin -
Tom Yard