×

Warning message

  • Cisco Support Forums is in Read Only mode while the site is being migrated.
  • Cisco Support Forums is in Read Only mode while the site is being migrated.

WLC roaming debug assistance

Unanswered Question
Sep 24th, 2014
User Badges:

I'm in a position where I need to prove that a suppliers device doesn't truly roam between APs on a WLC. The device will eventually drop the AP when the signal is low enough and then re-authenticate to a new AP, but it doesn't seamlessly roam.

As far as proving it, on the WLC Client Detail page, the device doesn't support CCX extensions, which, as far as I understand, is probably evidence enough in itself.

I've also logged the device and have only ever seen

xx:xx:xx:xx:xx Association received from mobile on BSSID aa:aa:aa:aa:aa

I've never seen a

xx:xx:xx:xx:xx Reassociation received from mobile on BSSID aa:aa:aa:aa:aa

Is that evidence enough that that device doesn't actually roam?

Is there a more elegant way, in layman's terms, to prove the point?

 

 

  • 1
  • 2
  • 3
  • 4
  • 5
Overall Rating: 1 (1 ratings)
Loading.
Rasika Nayanajith Wed, 09/24/2014 - 19:05
User Badges:
  • Purple, 4500 points or more
  • Cisco Designated VIP,

    2017 Wireless

Hi,

If you go to your WLC CLI  get "debug client <Client_MAC_Add>" you will see the full details of client connection flow. That will tells you seamless roaming occur or not. Attach that output onto your next response to see.

Also here is some reference post to understand what it involve in wireless roaming

http://mrncciew.com/2014/09/02/cwsp-802-11-roaming-basics/ 

HTH

Rasika

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

renoufi Wed, 09/24/2014 - 19:46
User Badges:

Thanks for your reply. I've already been running debug but what is not clear to me is how to prove that the device is not roaming, it is just losing signal and finding a new device to re-authenticate to.

I've attached the debug from a few days ago.

It should be obvious but 00:80:48:78:50:65 is the device that is not roaming and a4:17:31:25:00:e7 is a laptop that (hopefully) is roaming.

Rasika Nayanajith Sun, 09/28/2014 - 19:36
User Badges:
  • Purple, 4500 points or more
  • Cisco Designated VIP,

    2017 Wireless

Hi

I can see multiple time given client authentication failed. So it is look like given client unable to connect to the network.  See the reference time interval & Access-Reject message for this client.

 

*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 Processing Access-Reject for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 apfMsPeapSimReqCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 apfMsPeapSimReqFailureCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 PMK: Sending cache delete
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 Removing PMK cache entry for station 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 1 PMK-remove groupcast messages sent 
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 Removing PMK cache due to EAP-Failure for mobile 00:80:48:78:50:65 (EAP Id 167)
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 Sending EAP-Failure to mobile 00:80:48:78:50:65 (EAP Id 167)
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.536: 00:80:48:78:50:65 Entering Backend Auth Failure state (id=167) for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.537: 00:80:48:78:50:65 Setting quiet timer for 5 seconds for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:43:20.537: 00:80:48:78:50:65 dot1x - moving mobile 00:80:48:78:50:65 into Unknown state

.

.

*osapiBsnTimer: Sep 22 10:44:31.404: 00:80:48:78:50:65 802.1x 'timeoutEvt' Timer expired for station 00:80:48:78:50:65 and for message = M0
*dot1xMsgTask: Sep 22 10:44:31.404: 00:80:48:78:50:65 Retransmit 1 of EAP-Request (length 95) for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.418: 00:80:48:78:50:65 Received EAPOL EAPPKT from mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.419: 00:80:48:78:50:65 Received EAP Response from mobile 00:80:48:78:50:65 (EAP Id 231, EAP Type 25)
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.419: 00:80:48:78:50:65 Resetting reauth count 0 to 0 for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.419: 00:80:48:78:50:65 Entering Backend Auth Response state for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 Processing Access-Reject for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 apfMsPeapSimReqCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 apfMsPeapSimReqFailureCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 1 PMK-remove groupcast messages sent 
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 Removing PMK cache due to EAP-Failure for mobile 00:80:48:78:50:65 (EAP Id 231)
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 Sending EAP-Failure to mobile 00:80:48:78:50:65 (EAP Id 231)
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 Entering Backend Auth Failure state (id=231) for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 Setting quiet timer for 5 seconds for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:44:31.423: 00:80:48:78:50:65 dot1x - moving mobile 00:80:48:78:50:65 into Unknown state

.

.

 

*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.319: 00:80:48:78:50:65 Resetting reauth count 0 to 0 for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.320: 00:80:48:78:50:65 Entering Backend Auth Response state for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Processing Access-Reject for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 apfMsPeapSimReqCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 apfMsPeapSimReqFailureCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 1 PMK-remove groupcast messages sent 
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Removing PMK cache due to EAP-Failure for mobile 00:80:48:78:50:65 (EAP Id 140)
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Sending EAP-Failure to mobile 00:80:48:78:50:65 (EAP Id 140)
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Entering Backend Auth Failure state (id=140) for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 apfBlacklistMobileStationEntry2 (apf_ms.c:6172) Changing state for mobile 00:80:48:78:50:65 on AP 6c:99:89:77:41:e0 from Associated to Exclusion-list (1)

*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Scheduling deletion of Mobile Station:  (callerId: 44) in 10 seconds
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 10.0.45.201 8021X_REQD (3) Change state to START (0) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 10.0.45.201 START (0) Reached FAILURE: from line 5620
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Scheduling deletion of Mobile Station:  (callerId: 9) in 10 seconds
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Max AAA failure for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 Setting quiet timer for 5 seconds for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:47:28.327: 00:80:48:78:50:65 dot1x - moving mobile 00:80:48:78:50:65 into Unknown state
*osapiBsnTimer: Sep 22 10:47:33.204: 00:80:48:78:50:65 802.1x 'quiteWhile' Timer expired for station 00:80:48:78:50:65 and for message = M0
*osapiBsnTimer: Sep 22 10:47:38.204: 00:80:48:78:50:65 apfMsExpireCallback (apf_ms.c:632) Expiring Mobile!
*apfReceiveTask: Sep 22 10:47:38.204: 00:80:48:78:50:65 Freeing EAP Retransmit Bufer for mobile 00:80:48:78:50:65
*apfReceiveTask: Sep 22 10:47:38.204: 00:80:48:78:50:65 Sent Deauthenticate to mobile on BSSID 6c:99:89:77:41:e0 slot 0(caller apf_ms.c:7065)

..

.

*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.223: 00:80:48:78:50:65 Sending EAP Request from AAA to mobile 00:80:48:78:50:65 (EAP Id 31)
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.223: 00:80:48:78:50:65 Reusing allocated memory for  EAP Pkt for retransmission to mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.233: 00:80:48:78:50:65 Received EAPOL EAPPKT from mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.233: 00:80:48:78:50:65 Received EAP Response from mobile 00:80:48:78:50:65 (EAP Id 31, EAP Type 25)
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.233: 00:80:48:78:50:65 Resetting reauth count 0 to 0 for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.233: 00:80:48:78:50:65 Entering Backend Auth Response state for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.240: 00:80:48:78:50:65 Processing Access-Reject for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.240: 00:80:48:78:50:65 apfMsPeapSimReqCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.240: 00:80:48:78:50:65 apfMsPeapSimReqFailureCntInc
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.241: 00:80:48:78:50:65 1 PMK-remove groupcast messages sent 
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.241: 00:80:48:78:50:65 Removing PMK cache due to EAP-Failure for mobile 00:80:48:78:50:65 (EAP Id 31)
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.241: 00:80:48:78:50:65 Sending EAP-Failure to mobile 00:80:48:78:50:65 (EAP Id 31)
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.241: 00:80:48:78:50:65 Entering Backend Auth Failure state (id=31) for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.241: 00:80:48:78:50:65 Setting quiet timer for 5 seconds for mobile 00:80:48:78:50:65
*Dot1x_NW_MsgTask_5: Sep 22 10:52:47.241: 00:80:48:78:50:65 dot1x - moving mobile 00:80:48:78:50:65 into Unknown state

Also few times client forced to go to START status from RUN status with below reasoning. Make sure you disable management frame protection (802.11w) on this WLAN. Also if this is FlexConnect deployment, make sure you use FlexConnect Group if you required to support Opportunistic Key Caching (kind of fast roaming)

 

*apfMsConnTask_7: Sep 22 11:02:23.723: 00:80:48:78:50:65 apfValidateDot11wGroupMgmtCipher:1552, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning

*apfMsConnTask_7: Sep 22 11:02:23.723: 00:80:48:78:50:65 AID 1 in Assoc Req from flex AP 68:86:a7:29:cf:60 is same as in mscb 00:80:48:78:50:65
*apfMsConnTask_7: Sep 22 11:02:23.723: 00:80:48:78:50:65 apfMsRunStateDec
*apfMsConnTask_7: Sep 22 11:02:23.723: 00:80:48:78:50:65 apfMs1xStateDec
*apfMsConnTask_7: Sep 22 11:02:23.723: 00:80:48:78:50:65 10.0.45.201 RUN (20) Change state to START (0) last state RUN (20)

HTH

Rasika

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

renoufi Mon, 09/29/2014 - 00:39
User Badges:

 Thanks for having a look at the debug. I see the three auth failures at the start but I'm really only interested in roaming. Hence my original question

 

 

Thanks for looking at the debug output. I see the three auth failures at the start and MFP is set to optional on that WLAN.

I'm really only interested in roaming at this point. Any other issues are secondary.

Hence my original question in relation to association, reassociation and CCX.

xx:xx:xx:xx:xx Association received from mobile on BSSID aa:aa:aa:aa:aa

xx:xx:xx:xx:xx Reassociation received from mobile on BSSID aa:aa:aa:aa:aa

Rasika Nayanajith Mon, 09/29/2014 - 00:52
User Badges:
  • Purple, 4500 points or more
  • Cisco Designated VIP,

    2017 Wireless

Since we cannot see successful authentication to the network you won't see any further re-association.

yes, to start the roaming process client station has to send "reassociation request" to an AP.

HTH

Rasika

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

renoufi Mon, 09/29/2014 - 01:30
User Badges:

I'm confused. Isn't there a successful authentication at 11:01 to AP03 and then another successful authentication at 11:02 to AP01 for 00:80:48:78:50:65?

Actions

This Discussion