Mobility Express SSID mistake when APs reboot

[bulentkeser]

Hı,

We use 1830 series Mobility Express when AP s reboot apple phones and Ipads try to connect SSID it took wrong password mistake. I opened debug for one of this client and took this logs. When I change anything on SSID all device connected successfully.

*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d In processSsidIE:6954 setting Central switched to FALSE
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d Set Client MSCB as Central Association Disabled
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d Applying site-specific Local Bridging override for station bc:e1:43:4a:57:8d - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d Applying Local Bridging Interface Policy for station bc:e1:43:4a:57:8d - vlan 0, interface id 0, interface 'management', nasId:''
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d Set Client Non AP specific Flexgroup apfMsAccessVlan = 1
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d This apfMsAccessVlan may be changed later from AAA after L2 Auth
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d Cleared localSwitchingVlan, may be assigned later based on AAA override
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_0: Mar 22 14:41:22.751: bc:e1:43:4a:57:8d processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d STA - rates (8): 140 18 152 36 176 72 96 108 0 0 0 0 0 0 0 0
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Marking this mobile as TGr capable.
*apfMsConnTask_0: Mar 22 14:41:22.752: RSNIE in Assoc. Req.: (20)

*apfMsConnTask_0: Mar 22 14:41:22.752: [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_0: Mar 22 14:41:22.752: [0016] ac 04 0c 00

*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Processing RSN IE type 48, length 20 for mobile bc:e1:43:4a:57:8d
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d RSN Capabilities: 12
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d non-11w Capable mobile
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Received RSN IE with 0 PMKIDs from mobile bc:e1:43:4a:57:8d
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Validating FT AKM's on WLAN
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d FT AKM Negotiated. Setting adaptive AKM 4 into RSN Data at 19

*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Assigning flex webauth ACL ID :65535 for vlan : 1
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Updating AID for REAP AP Client 70:f3:5a:a8:d0:80 - AID ===> 3
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d apfVapSecurity=0x40004000 L2=16384 SkipWeb=0
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d AuthenticationRequired = 1
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Encryption policy is set to 0x80000001
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d 0.0.0.0 8021X_REQD (3) DHCP required on AP 70:f3:5a:a8:d0:80 vapId 1 apVapId 1for this client
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d flex webauth acl id to be sent :65535 name : client acl id : 65535
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d Vlan while overriding the policy = -1
*apfMsConnTask_0: Mar 22 14:41:22.752: bc:e1:43:4a:57:8d sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535

*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 70:f3:5a:a8:d0:80 vapId 1 apVapId 1 flex-acl-name:
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d apfPemAddUser2 (apf_policy.c:423) Changing state for mobile bc:e1:43:4a:57:8d on AP 70:f3:5a:a8:d0:80 from Associated to Associated

*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d apfPemAddUser2:session timeout forstation bc:e1:43:4a:57:8d - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Sending assoc-resp with status 0 station:bc:e1:43:4a:57:8d AP:70:f3:5a:a8:d0:8f-01 on apVapId 1
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d VHT Operation IE: width 80/1 ch 36 freq0 42 freq1 0 msc0 0x3f msc1 0x3f
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Including FT Mobility Domain IE (length 5) in Initial assoc Resp to mobile
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Sending R1KH-ID as 70:6b:b9:78:62:40
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Sending R0KH-ID as:192.168.1.250
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Including FT IE (length 98) in Initial Assoc Resp to mobile
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Clearing the existing FT session data for mobile as we received a fresh Association.
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d Sending Assoc Response (status: '0') to station on AP AP70F3.5AA8.19C8 on BSSID 70:f3:5a:a8:d0:8f ApVapId 1 Slot 1, mobility role 0
*apfMsConnTask_0: Mar 22 14:41:22.753: bc:e1:43:4a:57:8d apfProcessAssocReq (apf_80211.c:11962) Changing state for mobile bc:e1:43:4a:57:8d on AP 70:f3:5a:a8:d0:80 from Associated to Associated

*spamApTask0: Mar 22 14:41:22.754: bc:e1:43:4a:57:8d Add SGT:0 to AP 70:f3:5a:a8:d0:80
*spamApTask0: Mar 22 14:41:22.754: bc:e1:43:4a:57:8d Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0
*spamApTask0: Mar 22 14:41:22.754: bc:e1:43:4a:57:8d Successful transmission of LWAPP Add-Mobile to AP 70:f3:5a:a8:d0:80
*spamApTask0: Mar 22 14:41:22.754: bc:e1:43:4a:57:8d Setting ADD_MOBILE (idx 0, seqno 0, action 1, count 588234289) ack state for STA on AP 70:f3:5a:a8:d0:80
*spamApTask0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d Received ADD_MOBILE ack - Initiating 1x to STA bc:e1:43:4a:57:8d (idx 86)
*spamApTask0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d APF Initiating 1x to STA bc:e1:43:4a:57:8d
*spamApTask0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d Sent dot1x auth initiate message for mobile bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d dot1xProcessInitiate1XtoMobile to mobile station bc:e1:43:4a:57:8d (mscb 2, msg 2)
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d reauth_sm state transition 0 ---> 1 for mobile bc:e1:43:4a:57:8d at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d Normal psk client, full auth
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d Created PKC PMK Cache entry for station bc:e1:43:4a:57:8d (RSN 2)
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d Resetting MSCB PMK Cache Entry @index 0 for station bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.769: bc:e1:43:4a:57:8d Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Created PMKID PMK Cache for BSSID 70:f3:5a:a8:d0:8f at index 0 for station bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: [0000] 94 85 e6 a5 14 c6 fd d2 da e7 3f 73 e2 4c 70 1d

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Creating global PMK cache for this TGr client
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Created PMK Cache Entry for TGr AKM:PSK bc:e1:43:4a:57:8d

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d R0KH-ID:192.168.1.250 R1KH-ID:70:6b:b9:78:62:40 MSK Len:48
pmkValidTime:86415

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d apfCreatePmkCacheEntry: added a new pmk cache entry for bc:e1:43:4a:57:8d

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Adding Audit session ID payload in Mobility handoff

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d 0 PMK-update groupcast messages sent
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d EAP-PARAM Debug - eap-params for Wlan-Id :1 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d dot1x - moving mobile bc:e1:43:4a:57:8d into Force Auth state
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Skipping EAP-Success to mobile bc:e1:43:4a:57:8d (encryptBit:0)
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d key Desc Version FT - 1

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Found an cache entry for BSSID 70:f3:5a:a8:d0:8f in PMKID cache at index 0 of station bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Found an cache entry for BSSID 70:f3:5a:a8:d0:8f in PMKID cache at index 0 of station bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: [0000] 94 85 e6 a5 14 c6 fd d2 da e7 3f 73 e2 4c 70 1d

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: M1 - Key Data: (22)

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: [0000] dd 14 00 0f ac 04 94 85 e6 a5 14 c6 fd d2 da e7

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: [0016] 3f 73 e2 4c 70 1d

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Starting key exchange to mobile bc:e1:43:4a:57:8d, data packets will be dropped
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.770: bc:e1:43:4a:57:8d Sending EAPOL-Key Message to mobile bc:e1:43:4a:57:8d
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.771: bc:e1:43:4a:57:8d Allocating EAP Pkt for retransmission to mobile bc:e1:43:4a:57:8d
*CAPWAP DATA: Mar 22 14:41:22.776: bc:e1:43:4a:57:8d validating eapol pkt: key version = 3
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: bc:e1:43:4a:57:8d Received EAPOL-Key from mobile bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: bc:e1:43:4a:57:8d key Desc Version FT - 1

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: bc:e1:43:4a:57:8d Received EAPOL-key in PTK_START state (message 2) from mobile bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: bc:e1:43:4a:57:8d Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: R1KHID+S1KHID: (12)

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: [0000] 70 6b b9 78 62 40 bc e1 43 4a 57 8d

*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: bc:e1:43:4a:57:8d Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_0: Mar 22 14:41:22.776: bc:e1:43:4a:57:8d Received EAPOL-key M2 with invalid MIC from mobile bc:e1:43:4a:57:8d version 3
*osapiBsnTimer: Mar 22 14:41:23.764: bc:e1:43:4a:57:8d 802.1x 'timeoutEvt' Timer expired for station bc:e1:43:4a:57:8d and for message = M2
*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.764: bc:e1:43:4a:57:8d Retransmit 1 of EAPOL-Key M1 (length 121) for mobile bc:e1:43:4a:57:8d
*CAPWAP DATA: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d validating eapol pkt: key version = 3
*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d Received EAPOL-Key from mobile bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d key Desc Version FT - 1

*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d Received EAPOL-key in PTK_START state (message 2) from mobile bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: R1KHID+S1KHID: (12)

*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: [0000] 70 6b b9 78 62 40 bc e1 43 4a 57 8d

*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d Received EAPOL-key M2 with invalid MIC from mobile bc:e1:43:4a:57:8d version 3
*osapiBsnTimer: Mar 22 14:41:24.756: bc:e1:43:4a:57:8d 802.1x 'timeoutEvt' Timer expired for station bc:e1:43:4a:57:8d and for message = M2
*Dot1x_NW_MsgTask_0: Mar 22 14:41:24.756: bc:e1:43:4a:57:8d Retransmit 2 of EAPOL-Key M1 (length 121) for mobile bc:e1:43:4a:57:8d
*CAPWAP DATA: Mar 22 14:41:24.762: bc:e1:43:4a:57:8d validating eapol pkt: key version = 3
*Dot1x_NW_MsgTask_0: Mar 22 14:41:24.762: bc:e1:43:4a:57:8d Received EAPOL-Key from mobile bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:24.762: bc:e1:43:4a:57:8d key Desc Version FT - 1

*Dot1x_NW_MsgTask_0: Mar 22 14:41:24.762: bc:e1:43:4a:57:8d Received EAPOL-key in PTK_START state (message 2) from mobile bc:e1:43:4a:57:8d
*Dot1x_NW_MsgTask_0: Mar 22 14:41:24.762: bc:e1:43:4a:57:8d Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_0: Mar 22 14:41:24.763: R1KHID+S1KHID: (12)

*Dot1x_NW_MsgTask_0: Mar 22 14:41:24.763: [0000] 70 6b b9 78 62 40 bc e1 43 4a 57 8d

[Ric Beeching]

I think you're going to need to elaborate a bit further one what is occurring:

1) iPhone joined to ME AP SSID
2) ME AP is rebooted
3) iPhone disconnects until ME AP reboots then cannot join SSID
4) You make a change on SSID and iPhone can connect

Does that sound right..?

[bulentkeser]

Yes, it's definitely correct.

[Ric Beeching]

What version of ME software are you running? Go for 8.5.140.0 or 8.8.111.0 if not already on it.

https://www.cisco.com/c/en/us/support/docs/wireless/wireless-lan-controller-software/200046-tac-recommended-aireos.html#anc12

If you are, please attach a copy of your config. Does the issue affect just iPhones or other device types?
Ric

[bulentkeser]

ME software is 8.5.140. Yes, It only affects iphones and Ipads. I can't take config now. I have web interface connection.

[Ric Beeching]

It is odd, there are 3 instances of this message indicating an incorrect PSK but you're saying if you change any setting the devices can then authenticate?

*Dot1x_NW_MsgTask_0: Mar 22 14:41:23.769: bc:e1:43:4a:57:8d Received EAPOL-key M2 with invalid MIC from mobile bc:e1:43:4a:57:8d version 3

Are you using a profile/configurator to do the iOS device configs? What happens if during the error you turn WiFi off on an iPhone/iPad and try to connect OR forget the SSID and start again?

Do you have a backup ME set as well that takes over as the controller when the first one goes down?

Ric