User switching every few minutes between 2.4ghz and 5ghz

[simon.dwyer]

Hi All,

This first started when a user said they were getting disconnected and reconnected a few times a day to our wireless network.  He is in a remote office with a 1142 which is set to H-Reap talking back to our 5508.  Our WLC is running 7.0.166

The laptop has an intel ulitmate 6300agn wireless card with the latest 15.x drivers.

We are using an SSID with wpa2 and 802.1x auth back to our ACS server using PEAP with our windows credentials.

attached is what i am seeing on the wcs troubleshooting page.

When i do a debug client on the WLC i see many reauthentications coming from the client on the different radio.

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Reassociation received from mobile on AP 0c:85:25:f3:7d:40

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c 10.24.8.108 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1621)

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Applying site-specific IPv6 override for station 00:24:d7:d1:16:6c - vapId 512, site 'VH-GasWorks', interface 'management'

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Applying IPv6 Interface Policy for station 00:24:d7:d1:16:6c - vlan 2, interface id 0, interface 'management'

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Applying site-specific override for station 00:24:d7:d1:16:6c - vapId 512, site 'VH-GasWorks', interface 'management'

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c 10.24.8.108 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1621)

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c STA - rates (8): 140 18 24 36 48 72 96 108 48 72 96 108 0 0 0 0

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Processing RSN IE type 48, length 38 for mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Received RSN IE with 1 PMKIDs from mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: Received PMKID:  (16)

*apfMsConnTask_2: Aug 22 12:59:36.762:      [0000] e0 79 8a 5f 4d 38 a0 52 b5 64 96 22 23 86 be 24

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Searching for PMKID in MSCB PMKID cache for mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c No valid PMKID found in the MSCB PMKID cache for mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Trying to compute a PMKID from MSCB PMK cache for mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: CCKM: Find PMK in cache: BSSID =  (6)

*apfMsConnTask_2: Aug 22 12:59:36.762:      [0000] 0c 85 25 f3 7d 40

*apfMsConnTask_2: Aug 22 12:59:36.762: CCKM: Find PMK in cache: realAA =  (6)

*apfMsConnTask_2: Aug 22 12:59:36.762:      [0000] 0c 85 25 f3 7d 4f

*apfMsConnTask_2: Aug 22 12:59:36.762: CCKM: Find PMK in cache: PMKID =  (16)

*apfMsConnTask_2: Aug 22 12:59:36.762:      [0000] e0 79 8a 5f 4d 38 a0 52 b5 64 96 22 23 86 be 24

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Unable to compute a valid PMKID from MSCB PMK cache for mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Searching for PMK in global PMK cache for mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: 00:24:d7:d1:16:6c Found an entry in the global PMK cache for station 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.762: CCKM: AA (6)

*apfMsConnTask_2: Aug 22 12:59:36.763:      [0000] 0c 85 25 f3 7d 4f

*apfMsConnTask_2: Aug 22 12:59:36.763: CCKM: SPA (6)

*apfMsConnTask_2: Aug 22 12:59:36.763:      [0000] 00 24 d7 d1 16 6c

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c computed a valid PMKID from global PMK cache for mobile 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c Creating a PKC PMKID Cache entry for station 00:24:d7:d1:16:6c (RSN 0) on BSSID 0c:85:25:f3:7d:4f

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c Adding BSSID 0c:85:25:f3:7d:4f to PMKID cache for station 00:24:d7:d1:16:6c

*apfMsConnTask_2: Aug 22 12:59:36.763: New PMKID: (16)

*apfMsConnTask_2: Aug 22 12:59:36.763:      [0000] e0 79 8a 5f 4d 38 a0 52 b5 64 96 22 23 86 be 24

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c 10.24.8.108 RUN (20) Deleted mobile LWAPP rule on AP [0c:85:25:f3:7d:40]

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c Updated location for station old AP 0c:85:25:f3:7d:40-0, new AP 0c:85:25:f3:7d:40-1

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c apfMsRunStateDec

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c apfMs1xStateDec

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c 10.24.8.108 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c 10.24.8.108 START (0) Initializing policy

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c 10.24.8.108 START (0) Change state to AUTHCHECK (2) last state RUN (20)

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c 10.24.8.108 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c 10.24.8.108 8021X_REQD (3) DHCP required on AP 0c:85:25:f3:7d:40 vapId 512 apVapId 1for this client

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c 10.24.8.108 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 0c:85:25:f3:7d:40 vapId 512 apVapId 1

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 00:24:d7:d1:16:6c on AP 0c:85:25:f3:7d:40 from Associated to Associated

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c Sending Assoc Response to station on BSSID 0c:85:25:f3:7d:40 (status 0) ApVapId 1 Slot 1

*apfMsConnTask_2: Aug 22 12:59:36.763: 00:24:d7:d1:16:6c apfProcessAssocReq (apf_80211.c:5241) Changing state for mobile 00:24:d7:d1:16:6c on AP 0c:85:25:f3:7d:40 from Associated to Associated

*apfMsConnTask_2: Aug 22 12:59:36.807: 00:24:d7:d1:16:6c Updating AID for REAP AP Client 0c:85:25:f3:7d:40 - AID ===> 1

*dot1xMsgTask: Aug 22 12:59:36.862: 00:24:d7:d1:16:6c Initiating RSN with existing PMK to mobile 00:24:d7:d1:16:6c

*dot1xMsgTask: Aug 22 12:59:36.862: 00:24:d7:d1:16:6c Disable re-auth, use PMK lifetime.

*dot1xMsgTask: Aug 22 12:59:36.862: 00:24:d7:d1:16:6c dot1x - moving mobile 00:24:d7:d1:16:6c into Force Auth state

*dot1xMsgTask: Aug 22 12:59:36.862: 00:24:d7:d1:16:6c Skipping EAP-Success to mobile 00:24:d7:d1:16:6c

*dot1xMsgTask: Aug 22 12:59:36.863: Including PMKID in M1  (16)

*dot1xMsgTask: Aug 22 12:59:36.863:      [0000] e0 79 8a 5f 4d 38 a0 52 b5 64 96 22 23 86 be 24

*dot1xMsgTask: Aug 22 12:59:36.863: 00:24:d7:d1:16:6c Starting key exchange to mobile 00:24:d7:d1:16:6c, data packets will be dropped

*dot1xMsgTask: Aug 22 12:59:36.863: 00:24:d7:d1:16:6c Sending EAPOL-Key Message to mobile 00:24:d7:d1:16:6c

                                                                                                              state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.912: 00:24:d7:d1:16:6c Received EAPOL-Key from mobile 00:24:d7:d1:16:6c

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.912: 00:24:d7:d1:16:6c Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:24:d7:d1:16:6c

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.912: 00:24:d7:d1:16:6c Received EAPOL-key in PTK_START state (message 2) from mobile 00:24:d7:d1:16:6c

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.912: 00:24:d7:d1:16:6c PMK: Sending cache add

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.912: 00:24:d7:d1:16:6c Stopping retransmission timer for mobile 00:24:d7:d1:16:6c

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.913: 00:24:d7:d1:16:6c Sending EAPOL-Key Message to mobile 00:24:d7:d1:16:6c

                                                                                                                    state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c Received EAPOL-Key from mobile 00:24:d7:d1:16:6c

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:24:d7:d1:16:6c

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:24:d7:d1:16:6c

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c apfMs1xStateInc

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c 10.24.8.108 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20)

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c 10.24.8.108 L2AUTHCOMPLETE (4) DHCP required on AP 0c:85:25:f3:7d:40 vapId 512 apVapId 1for this client

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c 10.24.8.108 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 0c:85:25:f3:7d:40 vapId 512 apVapId 1

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c apfMsRunStateInc

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.960: 00:24:d7:d1:16:6c 10.24.8.108 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20)

*Dot1x_NW_MsgTask_4: Aug 22 12:59:36.961: 00:24:d7:d1:16:6c 10.24.8.108 RUN (20) Reached PLUMBFASTPATH: from line 4864

Now this may be not be the issue thats causing our dropouts a couple times a day as this is happening every 5 mins.

Any ideas would be brilliant.

Simon

[Leo Laohoo]

Duplicate post #1.