Cisco Support Community
cancel
Showing results for 
Search instead for 
Did you mean: 
Announcements

Welcome to Cisco Support Community. We would love to have your feedback.

For an introduction to the new site, click here. And see here for current known issues.

New Member

Help troubleshooting EAP timeout debugs

Hi all,

 

i have some wireless IPADs which need to be connected to the wireless 24/7 as they run an app which needs to keep refreshing data automatically.

I have managed to capture a debug output of one of the IPAD when they drop off and I can see attempts to re-authenticate the client but it looks like EAP times out.

Is there anywhere I can read to understand more about why this would happen and how to rectify this? We are using EAP-TLS on this particular SSID.

 

Thanks!

 

Mario

###############

*apfPmkCacheTimer: Mar 21 11:12:16.238: 60:fe:c5:6b:9a:13 Removing expired PMK cache entry for station 60:fe:c5:6b:9a:13 AKM was:APF_KEY_MGMT_80211i
*apfPmkCacheTimer: Mar 21 11:12:16.239: 60:fe:c5:6b:9a:13 Removing expired PTK entry for station 60:fe:c5:6b:9a:13
*apfReceiveTask: Mar 21 11:12:16.239: 60:fe:c5:6b:9a:13 Initiating 802.1x due to PMK Timeout Event for STA
*apfReceiveTask: Mar 21 11:12:16.239: 60:fe:c5:6b:9a:13 Found an cache entry for BSSID f4:7f:35:d8:fa:10 in PMKID cache at index 0 of station 60:fe:c5:6b:9a:13
*apfReceiveTask: Mar 21 11:12:16.239: 60:fe:c5:6b:9a:13 Removing BSSID f4:7f:35:d8:fa:10 from PMKID cache of station 60:fe:c5:6b:9a:13
*apfReceiveTask: Mar 21 11:12:16.239: 60:fe:c5:6b:9a:13 Resetting MSCB PMK Cache Entry 0 for station 60:fe:c5:6b:9a:13
*dot1xMsgTask: Mar 21 11:12:16.239: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Connecting state
*dot1xMsgTask: Mar 21 11:12:16.239: 60:fe:c5:6b:9a:13 Sending EAP-Request/Identity to mobile 60:fe:c5:6b:9a:13 (EAP Id 1)
*osapiBsnTimer: Mar 21 11:12:46.126: 60:fe:c5:6b:9a:13 802.1x 'txWhen' Timer expired for station 60:fe:c5:6b:9a:13 and for message = M0
*dot1xMsgTask: Mar 21 11:12:46.127: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Connecting state
*dot1xMsgTask: Mar 21 11:12:46.127: 60:fe:c5:6b:9a:13 Sending EAP-Request/Identity to mobile 60:fe:c5:6b:9a:13 (EAP Id 2)
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.275: 60:fe:c5:6b:9a:13 Received EAPOL START from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.275: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Connecting state
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.275: 60:fe:c5:6b:9a:13 Sending EAP-Request/Identity to mobile 60:fe:c5:6b:9a:13 (EAP Id 3)
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.277: 60:fe:c5:6b:9a:13 Received EAPOL EAPPKT from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.277: 60:fe:c5:6b:9a:13 Received Identity Response (count=3) from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.277: 60:fe:c5:6b:9a:13 Reached Max EAP-Identity Request retries (3) for STA 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.278: 60:fe:c5:6b:9a:13 Sent Deauthenticate to mobile on BSSID f4:7f:35:d8:fa:10 slot 0(caller 1x_auth_pae.c:3165)
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.278: 60:fe:c5:6b:9a:13 Scheduling deletion of Mobile Station:  (callerId: 6) in 10 seconds
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.278: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Disconnected state
*Dot1x_NW_MsgTask_3: Mar 21 11:12:56.279: 60:fe:c5:6b:9a:13 Not sending EAP-Failure for STA 60:fe:c5:6b:9a:13
*apfMsConnTask_4: Mar 21 11:12:56.875: 60:fe:c5:6b:9a:13 Association received from mobile on AP f4:7f:35:d8:fa:10
*apfMsConnTask_4: Mar 21 11:12:56.875: 60:fe:c5:6b:9a:13 apfApplyWlanPolicy: Retaining the ACL recieved in AAA attributes 255 on mobile
*apfMsConnTask_4: Mar 21 11:12:56.875: 60:fe:c5:6b:9a:13 Applying site-specific Local Bridging override for station 60:fe:c5:6b:9a:13 - vapId 1, site 'default-group', interface 'corp-wlan'
*apfMsConnTask_4: Mar 21 11:12:56.875: 60:fe:c5:6b:9a:13 Applying Local Bridging Interface Policy for station 60:fe:c5:6b:9a:13 - vlan 240, interface id 11, interface 'corp-wlan'
*apfMsConnTask_4: Mar 21 11:12:56.875: 60:fe:c5:6b:9a:13 processSsidIE  statusCode is 0 and status is 0
*apfMsConnTask_4: Mar 21 11:12:56.875: 60:fe:c5:6b:9a:13 processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 STA - rates (7): 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 0
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 suppRates  statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 Processing RSN IE type 48, length 20 for mobile 60:fe:c5:6b:9a:13
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 Received RSN IE with 0 PMKIDs from mobile 60:fe:c5:6b:9a:13
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 Setting active key cache index 0 ---> 8
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 unsetting PmkIdValidatedByAp
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 apfMsRunStateDec
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 apfMs1xStateDec
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 apfPemAddUser2 (apf_policy.c:270) Changing state for mobile 60:fe:c5:6b:9a:13 on AP f4:7f:35:d8:fa:10 from Associated to Associated

*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 Sending Assoc Response to station on BSSID f4:7f:35:d8:fa:10 (status 0) ApVapId 1 Slot 0
*apfMsConnTask_4: Mar 21 11:12:56.876: 60:fe:c5:6b:9a:13 apfProcessAssocReq (apf_80211.c:6309) Changing state for mobile 60:fe:c5:6b:9a:13 on AP f4:7f:35:d8:fa:10 from Associated to Associated

*dot1xMsgTask: Mar 21 11:12:56.878: 60:fe:c5:6b:9a:13 Station 60:fe:c5:6b:9a:13 setting dot1x reauth timeout = 1800
*dot1xMsgTask: Mar 21 11:12:56.878: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Connecting state
*dot1xMsgTask: Mar 21 11:12:56.878: 60:fe:c5:6b:9a:13 Sending EAP-Request/Identity to mobile 60:fe:c5:6b:9a:13 (EAP Id 1)
*pemReceiveTask: Mar 21 11:12:56.878: 60:fe:c5:6b:9a:13 10.129.65.226 Removed NPU entry.
*Dot1x_NW_MsgTask_3: Mar 21 11:13:06.895: 60:fe:c5:6b:9a:13 Received EAPOL START from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:06.895: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Connecting state
*Dot1x_NW_MsgTask_3: Mar 21 11:13:06.895: 60:fe:c5:6b:9a:13 Sending EAP-Request/Identity to mobile 60:fe:c5:6b:9a:13 (EAP Id 2)
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.927: 60:fe:c5:6b:9a:13 Received EAPOL START from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.927: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Connecting state
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.927: 60:fe:c5:6b:9a:13 Sending EAP-Request/Identity to mobile 60:fe:c5:6b:9a:13 (EAP Id 3)
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.931: 60:fe:c5:6b:9a:13 Received EAPOL EAPPKT from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.931: 60:fe:c5:6b:9a:13 Received Identity Response (count=3) from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.931: 60:fe:c5:6b:9a:13 Reached Max EAP-Identity Request retries (3) for STA 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.932: 60:fe:c5:6b:9a:13 Sent Deauthenticate to mobile on BSSID f4:7f:35:d8:fa:10 slot 0(caller 1x_auth_pae.c:3165)
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.932: 60:fe:c5:6b:9a:13 Scheduling deletion of Mobile Station:  (callerId: 6) in 10 seconds
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.933: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Disconnected state
*Dot1x_NW_MsgTask_3: Mar 21 11:13:11.933: 60:fe:c5:6b:9a:13 Not sending EAP-Failure for STA 60:fe:c5:6b:9a:13
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Association received from mobile on AP f4:7f:35:d8:fa:10
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 apfApplyWlanPolicy: Retaining the ACL recieved in AAA attributes 255 on mobile
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Applying site-specific Local Bridging override for station 60:fe:c5:6b:9a:13 - vapId 1, site 'default-group', interface 'corp-wlan'
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Applying Local Bridging Interface Policy for station 60:fe:c5:6b:9a:13 - vlan 240, interface id 11, interface 'corp-wlan'
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 processSsidIE  statusCode is 0 and status is 0
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 STA - rates (7): 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 0
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 suppRates  statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Processing RSN IE type 48, length 20 for mobile 60:fe:c5:6b:9a:13
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Received RSN IE with 0 PMKIDs from mobile 60:fe:c5:6b:9a:13
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Setting active key cache index 8 ---> 8
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 unsetting PmkIdValidatedByAp
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 apfPemAddUser2 (apf_policy.c:270) Changing state for mobile 60:fe:c5:6b:9a:13 on AP f4:7f:35:d8:fa:10 from Associated to Associated

*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_4: Mar 21 11:13:12.066: 60:fe:c5:6b:9a:13 Sending Assoc Response to station on BSSID f4:7f:35:d8:fa:10 (status 0) ApVapId 1 Slot 0
*apfMsConnTask_4: Mar 21 11:13:12.067: 60:fe:c5:6b:9a:13 apfProcessAssocReq (apf_80211.c:6309) Changing state for mobile 60:fe:c5:6b:9a:13 on AP f4:7f:35:d8:fa:10 from Associated to Associated

*dot1xMsgTask: Mar 21 11:13:12.068: 60:fe:c5:6b:9a:13 Station 60:fe:c5:6b:9a:13 setting dot1x reauth timeout = 1800
*dot1xMsgTask: Mar 21 11:13:12.068: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Connecting state
*dot1xMsgTask: Mar 21 11:13:12.068: 60:fe:c5:6b:9a:13 Sending EAP-Request/Identity to mobile 60:fe:c5:6b:9a:13 (EAP Id 1)
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.074: 60:fe:c5:6b:9a:13 Received EAPOL EAPPKT from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.074: 60:fe:c5:6b:9a:13 Received Identity Response (count=1) from mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.074: 60:fe:c5:6b:9a:13 EAP State update from Connecting to Authenticating for mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.074: 60:fe:c5:6b:9a:13 dot1x - moving mobile 60:fe:c5:6b:9a:13 into Authenticating state
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.074: 60:fe:c5:6b:9a:13 Entering Backend Auth Response state for mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.077: 60:fe:c5:6b:9a:13 Processing Access-Challenge for mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.077: 60:fe:c5:6b:9a:13 Entering Backend Auth Req state (id=26) for mobile 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.077: 60:fe:c5:6b:9a:13 WARNING: updated EAP-Identifier 1 ===> 26 for STA 60:fe:c5:6b:9a:13
*Dot1x_NW_MsgTask_3: Mar 21 11:13:12.078: 60:fe:c5:6b:9a:13 Sending EAP Request from AAA to mobile 60:fe:c5:6b:9a:13 (EAP Id 26)
*osapiBsnTimer: Mar 21 11:13:41.926: 60:fe:c5:6b:9a:13 802.1x 'timeoutEvt' Timer expired for station 60:fe:c5:6b:9a:13 and for message = M0
*dot1xMsgTask: Mar 21 11:13:41.927: 60:fe:c5:6b:9a:13 Retransmit 1 of EAP-Request (length 10) for mobile 60:fe:c5:6b:9a:13
*osapiBsnTimer: Mar 21 11:14:11.926: 60:fe:c5:6b:9a:13 802.1x 'timeoutEvt' Timer expired for station 60:fe:c5:6b:9a:13 and for message = M0
*dot1xMsgTask: Mar 21 11:14:11.927: 60:fe:c5:6b:9a:13 Retransmit 2 of EAP-Request (length 10) for mobile 60:fe:c5:6b:9a:13
*osapiBsnTimer: Mar 21 11:14:41.927: 60:fe:c5:6b:9a:13 802.1x 'timeoutEvt' Timer expired for station 60:fe:c5:6b:9a:13 and for message = M0
*dot1xMsgTask: Mar 21 11:14:41.927: 60:fe:c5:6b:9a:13 Retransmit failure for EAP-Request to mobile 60:fe:c5:6b:9a:13
*dot1xMsgTask: Mar 21 11:14:41.928: 60:fe:c5:6b:9a:13 Sent Deauthenticate to mobile on BSSID f4:7f:35:d8:fa:10 slot 0(caller 1x_ptsm.c:546)
*dot1xMsgTask: Mar 21 11:14:41.928: 60:fe:c5:6b:9a:13 Scheduling deletion of Mobile Station:  (callerId: 57) in 10 seconds
*osapiBsnTimer: Mar 21 11:14:51.927: 60:fe:c5:6b:9a:13 apfMsExpireCallback (apf_ms.c:591) Expiring Mobile!
*apfReceiveTask: Mar 21 11:14:51.927: 60:fe:c5:6b:9a:13 apfMsExpireMobileStation (apf_ms.c:5604) Changing state for mobile 60:fe:c5:6b:9a:13 on AP f4:7f:35:d8:fa:10 from Associated to Disassociated

*apfReceiveTask: Mar 21 11:14:51.927: 60:fe:c5:6b:9a:13 Scheduling deletion of Mobile Station:  (callerId: 45) in 10 seconds
*osapiBsnTimer: Mar 21 11:15:01.926: 60:fe:c5:6b:9a:13 apfMsExpireCallback (apf_ms.c:591) Expiring Mobile!
*apfReceiveTask: Mar 21 11:15:01.928: 60:fe:c5:6b:9a:13 Sent Deauthenticate to mobile on BSSID f4:7f:35:d8:fa:10 slot 0(caller apf_ms.c:5698)
*apfReceiveTask: Mar 21 11:15:01.928: 60:fe:c5:6b:9a:13 apfMsAssoStateDec
*apfReceiveTask: Mar 21 11:15:01.928: 60:fe:c5:6b:9a:13 apfMsExpireMobileStation (apf_ms.c:5736) Changing state for mobile 60:fe:c5:6b:9a:13 on AP f4:7f:35:d8:fa:10 from Disassociated to Idle

*apfReceiveTask: Mar 21 11:15:01.928: 60:fe:c5:6b:9a:13 Scheduling deletion of Mobile Station:  (callerId: 47) in 10 seconds
*osapiBsnTimer: Mar 21 11:15:11.926: 60:fe:c5:6b:9a:13 apfMsExpireCallback (apf_ms.c:591) Expiring Mobile!
*apfReceiveTask: Mar 21 11:15:11.927: 60:fe:c5:6b:9a:13 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.

############

269
Views
0
Helpful
0
Replies
CreatePlease login to create content