802.1X authentication issue.

S. ANIL · ‎10-14-2015

In my client network suddenly few users are not able to connect to Cooperate SSID or suddenly the connection will lost. I have pulled the debug output from the controller. I suspect its authentication issue but not sure and dont know how to fix it.. kindly help

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.315: ac:7b:a1:b2:d5:b3 EAP State update from Connecting to Authenticating for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.315: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Authenticating state

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.315: ac:7b:a1:b2:d5:b3 Entering Backend Auth Response state for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.322: ac:7b:a1:b2:d5:b3 Processing Access-Reject for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.322: ac:7b:a1:b2:d5:b3 Removing PMK cache due to EAP-Failure for mobile ac:7b:a1:b2:d5:b3 (EAP Id -1)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.322: ac:7b:a1:b2:d5:b3 Sending EAP-Failure to mobile ac:7b:a1:b2:d5:b3 (EAP Id -1)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.322: ac:7b:a1:b2:d5:b3 Entering Backend Auth Failure state (id=-1) for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.322: ac:7b:a1:b2:d5:b3 Setting quiet timer for 5 seconds for mobile ac:7b:a1:b2:d5:b3

?

(Cisco Controller) >un*Dot1x_NW_MsgTask_3: Oct 15 16:50:24.322: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Unknown state

*Dot1x_NW_MsgTask_3: Oct 15 16:50:25.331: ac:7b:a1:b2:d5:b3 Received EAPOL START from mobile ac:7b:a1:b2:d5:b3

*osapiBsnTimer: Oct 15 16:50:29.226: ac:7b:a1:b2:d5:b3 802.1x 'quiteWhile' Timer expired for station ac:7b:a1:b2:d5:b3 and for message = M0

*dot1xMsgTask: Oct 15 16:50:29.227: ac:7b:a1:b2:d5:b3 quiet timer completed for mobile ac:7b:a1:b2:d5:b3

*dot1xMsgTask: Oct 15 16:50:29.227: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Connecting state

*dot1xMsgTask: Oct 15 16:50:29.227: ac:7b:a1:b2:d5:b3 Sending EAP-Request/Identity to mobile ac:7b:a1:b2:d5:b3 (EAP Id 1)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.569: ac:7b:a1:b2:d5:b3 Received EAPOL EAPPKT from mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.569: ac:7b:a1:b2:d5:b3 Received Identity Response (count=3) from mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.569: ac:7b:a1:b2:d5:b3 Reached Max EAP-Identity Request retries (3) for STA ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.571: ac:7b:a1:b2:d5:b3 Sent Deauthenticate to mobile on BSSID d4:d7:48:d9:f6:80 slot 1(caller 1x_auth_pae.c:3241)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.571: ac:7b:a1:b2:d5:b3 Scheduling deletion of Mobile Station: (callerId: 6) in 10 seconds

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.571: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Disconnected state

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.571: ac:7b:a1:b2:d5:b3 Not sending EAP-Failure for STA ac:7b:a1:b2:d5:b3

*apfMsConnTask_2: Oct 15 16:50:29.797: ac:7b:a1:b2:d5:b3 Association received from mobile on BSSID 08:d0:9f:16:83:5d

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Global 200 Clients are allowed to AP radio

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Max Client Trap Threshold: 0 cur: 2

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 53

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Re-applying interface policy for client

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2018)

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2246)

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 In processSsidIE:4264 setting Central switched to FALSE

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Applying site-specific Local Bridging override for station ac:7b:a1:b2:d5:b3 - vapId 3, site 'NSW_CorpOff', interface 'lc-corporate'

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Applying Local Bridging Interface Policy for station ac:7b:a1:b2:d5:b3 - vlan 53, interface id 13, interface 'lc-corporate'

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Applying site-specific override for station ac:7b:a1:b2:d5:b3 - vapId 3, site 'NSW_CorpOff', interface 'lc-corporate'

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 53

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 Re-applying interface policy for client

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2018)

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2246)

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 processSsidIE statusCode is 0 and status is 0

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 processSsidIE ssid_done_flag is 0 finish_flag is 0

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 STA - rates (8): 140 18 152 36 176 72 96 108 0 0 0 0 0 0 0 0

*apfMsConnTask_2: Oct 15 16:50:29.798: ac:7b:a1:b2:d5:b3 suppRates statusCode is 0 and gotSuppRatesElement is 1

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 Processing RSN IE type 48, length 22 for mobile ac:7b:a1:b2:d5:b3

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 Received RSN IE with 0 PMKIDs from mobile ac:7b:a1:b2:d5:b3

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 Setting active key cache index 8 ---> 8

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 unsetting PmkIdValidatedByAp

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Deleted mobile LWAPP rule on AP [d4:d7:48:d9:f6:80]

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 Updated location for station old AP d4:d7:48:d9:f6:80-1, new AP 08:d0:9f:16:83:50-1

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Initializing policy

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Change state to AUTHCHECK (2) last state 8021X_REQD (3)

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) DHCP required on AP 08:d0:9f:16:83:50 vapId 3 apVapId 1for this client

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 08:d0:9f:16:83:50 vapId 3 apVapId 1 flex-acl-name:

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 apfPemAddUser2 (apf_policy.c:276) Changing state for mobile ac:7b:a1:b2:d5:b3 on AP 08:d0:9f:16:83:50 from Associated to Associated

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 apfPemAddUser2:session timeout forstation ac:7b:a1:b2:d5:b3 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_2: Oct 15 16:50:29.799: ac:7b:a1:b2:d5:b3 Sending Assoc Response to station on BSSID 08:d0:9f:16:83:5f (status 0) ApVapId 1 Slot 1

*apfMsConnTask_2: Oct 15 16:50:29.800: ac:7b:a1:b2:d5:b3 apfProcessAssocReq (apf_80211.c:7399) Changing state for mobile ac:7b:a1:b2:d5:b3 on AP 08:d0:9f:16:83:50 from Associated to Associated

*apfMsConnTask_2: Oct 15 16:50:29.800: ac:7b:a1:b2:d5:b3 Updating AID for REAP AP Client 08:d0:9f:16:83:50 - AID ===> 3

*dot1xMsgTask: Oct 15 16:50:29.810: ac:7b:a1:b2:d5:b3 Station ac:7b:a1:b2:d5:b3 setting dot1x reauth timeout = 1800

*dot1xMsgTask: Oct 15 16:50:29.810: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Connecting state

*dot1xMsgTask: Oct 15 16:50:29.810: ac:7b:a1:b2:d5:b3 Sending EAP-Request/Identity to mobile ac:7b:a1:b2:d5:b3 (EAP Id 1)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.813: ac:7b:a1:b2:d5:b3 Received EAPOL START from mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.813: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Connecting state

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.813: ac:7b:a1:b2:d5:b3 Sending EAP-Request/Identity to mobile ac:7b:a1:b2:d5:b3 (EAP Id 2)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.822: ac:7b:a1:b2:d5:b3 Received EAPOL EAPPKT from mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.822: ac:7b:a1:b2:d5:b3 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.827: ac:7b:a1:b2:d5:b3 Received EAPOL EAPPKT from mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.827: ac:7b:a1:b2:d5:b3 Received Identity Response (count=2) from mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.827: ac:7b:a1:b2:d5:b3 EAP State update from Connecting to Authenticating for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.828: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Authenticating state

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.828: ac:7b:a1:b2:d5:b3 Entering Backend Auth Response state for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.835: ac:7b:a1:b2:d5:b3 Processing Access-Reject for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.836: ac:7b:a1:b2:d5:b3 Removing PMK cache due to EAP-Failure for mobile ac:7b:a1:b2:d5:b3 (EAP Id -1)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.836: ac:7b:a1:b2:d5:b3 Sending EAP-Failure to mobile ac:7b:a1:b2:d5:b3 (EAP Id -1)

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.836: ac:7b:a1:b2:d5:b3 Entering Backend Auth Failure state (id=-1) for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.836: ac:7b:a1:b2:d5:b3 Setting quiet timer for 5 seconds for mobile ac:7b:a1:b2:d5:b3

*Dot1x_NW_MsgTask_3: Oct 15 16:50:29.836: ac:7b:a1:b2:d5:b3 dot1x - moving mobile ac:7b:a1:b2:d5:b3 into Unknown state

*Dot1x_NW_MsgTask_3: Oct 15 16:50:30.841: ac:7b:a1:b2:d5:b3 Received EAPOL START from mobile ac:7b:a1:b2:d5:b3

Rasika Nayanajith · ‎10-15-2015

What is your RADIUS server ?

Check that radius server log as it should say reason for these failures.

HTH

Rasika