Standardize WLC debug

ahcadmin1 · ‎08-25-2015

Hello,

We have recently added an SSID for employees to access the internet. Everything seems to be working fine, except that mobile devices will sporadically lose internet connection with the message: "DNSProbe finished no internet". Eventually, it will reconnect on it's own, but a manual disconnect and reconnect to the SSID temporarily resolves the issue faster. I have noticed that each time this happens, the devices renew their DHCP lease w/ the same IP address. I ran a debug on my mobile client and see that this occurs every time there is a loss of connectivity:

*apfMsConnTask_5: Aug 25 10:53:59.347: c0:bd:d1:c7:e5:4a Reassociation received from mobile on BSSID 68:bc:0c:cb:0e:35
*apfMsConnTask_5: Aug 25 10:53:59.347: c0:bd:d1:c7:e5:4a Global 200 Clients are allowed to AP radio

*apfMsConnTask_5: Aug 25 10:53:59.347: c0:bd:d1:c7:e5:4a Max Client Trap Threshold: 0 cur: 4

*apfMsConnTask_5: Aug 25 10:53:59.347: c0:bd:d1:c7:e5:4a Rf profile 200 Clients are allowed to AP wlan

*apfMsConnTask_5: Aug 25 10:53:59.347: c0:bd:d1:c7:e5:4a Applying Interface policy on Mobile, role Local. Ms NAC State 2 Quarantine
Vlan 0 Access Vlan 130

*apfMsConnTask_5: Aug 25 10:53:59.347: c0:bd:d1:c7:e5:4a Re-applying interface policy for client

*apfMsConnTask_5: Aug 25 10:53:59.347: c0:bd:d1:c7:e5:4a 172.20.0.11 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL
ID 255) --- (caller apf_policy.c:2018)
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a 172.20.0.11 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL
ID 255) --- (caller apf_policy.c:2246)
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a In processSsidIE:4202 setting Central switched to TRUE
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a In processSsidIE:4205 apVapId = 6 and Split Acl Id = 65535
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a Applying site-specific Local Bridging override for station c0:bd:d1:c7:e5:4
a - vapId 6, site 'default-group', interface 'employee_wifi'
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a Applying Local Bridging Interface Policy for station c0:bd:d1:c7:e5:4a - vl
an 130, interface id 14, interface 'employee_wifi'
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a STA - rates (8): 139 150 24 36 48 72 96 108 12 18 0 0 0 0 0 0
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a STA - rates (10): 139 150 24 36 48 72 96 108 12 18 0 0 0 0 0 0
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a 172.20.0.11 RUN (20) Deleted mobile LWAPP rule on AP [68:bc:0c:c9:12:60]
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a Updated location for station old AP 68:bc:0c:c9:12:60-0, new AP 68:bc:0c:cb
:0e:30-0
*pemReceiveTask: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a 172.20.0.11 Removed NPU entry.
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a apfMsRunStateDec
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a apfMs1xStateDec
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a 172.20.0.11 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a 172.20.0.11 START (0) Initializing policy
*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a 172.20.0.11 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a 172.20.0.11 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHE
CK (2)

*apfMsConnTask_5: Aug 25 10:53:59.348: c0:bd:d1:c7:e5:4a Not Using WMM Compliance code qosCap 00
*apfMsConnTask_5: Aug 25 10:53:59.349: c0:bd:d1:c7:e5:4a 172.20.0.11 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 68:bc:0c:cb:0e:3
0 vapId 6 apVapId 6 flex-acl-name:
*apfMsConnTask_5: Aug 25 10:53:59.349: c0:bd:d1:c7:e5:4a apfPemAddUser2 (apf_policy.c:276) Changing state for mobile c0:bd:d1:c7:e5:
4a on AP 68:bc:0c:cb:0e:30 from Associated to Associated

*apfMsConnTask_5: Aug 25 10:53:59.349: c0:bd:d1:c7:e5:4a apfPemAddUser2:session timeout forstation c0:bd:d1:c7:e5:4a - Session Tout
0, apfMsTimeOut '0' and sessionTimerRunning flag is 0
*apfMsConnTask_5: Aug 25 10:53:59.349: c0:bd:d1:c7:e5:4a Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_5: Aug 25 10:53:59.349: c0:bd:d1:c7:e5:4a Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_5: Aug 25 10:53:59.349: c0:bd:d1:c7:e5:4a Sending Assoc Response to station on BSSID 68:bc:0c:cb:0e:35 (status 0) ApV
apId 6 Slot 0
*apfMsConnTask_5: Aug 25 10:53:59.349: c0:bd:d1:c7:e5:4a apfProcessAssocReq (apf_80211.c:7391) Changing state for mobile c0:bd:d1:c7
:e5:4a on AP 68:bc:0c:cb:0e:30 from Associated to Associated

*dot1xMsgTask: Aug 25 10:53:59.351: c0:bd:d1:c7:e5:4a dot1x - moving mobile c0:bd:d1:c7:e5:4a into Connecting state
*dot1xMsgTask: Aug 25 10:53:59.351: c0:bd:d1:c7:e5:4a Sending EAP-Request/Identity to mobile c0:bd:d1:c7:e5:4a (EAP Id 1)
*apfMsConnTask_3: Aug 25 10:53:59.381: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:53:59.381: Stats update: Non Zero value

*apfMsConnTask_4: Aug 25 10:54:00.045: Stats update: Non Zero value

*apfMsConnTask_4: Aug 25 10:54:00.046: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:00.194: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:00.195: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:00.299: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:00.302: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:00.303: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:01.584: Stats update: Non Zero value

*apfMsConnTask_7: Aug 25 10:54:01.639: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:02.396: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:02.423: Stats update: Non Zero value

*apfMsConnTask_5: Aug 25 10:54:09.463: Stats update: Non Zero value

*apfMsConnTask_5: Aug 25 10:54:09.464: Stats update: Non Zero value

*apfMsConnTask_5: Aug 25 10:54:09.465: Stats update: Non Zero value

*apfMsConnTask_5: Aug 25 10:54:09.467: Stats update: Non Zero value

*apfMsConnTask_5: Aug 25 10:54:09.468: Stats update: Non Zero value

*apfMsConnTask_0: Aug 25 10:54:11.932: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:19.009: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:19.010: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:19.012: Stats update: Non Zero value

*apfMsConnTask_7: Aug 25 10:54:25.522: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:26.563: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:26.564: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:26.565: Stats update: Non Zero value

*osapiBsnTimer: Aug 25 10:54:29.160: c0:bd:d1:c7:e5:4a 802.1x 'txWhen' Timer expired for station c0:bd:d1:c7:e5:4a and for message =
M0
*dot1xMsgTask: Aug 25 10:54:29.160: c0:bd:d1:c7:e5:4a dot1x - moving mobile c0:bd:d1:c7:e5:4a into Connecting state
*dot1xMsgTask: Aug 25 10:54:29.160: c0:bd:d1:c7:e5:4a Sending EAP-Request/Identity to mobile c0:bd:d1:c7:e5:4a (EAP Id 2)
*apfMsConnTask_3: Aug 25 10:54:31.275: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:31.276: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:31.285: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:31.352: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:31.354: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:33.062: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:33.063: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:34.528: Stats update: Non Zero value

*apfMsConnTask_7: Aug 25 10:54:41.163: Stats update: Non Zero value

*apfMsConnTask_7: Aug 25 10:54:41.164: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:44.080: Stats update: Non Zero value

*apfMsConnTask_7: Aug 25 10:54:44.880: Stats update: Non Zero value

*apfMsConnTask_7: Aug 25 10:54:44.881: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:47.528: Stats update: Non Zero value

*apfMsConnTask_7: Aug 25 10:54:50.018: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:51.963: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:51.964: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:51.966: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:53.046: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:53.047: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:55.711: Stats update: Non Zero value

*apfMsConnTask_3: Aug 25 10:54:55.712: Stats update: Non Zero value

*apfMsConnTask_4: Aug 25 10:54:56.970: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:57.329: Stats update: Non Zero value

*apfMsConnTask_6: Aug 25 10:54:57.331: Stats update: Non Zero value

*osapiBsnTimer: Aug 25 10:54:59.160: c0:bd:d1:c7:e5:4a 802.1x 'txWhen' Timer expired for station c0:bd:d1:c7:e5:4a and for message =
M0
*dot1xMsgTask: Aug 25 10:54:59.161: c0:bd:d1:c7:e5:4a dot1x - moving mobile c0:bd:d1:c7:e5:4a into Connecting state
*dot1xMsgTask: Aug 25 10:54:59.161: c0:bd:d1:c7:e5:4a Sending EAP-Request/Identity to mobile c0:bd:d1:c7:e5:4a (EAP Id 3)

Also worth noting that this happens without roaming, just sitting at my desk. Any help is greatly appreciated.

Sandeep Choudhary · ‎08-25-2015

Hi,

Can you provide more info: Paste the output of these commands from WLC.

1. sh wlan <wlan_id>

2. Sh sysinfo

Regards

ahcadmin1 · ‎08-27-2015

I would rather not. I can provide any info you need specifically though.

mohanak · ‎08-28-2015

Standardize WLC debug messages across release

CSCut93840

Description

Symptom:
Debug logs from WLC look in different format in different releases

Conditions:
Prior to 7.6 release, on WLC debug client output looked like:

*apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 192.168.120.21 START (0) Deleted mobile LWAPP rule on AP [ec:c8:82:a4:5b:c0]

After 8.0:
*apfMsConnTask_3: Jan 28 10:38:53.305: [PA] 00:0e:8e:50:86:87 Applying Interface policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 523
*apfMsConnTask_3: Jan 28 10:38:53.305: [PA] 00:0e:8e:50:86:87 Re-applying interface policy for client

We started adding works [PA] into debugs which is of no useful info. But affects debug parsers like https://scripts.cisco.com/ui/use/WirelessDebugClientGold

Need to make sure that we have a standard version for future parsing needs and not keep editing the way debug looks.

Mobile device reassociation