ACS 1121 error 5411 EAP session timed out w/Peap Wireless logins

[NPT_2]

I am having issues that came up in the last month where all of my wireless client devices (using 4400 WLC and AC 1121 Appliance w/Active Directory integration) using PEAP MSCHAP2 are being prompted multiple times one after another for their userid/password. 

This is very intermitant with clients sometimes being able to authenticate on the first try and later in the day getting prompted 20 times for authentication before it works.  This affects all brands of laptops/tablets/smartphones and other devices. 

My ACS log files show an error of 5411 EAP session timed out. 

I have had a TAC case open for over a month but they still haven't found a solution.

Has anyone run into this and have any thoughts?  I have already increased my timeout on the controller from the default 2 seconds to 8 seconds but the delay between prompts asking for authentication credentials on clients is less than a second.

What do you think? 

Jim

[Richard Atkin]

What software is on the ACS and the WLC?

Has your Cert expired?

Have you recently changed or updated the Cert?

Have you tried turning off all the clever features (Like fast re-connect, .11r, etc) in the WLC / ACS to simplify things?

Do your Clients produce any error messages?

If you run a 'Debug Client ' on the WLC, what's the output?

Sent from Cisco Technical Support iPad App

[NPT_2]

We are running 5.2.0.26.11 on the ACS engine and 7.0.240.0 on the WLC's.  The certificate on the ACS was expired, but for over a year without issues prior to about a month ago (our clients do have the verify certificate box unchecked).  I did renew the certificate on the ACS (self signed, just told it to renew) but that didn't help. 

The only thing the clients get are multiple prompts for authentication usually a second or 2 apart even though my timeout on the WLC is set to 8 seconds.  A debug on the WLC shows the following.  Any ideas on what could be the issue? 

(Cisco Controller) >*dot1xMsgTask: Jun 18 11:07:16.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 8)
*osapiBsnTimer: Jun 18 11:07:17.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:17.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:17.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 9)
*osapiBsnTimer: Jun 18 11:07:18.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:18.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:18.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 10)
*apfLbsTask: Jun 18 11:07:18.319: 00:27:10:c9:91:2c Copy AP LOCP - mode:0 slotId:1, apMac 0x0:1c:b1:6:ee:a0
*apfLbsTask: Jun 18 11:07:18.319: 00:27:10:c9:91:2c Copy WLAN LOCP EssIndex:2 aid:1 ssid:NPT-SECURE
*apfLbsTask: Jun 18 11:07:18.319: 00:27:10:c9:91:2c Copy Security LOCP ecypher:0x0 ptype:0x2, p:0x1, eaptype:0x6 w:0x1 aalg:0x0, PMState: 8021X_REQD
*apfLbsTask: Jun 18 11:07:18.319: 00:27:10:c9:91:2c Copy 802.11 LOCP a:0x0 b:0x0 c:0x0 d:0x0 e:0x0 protocol2:0x1 statuscode 0, reasoncode 99, status 3
*apfLbsTask: Jun 18 11:07:18.319: 00:27:10:c9:91:2c Copy CCX LOCP 4
*apfLbsTask: Jun 18 11:07:18.319: 00:27:10:c9:91:2c Copy e2e LOCP 0x1
*apfLbsTask: Jun 18 11:07:18.319: 00:27:10:c9:91:2c Copy MobilityData LOCP status:0, anchorip:0x0
*osapiBsnTimer: Jun 18 11:07:19.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:19.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:19.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 11)
*osapiBsnTimer: Jun 18 11:07:20.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:20.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:20.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 12)
*osapiBsnTimer: Jun 18 11:07:21.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:21.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:21.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 13)
*osapiBsnTimer: Jun 18 11:07:22.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:22.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:22.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 14)
*osapiBsnTimer: Jun 18 11:07:23.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:23.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:23.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 15)
*osapiBsnTimer: Jun 18 11:07:24.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:24.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:24.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 16)
*osapiBsnTimer: Jun 18 11:07:25.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:25.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:25.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 17)
*osapiBsnTimer: Jun 18 11:07:26.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:26.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:26.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 18)
*osapiBsnTimer: Jun 18 11:07:27.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:27.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:27.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 19)
*osapiBsnTimer: Jun 18 11:07:28.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:28.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:28.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 20)
*osapiBsnTimer: Jun 18 11:07:29.317: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:29.318: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:29.318: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 21)
*dot1xMsgTask: Jun 18 11:07:29.318: 00:27:10:c9:91:2c Reached Max EAP-Identity Request retries (21) for STA 00:27:10:c9:91:2c
*dot1xMsgTask: Jun 18 11:07:29.318: 00:27:10:c9:91:2c Sent Deauthenticate to mobile on BSSID 00:1c:b1:06:ee:a0 slot 1(caller 1x_auth_pae.c:3121)
*dot1xMsgTask: Jun 18 11:07:29.319: 00:27:10:c9:91:2c Scheduling deletion of Mobile Station:  (callerId: 6) in 10 seconds
*dot1xMsgTask: Jun 18 11:07:29.319: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Disconnected state
*dot1xMsgTask: Jun 18 11:07:29.319: 00:27:10:c9:91:2c Not sending EAP-Failure for STA 00:27:10:c9:91:2c
*spamReceiveTask: Jun 18 11:07:29.979: 00:27:10:c9:91:2c Received Idle-Timeout from AP 00:1d:71:0a:de:70, slot 1 for STA 00:27:10:c9:91:2c
*spamReceiveTask: Jun 18 11:07:29.979: 00:27:10:c9:91:2c Warning, ignore the DELETE_MOBILE_PAYLOAD from AP: 00:1d:71:0a:de:70, slot 1. STA connecting AP: 00:1c:b1:06:ee:a0, slot 1
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c Association received from mobile on AP 00:1d:71:0a:de:70
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c 0.0.0.0 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c Applying site-specific IPv6 override for station 00:27:10:c9:91:2c - vapId 2, site 'none', interface 'management'
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c Applying IPv6 Interface Policy for station 00:27:10:c9:91:2c - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c STA - rates (8): 140 18 152 36 176 72 96 108 0 0 0 0 0 0 0 0
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c Processing RSN IE type 48, length 22 for mobile 00:27:10:c9:91:2c
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c Received RSN IE with 0 PMKIDs from mobile 00:27:10:c9:91:2c
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c 0.0.0.0 8021X_REQD (3) Deleted mobile LWAPP rule on AP [00:1c:b1:06:ee:a0]
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c Updated location for station old AP 00:1c:b1:06:ee:a0-1, new AP 00:1d:71:0a:de:70-1
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c 0.0.0.0 8021X_REQD (3) Initializing policy
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c 0.0.0.0 8021X_REQD (3) Change state to AUTHCHECK (2) last state 8021X_REQD (3)

*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:1d:71:0a:de:70 vapId 2 apVapId 2for this client
*apfMsConnTask_0: Jun 18 11:07:30.834: 00:27:10:c9:91:2c Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Jun 18 11:07:30.835: 00:27:10:c9:91:2c 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1d:71:0a:de:70 vapId 2 apVapId 2
*apfMsConnTask_0: Jun 18 11:07:30.835: 00:27:10:c9:91:2c apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 00:27:10:c9:91:2c on AP 00:1d:71:0a:de:70 from Associated to Associated

*apfMsConnTask_0: Jun 18 11:07:30.835: 00:27:10:c9:91:2c Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_0: Jun 18 11:07:30.835: 00:27:10:c9:91:2c Sending Assoc Response to station on BSSID 00:1d:71:0a:de:70 (status 0) ApVapId 2 Slot 1
*apfMsConnTask_0: Jun 18 11:07:30.835: 00:27:10:c9:91:2c apfProcessAssocReq (apf_80211.c:5276) Changing state for mobile 00:27:10:c9:91:2c on AP 00:1d:71:0a:de:70 from Associated to Associated

*dot1xMsgTask: Jun 18 11:07:30.838: 00:27:10:c9:91:2c Disable re-auth, use PMK lifetime.
*dot1xMsgTask: Jun 18 11:07:30.838: 00:27:10:c9:91:2c Station 00:27:10:c9:91:2c setting dot1x reauth timeout = 0
*dot1xMsgTask: Jun 18 11:07:30.838: 00:27:10:c9:91:2c Stopping reauth timeout for 00:27:10:c9:91:2c
*dot1xMsgTask: Jun 18 11:07:30.838: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:30.838: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 1)
*osapiBsnTimer: Jun 18 11:07:31.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:31.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:31.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 2)
*osapiBsnTimer: Jun 18 11:07:32.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:32.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:32.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 3)
*osapiBsnTimer: Jun 18 11:07:33.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:33.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:33.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 4)
*apfLbsTask: Jun 18 11:07:34.318: 00:27:10:c9:91:2c Copy AP LOCP - mode:0 slotId:1, apMac 0x0:1d:71:a:de:70
*apfLbsTask: Jun 18 11:07:34.319: 00:27:10:c9:91:2c Copy WLAN LOCP EssIndex:2 aid:1 ssid:NPT-SECURE
*apfLbsTask: Jun 18 11:07:34.319: 00:27:10:c9:91:2c Copy Security LOCP ecypher:0x0 ptype:0x2, p:0x1, eaptype:0x6 w:0x1 aalg:0x0, PMState: 8021X_REQD
*apfLbsTask: Jun 18 11:07:34.319: 00:27:10:c9:91:2c Copy 802.11 LOCP a:0x0 b:0x0 c:0x0 d:0x0 e:0x0 protocol2:0x1 statuscode 0, reasoncode 99, status 3
*apfLbsTask: Jun 18 11:07:34.320: 00:27:10:c9:91:2c Copy CCX LOCP 4
*apfLbsTask: Jun 18 11:07:34.320: 00:27:10:c9:91:2c Copy e2e LOCP 0x1
*apfLbsTask: Jun 18 11:07:34.320: 00:27:10:c9:91:2c Copy MobilityData LOCP status:0, anchorip:0x0
*osapiBsnTimer: Jun 18 11:07:34.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:34.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:34.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 5)
*osapiBsnTimer: Jun 18 11:07:35.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:35.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:35.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 6)
*osapiBsnTimer: Jun 18 11:07:36.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:36.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:36.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 7)
*osapiBsnTimer: Jun 18 11:07:37.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:37.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:37.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 8)
*osapiBsnTimer: Jun 18 11:07:38.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:38.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state
*dot1xMsgTask: Jun 18 11:07:38.718: 00:27:10:c9:91:2c Sending EAP-Request/Identity to mobile 00:27:10:c9:91:2c (EAP Id 9)
*osapiBsnTimer: Jun 18 11:07:39.717: 00:27:10:c9:91:2c 802.1x 'txWhen' Timer expired for station 00:27:10:c9:91:2c and for message = M0
*dot1xMsgTask: Jun 18 11:07:39.718: 00:27:10:c9:91:2c dot1x - moving mobile 00:27:10:c9:91:2c into Connecting state