10-26-2020 04:42 AM - edited 07-05-2021 12:42 PM
I'm trying to troubleshoot a roaming problem, where some of our client sometimes experience a 20 second interruption of connectivity. The problem occurs about once in every 50 times the clients roams.
All involved access-points are connected to the same, local WLC 5508 (SW Version 8.5.161.0).
I have recorded debug logs of good and bad roamings to compare ("debug client xxxx.xxxx.xxxx") and have identified this section as the culprit:
*spamApTask6: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 Setting ADD_MOBILE (idx 2, seqno 243, action 6, count 243, last count 0) ack state for STA on AP cc:d5:39:ba:18:00 *spamApTask6: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 Delete Mobile request on slot 0 sent to the AP cc:d5:39:ba:18:00 IP: 10.58.44.121:53857 *spamApTask6: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 Received add/del ack packet with sequence number: got 243 expected 243 action = 6 *spamApTask6: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 apfUpdateDeleteAckInMscb (apf_api.c:54425) Expiring Mobile! *spamApTask7: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 Add SGT:0 to AP 24:01:c7:15:01:40 *spamApTask7: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0 *spamApTask7: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 Successful transmission of LWAPP Add-Mobile to AP 24:01:c7:15:01:40 *spamApTask7: Oct 23 14:10:50.518: 8c:27:8a:05:6b:99 Setting ADD_MOBILE (idx 17, seqno 222, action 1, count 222, last count 232) ack state for STA on AP 24:01:c7:15:01:40 *spamApTask7: Oct 23 14:10:50.520: 8c:27:8a:05:6b:99 Received add/del ack packet with sequence number: got 222 expected 222 action = 1 *spamApTask7: Oct 23 14:10:50.520: 8c:27:8a:05:6b:99 Received ADD_MOBILE ack - Initiating 1x to STA 8c:27:8a:05:6b:99 (idx 17) *spamApTask7: Oct 23 14:10:50.520: 8c:27:8a:05:6b:99 APF Initiating 1x to STA 8c:27:8a:05:6b:99 *spamApTask7: Oct 23 14:10:50.520: 8c:27:8a:05:6b:99 Sent dot1x auth initiate message for mobile 8c:27:8a:05:6b:99
In this example, everything works as expected. After this follows a section of "Dot1x_NW_MsgTask"-Messages and the connection is established.
Here's an example of a bad roaming to compare:
*spamApTask6: Oct 23 15:55:34.539: 8c:27:8a:08:10:4b Add SGT:0 to AP cc:d5:39:ba:18:00 *spamApTask6: Oct 23 15:55:34.539: 8c:27:8a:08:10:4b Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0 *spamApTask6: Oct 23 15:55:34.540: 8c:27:8a:08:10:4b Successful transmission of LWAPP Add-Mobile to AP cc:d5:39:ba:18:00 *spamApTask6: Oct 23 15:55:34.540: 8c:27:8a:08:10:4b Setting ADD_MOBILE (idx 68, seqno 141, action 1, count 141, last count 206) ack state for STA on AP cc:d5:39:ba:18:00 *spamApTask7: Oct 23 15:55:34.541: 8c:27:8a:08:10:4b Setting DEL_MOBILE (seqno 0, action 6) ack state for STA on AP 24:01:c7:15:01:40 *spamApTask7: Oct 23 15:55:34.541: 8c:27:8a:08:10:4b Setting ADD_MOBILE (idx 44, seqno 81, action 6, count 81, last count 0) ack state for STA on AP 24:01:c7:15:01:40 *spamApTask7: Oct 23 15:55:34.541: 8c:27:8a:08:10:4b Delete Mobile request on slot 0 sent to the AP 24:01:c7:15:01:40 IP: 10.58.44.116:53973 *spamApTask6: Oct 23 15:55:34.541: 8c:27:8a:08:10:4b Received add/del ack packet with sequence number: got 141 expected 141 action = 1 *spamApTask6: Oct 23 15:55:34.541: 8c:27:8a:08:10:4b Received ADD_MOBILE ack - Initiating 1x to STA 8c:27:8a:08:10:4b (idx 68) *spamApTask6: Oct 23 15:55:34.541: 8c:27:8a:08:10:4b expected addMobileAckCount 81, got 141 *spamApTask7: Oct 23 15:55:34.542: 8c:27:8a:08:10:4b Received add/del ack packet with sequence number: got 81 expected 81 action = 6 *spamApTask7: Oct 23 15:55:34.542: 8c:27:8a:08:10:4b apfUpdateDeleteAckInMscb (apf_api.c:54425) Expiring Mobile!
Differences:
My questions:
I would appreciate any insights you can provide!
Solved! Go to Solution.
10-26-2020 06:08 AM
I think you are victim of the bug CSCvq55777. A solution would be to upgrade your controller to the 8.5.164.0 version that correct the problem.
Extract of the bug description:
Symptom:
[...]
Symptom 2: a client roams to a new AP but is unable to pass traffic. "debug client" shows this message immediately
after the client associates:
*spamApTask4: Mar 06 12:40:24.312: 00:01:02:cd:00:6b apfUpdateDeleteAckInMscb (apf_api.c:54425) Expiring Mobile!
rather than:
*spamApTask4: Mar 06 12:40:01.262: 00:01:02:cd:00:6b Sent dot1x auth initiate message for mobile 00:01:02:cd:00:6b
[...]
10-26-2020 06:08 AM
I think you are victim of the bug CSCvq55777. A solution would be to upgrade your controller to the 8.5.164.0 version that correct the problem.
Extract of the bug description:
Symptom:
[...]
Symptom 2: a client roams to a new AP but is unable to pass traffic. "debug client" shows this message immediately
after the client associates:
*spamApTask4: Mar 06 12:40:24.312: 00:01:02:cd:00:6b apfUpdateDeleteAckInMscb (apf_api.c:54425) Expiring Mobile!
rather than:
*spamApTask4: Mar 06 12:40:01.262: 00:01:02:cd:00:6b Sent dot1x auth initiate message for mobile 00:01:02:cd:00:6b
[...]
10-26-2020 09:04 AM
Thanks a lot! The description does perfectly match what I see and our release is listed as affected, so I'm pretty sure this must be it.
10-26-2020 09:02 AM
- Besides other reply , you can also have your debugs analyzed with this tool :
https://cway.cisco.com/tools/WirelessDebugAnalyzer/
M.
10-29-2020 11:56 AM
8.5.164.0 is for the IRCM deployment. As per the TAC recommended AireOS document, this image is not supported for other platforms, nor is it supported for non-IRCM deployments. The CSCvq55777 is fixed in 8.5.161.x escalation image. If you are not running IRCM deployment you should reach out to TAC and they can provide you escalation image with the fix.
11-05-2020 12:07 AM
Thanks for the input. After headquarters consulted with Cisco, we went with 8.5.161.7.
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide