802.1X PEAP issues

[Brett Verney]

Hi guys,

I'm attempting to setup 802.X at a client site and are having issues and can't make sense of the logs. I have a created a test SSID with the modifed L2 Security settings (WPA2-->AES--802.1X). I have access to the WLC but because the client is on the other side of the world (2Mbps Satellite, language barriers etc etc) so testing is rather difficult.

My server guys have setup an NPS server (on the local DC), matching client settings via group policy. The client associates to the WLAN, but has a 0.0.0.0 IP Address, then disconnects shortly after. NPS also sees the client authenticated. 

When we test the WLAN using PSK instead, the clients get an IP address and successfully connects, so not a DHCP issue

I did manage to do some debugging. Client MAC is '34:02:86:75:35:69'   I see timeouts and interface 'overrides'.

PLEASE HELP! -->

(Cisco Controller) >*radiusTransportThread: Jun 19 16:13:55.860: 1c:df:0f:51:25:7b Accounting-Response received from RADIUS server 10.3.4.4 for mobile 1c:df:0f:51:25:7b receiveId = 0
*apfMsConnTask_2: Jun 19 16:16:10.946: 34:02:86:75:35:69 Processing assoc-req station:34:02:86:75:35:69 AP:b0:aa:77:00:97:90-00 thread:15101b00
*apfMsConnTask_2: Jun 19 16:16:10.946: 34:02:86:75:35:69 Adding mobile on LWAPP AP b0:aa:77:00:97:90(0)
*apfMsConnTask_2: Jun 19 16:16:10.946: 34:02:86:75:35:69 Association received from mobile on BSSID b0:aa:77:00:97:93 AP FRL-APP01p-ap
*apfMsConnTask_2: Jun 19 16:16:10.946: 34:02:86:75:35:69 Rf profile 200 Clients are allowed to AP radio

*apfMsConnTask_2: Jun 19 16:16:10.946: 34:02:86:75:35:69 Max Client Trap Threshold: 12  cur: 5

*apfMsConnTask_2: Jun 19 16:16:10.946: 34:02:86:75:35:69 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 override for default ap group, marking intgrp NULL
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0

*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Re-applying interface policy for client

*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 In processSsidIE:5682 setting Central switched to TRUE
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 In processSsidIE:5685 apVapId = 4 and Split Acl Id = 65535
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Applying site-specific Local Bridging override for station 34:02:86:75:35:69 - vapId 4, site 'Offices', interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Applying Local Bridging Interface Policy for station 34:02:86:75:35:69 - vlan 112, interface id 12, interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 override from ap group, removing intf group from mscb
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Applying site-specific override for station 34:02:86:75:35:69 - vapId 4, site 'Offices', interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 112

*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Re-applying interface policy for client

*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 processSsidIE  statusCode is 0 and status is 0
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 STA - rates (8): 140 18 152 36 48 72 96 108 0 0 0 0 0 0 0 0
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 suppRates  statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_2: Jun 19 16:16:10.947: RSNIE in Assoc. Req.: (22)

*apfMsConnTask_2: Jun 19 16:16:10.947:      [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_2: Jun 19 16:16:10.947:      [0016] ac 01 3c 00 00 00

*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Processing RSN IE type 48, length 22 for mobile 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_2: Jun 19 16:16:10.947: 34:02:86:75:35:69 RSN Capabilities:  60
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 apfValidateDot11iCapabilities:1286 Received RSNIE with Capabilities with STA MFPC: 0, STA MFPR:0, & AP MFPC:0MFPR:0
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Marking Mobile as non-11w Capable
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Received RSN IE with 0 PMKIDs from mobile 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Setting active key cache index 8 ---> 8
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 unsetting PmkIdValidatedByAp
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 apfValidateDot11wGroupMgmtCipher:1716, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning

*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Encryption policy is set to 0x80000001
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Not Using WMM Compliance code qosCap 2f
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Sending 11w Flag 0 for Client 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP b0:aa:77:00:97:90 vapId 4 apVapId 4 flex-acl-name:
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 apfMsAssoStateInc
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 apfPemAddUser2 (apf_policy.c:352) Changing state for mobile 34:02:86:75:35:69 on AP b0:aa:77:00:97:90 from Idle to Associated

*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 apfPemAddUser2:session timeout forstation 34:02:86:75:35:69 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Sending assoc-resp with status 0 station:34:02:86:75:35:69 AP:b0:aa:77:00:97:90-00 on apVapId 4
*apfMsConnTask_2: Jun 19 16:16:10.948: 34:02:86:75:35:69 Sending Assoc Response to station on BSSID b0:aa:77:00:97:93 (status 0) ApVapId 4 Slot 0
*apfMsConnTask_2: Jun 19 16:16:10.949: 34:02:86:75:35:69 apfProcessAssocReq (apf_80211.c:9458) Changing state for mobile 34:02:86:75:35:69 on AP b0:aa:77:00:97:90 from Associated to Associated

*spamApTask1: Jun 19 16:16:10.950: 34:02:86:75:35:69 Sent 1x initiate message to multi thread task for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.950: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 1 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.951: 34:02:86:75:35:69 EAP-PARAM Debug - eap-params for Wlan-Id :4 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.951: 34:02:86:75:35:69 Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.951: 34:02:86:75:35:69 Station 34:02:86:75:35:69 setting dot1x reauth timeout = 1800
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.951: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.951: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 1)
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.966: 34:02:86:75:35:69 Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.966: 34:02:86:75:35:69 reauth_sm state transition 1 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.966: 34:02:86:75:35:69 Received EAPOL START from mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.966: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.966: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 2)
*Dot1x_NW_MsgTask_1: Jun 19 16:16:10.966: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*apfMsConnTask_2: Jun 19 16:16:29.187: 34:02:86:75:35:69 Processing assoc-req station:34:02:86:75:35:69 AP:b0:aa:77:00:97:90-00 thread:15101b00
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Association received from mobile on BSSID b0:aa:77:00:97:93 AP FRL-APP01p-ap
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Rf profile 200 Clients are allowed to AP radio

*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Max Client Trap Threshold: 12  cur: 6

*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 override for default ap group, marking intgrp NULL
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 112

*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Re-applying interface policy for client

*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 In processSsidIE:5682 setting Central switched to TRUE
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 In processSsidIE:5685 apVapId = 4 and Split Acl Id = 65535
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Applying site-specific Local Bridging override for station 34:02:86:75:35:69 - vapId 4, site 'Offices', interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Applying Local Bridging Interface Policy for station 34:02:86:75:35:69 - vlan 112, interface id 12, interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 override from ap group, removing intf group from mscb
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Applying site-specific override for station 34:02:86:75:35:69 - vapId 4, site 'Offices', interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 112

*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 Re-applying interface policy for client

*apfMsConnTask_2: Jun 19 16:16:29.188: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 processSsidIE  statusCode is 0 and status is 0
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 STA - rates (8): 140 18 152 36 48 72 96 108 0 0 0 0 0 0 0 0
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 suppRates  statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_2: Jun 19 16:16:29.189: RSNIE in Assoc. Req.: (22)

*apfMsConnTask_2: Jun 19 16:16:29.189:      [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_2: Jun 19 16:16:29.189:      [0016] ac 01 3c 00 00 00

*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Processing RSN IE type 48, length 22 for mobile 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 RSN Capabilities:  60
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 apfValidateDot11iCapabilities:1286 Received RSNIE with Capabilities with STA MFPC: 0, STA MFPR:0, & AP MFPC:0MFPR:0
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Marking Mobile as non-11w Capable
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Received RSN IE with 0 PMKIDs from mobile 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Setting active key cache index 8 ---> 8
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 unsetting PmkIdValidatedByAp
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 apfValidateDot11wGroupMgmtCipher:1716, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning

*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Initializing policy
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Change state to AUTHCHECK (2) last state 8021X_REQD (3)

*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Encryption policy is set to 0x80000001
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Not Using WMM Compliance code qosCap 2f
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 Sending 11w Flag 0 for Client 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP b0:aa:77:00:97:90 vapId 4 apVapId 4 flex-acl-name:
*apfMsConnTask_2: Jun 19 16:16:29.189: 34:02:86:75:35:69 apfPemAddUser2 (apf_policy.c:352) Changing state for mobile 34:02:86:75:35:69 on AP b0:aa:77:00:97:90 from Associated to Associated

*apfMsConnTask_2: Jun 19 16:16:29.190: 34:02:86:75:35:69 apfPemAddUser2:session timeout forstation 34:02:86:75:35:69 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0
*apfMsConnTask_2: Jun 19 16:16:29.190: 34:02:86:75:35:69 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_2: Jun 19 16:16:29.190: 34:02:86:75:35:69 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_2: Jun 19 16:16:29.190: 34:02:86:75:35:69 Sending assoc-resp with status 0 station:34:02:86:75:35:69 AP:b0:aa:77:00:97:90-00 on apVapId 4
*apfMsConnTask_2: Jun 19 16:16:29.190: 34:02:86:75:35:69 Sending Assoc Response to station on BSSID b0:aa:77:00:97:93 (status 0) ApVapId 4 Slot 0
*apfMsConnTask_2: Jun 19 16:16:29.190: 34:02:86:75:35:69 apfProcessAssocReq (apf_80211.c:9458) Changing state for mobile 34:02:86:75:35:69 on AP b0:aa:77:00:97:90 from Associated to Associated

*spamApTask1: Jun 19 16:16:29.191: 34:02:86:75:35:69 Sent 1x initiate message to multi thread task for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.192: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.192: 34:02:86:75:35:69 EAP-PARAM Debug - eap-params for Wlan-Id :4 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.192: 34:02:86:75:35:69 Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.192: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.192: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 1)
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.209: 34:02:86:75:35:69 Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.209: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.209: 34:02:86:75:35:69 Received EAPOL START from mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.209: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.209: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 2)
*Dot1x_NW_MsgTask_1: Jun 19 16:16:29.209: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*osapiBsnTimer: Jun 19 16:16:59.084: 34:02:86:75:35:69 802.1x 'txWhen' Timer expired for station 34:02:86:75:35:69 and for message = M0
*dot1xMsgTask: Jun 19 16:16:59.084: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*dot1xMsgTask: Jun 19 16:16:59.084: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 3)
*dot1xMsgTask: Jun 19 16:16:59.085: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 Received EAPOL EAPPKT from mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 Received Identity Response (count=2) from mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 Resetting reauth count 2 to 0 for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 EAP State update from Connecting to Authenticating for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Authenticating state
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 Entering Backend Auth Response state for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.596: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 Processing Access-Reject for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 0 PMK-remove groupcast messages sent
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 Removing PMK cache due to EAP-Failure for mobile 34:02:86:75:35:69 (EAP Id -1)
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 Sending EAP-Failure to mobile 34:02:86:75:35:69 (EAP Id -1)
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 Entering Backend Auth Failure state (id=-1) for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 Setting quiet timer for 5 seconds for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Unknown state
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.630: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*Dot1x_NW_MsgTask_1: Jun 19 16:16:59.631: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 Processing assoc-req station:34:02:86:75:35:69 AP:b0:aa:77:00:97:90-00 thread:15101b00
*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 Association received from mobile on BSSID b0:aa:77:00:97:93 AP FRL-APP01p-ap
*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 Rf profile 200 Clients are allowed to AP radio

*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 Max Client Trap Threshold: 12  cur: 6

*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 override for default ap group, marking intgrp NULL
*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 112

*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 Re-applying interface policy for client

*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
*apfMsConnTask_2: Jun 19 16:17:03.525: 34:02:86:75:35:69 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 In processSsidIE:5682 setting Central switched to TRUE
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 In processSsidIE:5685 apVapId = 4 and Split Acl Id = 65535
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Applying site-specific Local Bridging override for station 34:02:86:75:35:69 - vapId 4, site 'Offices', interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Applying Local Bridging Interface Policy for station 34:02:86:75:35:69 - vlan 112, interface id 12, interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 override from ap group, removing intf group from mscb
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Applying site-specific override for station 34:02:86:75:35:69 - vapId 4, site 'Offices', interface 'frieda-staff_wireless'
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 112

*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Re-applying interface policy for client

*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 processSsidIE  statusCode is 0 and status is 0
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 STA - rates (8): 140 18 152 36 48 72 96 108 0 0 0 0 0 0 0 0
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 suppRates  statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_2: Jun 19 16:17:03.526: RSNIE in Assoc. Req.: (22)

*apfMsConnTask_2: Jun 19 16:17:03.526:      [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_2: Jun 19 16:17:03.526:      [0016] ac 01 3c 00 00 00

*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Processing RSN IE type 48, length 22 for mobile 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 RSN Capabilities:  60
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 apfValidateDot11iCapabilities:1286 Received RSNIE with Capabilities with STA MFPC: 0, STA MFPR:0, & AP MFPC:0MFPR:0
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Marking Mobile as non-11w Capable
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Received RSN IE with 0 PMKIDs from mobile 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 Setting active key cache index 8 ---> 8
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 unsetting PmkIdValidatedByAp
*apfMsConnTask_2: Jun 19 16:17:03.526: 34:02:86:75:35:69 apfValidateDot11wGroupMgmtCipher:1716, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning

*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Initializing policy
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Change state to AUTHCHECK (2) last state 8021X_REQD (3)

*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 Encryption policy is set to 0x80000001
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 Not Using WMM Compliance code qosCap 2f
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 Sending 11w Flag 0 for Client 34:02:86:75:35:69
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP b0:aa:77:00:97:90 vapId 4 apVapId 4 flex-acl-name:
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 apfPemAddUser2 (apf_policy.c:352) Changing state for mobile 34:02:86:75:35:69 on AP b0:aa:77:00:97:90 from Associated to Associated

*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 apfPemAddUser2:session timeout forstation 34:02:86:75:35:69 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 Sending assoc-resp with status 0 station:34:02:86:75:35:69 AP:b0:aa:77:00:97:90-00 on apVapId 4
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 Sending Assoc Response to station on BSSID b0:aa:77:00:97:93 (status 0) ApVapId 4 Slot 0
*apfMsConnTask_2: Jun 19 16:17:03.527: 34:02:86:75:35:69 apfProcessAssocReq (apf_80211.c:9458) Changing state for mobile 34:02:86:75:35:69 on AP b0:aa:77:00:97:90 from Associated to Associated

*spamApTask1: Jun 19 16:17:03.529: 34:02:86:75:35:69 Sent 1x initiate message to multi thread task for mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.529: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.529: 34:02:86:75:35:69 EAP-PARAM Debug - eap-params for Wlan-Id :4 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.529: 34:02:86:75:35:69 Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.529: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.529: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 1)
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.546: 34:02:86:75:35:69 Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.546: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.547: 34:02:86:75:35:69 Received EAPOL START from mobile 34:02:86:75:35:69
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.547: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.547: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 2)
*Dot1x_NW_MsgTask_1: Jun 19 16:17:03.547: 34:02:86:75:35:69 reauth_sm state transition 0 ---> 0 for mobile 34:02:86:75:35:69 at 1x_reauth_sm.c:71
*osapiBsnTimer: Jun 19 16:17:33.484: 34:02:86:75:35:69 802.1x 'txWhen' Timer expired for station 34:02:86:75:35:69 and for message = M0
*dot1xMsgTask: Jun 19 16:17:33.485: 34:02:86:75:35:69 dot1x - moving mobile 34:02:86:75:35:69 into Connecting state
*dot1xMsgTask: Jun 19 16:17:33.485: 34:02:86:75:35:69 Sending EAP-Request/Identity to mobile 34:02:86:75:35:69 (EAP Id 3)

[Scott Fella]

When you are testing, the 802.1x and the psk WLAN is mapped to the same subnet correct?  PSK authentication happens at the AP and 802.1x has to have WLC and radius along with AD. If your test SSID's are mapped to the same subnet, then at least we know that DHCP is indeed working. If you then test 802.1x and you see logs on the radius that the client gets access accept, then maybe look at the WLC and see if the client is in 802.1x_reqd state or in the RUN state. 

You can also run debugs for AAA to verify that the communication from the radius to the WLC is not being dropped.  The issue can be the latency between the radius and the WLC.

-Scott

[Brett Verney]

Thanks Scott,

That is correct. I am flicking between PSK and 802.1X on the test SSID. I am mapping it to the same interface as a working production SSID (using PSK until I get 802.1X working on the test SSID), so I think DHCP is good...

Tomorrow morning I will get the client to attempt the connection again. Are there any specific AAA debugs that I should be running in order to see which state they are stuck (if any) from the CLI? The GUI is incredibly slow over the VPN connection.

Brett

[Scott Fella]

Makensure you have Fast SSID enabled on the WLC and post your show WLAN <WLAN id>.

Now when troubleshooting 802.1x, you want to look at the radius logs along with looking at the show client <MAC address> and debug aaa events enable and debug aaa packet enable. 

Verify that the client is configured properly also!!!! Make sure your using WPA2/AES only and not a mix of WPA and or TKIP.  Make sure that the shared secret being used on the WLC and the radius servers are identical and also tell me what certificate did you install on the radius server. What type of EAP are you using also.

-Scott

[Brett Verney]

Hi Scott,

I have attached two .txt files, one with the debugs and one with the 'show wlan' command. The debug was probably too big copy and paste. 

To answer your questions;

- Fast SSID has been enabled (works great, thank you!)
- Only WPA2 is is being used
- I have confirmed shared secret is correct on both ends
- Using PEAP
- Unsure about certificate... The server team set this up for me. The Radius server NPS on the site's local DC. Cert was issues from the internal PKI, client trust's root CA.
- Client gets stuck in 802.1X auth required state

I am getting the server guys to look at the Radius logs again now...

[Brett Verney]

Scott,

Sorry I forgot to give you an update on this one. We figured this out a couple of weeks ago. It turns out one of my colleagues had entered an incorrect Subject Alternative Name in the NPS certificate.

Once this was resolved, clients could authenticate. However I did have to increase the EAP timers to get it working flawlessly.

Thanks for your help!

-Brett