Wireless EAP issues

Kevin Haag · ‎10-25-2013

Hello Community

Since ca. 2 - 3 weeks we heard about wireless troubles from our customers. Now a few days of troubleshooting later, i don't any idea why this would happen.

Our Wireless Controller is an WLC4404 with software Rev. 7.0.220.0 the controller stand in our headquarter. The Accesspoints connect over an GRE Tunnel from the branch.

Accesspoint --> Branch Router --> WAN 1Gbps GRE Tunnel --> Headquarter Router --> Core Switch --> WLC 4404

When i'm logging some Client MAC on the WLC i become the following log:

(Cisco Controller) >*spamReceiveTask: Oct 24 10:18:39.712: 8c:70:5a:8e:09:40 Received Idle-Timeout from AP 00:1d:a2:86:db:d0, slot 0 for STA 8c:70:5a:8e:09:40

*spamReceiveTask: Oct 24 10:18:39.712: 8c:70:5a:8e:09:40 Warning, ignore the DELETE_MOBILE_PAYLOAD from AP: 00:1d:a2:86:db:d0, slot 0. STA connecting AP: 00:1d:a2:86:cb:40, slot 0

*osapiBsnTimer: Oct 24 10:18:50.204: 8c:70:5a:8e:09:40 802.1x 'txWhen' Timer expired for station 8c:70:5a:8e:09:40 and for message = M0

*dot1xMsgTask: Oct 24 10:18:50.205: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*dot1xMsgTask: Oct 24 10:18:50.205: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 3)

*dot1xMsgTask: Oct 24 10:18:50.205: 8c:70:5a:8e:09:40 Reached Max EAP-Identity Request retries (3) for STA 8c:70:5a:8e:09:40

*dot1xMsgTask: Oct 24 10:18:50.206: 8c:70:5a:8e:09:40 Sent Deauthenticate to mobile on BSSID 00:1d:a2:86:cb:40 slot 0(caller 1x_auth_pae.c:3057)

*dot1xMsgTask: Oct 24 10:18:50.207: 8c:70:5a:8e:09:40 Scheduling deletion of Mobile Station: (callerId: 6) in 10 seconds

*dot1xMsgTask: Oct 24 10:18:50.207: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Disconnected state

*dot1xMsgTask: Oct 24 10:18:50.207: 8c:70:5a:8e:09:40 Not sending EAP-Failure for STA 8c:70:5a:8e:09:40

*osapiBsnTimer: Oct 24 10:19:00.204: 8c:70:5a:8e:09:40 apfMsExpireCallback (apf_ms.c:608) Expiring Mobile!

*apfReceiveTask: Oct 24 10:19:00.205: 8c:70:5a:8e:09:40 apfMsExpireMobileStation (apf_ms.c:5009) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:cb:40 from Associated to Disassociated

*apfReceiveTask: Oct 24 10:19:00.205: 8c:70:5a:8e:09:40 Scheduling deletion of Mobile Station: (callerId: 45) in 10 seconds

*osapiBsnTimer: Oct 24 10:19:10.204: 8c:70:5a:8e:09:40 apfMsExpireCallback (apf_ms.c:608) Expiring Mobile!

*apfReceiveTask: Oct 24 10:19:10.205: 8c:70:5a:8e:09:40 apfMsAssoStateDec

*apfReceiveTask: Oct 24 10:19:10.205: 8c:70:5a:8e:09:40 apfMsExpireMobileStation (apf_ms.c:5139) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:cb:40 from Disassociated to Idle

*apfReceiveTask: Oct 24 10:19:10.205: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Deleted mobile LWAPP rule on AP [00:1d:a2:86:cb:40]

*apfReceiveTask: Oct 24 10:19:10.205: 8c:70:5a:8e:09:40 Deleting mobile on AP 00:1d:a2:86:cb:40(0)

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Adding mobile on LWAPP AP 00:1d:a2:86:db:d0(0)

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Association received from mobile on AP 00:1d:a2:86:db:d0

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Applying site-specific IPv6 override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Applying IPv6 Interface Policy for station 8c:70:5a:8e:09:40 - vlan 222, interface id 9, interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Applying site-specific override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 STA - rates (7): 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 0

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Processing RSN IE type 48, length 22 for mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Received RSN IE with 0 PMKIDs from mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 0.0.0.0 START (0) Initializing policy

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state AUTHCHECK (2)

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:1d:a2:86:db:d0 vapId 3 apVapId 1for this client

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1d:a2:86:db:d0 vapId 3 apVapId 1

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 apfMsAssoStateInc

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:db:d0 from Idle to Associated

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 Sending Assoc Response to station on BSSID 00:1d:a2:86:db:d0 (status 0) ApVapId 1 Slot 0

*apfMsConnTask_0: Oct 24 10:19:52.930: 8c:70:5a:8e:09:40 apfProcessAssocReq (apf_80211.c:5237) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:db:d0 from Associated to Associated

*dot1xMsgTask: Oct 24 10:19:52.933: 8c:70:5a:8e:09:40 Station 8c:70:5a:8e:09:40 setting dot1x reauth timeout = 0

*dot1xMsgTask: Oct 24 10:19:52.933: 8c:70:5a:8e:09:40 Stopping reauth timeout for 8c:70:5a:8e:09:40

*dot1xMsgTask: Oct 24 10:19:52.933: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*dot1xMsgTask: Oct 24 10:19:52.933: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 1)

*Dot1x_NW_MsgTask_0: Oct 24 10:19:52.959: 8c:70:5a:8e:09:40 Received EAPOL START from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:19:52.959: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*Dot1x_NW_MsgTask_0: Oct 24 10:19:52.959: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 2)

*Dot1x_NW_MsgTask_0: Oct 24 10:19:52.961: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:19:52.961: 8c:70:5a:8e:09:40 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:19:52.965: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.959: 8c:70:5a:8e:09:40 Received EAPOL START from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.959: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.960: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 3)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.960: 8c:70:5a:8e:09:40 Reached Max EAP-Identity Request retries (3) for STA 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.961: 8c:70:5a:8e:09:40 Sent Deauthenticate to mobile on BSSID 00:1d:a2:86:db:d0 slot 0(caller 1x_auth_pae.c:3057)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.961: 8c:70:5a:8e:09:40 Scheduling deletion of Mobile Station: (callerId: 6) in 10 seconds

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.962: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Disconnected state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:10.962: 8c:70:5a:8e:09:40 Not sending EAP-Failure for STA 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:11.305: 8c:70:5a:8e:09:40 Association received from mobile on AP 00:1d:a2:86:cc:10

*apfMsConnTask_0: Oct 24 10:20:11.305: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 Applying site-specific IPv6 override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 Applying IPv6 Interface Policy for station 8c:70:5a:8e:09:40 - vlan 222, interface id 9, interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 Applying site-specific override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 STA - rates (7): 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 0

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 Processing RSN IE type 48, length 22 for mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 Received RSN IE with 0 PMKIDs from mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Deleted mobile LWAPP rule on AP [00:1d:a2:86:db:d0]

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 Updated location for station old AP 00:1d:a2:86:db:d0-0, new AP 00:1d:a2:86:cc:10-0

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Initializing policy

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Change state to AUTHCHECK (2) last state 8021X_REQD (3)

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:1d:a2:86:cc:10 vapId 3 apVapId 1for this client

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1d:a2:86:cc:10 vapId 3 apVapId 1

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:cc:10 from Associated to Associated

*apfMsConnTask_0: Oct 24 10:20:11.306: 8c:70:5a:8e:09:40 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Oct 24 10:20:11.307: 8c:70:5a:8e:09:40 Sending Assoc Response to station on BSSID 00:1d:a2:86:cc:10 (status 0) ApVapId 1 Slot 0

*apfMsConnTask_0: Oct 24 10:20:11.307: 8c:70:5a:8e:09:40 apfProcessAssocReq (apf_80211.c:5237) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:cc:10 from Associated to Associated

*dot1xMsgTask: Oct 24 10:20:11.311: 8c:70:5a:8e:09:40 Station 8c:70:5a:8e:09:40 setting dot1x reauth timeout = 0

*dot1xMsgTask: Oct 24 10:20:11.311: 8c:70:5a:8e:09:40 Stopping reauth timeout for 8c:70:5a:8e:09:40

*dot1xMsgTask: Oct 24 10:20:11.312: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*dot1xMsgTask: Oct 24 10:20:11.312: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 1)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:11.317: 8c:70:5a:8e:09:40 Received EAPOL START from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:11.317: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:11.317: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 2)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:11.319: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:11.319: 8c:70:5a:8e:09:40 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:11.321: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.321: 8c:70:5a:8e:09:40 Received EAPOL START from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.321: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.321: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 3)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.321: 8c:70:5a:8e:09:40 Reached Max EAP-Identity Request retries (3) for STA 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.322: 8c:70:5a:8e:09:40 Sent Deauthenticate to mobile on BSSID 00:1d:a2:86:cc:10 slot 0(caller 1x_auth_pae.c:3057)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.322: 8c:70:5a:8e:09:40 Scheduling deletion of Mobile Station: (callerId: 6) in 10 seconds

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.323: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Disconnected state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.323: 8c:70:5a:8e:09:40 Not sending EAP-Failure for STA 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Association received from mobile on AP 00:1d:a2:86:cc:10

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Applying site-specific IPv6 override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Applying IPv6 Interface Policy for station 8c:70:5a:8e:09:40 - vlan 222, interface id 9, interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Applying site-specific override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 STA - rates (7): 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 0

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Processing RSN IE type 48, length 22 for mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Received RSN IE with 0 PMKIDs from mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Initializing policy

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Change state to AUTHCHECK (2) last state 8021X_REQD (3)

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:1d:a2:86:cc:10 vapId 3 apVapId 1for this client

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1d:a2:86:cc:10 vapId 3 apVapId 1

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:cc:10 from Associated to Associated

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 Sending Assoc Response to station on BSSID 00:1d:a2:86:cc:10 (status 0) ApVapId 1 Slot 0

*apfMsConnTask_0: Oct 24 10:20:29.668: 8c:70:5a:8e:09:40 apfProcessAssocReq (apf_80211.c:5237) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:a2:86:cc:10 from Associated to Associated

*dot1xMsgTask: Oct 24 10:20:29.673: 8c:70:5a:8e:09:40 Station 8c:70:5a:8e:09:40 setting dot1x reauth timeout = 0

*dot1xMsgTask: Oct 24 10:20:29.674: 8c:70:5a:8e:09:40 Stopping reauth timeout for 8c:70:5a:8e:09:40

*dot1xMsgTask: Oct 24 10:20:29.674: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*dot1xMsgTask: Oct 24 10:20:29.674: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 1)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.680: 8c:70:5a:8e:09:40 Received EAPOL START from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.680: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.680: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 2)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.683: 8c:70:5a:8e:09:40 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.682: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:29.685: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.682: 8c:70:5a:8e:09:40 Received EAPOL START from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.682: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.682: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 3)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.683: 8c:70:5a:8e:09:40 Reached Max EAP-Identity Request retries (3) for STA 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.684: 8c:70:5a:8e:09:40 Sent Deauthenticate to mobile on BSSID 00:1d:a2:86:cc:10 slot 0(caller 1x_auth_pae.c:3057)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.684: 8c:70:5a:8e:09:40 Scheduling deletion of Mobile Station: (callerId: 6) in 10 seconds

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.685: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Disconnected state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:47.685: 8c:70:5a:8e:09:40 Not sending EAP-Failure for STA 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 Association received from mobile on AP 00:1d:e5:8e:53:b0

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 Applying site-specific IPv6 override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 Applying IPv6 Interface Policy for station 8c:70:5a:8e:09:40 - vlan 222, interface id 9, interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 Applying site-specific override for station 8c:70:5a:8e:09:40 - vapId 3, site 'standard_ogp', interface 'schul_client222'

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1626)

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 STA - rates (7): 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 0

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 Processing RSN IE type 48, length 22 for mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:48.029: 8c:70:5a:8e:09:40 Received RSN IE with 0 PMKIDs from mobile 8c:70:5a:8e:09:40

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Deleted mobile LWAPP rule on AP [00:1d:a2:86:cc:10]

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 Updated location for station old AP 00:1d:a2:86:cc:10-0, new AP 00:1d:e5:8e:53:b0-0

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Initializing policy

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Change state to AUTHCHECK (2) last state 8021X_REQD (3)

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:1d:e5:8e:53:b0 vapId 3 apVapId 1for this client

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1d:e5:8e:53:b0 vapId 3 apVapId 1

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:e5:8e:53:b0 from Associated to Associated

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 Sending Assoc Response to station on BSSID 00:1d:e5:8e:53:b0 (status 0) ApVapId 1 Slot 0

*apfMsConnTask_0: Oct 24 10:20:48.030: 8c:70:5a:8e:09:40 apfProcessAssocReq (apf_80211.c:5237) Changing state for mobile 8c:70:5a:8e:09:40 on AP 00:1d:e5:8e:53:b0 from Associated to Associated

*dot1xMsgTask: Oct 24 10:20:48.033: 8c:70:5a:8e:09:40 Station 8c:70:5a:8e:09:40 setting dot1x reauth timeout = 0

*dot1xMsgTask: Oct 24 10:20:48.033: 8c:70:5a:8e:09:40 Stopping reauth timeout for 8c:70:5a:8e:09:40

*dot1xMsgTask: Oct 24 10:20:48.033: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*dot1xMsgTask: Oct 24 10:20:48.034: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 1)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:48.042: 8c:70:5a:8e:09:40 Received EAPOL START from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:48.042: 8c:70:5a:8e:09:40 dot1x - moving mobile 8c:70:5a:8e:09:40 into Connecting state

*Dot1x_NW_MsgTask_0: Oct 24 10:20:48.042: 8c:70:5a:8e:09:40 Sending EAP-Request/Identity to mobile 8c:70:5a:8e:09:40 (EAP Id 2)

*Dot1x_NW_MsgTask_0: Oct 24 10:20:48.044: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:48.044: 8c:70:5a:8e:09:40 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile 8c:70:5a:8e:09:40

*Dot1x_NW_MsgTask_0: Oct 24 10:20:48.049: 8c:70:5a:8e:09:40 Received EAPOL EAPPKT from mobile 8c:70:5a:8e:09:40

In the Log i will see that the EAP Request successfuly sended to the client but the Respond missmatch and after 3 times the controller will delete the client

Sometimes it works and somtimes not...

Through the troubleshooting i found some other interesting thing:

On the controller:

Oct 24 13:31:05.667 MET: ICMP: dst (10.2.128.142) frag. needed and DF set unreachable sent to 10.2.169.1

On the AccessPoint:

Oct 24 12:18:31.001: ICMP: dst (10.2.169.10) frag. needed and DF set unreachable rcv from 10.2.169.1

But i don't think thats the primary cause of the problem, because the MTU or MSS Size was never changed since 2010.

By the way, i don't understand why the client and the controller can't handle out the right MTU (ICMP is not blocking), maybe i'm on the wrong way regarding MTU, MSS and PMTU Discovery.

This error only happen in the Wireless interface i don't see it for other networks... and the log message are on all branch routers...

It would be great to hear somthing from somewhere who can help me to understand or to solve the problem

Many thanks for a reply!

Best regards
Kevin

Best regards Kevin

Joseph Vasanth Louis · ‎10-25-2013

Hi Kevin,

i see the client goes to dot1x auth reqd state and then gets deleted.

i believe the radius request does not reach the radius server? can you check the radius server if the request reaches?

is 10.2.128.142 your Radius server?

is it a consistent issue or happens once in a while? if it happens once in a while, is that the time you see the pmtu errors?

Kevin Haag · ‎10-25-2013

Hello Joseph

Thanks for reply

I've already looked at the radius server (Windows Server 2008 R2) and don't found any Event Log that seams have not todo with the problem.

A possible reason only can be that the server has to long to send an reply...

Strange is that some times the client's can auth without problems and sometimes they get an timeout message...

No 10.2.128.142, 10.2.128.144 are the ap-manager adress of the WLC and 10.2.128.241, 10.2.128.243 are the adresses for management (SSH, GUI)

The WLC can connect the radius server over an firewall, on the firewall i don't see any deny between the wlc and the radius server and additionally i don't made any changes on the radius server, firewall or wlc...

We hear about many users who have problems with the wireless so i think it happens constant, the pmtu errors happen in equal intervals (look likes an update from the controller or ap (heartbeat etc.)

I don't think there is an relation between the pmtu and eap, because i think an eap req can not contain so many data for an fragmentation, or am I wrong ?

Best regards
Kevin

Best regards Kevin

David Watkins · ‎03-20-2014

You may want to adjust EAP timers as George suggested, however when I look at the debug, first the WLC sends an Identity request (ID=1). The Client immediatley sends an EAPOL-Start to that. That's no big deal, it just means the supplicant has started the EAPOL exhange, therefore the WLC then sends another Identity Request (ID=2). This would be the point that your client sends an EAPOL-Response, ie. the debug would indicate EAPOL-Packet received from client station, however it simply receives a new EAPOL-Start.

The supplicant seems to be acting problematic or you simply have something wrong "over the air" that's causing these EAPOL exchanges to not be heard on either end.

I would start by updating your device drivers and supplicant software. For instance, if you are using Intel, make sure you are using the latest driver and version of ProSet supplicant software. Another "test" would be to change the supplicant software you are using, such as not using Intel ProSet or whatever supplicant you have and simply connect via the native Wireless Zero Config of Windows.

George Stefanick · ‎10-27-2013

Kevin

You may look at adjusting the eap timers .. Read this link

https://supportforums.cisco.com/docs/DOC-12110

Sent from Cisco Technical Support iPad App

"Satisfaction does not come from knowing the solution, it comes from knowing why." - Rosalind Franklin
___________________________________________________________

Kevin Haag · ‎10-30-2013

Hi George

Thanks for your reply!

Now we restarted the WLC's and it seams the problem is solved, but we don't no why :S

I would think about your tip with adjusting the MTU size of the EAP packet... I hope it solves the problem with the to big packets...

Best regards
Kevin

Best regards Kevin