topic Re: Analyzing another Roaming Problem (WLC 5508) - debug included in Wireless

Analyzing another Roaming Problem (WLC 5508) - debug included

gmlucco — Mon, 05 Jul 2021 19:44:23 GMT

After our last roaming problem could be attributed to a bug in our WLCs IOS, we switched to 8.5.161.7 and the problems described here disappeared. With those issues gone, I can now focus on troubleshooting another issue, that has been around before the IOS change as well.

We have some fast moving clients, that basically drop traffic for a few seconds, whenever they roam. The clients run Microsoft Windows with a Qualcomm Atheros QCA61x4A, Driver version 12.0.0.722 (also tested with 12.0.0.948).

The Debug Logs appear to show the clients roaming flawlessly every single time:

Nov 02 15:57:22.939	*apfMsConnTask_6	Client roamed to AP/BSSID BSSID 84:78:ac:xx:xx:xx AP [AP-Name]
Nov 02 15:57:22.940	*apfMsConnTask_6	The WLC/AP has found from client association request Information Element that claims PMKID Caching support
Nov 02 15:57:22.941	*apfMsConnTask_6	The Reassociation Request from the client comes with 0 PMKID
Nov 02 15:57:22.941	*apfMsConnTask_6	Client is entering the 802.1x or PSK Authentication state
Nov 02 15:57:22.942	*apfMsConnTask_6	WLC/AP is sending an Association Response to the client with status code 0 = Successful association
Nov 02 15:57:22.946	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Sending M1
Nov 02 15:57:22.954	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Received M2
Nov 02 15:57:22.955	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Sending M3
Nov 02 15:57:22.959	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Received M4
Nov 02 15:57:22.959	*Dot1x_NW_MsgTask_1	Client has completed PSK Dot1x or WEP authentication phase
Nov 02 15:57:22.959	*Dot1x_NW_MsgTask_1	Client has entered RUN state
Nov 02 15:57:22.999	*DHCP Socket Task	Received DHCP request from client
Nov 02 15:57:23.001	*DHCP Socket Task	Received DHCP ACK from DHCP server
Nov 02 15:57:23.002	*DHCP Socket Task	Received DHCP ACK from DHCP server

Meanwhile, a continuous ping to the client shows the following picture:

So it usually takes another 5 seconds, before ICMP goes through again.

The program I use (GPING.exe) will continue sending pings every 0.1 seconds, even if the last ping hasn't been answered yet. Unanswered pings are shown as a black space in the timeline. A weird phenomenon I see, is that right when traffic is forwarded again, about 1 second of previously unanswered pings (black area) is suddenly filled with blue (ping answer <5ms) which doesn't really make sense to me. It's as if the last second, before forwarding works again, is somehow buffered and forwarded all at once.

Any ideas on what might cause this kind of behavior, are greatly appreciated. Also I'd like to further troubleshoot the issue from the clients side. Is there a possibility to get useful logs on Windows?

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Leo Laohoo — Tue, 03 Nov 2020 10:32:30 GMT

What happens if you try a different wireless client like, say, a smartphone or a tablet? Do you get the same behaviour?

What happens if you use PSK?

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

gmlucco — Wed, 04 Nov 2020 16:00:52 GMT

I managed to do side-by-side testing with a Samsung XCover 4 mobile phone today. The phone does not suffer from the same interruptions in connectivity, even when moving at the same high speeds as the other devices.

Here's a comparison of 2 roaming events with both clients side-by-side:

The affected clients/SSID already use PSK.

Sadly, I don't have a baseline of how these clients performed on previous IOS versions. But from what I can gather, the problem seem to be client sided. Maybe we can try running a different OS / drivers to see, if the device is capable of seamless connectivity with different setups. Or we'll just switch to different hardware...

If anyone knows a way to do in depth debugging on the client in widows, that would also be appreciated.

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

patoberli — Thu, 05 Nov 2020 13:12:52 GMT

Do you have FT (802.11r) enabled? That can cause various device specific issues and it's worth a try to disable it for testing. If it's already disabled, leave it (or set to optional).

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

gmlucco — Fri, 06 Nov 2020 15:13:01 GMT

Fast Transition is disabled.

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

patoberli — Mon, 09 Nov 2020 16:47:52 GMT

I know that this Qualcomm card is known to cause issue, but I hope you find a way to improve it.

Can you attach the full debug log? The analyzer omits various lines.

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

gmlucco — Tue, 10 Nov 2020 09:02:47 GMT

Of course. Here's a full debug log of the Qualcomm client roaming:

*apfOpenDtlSocket: Nov 02 15:57:22.938: 00:0e:8e:8a:8e:79 Received management frame REASSOCIATION REQUEST  on BSSID 84:78:ac:8d:cb:ce destination addr 84:78:ac:8d:cb:ce
*apfMsConnTask_6: Nov 02 15:57:22.938: 00:0e:8e:8a:8e:79 Processing assoc-req station:00:0e:8e:8a:8e:79 AP:84:78:ac:8d:cb:c0-01 ssid : [SSID-Name] thread:1b2aad38
*apfMsConnTask_6: Nov 02 15:57:22.938: 00:0e:8e:8a:8e:79 Station:  00:0E:8E:8A:8E:79  11v BSS Transition not enabled on the AP  84:78:AC:8D:CB:C0 
*apfMsConnTask_6: Nov 02 15:57:22.938: 00:0e:8e:8a:8e:79 Client AVC Roaming context transfer needed? NO
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Setting RTTS enabled to 0 
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Reassociation received from mobile on BSSID 84:78:ac:8d:cb:cf AP [AP-Hostname]
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Station:  00:0E:8E:8A:8E:79  11v BSS Transition not enabled on the AP  84:78:AC:8D:CB:C0 
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Global 200 Clients are allowed to AP radio

*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Max Client Trap Threshold: 0  cur: 0

*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 override for default ap group, marking intgrp NULL
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Applying Interface([Interface-Name]) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan [VLAN-ID]

*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Re-applying interface policy for client 

*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3286)
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255),Default action is '0' --- (caller apf_policy.c:3306)
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3327)
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid:, APgrpset:0
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Check before Setting the NAS Id to WLAN specific Id ''
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 In processSsidIE:6947 setting Central switched to TRUE
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 In processSsidIE:6950 apVapId = 2 and Split Acl Id = 65535
*apfMsConnTask_6: Nov 02 15:57:22.939: 00:0e:8e:8a:8e:79 Applying site-specific Local Bridging override for station 00:0e:8e:8a:8e:79 - vapId 1, site '[SSID-Name]', interface '[Interface-Name]'
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Applying Local Bridging Interface Policy for station 00:0e:8e:8a:8e:79 - vlan [VLAN-ID], interface id 13, interface '[Interface-Name]', nasId:''
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 override from ap group, removing intf group from mscb
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Applying site-specific override for station 00:0e:8e:8a:8e:79 - vapId 1, site '[SSID-Name]', interface '[Interface-Name]'
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Not applying Local Bridge Policy because Site Specific Interface([Interface-Name]) Policy is already applied.

*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Applying Interface([Interface-Name]) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan [VLAN-ID]

*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Re-applying interface policy for client 

*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3286)
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255),Default action is '0' --- (caller apf_policy.c:3306)
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3327)
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid:, APgrpset:0
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 processSsidIE  statusCode is 0 and status is 0 
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 STA - rates (8): 12 18 152 36 176 72 96 108 48 72 96 108 0 0 0 0
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 suppRates  statusCode is 0 and gotSuppRatesElement is 1 
*apfMsConnTask_6: Nov 02 15:57:22.940: RSNIE in Assoc. Req.: (20)

*apfMsConnTask_6: Nov 02 15:57:22.940:      [0000] 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_6: Nov 02 15:57:22.940:      [0016] ac 02 00 00

*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Processing RSN IE type 48, length 20 for mobile 00:0e:8e:8a:8e:79
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 Received 802.11i PSK key management suite, enabling Authentication
*apfMsConnTask_6: Nov 02 15:57:22.940: 00:0e:8e:8a:8e:79 RSN Capabilities:  0
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 non-11w Capable mobile 
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Received RSN IE with 0 PMKIDs from mobile 00:0e:8e:8a:8e:79
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 the value of url acl preserve flag is 1 for mobile 00:0e:8e:8a:8e:79 (caller pem_api.c:4931)
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Deleted mobile LWAPP rule on AP [cc:d5:39:cc:1e:f0]
*pemReceiveTask: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 10.58.18.127 Removed NPU entry.
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Succesfully freed AID 3, slot 1 on AP cc:d5:39:cc:1e:f0, #client on this slot 1
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 New ctxOwnerMwarIp:  10.58.253.11 New ctxOwnerApMac:  84:78:AC:8D:CB:C0 New ctxOwnerApEthMac:  E4:D3:F1:EF:9B:5D New ctxOwnerApSlotId: 1
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Updated location for station old AP cc:d5:39:cc:1e:f0 oldSlot 1, new AP 84:78:ac:8d:cb:c0 newSlot 1, AID 0 MsType 0 MobilityRole 1
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Assigning flex webauth ACL ID :65535 for vlan : 2
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Updating AID for REAP AP Client 84:78:ac:8d:cb:c0 - AID ===> 1
*spamApTask6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Setting DEL_MOBILE (seqno 0, action 6) ack state for STA on AP cc:d5:39:cc:1e:f0
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 apfMsRunStateDec
*spamApTask6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Setting ADD_MOBILE (idx 97, seqno 54, action 6, count 54, last count 54) ack state for STA on AP cc:d5:39:cc:1e:f0
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 apfMs1xStateDec
*spamApTask6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Delete Mobile request on slot 1 sent to the AP cc:d5:39:cc:1e:f0 IP: 10.58.42.107:63926

*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 the value of url acl preserve flag is 0 for mobile 00:0e:8e:8a:8e:79 (caller pem_api.c:3504)
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 10.58.18.127 START (0) Initializing policy
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 10.58.18.127 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79  apfVapSecurity=0x40004000 L2=16384 SkipWeb=0 
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79  AuthenticationRequired = 1 
*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 10.58.18.127 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_6: Nov 02 15:57:22.941: 00:0e:8e:8a:8e:79 Encryption policy is set to 0x80000001
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 flex webauth acl id to be sent when fabric is disabled:65535
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 flex webauth acl id to be sent :65535 name : client acl id : 65535
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 Vlan while overriding the policy = -1
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535

*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 10.58.18.127 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 84:78:ac:8d:cb:c0 vapId 1 apVapId 2 flex-acl-name: 
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 apfPemAddUser2 (apf_policy.c:438) Changing state for mobile 00:0e:8e:8a:8e:79 on AP 84:78:ac:8d:cb:c0 from Associated to Associated

*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 apfPemAddUser2:session timeout forstation 00:0e:8e:8a:8e:79 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0 
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 Sending assoc-resp with status 0 station:00:0e:8e:8a:8e:79 AP:84:78:ac:8d:cb:c0-01 on apVapId 2
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 Sending Assoc Response (status: '0') to station on AP [AP-Hostname] on BSSID 84:78:ac:8d:cb:ce ApVapId 2 Slot 1, mobility role 1
*apfMsConnTask_6: Nov 02 15:57:22.942: 00:0e:8e:8a:8e:79 apfProcessAssocReq (apf_80211.c:12012) Changing state for mobile 00:0e:8e:8a:8e:79 on AP 84:78:ac:8d:cb:c0 from Associated to Associated

*spamApTask2: Nov 02 15:57:22.943: 00:0e:8e:8a:8e:79 Add SGT:0 to AP 84:78:ac:8d:cb:c0
*spamApTask2: Nov 02 15:57:22.943: 00:0e:8e:8a:8e:79 Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0
*spamApTask2: Nov 02 15:57:22.943: 00:0e:8e:8a:8e:79 Successful transmission of LWAPP Add-Mobile to AP 84:78:ac:8d:cb:c0
*spamApTask2: Nov 02 15:57:22.943: 00:0e:8e:8a:8e:79 Setting ADD_MOBILE (idx 39, seqno 232, action 1, count 232, last count 232) ack state for STA on AP 84:78:ac:8d:cb:c0
*spamApTask6: Nov 02 15:57:22.943: 00:0e:8e:8a:8e:79 Received add/del ack packet with sequence number: got 54 expected 54 action = 6
*spamApTask6: Nov 02 15:57:22.943: 00:0e:8e:8a:8e:79 apfUpdateDeleteAckInMscb (apf_api.c:54425) Expiring Mobile!
*spamApTask2: Nov 02 15:57:22.944: 00:0e:8e:8a:8e:79 Received add/del ack packet with sequence number: got 232 expected 232 action = 1
*spamApTask2: Nov 02 15:57:22.944: 00:0e:8e:8a:8e:79 Received ADD_MOBILE ack - Initiating 1x to STA 00:0e:8e:8a:8e:79 (idx 39)
*spamApTask2: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 APF Initiating 1x to STA 00:0e:8e:8a:8e:79
*spamApTask2: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Sent dot1x auth initiate message for mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 dot1xProcessInitiate1XtoMobile to mobile station 00:0e:8e:8a:8e:79 (mscb 113, msg 113)
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 reauth_sm state transition 0 ---> 0 for mobile 00:0e:8e:8a:8e:79 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Normal psk client, full auth
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Created PKC PMK Cache entry for station 00:0e:8e:8a:8e:79 (RSN 2)
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Resetting MSCB PMK Cache Entry @index 0 for station 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Removing BSSID cc:d5:39:cc:1e:fe from PMKID cache of station 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Setting active key cache index 0 ---> 8
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Created PMKID PMK Cache for BSSID 84:78:ac:8d:cb:ce  at index 0 for station 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: New PMKID: (16)

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945:      [0000] 76 df c5 1c 4e b4 0d d0 bd ac 9c b3 d3 5e 38 64

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.945: 00:0e:8e:8a:8e:79 Initiating RSN PSK to mobile 00:0e:8e:8a:8e:79keyMgmtType : 0
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 EAP-PARAM Debug - eap-params for Wlan-Id :1 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 dot1x - moving mobile 00:0e:8e:8a:8e:79 into Force Auth state
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 Skipping EAP-Success to mobile 00:0e:8e:8a:8e:79 (encryptBit:0)
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 key Desc Version FT - 0

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 Found an cache entry for BSSID 84:78:ac:8d:cb:ce in PMKID cache at index 0 of station 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 Found an cache entry for BSSID 84:78:ac:8d:cb:ce in PMKID cache at index 0 of station 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: Including PMKID in M1  (16)

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946:      [0000] 76 df c5 1c 4e b4 0d d0 bd ac 9c b3 d3 5e 38 64

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: M1 - Key Data: (22)

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946:      [0000] dd 14 00 0f ac 04 76 df c5 1c 4e b4 0d d0 bd ac

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946:      [0016] 9c b3 d3 5e 38 64

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 Starting key exchange to mobile 00:0e:8e:8a:8e:79, data packets will be dropped
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 Sending EAPOL-Key Message to mobile 00:0e:8e:8a:8e:79
   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.946: 00:0e:8e:8a:8e:79 Allocating EAP Pkt for retransmission to mobile 00:0e:8e:8a:8e:79
*dot1xSocketTask: Nov 02 15:57:22.953: 00:0e:8e:8a:8e:79 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Received EAPOL-Key from mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 key Desc Version FT - 0

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Received EAPOL-key in PTK_START state (message 2) from mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Received valid MIC in EAPOL Key Message M2!!!!!
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Compare RSN IE in association and EAPOL-M2 frame(rsnie_len :20, and grpMgmtCipherLen:0)
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 rsnieCapabilty = 0 rsnie_len =18
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Dumping RSNIE received in Association request(len = 22):
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00000000: 30 14 01 00 00 0f ac 02  01 00 00 0f ac 04 01 00  0...............
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00000010: 00 0f ac 02 00 00                                 ......
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Dumping RSNIE received in EAPOL M2 (len = 20):
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00000000: 01 00 00 0f ac 02 01 00  00 0f ac 04 01 00 00 0f  ................
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00000010: ac 02 00 00                                       ....
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 Stopping retransmission timer for mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.954: 00:0e:8e:8a:8e:79 key Desc Version FT - 0

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.955: 00:0e:8e:8a:8e:79 key Desc Version FT - 0

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.955: 00:0e:8e:8a:8e:79 Sending EAPOL-Key Message to mobile 00:0e:8e:8a:8e:79
   state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.955: 00:0e:8e:8a:8e:79 Reusing allocated memory for  EAP Pkt for retransmission to mobile 00:0e:8e:8a:8e:79
*dot1xSocketTask: Nov 02 15:57:22.958: 00:0e:8e:8a:8e:79 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 Received EAPOL-Key from mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 key Desc Version FT - 0

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 Stopping retransmission timer for mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 Freeing EAP Retransmit Bufer for mobile 00:0e:8e:8a:8e:79
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 apfMs1xStateInc
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 10.58.18.127 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 flex webauth acl id to be sent when fabric is disabled:65535
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 flex webauth acl id to be sent :65535 name : client acl id : 65535
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 Vlan while overriding the policy = -1
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 10.58.18.127 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 84:78:ac:8d:cb:c0 vapId 1 apVapId 2 flex-acl-name: 
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 apfMsRunStateInc
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 10.58.18.127 L2AUTHCOMPLETE (4) Change state to RUN (20) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Reached PLUMBFASTPATH: from line 7157, null
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Adding Fast Path rule
  type = Airespace AP Client
  on AP 84:78:ac:8d:cb:c0, slot 1, interface = 13, QOS = 2
  IPv4 ACL ID = 255, IPv6 ACL ID = 
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.959: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Fast Path rule (contd...) 802.1P = 5, DSCP = 46, TokenID = 15206, IntfId = 13  Local Bridging Vlan = [VLAN-ID], Local Bridging intf id = 13
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 

*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255,URL ACL ID 255,URL ACL Action 0)
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) No 11v BTM 
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 10.58.18.127 RUN (20) NO release MSCB
*Dot1x_NW_MsgTask_1: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 Successfully Plumbed PTK session Keysfor mobile 00:0e:8e:8a:8e:79
*spamApTask2: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 Add SGT:0 to AP 84:78:ac:8d:cb:c0
*pemReceiveTask: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 10.58.18.127 Added NPU entry of type 1, dtlFlags 0x0
*spamApTask2: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0
*pemReceiveTask: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 Pushing IPv6: fe80:0000:0000:0000:cda9:b704:4d33:d165 , intfId:13 and MAC: 00:0E:8E:8A:8E:79 , Binding to Data Plane. SUCCESS !!
*spamApTask2: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 Successful transmission of LWAPP Add-Mobile to AP 84:78:ac:8d:cb:c0
*spamApTask2: Nov 02 15:57:22.960: 00:0e:8e:8a:8e:79 Setting ADD_MOBILE (idx 42,  action 0, last count 232) ack state for STA on AP 84:78:ac:8d:cb:c0
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP received op BOOTREQUEST (1) (len 326,vlan 398, port 13, encap 0xec03, xid 0xc45c1218)
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP processing DHCP REQUEST (3)
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP   xid: 0xc45c1218 (3294368280), secs: 0, flags: 0
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP   chaddr: 00:0e:8e:8a:8e:79
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP   siaddr: 0.0.0.0,  giaddr: 0.0.0.0
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP   requested ip: 10.58.18.127
*DHCP Socket Task: Nov 02 15:57:22.999: 00:0e:8e:8a:8e:79 DHCP Opt82 bridge mode insertion enabled, inserts opt82 if opt82 is enabled vlan=[VLAN-ID], datalen =18, optlen=82
*DHCP Socket Task: Nov 02 15:57:23.000: 00:0e:8e:8a:8e:79 DHCP successfully bridged packet to DS
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP received op BOOTREPLY (2) (len 346,vlan [VLAN-ID], port 13, encap 0xec00, xid 0xc45c1218)
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP processing DHCP ACK (5)
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP   xid: 0xc45c1218 (3294368280), secs: 0, flags: 0
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP   chaddr: 00:0e:8e:8a:8e:79
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP   ciaddr: 0.0.0.0,  yiaddr: 10.58.18.127
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP   siaddr: 0.0.0.0,  giaddr: 10.58.18.2
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP   server id: 10.60.1.110  rcvd server id: 10.60.1.110
*DHCP Socket Task: Nov 02 15:57:23.001: 00:0e:8e:8a:8e:79 DHCP successfully bridged packet to STA
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP received op BOOTREPLY (2) (len 346,vlan [VLAN-ID], port 13, encap 0xec00, xid 0xc45c1218)
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP processing DHCP ACK (5)
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP   xid: 0xc45c1218 (3294368280), secs: 0, flags: 0
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP   chaddr: 00:0e:8e:8a:8e:79
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP   ciaddr: 0.0.0.0,  yiaddr: 10.58.18.127
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP   siaddr: 0.0.0.0,  giaddr: 10.58.18.3
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP   server id: 10.60.1.110  rcvd server id: 10.60.1.110
*DHCP Socket Task: Nov 02 15:57:23.002: 00:0e:8e:8a:8e:79 DHCP successfully bridged packet to STA

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Mark Elsen — Tue, 10 Nov 2020 11:40:35 GMT

- Below is the result when the debug log is processed by : https://cway.cisco.com/wireless-debug-analyzer/

Note you may run this yourself again, as the forum may wrap vital output, you also get extra info's when checking the flag Show Original

Time Task Translated

Nov 02 15:57:22.939	*apfMsConnTask_6	Client roamed to AP/BSSID BSSID 84:78:ac:8d:cb:cf AP [AP-Hostname]
Nov 02 15:57:22.940	*apfMsConnTask_6	The WLC/AP has found from client association request Information Element that claims PMKID Caching support
Nov 02 15:57:22.941	*apfMsConnTask_6	The Reassociation Request from the client comes with 0 PMKID
Nov 02 15:57:22.941	*apfMsConnTask_6	Client is entering the 802.1x or PSK Authentication state
Nov 02 15:57:22.942	*apfMsConnTask_6	WLC/AP is sending an Association Response to the client with status code 0 = Successful association
Nov 02 15:57:22.946	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Sending M1
Nov 02 15:57:22.954	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Received M2
Nov 02 15:57:22.955	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Sending M3
Nov 02 15:57:22.959	*Dot1x_NW_MsgTask_1	4-Way PTK Handshake, Received M4
Nov 02 15:57:22.959	*Dot1x_NW_MsgTask_1	Client has completed PSK Dot1x or WEP authentication phase
Nov 02 15:57:22.959	*Dot1x_NW_MsgTask_1	Client has entered RUN state
Nov 02 15:57:22.999	*DHCP Socket Task	Received DHCP request from client
Nov 02 15:57:23.001	*DHCP Socket Task	Received DHCP ACK from DHCP server
Nov 02 15:57:23.002	*DHCP Socket Task	Received DHCP ACK from DHCP server

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

patoberli — Thu, 12 Nov 2020 15:24:01 GMT

On this example the client has roamed within 1 second, that looks correct.

回复： Analyzing another Roaming Problem (WLC 5508) - debug included

eric888888 — Sun, 23 Jan 2022 06:55:15 GMT

请问Client roamed to AP/BSSID BSSID 00:2c:c8:3e:a1:cf AP TEST-1，Client made new Association to AP/BSSID BSSID 00:2c:c8:3e:a1:cf AP TEST-1的区别是？

topic Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included in Wireless

Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

Re: Analyzing *another* Roaming Problem (WLC 5508) - debug included

回复： Analyzing *another* Roaming Problem (WLC 5508) - debug included

topic Re: Analyzing another Roaming Problem (WLC 5508) - debug included in Wireless

Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

Re: Analyzing another Roaming Problem (WLC 5508) - debug included

回复： Analyzing another Roaming Problem (WLC 5508) - debug included