Iphones not connecting automatically following 4402 IOS upgrade.

[jcroft]

Upgraded to 7.0.98.218 from 7.0.98.0 to clear up a couple of bugs. Since the upgrade The iphone and other smartphone users are complaining that they have to manually connected to an SSID that their phone has already learned and is configured to connect automatically. Is this a bug with the version? This issue started almost immediately following the upgrade. Any feedback or a nudge in the right direction would be most appreciated.

[Surendra BG]

Please run the debug on the WLC and paste it here..

debug client

ex - debug client XX:XX:XX:XX:XX

Regards

Surendra

[jcroft]

this is initial response

(Cisco Controller) >debug client 98:03:d8:e5:0e:d1

(Cisco Controller) >*spamReceiveTask: Aug 02 12:23:07.443: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:23:37.239: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:23:42.079: CCKM: Send CCKM cache entry

*apfMsConnTask_0: Aug 02 12:23:46.883: Deleting the client immediatly since WLAN is changed

I then hit Forget this Network and reassociated and logged in with credentials.

(Cisco Controller) >

(Cisco Controller) >debug client 98:03:d8:e5:0e:d1

(Cisco Controller) >*spamReceiveTask: Aug 02 12:23:51.378: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:24:12.044: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:24:55.690: CCKM: Send CCKM cache entry

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 Association received from mobile on AP 00:22:55:75:09:90

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 Applying site-specific IPv6 override for station 98:03:d8:e5:0e:d1 - vapId 4, site 'default-group', interface 'wl-abcd'

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 Applying IPv6 Interface Policy for station 98:03:d8:e5:0e:d1 - vlan 10, interface id 10, interface 'wl-abcd'

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 STA - rates (8): 2 4 11 150 36 48 72 108 12 18 24 96 0 0 0 0

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 STA - rates (12): 2 4 11 150 36 48 72 108 12 18 24 96 0 0 0 0

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 Processing RSN IE type 48, length 20 for mobile 98:03:d8:e5:0e:d1

*apfMsConnTask_0: Aug 02 12:24:58.997: 98:03:d8:e5:0e:d1 Received RSN IE with 0 PMKIDs from mobile 98:03:d8:e5:0e:d1

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Deleted mobile LWAPP rule on AP [00:22:55:73:c1:d0]

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 Updated location for station old AP 00:22:55:73:c1:d0-0, new AP 00:22:55:75:09:90-0

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 apfMsRunStateDec

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 apfMs1xStateDec

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 10.100.10.65 START (0) Initializing policy

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 10.100.10.65 START (0) Change state to AUTHCHECK (2) last state RUN (20)

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 10.100.10.65 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:22:55:75:09:90 vapId 4 apVapId 4

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 apfPemAddUser2 (apf_policy.c:222) Changing state for mobile 98:03:d8:e5:0e:d1 on AP 00:22:55:75:09:90 from Associated to Associated

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 Sending Assoc Response to station on BSSID 00:22:55:75:09:90 (status 0) ApVapId 4 Slot 0

*apfMsConnTask_0: Aug 02 12:24:58.998: 98:03:d8:e5:0e:d1 apfProcessAssocReq (apf_80211.c:4672) Changing state for mobile 98:03:d8:e5:0e:d1 on AP 00:22:55:75:09:90 from Associated to Associated

*dot1xMsgTask: Aug 02 12:24:59.010: 98:03:d8:e5:0e:d1 Disable re-auth, use PMK lifetime.

*pemReceiveTask: Aug 02 12:24:59.010: 98:03:d8:e5:0e:d1 10.100.10.65 Removed NPU entry.

*dot1xMsgTask: Aug 02 12:24:59.011: 98:03:d8:e5:0e:d1 dot1x - moving mobile 98:03:d8:e5:0e:d1 into Connecting state

*dot1xMsgTask: Aug 02 12:24:59.014: 98:03:d8:e5:0e:d1 Sending EAP-Request/Identity to mobile 98:03:d8:e5:0e:d1 (EAP Id 1)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.056: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.057: 98:03:d8:e5:0e:d1 Received Identity Response (count=1) from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.057: 98:03:d8:e5:0e:d1 EAP State update from Connecting to Authenticating for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.057: 98:03:d8:e5:0e:d1 dot1x - moving mobile 98:03:d8:e5:0e:d1 into Authenticating state

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.057: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.342: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.342: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=2) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.342: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 2)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.366: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.366: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 2, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.366: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.367: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.368: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=3) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.368: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 3)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.372: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.373: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 3, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.373: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.374: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.374: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=4) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.374: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 4)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.382: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.382: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 4, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.382: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.383: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.383: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=5) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.384: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 5)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.389: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.389: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 5, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.389: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.390: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.391: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=6) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.391: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 6)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.428: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.428: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 6, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.428: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.430: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.431: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=7) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:24:59.431: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 7)

*spamReceiveTask: Aug 02 12:25:05.099: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:25:06.034: CCKM: Send CCKM cache entry

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 Association received from mobile on AP 00:22:55:73:c1:d0

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 Applying site-specific IPv6 override for station 98:03:d8:e5:0e:d1 - vapId 4, site 'default-group', interface 'wl-abcd'

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 Applying IPv6 Interface Policy for station 98:03:d8:e5:0e:d1 - vlan 10, interface id 10, interface 'wl-abcd'

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 STA - rates (8): 2 4 11 150 36 48 72 108 12 18 24 96 0 0 0 0

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 STA - rates (12): 2 4 11 150 36 48 72 108 12 18 24 96 0 0 0 0

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 Processing RSN IE type 48, length 20 for mobile 98:03:d8:e5:0e:d1

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 Received RSN IE with 0 PMKIDs from mobile 98:03:d8:e5:0e:d1

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Deleted mobile LWAPP rule on AP [00:22:55:75:09:90]

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 Updated location for station old AP 00:22:55:75:09:90-0, new AP 00:22:55:73:c1:d0-0

*apfMsConnTask_0: Aug 02 12:25:09.980: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Initializing policy

*apfMsConnTask_0: Aug 02 12:25:09.981: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Change state to AUTHCHECK (2) last state RUN (20)

*apfMsConnTask_0: Aug 02 12:25:09.981: 98:03:d8:e5:0e:d1 10.100.10.65 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)

*apfMsConnTask_0: Aug 02 12:25:09.981: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:22:55:73:c1:d0 vapId 4 apVapId 4

*apfMsConnTask_0: Aug 02 12:25:09.981: 98:03:d8:e5:0e:d1 apfPemAddUser2 (apf_policy.c:222) Changing state for mobile 98:03:d8:e5:0e:d1 on AP 00:22:55:73:c1:d0 from Associated to Associated

*apfMsConnTask_0: Aug 02 12:25:09.981: 98:03:d8:e5:0e:d1 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Aug 02 12:25:09.981: 98:03:d8:e5:0e:d1 Sending Assoc Response to station on BSSID 00:22:55:73:c1:d0 (status 0) ApVapId 4 Slot 0

*apfMsConnTask_0: Aug 02 12:25:09.981: 98:03:d8:e5:0e:d1 apfProcessAssocReq (apf_80211.c:4672) Changing state for mobile 98:03:d8:e5:0e:d1 on AP 00:22:55:73:c1:d0 from Associated to Associated

*dot1xMsgTask: Aug 02 12:25:09.983: 98:03:d8:e5:0e:d1 Disable re-auth, use PMK lifetime.

*dot1xMsgTask: Aug 02 12:25:09.983: 98:03:d8:e5:0e:d1 dot1x - moving mobile 98:03:d8:e5:0e:d1 into Connecting state

*dot1xMsgTask: Aug 02 12:25:09.983: 98:03:d8:e5:0e:d1 Sending EAP-Request/Identity to mobile 98:03:d8:e5:0e:d1 (EAP Id 1)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.006: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.007: 98:03:d8:e5:0e:d1 Received Identity Response (count=1) from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.007: 98:03:d8:e5:0e:d1 EAP State update from Connecting to Authenticating for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.007: 98:03:d8:e5:0e:d1 dot1x - moving mobile 98:03:d8:e5:0e:d1 into Authenticating state

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.008: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*spamReceiveTask: Aug 02 12:25:10.135: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:25:10.261: CCKM: Send CCKM cache entry

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.353: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.354: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=2) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.354: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 2)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.376: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.376: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 2, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.377: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.378: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.378: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=3) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.378: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 3)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.383: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.383: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 3, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.383: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.384: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.385: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=4) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.385: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 4)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.391: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.391: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 4, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.391: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.392: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.393: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=5) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.393: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 5)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.398: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.398: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 5, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.398: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.399: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.399: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=6) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.399: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 6)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.433: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.434: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 6, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.434: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.436: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.436: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=7) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.436: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 7)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.472: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.472: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 7, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.472: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.473: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.474: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=8) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.474: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 8)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.487: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.487: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 8, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.487: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.489: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.489: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=9) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.489: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 9)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.494: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.494: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 9, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.494: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.497: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.498: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=10) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.498: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 10)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.502: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.502: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 10, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.503: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.504: 98:03:d8:e5:0e:d1 Processing Access-Challenge for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.504: 98:03:d8:e5:0e:d1 Entering Backend Auth Req state (id=11) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.505: 98:03:d8:e5:0e:d1 Sending EAP Request from AAA to mobile 98:03:d8:e5:0e:d1 (EAP Id 11)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.509: 98:03:d8:e5:0e:d1 Received EAPOL EAPPKT from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.510: 98:03:d8:e5:0e:d1 Received EAP Response from mobile 98:03:d8:e5:0e:d1 (EAP Id 11, EAP Type 25)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.510: 98:03:d8:e5:0e:d1 Entering Backend Auth Response state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.512: 98:03:d8:e5:0e:d1 Processing Access-Accept for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513: 98:03:d8:e5:0e:d1 Setting re-auth timeout to 0 seconds, got from WLAN config.

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513: 98:03:d8:e5:0e:d1 Station 98:03:d8:e5:0e:d1 setting dot1x reauth timeout = 0

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513: 98:03:d8:e5:0e:d1 Stopping reauth timeout for 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513: 98:03:d8:e5:0e:d1 Creating a PKC PMKID Cache entry for station 98:03:d8:e5:0e:d1 (RSN 2)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513: 98:03:d8:e5:0e:d1 Adding BSSID 00:22:55:73:c1:d3 to PMKID cache for station 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513:      [0000] 6e 6c db 0b 0d a1 e6 f6 dd 3c dd 1f cc eb fb 24

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.513: 98:03:d8:e5:0e:d1 Disabling re-auth since PMK lifetime can take care of same.

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.514: 98:03:d8:e5:0e:d1 PMK sent to mobility group

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.514: 98:03:d8:e5:0e:d1 Sending EAP-Success to mobile 98:03:d8:e5:0e:d1 (EAP Id 12)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.514: Including PMKID in M1  (16)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.515:      [0000] 6e 6c db 0b 0d a1 e6 f6 dd 3c dd 1f cc eb fb 24

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.515: 98:03:d8:e5:0e:d1 Starting key exchange to mobile 98:03:d8:e5:0e:d1, data packets will be dropped

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.515: 98:03:d8:e5:0e:d1 Sending EAPOL-Key Message to mobile 98:03:d8:e5:0e:d1

                                                                                                                    state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.515: 98:03:d8:e5:0e:d1 Entering Backend Auth Success state (id=12) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.515: 98:03:d8:e5:0e:d1 Received Auth Success while in Authenticating state for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:10.515: 98:03:d8:e5:0e:d1 dot1x - moving mobile 98:03:d8:e5:0e:d1 into Authenticated state

*osapiBsnTimer: Aug 02 12:25:11.417: 98:03:d8:e5:0e:d1 802.1x 'timeoutEvt' Timer expired for station 98:03:d8:e5:0e:d1

*dot1xMsgTask: Aug 02 12:25:11.417: 98:03:d8:e5:0e:d1 Retransmit 1 of EAPOL-Key M1 (length 121) for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.530: 98:03:d8:e5:0e:d1 Received EAPOL-Key from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.530: 98:03:d8:e5:0e:d1 Received EAPOL-key in PTK_START state (message 2) from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.530: 98:03:d8:e5:0e:d1 Stopping retransmission timer for mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.530: 98:03:d8:e5:0e:d1 Sending EAPOL-Key Message to mobile 98:03:d8:e5:0e:d1

                                                                                                                    state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.02

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.536: 98:03:d8:e5:0e:d1 Received EAPOL-Key from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.536: 98:03:d8:e5:0e:d1 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 98:03:d8:e5:0e:d1

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.536: 98:03:d8:e5:0e:d1 apfMs1xStateInc

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.536: 98:03:d8:e5:0e:d1 10.100.10.65 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.537: 98:03:d8:e5:0e:d1 10.100.10.65 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:22:55:73:c1:d0 vapId 4 apVapId 4

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.537: 98:03:d8:e5:0e:d1 apfMsRunStateInc

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.537: 98:03:d8:e5:0e:d1 10.100.10.65 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.539: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Reached PLUMBFASTPATH: from line 4605

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.539: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Adding Fast Path rule

  type = Airespace AP Client

  on AP 00:22:55:73:c1:d0, slot 0, interface = 1, QOS = 0

  ACL Id = 255, Jumbo Frames = NO

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.539: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 5006  IPv6 Vlan = 10, IPv6 intf id = 10

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.539: 98:03:d8:e5:0e:d1 10.100.10.65 RUN (20) Successfully plumbed mobile rule (ACL ID 255)

*Dot1x_NW_MsgTask_0: Aug 02 12:25:11.539: 98:03:d8:e5:0e:d1 Stopping retransmission timer for mobile 98:03:d8:e5:0e:d1

*pemReceiveTask: Aug 02 12:25:11.544: 98:03:d8:e5:0e:d1 10.100.10.65 Added NPU entry of type 1, dtlFlags 0x0

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.685: 98:03:d8:e5:0e:d1 DHCP received op BOOTREQUEST (1) (len 308,vlan 0, port 1, encap 0xec03)

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.685: 98:03:d8:e5:0e:d1 DHCP selecting relay 1 - control block settings:

                        dhcpServer: 10.1.1.191, dhcpNetmask: 255.255.254.0,

                        dhcpGateway: 10.100.10.1, dhcpRelay: 10.100.10.5  VLAN: 10

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.685: 98:03:d8:e5:0e:d1 DHCP selected relay 1 - 10.1.1.191 (local address 10.100.10.5, gateway 10.100.10.1, VLAN 10, port 1)

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.685: 98:03:d8:e5:0e:d1 DHCP transmitting DHCP REQUEST (3)

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.685: 98:03:d8:e5:0e:d1 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.685: 98:03:d8:e5:0e:d1 DHCP   xid: 0x16f1fa63 (384957027), secs: 0, flags: 0

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.685: 98:03:d8:e5:0e:d1 DHCP   chaddr: 98:03:d8:e5:0e:d1

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.686: 98:03:d8:e5:0e:d1 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.686: 98:03:d8:e5:0e:d1 DHCP   siaddr: 0.0.0.0,  giaddr: 10.100.10.5

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.686: 98:03:d8:e5:0e:d1 DHCP   requested ip: 10.100.10.65

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.686: 98:03:d8:e5:0e:d1 DHCP sending REQUEST to 10.100.10.1 (len 350, port 1, vlan 10)

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.686: 98:03:d8:e5:0e:d1 DHCP selecting relay 2 - control block settings:

                        dhcpServer: 10.1.1.191, dhcpNetmask: 255.255.254.0,

                        dhcpGateway: 10.100.10.1, dhcpRelay: 10.100.10.5  VLAN: 10

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.686: 98:03:d8:e5:0e:d1 DHCP selected relay 2 - NONE

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.687: 98:03:d8:e5:0e:d1 DHCP received op BOOTREPLY (2) (len 318,vlan 10, port 1, encap 0xec00)

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.687: 98:03:d8:e5:0e:d1 DHCP sending REPLY to STA (len 426, port 1, vlan 2)

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.688: 98:03:d8:e5:0e:d1 DHCP transmitting DHCP ACK (5)

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.688: 98:03:d8:e5:0e:d1 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.688: 98:03:d8:e5:0e:d1 DHCP   xid: 0x16f1fa63 (384957027), secs: 0, flags: 0

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.688: 98:03:d8:e5:0e:d1 DHCP   chaddr: 98:03:d8:e5:0e:d1

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.688: 98:03:d8:e5:0e:d1 DHCP   ciaddr: 0.0.0.0,  yiaddr: 10.100.10.65

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.688: 98:03:d8:e5:0e:d1 DHCP   siaddr: 0.0.0.0,  giaddr: 0.0.0.0

*DHCP Proxy DTL Recv Task: Aug 02 12:25:11.688: 98:03:d8:e5:0e:d1 DHCP   server id: 1.1.1.1  rcvd server id: 10.1.1.191

*spamReceiveTask: Aug 02 12:25:15.908: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:25:23.023: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:25:24.970: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:26:58.867: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:27:40.165: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:27:54.721: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:28:03.503: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:28:07.590: CCKM: Send CCKM cache entry

*spamReceiveTask: Aug 02 12:28:40.175: CCKM: Send CCKM cache entry

[Leo Laohoo]

Try using WPA OR WPA2 only.  Don't use both and rely on the smartphones to choose which ones they'll try.

[romainpage]

Hi,

Any solution found to that issue ? I am having similar issue with 4400 controller in 7.0.116 version.

Thanks for the help.

Best regards.

Romain

[jcroft]

Unfortunatley for the time being I can't do that. This SSID also supports laptops and some are older machines that only have WPA as an option.

I am curious about the CCKM calls here and mine is disabled

CCKM: Send CCKM cache entry

[jcroft]

Another thing I discovered today. My RADIUS server timeouts have been 5 seconds for over 2 years on all the previous versions. I noticed today that they are defaulted to back to the 2 second timeout. I originally opened this up to accomodate a bunch of crappy Avaya 3631 phones that were having issues (not my choice of phones). They still have a number of issues but unrelated to wireless. When I sent to change the timeouts using the WCS template to make the change to all my controllers it wiped out my RADIUS server secret password. I have never seen such of number of issues in any WLC version since I upgraded to 7.0.98.218. I am actually considering going back to 7.0.98.0 till Cisco comes up with something else. Actually I am pretty disappointed in the whole 7.0 train as a whole.

[jcroft]

I am moving back to 6.0.202.0 Monday night. This 7.0.98 crap is the worst IOS I have ever seen. Reminds me of the nightmare 12.1 issues in the 3600 routers a few years back.