Just an update to this, TAC

Vasco Costa · ‎08-21-2014

We've have a customer that has a 5760 with version 3.3.3

They were complaining that some of they wireless clients failed to roam (intra roaming). The symptoms were similar to some caveats reported on the versions 3.3.x so last Tuesday we've migrated the WLC to 3.6 but it seems that the problem got worse.

We see that sometimes, the client gets to the AP, starts the roaming process but then fails on the 4-way handshake step.

(Client begings the roaming process)

Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: Processing assoc-req station: 000e.8e35.2efc AP: c025.5ca3.f480 -00 thread:-111788424
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Adding mobile on LWAPP AP c025.5ca3.f480 (0)
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Creating WL station entry for client - rc 0
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Association received from mobile on AP c025.5ca3.f480
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc qos upstream policy is unknown and downstream policy is unknown
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc apChanged 0 wlanChanged 0 mscb ipAddr 0.0.0.0, apf RadiusOverride 0x0, numIPv6Addr=0
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying WLAN policy on MSCB.
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying WLAN ACL policies to client
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc No Interface ACL used for Wireless client in WCM(NGWC)
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying site-specific IPv6 override for station 000e.8e35.2efc - vapId 22, site 'Transformacao', interface 'AGVs'
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying local bridging Interface Policy for station 000e.8e35.2efc - vlan 22, interface 'AGVs'
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying site-specific override for station 000e.8e35.2efc - vapId 22, site 'Transformacao', interface 'AGVs'
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying local bridging Interface Policy for station 000e.8e35.2efc - vlan 22, interface 'AGVs'
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Override multicast vlan 22 to AP group vlan 22
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc STA - rates (8): 2 4 11 22 12 18 24 36 0 0 0 0 0 0 0 0
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc STA - rates (12): 2 4 11 22 12 18 24 36 48 72 96 108 0 0 0 0
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Received 802.11i PSK key management suite, enabling Authentication
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc new capwap_wtp_iif_id 5b608000001495, sm capwap_wtp_iif_id 0
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ADD: Radio IIFID 0x5004c000001496, BSSID IIF Id 0x77cd0000001498, COS 4
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: Load Balancer: Success, Resource allocated are: Active Switch number: 1, Active Asic number : 2, Reserve Switch number 2 Reserve Asic number 2. AP Asic num 2
Aug 20 19:06:16.779: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ADD: Anchor Sw 1, Doppler 2

Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ALLOCATE: Client IIF Id alloc SUCCESS w/ client 4cc0400000156b (state 0).
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc iifid Clearing Ack flag
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ADD: Platform ID allocated successfully ID:1829
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ADD: Adding opt82 len 0
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ADD: Cleaering Ack flag
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: WCDB_IIF: Ack Message ID: 0x4cc0400000156b code 1001

Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ADD: ssid AGVs bssid c025.5ca3.f480 vlan 22 auth=ASSOCIATION(0) wlan(ap-group/global) 4/22 client 0 assoc 1 mob=Unassoc(0) radio 0 m_vlan 22 ip 0.0.0.0 src 0x5b608000001495 dst 0x0 cid 0x4cc0400000156b glob rsc id 1829dhcpsrv 0.0.0.0
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_ADD: mscb iifid 0x4cc0400000156b msinfo iifid 0x0
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc 0.0.0.0 START (0) Initializing policy
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Change state to AUTHCHECK (2) last state START (0)
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Change state to 8021X_REQD (3) last state AUTHCHECK (2)
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc 0.0.0.0 8021X_REQD (3) DHCP Not required on AP c025.5ca3.f480 vapId 22 apVapId 4for this client
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Not Using WMM Compliance code qosCap 00
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c025.5ca3.f480 vapId 22 apVapId 4

Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc apfPemAddUser2 (apf_policy.c:204) Changing state for mobile 000e.8e35.2efc on AP c025.5ca3.f480 from Idle to Associated
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Reason code 0, Preset 4, AAA cause 1
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Ms Timeout = 1800, Session Timeout = 1800
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: Sending assoc-resp station: 000e.8e35.2efc AP: c025.5ca3.f480 -00 thread:-111788424
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Sending Assoc Response to station on BSSID c025.5ca3.f480 (status 0) ApVapId 4 Slot 0
WLC1#
Aug 20 19:06:16.780: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc apfProcessAssocReq (apf_80211.c:6288) Changing state for mobile 000e.8e35.2efc on AP c025.5ca3.f480 from Associated to Associated
Aug 20 19:06:16.876: %IOSXE-7-PLATFORM: 1 process wcm: LLM-SPI: local handle: 97000017, remote handle:83000007, group handle: cc000006
Aug 20 19:06:16.876: %IOSXE-7-PLATFORM: 1 process wcm: LLM-SPI: Sent LLM client Add to FED.
Aug 20 19:06:16.876: %IOSXE-7-PLATFORM: 1 process wcm: PEM recv processing msg Add SCB(3)
WLC1#

Aug 20 19:06:19.684: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Sent Deauthenticate to mobile with deauth reason code 15 on BSSID c025.5ca3.f480 slot 0(caller dot1xapi_api.c:1725)
Aug 20 19:06:19.684: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Deleting the PMK cache when de-authenticating the client.
Aug 20 19:06:19.684: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Global PMK Cache deletion failed.
Aug 20 19:06:19.684: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Reason code 0, Preset 15, AAA cause 1
WLC1#

WLC1#

And then, it remains constantly repeanting the associanto process to the AP, but always fails at the 4-way handskake process:

Aug 20 19:06:19.684: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Scheduling deletion of Mobile Station: (callerId: 7) in 10 seconds
Aug 20 19:06:19.684: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Calling SM stop unconditionally for dot1x/open ifid: 4cc0400000156b capwap id: 5b608000001495 old capwap id:0
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: Processing assoc-req station: 000e.8e35.2efc AP: c025.5ca3.f480 -00 thread:-111788424
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Association received from mobile on AP c025.5ca3.f480
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc qos upstream policy is unknown and downstream policy is unknown
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc apChanged 0 wlanChanged 0 mscb ipAddr 0.0.0.0, apf RadiusOverride 0x0, numIPv6Addr=0
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying WLAN policy on MSCB.
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying WLAN ACL policies to client
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc No Interface ACL used for Wireless client in WCM(NGWC)
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying site-specific IPv6 override for station 000e.8e35.2efc - vapId 22, site 'Transformacao', interface 'AGVs'
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying local bridging Interface Policy for station 000e.8e35.2efc - vlan 22, interface 'AGVs'
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying site-specific override for station 000e.8e35.2efc - vapId 22, site 'Transformacao', interface 'AGVs'
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Applying local bridging Interface Policy for station 000e.8e35.2efc - vlan 22, interface 'AGVs'
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Override multicast vlan 22 to AP group vlan 22
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc STA - rates (8): 2 4 11 22 12 18 24 36 48 72 96 108 0 0 0 0
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc STA - rates (12): 2 4 11 22 12 18 24 36 48 72 96 108 0 0 0 0
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Received 802.11i PSK key management suite, enabling Authentication
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc new capwap_wtp_iif_id 5b608000001495, sm capwap_wtp_iif_id 0
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_CHANGE: Client 1 vlan 22 m_vlan 22 Radio iif id 0x5004c000001496 bssid iif id 0x77cd0000001498, bssid c025.5ca3.f480
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_AUTH: Adding opt82 len 0
Aug 20 19:06:20.810: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_LLM: NoRun Prev Mob 0, Curr Mob 0 llmReq 1, return False
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc auth state 0 mob state 0 setWme 0 wme 1 roam_sent 0
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc WCDB_CHANGE: auth=ASSOCIATION(0) vlan 22 radio 0 client_id 0x4cc0400000156b mobility=Unassoc(0) src_int 0x5b608000001495 dst_int 0x0 ackflag 0 reassoc_client 0 llm_notif 0 ip 0.0.0.0 ip_learn_type 0
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc 0.0.0.0 8021X_REQD (3) Initializing policy
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Change state to AUTHCHECK (2) last state 8021X_REQD (3)
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Change state to 8021X_REQD (3) last state AUTHCHECK (2)
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc 0.0.0.0 8021X_REQD (3) DHCP Not required on AP c025.5ca3.f480 vapId 22 apVapId 4for this client
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Not Using WMM Compliance code qosCap 00
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c025.5ca3.f480 vapId 22 apVapId 4
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc apfPemAddUser2 (apf_policy.c:204) Changing state for mobile 000e.8e35.2efc on AP c025.5ca3.f480 from Associated to Associated
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Reason code 0, Preset 4, AAA cause 1
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds
WLC1#
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Ms Timeout = 1800, Session Timeout = 1800
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: Sending assoc-resp station: 000e.8e35.2efc AP: c025.5ca3.f480 -00 thread:-111788424
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Sending Assoc Response to station on BSSID c025.5ca3.f480 (status 0) ApVapId 4 Slot 0
Aug 20 19:06:20.811: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc apfProcessAssocReq (apf_80211.c:6288) Changing state for mobile 000e.8e35.2efc on AP c025.5ca3.f480 from Associated to Associated
Aug 20 19:06:21.381: %IOSXE-7-PLATFORM: 1 process wcm: Processing assoc-req station: 289a.fa04.ffe3 AP: c025.5c68.4e30 -00 thread:-111787536
Aug 20 19:06:21.381: %IOSXE-7-PLATFORM: 1 process wcm: Sending assoc-resp station: 289a.fa04.ffe3 AP: c025.5c68.4e30 -00 thread:-111787536
Aug 20 19:06:21.381: %IOSXE-7-PLATFORM: 1 process wcm: PEM recv processing msg Del SCB(4)
Aug 20 19:06:21.554: %IOSXE-7-PLATFORM: 1 process wcm: LLM-SPI: local handle: 97000017, remote handle:83000007, group handle: cc000006
Aug 20 19:06:21.554: %IOSXE-7-PLATFORM: 1 process wcm: LLM-SPI: Sent LLM client Add to FED.
WLC1#
Aug 20 19:06:21.555: %IOSXE-7-PLATFORM: 1 process wcm: PEM recv processing msg Add SCB(3)
WLC1#
Aug 20 19:06:23.651: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Sent Deauthenticate to mobile with deauth reason code 15 on BSSID c025.5ca3.f480 slot 0(caller dot1xapi_api.c:1725)
Aug 20 19:06:23.651: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Deleting the PMK cache when de-authenticating the client.
Aug 20 19:06:23.651: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Global PMK Cache deletion failed.
Aug 20 19:06:23.651: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Reason code 0, Preset 15, AAA cause 1
Aug 20 19:06:23.651: %IOSXE-7-PLATFORM: 1 process wcm: 000e.8e35.2efc Scheduling deletion of Mobile Station: (callerId: 7) in 10 seconds
WLC1#

There are more WLANs configured on the network but those are 802.1x, authenticated by an ISE.

Any thoughts of what might be causing the 4-way handshake problem?

Thoes anyone migrated their WLC 5760 to 3.6 and how did the PSK wlans coped with that?

Kind regards,

Vasco

Cheers,
Vasco

Rasika Nayanajith · ‎08-21-2014

Yes, Reason code 15 is "4 way handshake timeout" for deatuthentication. See below.

https://supportforums.cisco.com/document/141136/80211-association-status-80211-deauth-reason-codes

what is the output "show run | sec wlan <PSK-WLAN>" looks like.

Have you gone to TAC yet ? I think it is better get their input

HTH

Rasika

**** Pls rate all useful responses ****

Vasco Costa · ‎08-22-2014

Hi Rasika,

Thanks for the input.

The customer is a factory and we need to provided a solution ASAP so we've downgraded the secondary WLC 5760 to version 3.3.3.

Also, i've took out the session-timeout parameter on both WLANs

WLC1#sh run | sec wlan AGVs
wlan AGVs 22 AGVs
no broadcast-ssid
client vlan 22
no mobility anchor sticky
no security wpa akm dot1x
security wpa akm psk set-key ascii 0 <psk key>
session-timeout 1800 (issued the "no session-timeout" command)
no shutdown
wlan AGVs
vlan AGVs
wlan AGVs
vlan AGVs
wlan AGVs
vlan AGVs
wlan AGVs
vlan AGVs
wlan AGVs
vlan AGVs

wlan LGVOCME 7 LGVOCME
client vlan 7
no security wpa akm dot1x
security wpa akm psk set-key ascii 0 <psk>
session-timeout 1800 (issued the "no session-timeout" command )
no shutdown
wlan LGVOCME
vlan LGVOCME
wlan LGVOCME
vlan LGVOCME
wlan LGVOCME
vlan LGVOCME
wlan LGVOCME
vlan LGVOCME
wlan LGVOCME
vlan LGVOCME

We have several APs in the secondary controller and we're checking is the problem is solved that way.

Cheers,

Vasco

Cheers,
Vasco

Vasco Costa · ‎09-10-2014

We've replaced the 5760 with an 2504 and everything is fine now.....

Meanwhile, we've opened an TAC to analyze properly this issue with the 5760.

Cheers,
Vasco

Alcides Miguel · ‎11-06-2014

Hi Vasco,

Have you solved your problem?

Best regards,

Alcides

Vasco Costa · ‎11-14-2014

It seems version 3.3.5 solves this issue.

The roaming is faster and the clients recover on their own when they get a deauth reason code 15 error.

Cheers,
Vasco

Robert Sutton · ‎04-30-2015

Hi Vasco,

Sorry to post to your old thread but I was wondering if TAC ever identified what bug you were hitting. We have a very similar issue with iPhones running WPA2/AES PSK on 3.6 code. We are in the process of upgrading to 3.6.2.

Thanks,

Rob

Vasco Costa · ‎05-03-2015

Hi Rob,

Still a pending issue.

The last version we tested was 3.7.0 but went so bad that 3 hours later we roll-backed to 3.3.5.

We even considering replacing the 5760 with some good old 5508.

Good luck with your issue.

Cheers,

Vasco

Cheers,
Vasco

Robert Sutton · ‎05-04-2015

Hi Vasco,

Thanks for your response! Disappointing news. We have an open case with TAC and also Apple Development as it is affecting iPhones. I'll post here if we find a solution. We still have our 5508's, but are trying not to go back to them.

Rob

Robert Sutton · ‎05-26-2015

Just an update to this, TAC suggested increasing the eapol timers, but that did not help. After reading about Fast Transition we decided to try it and things are much better. We rarely ever see a deauth code 15 anymore and our application is working correctly.

wlan PSK-NET 15 PSK-NET
no ccx aironet-iesupport
no chd
client vlan psknet
no exclusionlist
no security wpa akm dot1x
security wpa akm ft psk
security wpa akm psk set-key ascii 0 "******"
security ft
no shutdown

Vasco Costa · ‎05-26-2015

Hi Rob,

Thanks for sharing.

I'm going to try it on our customers network and I'll send the results ASAP.

Cheers,

Vasco

Cheers,
Vasco

5760 - authenticated clients in WPA2+AES PSK wlan failed to roam (deauth reason code 15)