WLC Client Debug – Part 2

17 Friday Oct 2014

Posted by nayarasi in Wireless Troubleshooting

Tags

In this post we will see how to utilize “debug clinet x.x.x.x” output to understand the process a wireless client go through get connected to WPA2-PSK configured wireless network. Here is the basic topology used in this post

Compare to Open Authentication (see WLC Client Debug – Part 1 post for detail) you would see the 4-Way handshake process takes place to derive the encryption keys prior to go through the DHCP process. Here is the summary steps you should see in this WPA2-PSK client association process.

1. Open System Authentication (Request initiate by client)
2. Open system Authentication (Response by AP)
3. Association Request (sent by client)
4. Association Response (send by AP)
5. 4-Way Handshake – EAPoL Key Exchange Message 1
6. 4-Way Handshake – EAPoL Key Exchange Message 2
7. 4-Way Handshake – EAPoL Key Exchange Message 3
8. 4-Way Handshake – EAPoL Key Exchange Message 4
9. DHCP Discover (send by client to L2 broadcast)
10. DHCP Offer (send by DHCP server)
11. DHCP Reqeust (send by client to L2 broadcast)
12. DHCP ACK (send by DHCP server to client)

Once you issue the “debug client x.x.x.x” CLI command you would see it give the output detailing what’s happening. If you understand this debug, then it is easy to identify issues come across.

(5508-1) > debug client 04:f7:e4:ea:5b:66
*apfMsConnTask_5: Oct 17 09:20:02.901: 04:f7:e4:ea:5b:66 Processing assoc-req station:04:f7:e4:ea:5b:66 AP:1c:6a:7a:bc:4d:60-01 thread:150e53e0
*apfMsConnTask_5: Oct 17 09:20:02.901: 04:f7:e4:ea:5b:66 Adding mobile on LWAPP AP 1c:6a:7a:bc:4d:60(1) 
*apfMsConnTask_5: Oct 17 09:20:02.901: 04:f7:e4:ea:5b:66 Association received from mobile on BSSID 1c:6a:7a:bc:4d:5c AP TEST-AP

For the simplicity I have stripped “*apfMsConnTask_5: Oct 17” from the above debug output. (Full output attached at the end of the post). As you can see client state move from START(0) -> AUTHCHECK (2) -> 802.1X_REQD (3) during this open authentication phase.

09:20:02.901: 04:f7:e4:ea:5b:66 Processing assoc-req station:04:f7:e4:ea:5b:66 AP:1c:6a:7a:bc:4d:60-01 thread:150e53e0
09:20:02.901: 04:f7:e4:ea:5b:66 Adding mobile on LWAPP AP 1c:6a:7a:bc:4d:60(1) 
09:20:02.901: 04:f7:e4:ea:5b:66 Association received from mobile on BSSID 1c:6a:7a:bc:4d:5c AP TEST-AP
09:20:02.901: 04:f7:e4:ea:5b:66 Global 200 Clients are allowed to AP radio
09:20:02.901: 04:f7:e4:ea:5b:66 Max Client Trap Threshold: 0  cur: 0
09:20:02.901: 04:f7:e4:ea:5b:66 Rf profile 600 Clients are allowed to AP wlan
09:20:02.901: 04:f7:e4:ea:5b:66 override for default ap group, marking intgrp NULL
09:20:02.901: 04:f7:e4:ea:5b:66 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0
09:20:02.901: 04:f7:e4:ea:5b:66 Re-applying interface policy for client 
09:20:02.901: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
09:20:02.901: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
09:20:02.901: 04:f7:e4:ea:5b:66 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
09:20:02.901: 04:f7:e4:ea:5b:66 In processSsidIE:5680 setting Central switched to TRUE
09:20:02.901: 04:f7:e4:ea:5b:66 In processSsidIE:5683 apVapId = 1 and Split Acl Id = 65535
09:20:02.901: 04:f7:e4:ea:5b:66 Applying site-specific Local Bridging override for station 04:f7:e4:ea:5b:66 - vapId 20, site 'LTU-APG1', interface 'vlan1422'
09:20:02.901: 04:f7:e4:ea:5b:66 Applying Local Bridging Interface Policy for station 04:f7:e4:ea:5b:66 - vlan 1422, interface id 13, interface 'vlan1422'
09:20:02.902: 04:f7:e4:ea:5b:66 override from ap group, removing intf group from mscb
09:20:02.902: 04:f7:e4:ea:5b:66 Applying site-specific override for station 04:f7:e4:ea:5b:66 - vapId 20, site 'LTU-APG1', interface 'vlan1422'
09:20:02.902: 04:f7:e4:ea:5b:66 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 1422
09:20:02.902: 04:f7:e4:ea:5b:66 Re-applying interface policy for client 
09:20:02.902: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385)
09:20:02.902: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406)
09:20:02.902: 04:f7:e4:ea:5b:66 processSsidIE  statusCode is 0 and status is 0 
09:20:02.902: 04:f7:e4:ea:5b:66 processSsidIE  ssid_done_flag is 0 finish_flag is 0
09:20:02.902: 04:f7:e4:ea:5b:66 STA - rates (4): 176 72 96 108 0 0 0 0 0 0 0 0 0 0 0 0
09:20:02.902: 04:f7:e4:ea:5b:66 suppRates  statusCode is 0 and gotSuppRatesElement is 1 
09:20:02.902: RSNIE in Assoc. Req.: (20)
09:20:02.902:      [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f
09:20:02.902:      [0016] ac 02 0c 00
09:20:02.902: 04:f7:e4:ea:5b:66 Processing RSN IE type 48, length 20 for mobile 04:f7:e4:ea:5b:66
09:20:02.902: 04:f7:e4:ea:5b:66 Received 802.11i PSK key management suite, enabling Authentication
09:20:02.902: 04:f7:e4:ea:5b:66 RSN Capabilities:  12
09:20:02.902: 04:f7:e4:ea:5b:66 apfValidateDot11iCapabilities:1122 Received RSNIE with Capabilities with STA MFPC: 0, STA MFPR:0, & AP MFPC:0MFPR:0
09:20:02.902: 04:f7:e4:ea:5b:66 Marking Mobile as non-11w Capable 
09:20:02.902: 04:f7:e4:ea:5b:66 apfValidateDot11wGroupMgmtCipher:1552, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning
09:20:02.902: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Initializing policy
09:20:02.902: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)
09:20:02.902: 04:f7:e4:ea:5b:66 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)
09:20:02.902: 04:f7:e4:ea:5b:66 Encryption policy is set to 0x80000001
09:20:02.902: 04:f7:e4:ea:5b:66 Not Using WMM Compliance code qosCap 00
09:20:02.902: 04:f7:e4:ea:5b:66 Sending 11w Flag 0 for Client 04:F7:E4:EA:5B:66 
09:20:02.902: 04:f7:e4:ea:5b:66 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 1c:6a:7a:bc:4d:60 vapId 20 apVapId 1 flex-acl-name: 
09:20:02.903: 04:f7:e4:ea:5b:66 apfMsAssoStateInc
09:20:02.903: 04:f7:e4:ea:5b:66 apfMsWepPskStateInc
09:20:02.903: 04:f7:e4:ea:5b:66 apfPemAddUser2 (apf_policy.c:352) Changing state for mobile 04:f7:e4:ea:5b:66 on AP 1c:6a:7a:bc:4d:60 from Idle to Associated
09:20:02.903: 04:f7:e4:ea:5b:66 apfPemAddUser2:session timeout forstation 04:f7:e4:ea:5b:66 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0 
09:20:02.903: 04:f7:e4:ea:5b:66 Stopping deletion of Mobile Station: (callerId: 48)
09:20:02.903: 04:f7:e4:ea:5b:66 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0
09:20:02.903: 04:f7:e4:ea:5b:66 Sending assoc-resp with status 0 station:04:f7:e4:ea:5b:66 AP:1c:6a:7a:bc:4d:60-01 on apVapId 1
09:20:02.903: 04:f7:e4:ea:5b:66 Sending Assoc Response to station on BSSID 1c:6a:7a:bc:4d:6f (status 0) ApVapId 1 Slot 1
09:20:02.903: 04:f7:e4:ea:5b:66 apfProcessAssocReq (apf_80211.c:9452) Changing state for mobile 04:f7:e4:ea:5b:66 on AP 1c:6a:7a:bc:4d:60 from Associated to Associated
09:20:02.905: 04:f7:e4:ea:5b:66 Got action frame from this client.

Here are the initial 4 frames (Authentication Request, Authentication Response, Association Request, Association Response) captured during the process.

Here is the Authentication response sent by AP. Note that status code 0 for successful open system authentication.Here is the client association request specifying the CCMP (00-0F-AC-04) listed as encryption cipher & PSK (00-0F-AC-02) listed as Auth cipher in RSN IE.

Here is the association response from AP confirming successful association (status code 0) where AID is allocated.Once Open System Authentication & association Phase is completed it will move onto 4-Way handsahke process. In PSK method, Pairwise Master Key (PMK) is derived from the PSK (Preshared Key). Then PMK is used to derive PTK which use to encrypt unicast traffic (Group Temporal Key – GTK is used for multicast/broadcast traffic encryption). These debug messages you will see like this.

*Dot1x_NW_MsgTask_6: Oct 17 09:20:02.905: 04:f7:e4:ea:5b:66 reauth_sm state transition 0 ---> 1 for mobile 04:f7:e4:ea:5b:66 at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_6: Oct 17 09:20:02.905: 04:f7:e4:ea:5b:66 Creating a PKC PMKID Cache entry for station 04:f7:e4:ea:5b:66 (RSN 2)
*Dot1x_NW_MsgTask_6: Oct 17 09:20:02.905: 04:f7:e4:ea:5b:66 Resetting MSCB PMK Cache Entry 0 for station 04:f7:e4:ea:5b:66

Again for the simplicity I have stripped “*Dot1x_NW_MsgTask_6: Oct 17 ” from the below. As you can see in the debug messages AP will start the 4-way handshaking by sending message 1 to the client. Also it create PMKID (14 d6 77 1e 1b eb f2 54 89 91 4d 2f 5f 90 ad c3) for this association & include it in message 1. This message include Authenticator Nonce (A Nonce) which require by client to derive PTK.

*spamApTask7: Oct 17 09:20:02.905: 04:f7:e4:ea:5b:66 Sent 1x initiate message to multi thread task for mobile 04:f7:e4:ea:5b:66
09:20:02.905: 04:f7:e4:ea:5b:66 reauth_sm state transition 0 ---> 1 for mobile 04:f7:e4:ea:5b:66 at 1x_reauth_sm.c:47
09:20:02.905: 04:f7:e4:ea:5b:66 Creating a PKC PMKID Cache entry for station 04:f7:e4:ea:5b:66 (RSN 2)
09:20:02.905: 04:f7:e4:ea:5b:66 Resetting MSCB PMK Cache Entry 0 for station 04:f7:e4:ea:5b:66
09:20:02.905: 04:f7:e4:ea:5b:66 Setting active key cache index 8 ---> 8
09:20:02.905: 04:f7:e4:ea:5b:66 Setting active key cache index 8 ---> 0
09:20:02.905: 04:f7:e4:ea:5b:66 Adding BSSID 1c:6a:7a:bc:4d:6f to PMKID cache at index 0 for station 04:f7:e4:ea:5b:66
09:20:02.905: New PMKID: (16)
09:20:02.905:      [0000] 14 d6 77 1e 1b eb f2 54 89 91 4d 2f 5f 90 ad c3
09:20:02.905: 04:f7:e4:ea:5b:66 Initiating RSN PSK to mobile 04:f7:e4:ea:5b:66
09:20:02.905: 04:f7:e4:ea:5b:66 EAP-PARAM Debug - eap-params for Wlan-Id :20 is disabled - applying Global eap timers and retries
09:20:02.905: 04:f7:e4:ea:5b:66 Disable re-auth, use PMK lifetime.
09:20:02.905: 04:f7:e4:ea:5b:66 dot1x - moving mobile 04:f7:e4:ea:5b:66 into Force Auth state
09:20:02.906: 04:f7:e4:ea:5b:66 Skipping EAP-Success to mobile 04:f7:e4:ea:5b:66
09:20:02.906: 04:f7:e4:ea:5b:66 Found an cache entry for BSSID 1c:6a:7a:bc:4d:6f in PMKID cache at index 0 of station 04:f7:e4:ea:5b:66
09:20:02.906: 04:f7:e4:ea:5b:66 Found an cache entry for BSSID 1c:6a:7a:bc:4d:6f in PMKID cache at index 0 of station 04:f7:e4:ea:5b:66
09:20:02.906: Including PMKID in M1  (16)
09:20:02.906:      [0000] 14 d6 77 1e 1b eb f2 54 89 91 4d 2f 5f 90 ad c3
09:20:02.906: 04:f7:e4:ea:5b:66 Starting key exchange to mobile 04:f7:e4:ea:5b:66, data packets will be dropped
09:20:02.906: 04:f7:e4:ea:5b:66 Sending EAPOL-Key Message to mobile 04:f7:e4:ea:5b:66
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00

Here is the frame capture of M1. As you can see those ANonce & PMKID in there. Also note that AP send it as UP value 7 which is highest priority that can set.

Then client will respond with message 2 (M2). By this time client already derive the PTK (using PMK, Anonce, Snonnce, Authenticator add, Supplicant address) & encrypt the M2 using PTK.

09:20:02.906: 04:f7:e4:ea:5b:66 Allocating EAP Pkt for retransmission to mobile 04:f7:e4:ea:5b:66
09:20:02.909: 04:f7:e4:ea:5b:66 Received EAPOL-Key from mobile 04:f7:e4:ea:5b:66
09:20:02.909: 04:f7:e4:ea:5b:66 Received EAPOL-key in PTK_START state (message 2) from mobile 04:f7:e4:ea:5b:66
09:20:02.909: 04:f7:e4:ea:5b:66 Dumping RSNIE received in Association request:
09:20:02.909: 00000000: 30 14 01 00 00 0f ac 04  01 00 00 0f ac 04 01 00  0...............
09:20:02.909: 00000010: 00 0f ac 02 0c 00                                 ......
09:20:02.909: 04:f7:e4:ea:5b:66 Dumping RSNIE received in EAPOL M2 :
09:20:02.909: 00000000: 01 00 00 0f ac 04 01 00  00 0f ac 04 01 00 00 0f  ................
09:20:02.909: 00000010: ac 02 0c 00                                       ....
09:20:02.909: 04:f7:e4:ea:5b:66 Stopping retransmission timer for mobile 04:f7:e4:ea:5b:66

Here is the M2 frame capture. Note that since my client is not set any UP value on this (so default 0). Also you see MIC in use & S-Nonce send to AP to compute PTK. Also M2 include the RSN-IE indicate client capability (Auth & Encryp ciphers)

Then AP/WLC derive the the GTK & send it to client using M3. This key is used for broadcast/multicast traffic encryption. By this time since AP derived the PTK it will encrypt this using PTK & using MIC.

09:20:02.909: 04:f7:e4:ea:5b:66 Sending EAPOL-Key Message to mobile 04:f7:e4:ea:5b:66
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
09:20:02.909: 04:f7:e4:ea:5b:66 Reusing allocated memory for  EAP Pkt for retransmission to mobile 04:f7:e4:ea:5b:66

Here is the M3 frame capture. Note that key data encrypted & MIC in used. Also install bit set to 1 to inform client to install these GTK.

Finally client send M4 to complete the 4-Way Handshake process. Then client state on the WLC move from 802.1X_REQD(3) to L2AUTHCOMPLETE(4)

09:20:02.912: 04:f7:e4:ea:5b:66 Received EAPOL-Key from mobile 04:f7:e4:ea:5b:66
09:20:02.912: 04:f7:e4:ea:5b:66 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 04:f7:e4:ea:5b:66
09:20:02.912: 04:f7:e4:ea:5b:66 Stopping retransmission timer for mobile 04:f7:e4:ea:5b:66
09:20:02.912: 04:f7:e4:ea:5b:66 Freeing EAP Retransmit Bufer for mobile 04:f7:e4:ea:5b:66
09:20:02.912: 04:f7:e4:ea:5b:66 apfMs1xStateInc
09:20:02.912: 04:f7:e4:ea:5b:66 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)
09:20:02.912: 04:f7:e4:ea:5b:66 Mobility query, PEM State: L2AUTHCOMPLETE
09:20:02.912: mm_exec_mobAgent_fsm:597 currState:Init, event:MM_MAFSM_EV_FULL_AUTH, caller mmMaRxAssocReq:6613
09:20:02.912: 04:f7:e4:ea:5b:66 OUthdr length is 74 
09:20:02.912: 04:f7:e4:ea:5b:66 mmBuildMsgVlanIdPayload: rc1 = 0,no vlan group. intfName = vlan1422 Vlanid = 0 
*mcListen: Oct 17 09:20:02.912: 04:f7:e4:ea:5b:66 MC:Mobile announce received from internal MA, will fwd this to peer MC,Xid 63508, Retry#0.
*mcListen: Oct 17 09:20:02.913: Mobile announce from MA and Client entry not found, groupcasted to peer MC's
09:20:02.913: 04:f7:e4:ea:5b:66 Not Using WMM Compliance code qosCap 00
09:20:02.913: 04:f7:e4:ea:5b:66 Sending 11w Flag 0 for Client 04:F7:E4:EA:5B:66 
09:20:02.913: 04:f7:e4:ea:5b:66 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 1c:6a:7a:bc:4d:60 vapId 20 apVapId 1 flex-acl-name:

Here is the M4 frame capture.Once 4 way handshake completes you will see DHCP related debug messages coming during client trying to get the IP. You will see these messages start with “*DHCP Socket Task: Oct 17 ” but stripped it for simplicity. You can see the mobility messages (starging with *mmMaListen:) in this debug with respect to this client MAC.

09:20:02.913: 04:f7:e4:ea:5b:66 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)
09:20:02.913: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6486, Adding TMP rule
09:20:02.913: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
  type = Airespace AP - Learn IP address
  on AP 1c:6a:7a:bc:4d:60, slot 1, interface = 1, QOS = 2
  IPv4 ACL ID = 255, IPv
09:20:02.913: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 6, DSCP = 0, TokenID = 15206, IntfId = 13  Local Bridging Vlan = 1422, Local Bridging intf id = 13
09:20:02.913: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 
09:20:02.913: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 
09:20:02.914: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 
09:20:02.914: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*pemReceiveTask: Oct 17 09:20:02.914: 04:f7:e4:ea:5b:66 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
09:20:04.163: 04:f7:e4:ea:5b:66 DHCP received op BOOTREQUEST (1) (len 308,vlan 1600, port 1, encap 0xec03)
09:20:04.163: 04:f7:e4:ea:5b:66 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
09:20:04.163: 04:f7:e4:ea:5b:66 DHCP dropping packet due to ongoing mobility handshake exchange, (siaddr 0.0.0.0,  mobility state = 'apfMsMmQueryRequested'

*mmMaListen: Oct 17 09:20:04.861: Entering maMCAnnounceMipResendTimeoutNotify
*mmMaListen: Oct 17 09:20:04.862: 04:f7:e4:ea:5b:66 Mobility packet retry: Peer IP: 0.0.0.0, Anchor IP: 0.0.0.0
*mmMaListen: Oct 17 09:20:04.862: Leaving maMCAnnounceMipResendTimeoutNotify
*mcListen: Oct 17 09:20:04.862: 04:f7:e4:ea:5b:66 MC:Mobile announce received from internal MA, will fwd this to peer MC,Xid 63508, Retry#2.
*mcListen: Oct 17 09:20:04.862: Mobile announce from MA and Client entry not found, groupcasted to peer MC's
*mmMaListen: Oct 17 09:20:05.862: Entering maMCAnnounceMipResendTimeoutNotify
*mmMaListen: Oct 17 09:20:05.862: Executing the state machine in maMCAnnounceMipResendTimeoutNotify
*mmMaListen: Oct 17 09:20:05.862: mm_exec_mobAgent_fsm:597 currState:Init_Wait_Announce_Response, event:MM_MAFSM_EV_MA_NAK_FROM_MC_OR_MAX_RETX_TIMEOUT, caller maMCAnnounceMipResendTimeoutNotify:5876
*mmMaListen: Oct 17 09:20:05.862: Entering mmMA_TxHdoffComplete2MC 
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) mobility role update request from Unassociated to Local
  Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 10.160.33.1
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6102, Adding TMP rule
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule
  type = Airespace AP - Learn IP address
  on AP 1c:6a:7a:bc:4d:60, slot 1, interface = 1, QOS = 2
  IPv4 ACL ID = 255, 
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 6, DSCP = 0, TokenID = 15206, IntfId = 13  Local Bridging Vlan = 1422, Local Bridging intf id = 13
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0 
*mmMaListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*mmMaListen: Oct 17 09:20:05.862: Entering mmBuildMsgHandoffComplete
*mmMaListen: Oct 17 09:20:05.862: Leaving mmBuildMsgHandoffComplete
*mmMaListen: Oct 17 09:20:05.862: Leaving mmMA_TxHdoffComplete2MC
*mcListen: Oct 17 09:20:05.862: Found tunnel id 0 for 10.160.33.1
*mmMaListen: Oct 17 09:20:05.862: Leaving maMCAnnounceMipResendTimeoutNotify
*mcListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 Handoff Complete msg for Client(Ip: 0.0.0.0 roam-type: None)Sender(Ip: 10.160.33.1 Type: 1) Anchor(Ip: 0.0.0.0  MC : 0.0.0.0)Foreign(Ip : 0.0.0.0 MC : 0.0.0.0)
*pemReceiveTask: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*mcListen: Oct 17 09:20:05.862: 04:f7:e4:ea:5b:66 Created a new Client Entry for  04:F7:E4:EA:5B:66 
*pemReceiveTask: Oct 17 09:20:05.863: 04:f7:e4:ea:5b:66 Sent an XID frame
*mcListen: Oct 17 09:20:05.863: 04:f7:e4:ea:5b:66 Handoff Complete Ack Done sent to IP: 10.160.33.1
*mcListen: Oct 17 09:20:05.863: 04:f7:e4:ea:5b:66 Handoff complete from MA,client->clientState is 0, anchorMcIp is 0,oldForeignMcIp is 0  
*mcListen: Oct 17 09:20:05.863: 04:f7:e4:ea:5b:66 DROPPING mcFwdHandOff as anchorMcIp is 0.0.0.0
*mcListen: Oct 17 09:20:05.863: 04:f7:e4:ea:5b:66 Could not forward handoff complete to MO
*mcListen: Oct 17 09:20:05.863: 04:f7:e4:ea:5b:66 MC: Changing client state from Init to Local
*mmMaListen: Oct 17 09:20:05.863: mm_exec_mobAgent_fsm:597 currState:Local, event:MM_MAFSM_EV_HDOFF_COMPL_ACK, caller mmProcessInMsg:1332
*mmMaListen: Oct 17 09:20:05.863: Entering mmMA_Tun2Peer

Then client go through DHCP DORA (Discover, Offer, Request & ACK) process to get the IP. Most of the time clients requesting previously associated wireless network IP, so most of the case you will see a NACK initially for that request. You can see in my case client sending a DHCP Request for x.x.y4.58 IP which is NACK by DHCP as that IP is not what WLC configured for this SSID.

Here is the debug related to this. You can see client move from DHCP_REQD(7) to RUN(20) which is the final operational status you should see.

09:20:06.263: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP REQUEST (3)
09:20:06.264: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 2
09:20:06.264: 04:f7:e4:ea:5b:66 DHCP   xid: 0x7071adbc (1886498236), secs: 4, flags: 0
09:20:06.264: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
09:20:06.264: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
09:20:06.264: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: x.x.x8.120
09:20:06.264: 04:f7:e4:ea:5b:66 DHCP   requested ip: x.x.y4.58
09:20:06.264: 04:f7:e4:ea:5b:66 DHCP sending REQUEST to x.x.x8.125 (len 350, port 1, vlan 1422)
09:20:06.265: 04:f7:e4:ea:5b:66 DHCP received op BOOTREPLY (2) (len 308,vlan 1422, port 1, encap 0xec00)
09:20:06.265: 04:f7:e4:ea:5b:66 DHCP sending REPLY to STA (len 418, port 1, vlan 1600)
09:20:06.265: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP NAK (6)

09:20:06.409: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP DISCOVER (1)
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP   xid: 0x7071adbd (1886498237), secs: 0, flags: 0
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: x.x.x8.120
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP sending REQUEST to x.x.x8.125 (len 350, port 1, vlan 1422)
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP selecting relay 2 - control block settings:
                        dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0,
                        dhcpGateway: 0.0.0.0, dhcpRelay: x.x.x8.120  VLAN: 1422
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP selected relay 2 - x.x.x6.200 (local address x.x.x8.120, gateway x.x.x8.125, VLAN 1422, port 1)
09:20:06.409: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP DISCOVER (1)
09:20:06.410: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 2
09:20:06.410: 04:f7:e4:ea:5b:66 DHCP   xid: 0x7071adbd (1886498237), secs: 0, flags: 0
09:20:06.410: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
09:20:06.410: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
09:20:06.410: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: x.x.x8.120
09:20:06.410: 04:f7:e4:ea:5b:66 DHCP sending REQUEST to x.x.x8.125 (len 350, port 1, vlan 1422)
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP received op BOOTREPLY (2) (len 308,vlan 1422, port 1, encap 0xec00)
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP setting server from OFFER (server x.x.x6.100, yiaddr x.x.x8.67)
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP sending REPLY to STA (len 418, port 1, vlan 1600)
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP OFFER (2)
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP   xid: 0x7071adbd (1886498237), secs: 0, flags: 0
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: x.x.x8.67
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: 0.0.0.0
09:20:07.413: 04:f7:e4:ea:5b:66 DHCP   server id: 192.0.2.1  rcvd server id: x.x.x6.100
*apfLbsTask: Oct 17 09:20:07.862: 04:f7:e4:ea:5b:66 Copy AP LOCP - mode:0 slotId:137, apMac 0x1c:6a:7a:bc:4d:60
*apfLbsTask: Oct 17 09:20:07.862: 04:f7:e4:ea:5b:66 Copy WLAN LOCP EssIndex:20 aid:1 ssid: ABC-PSK
*apfLbsTask: Oct 17 09:20:07.862: 04:f7:e4:ea:5b:66 Copy Security LOCP ecypher:0x0 ptype:0x2, p:0x1, eaptype:0x6 w:0x1 aalg:0x0, PMState:  DHCP_REQD
*apfLbsTask: Oct 17 09:20:07.862: 04:f7:e4:ea:5b:66 Copy 802.11 LOCP a:0x0 b:0x0 c:0x0 d:0x0 e:0x0  protocol1:0x0 protocol2:0x7 statuscode 0, reasoncode 99, status 3
*apfLbsTask: Oct 17 09:20:07.862: 04:f7:e4:ea:5b:66 Copy MobilityData LOCP status:1, anchorip:0x0
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP received op BOOTREQUEST (1) (len 308,vlan 1600, port 1, encap 0xec03)
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP selecting relay 1 - control block settings:
                        dhcpServer: x.x.x6.100, dhcpNetmask: 0.0.0.0,
                        dhcpGateway: 0.0.0.0, dhcpRelay: x.x.x8.120  VLAN: 1422
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP mscbVapLocalAddr=x.x.x8.120 mscbVapLocalNetMask= 255.255.255.128 mscbdhcpRelay=x.x.x8.120
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP selected relay 1 - x.x.x6.100 (local address x.x.x8.120, gateway x.x.x8.125, VLAN 1422, port 1)
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP REQUEST (3)
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP   xid: 0x7071adbd (1886498237), secs: 2, flags: 0
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: x.x.x8.120
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP   requested ip: x.x.x8.67
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP   server id: x.x.x6.100  rcvd server id: 192.0.2.1
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP sending REQUEST to x.x.x8.125 (len 350, port 1, vlan 1422)
09:20:08.514: 04:f7:e4:ea:5b:66 DHCP selecting relay 2 - control block settings:
                        dhcpServer: x.x.x6.100, dhcpNetmask: 0.0.0.0,
                        dhcpGateway: 0.0.0.0, dhcpRelay: x.x.x8.120  VLAN: 1422
09:20:08.515: 04:f7:e4:ea:5b:66 DHCP selected relay 2 - NONE
09:20:08.517: 04:f7:e4:ea:5b:66 DHCP received op BOOTREPLY (2) (len 308,vlan 1422, port 1, encap 0xec00)
09:20:08.517: 04:f7:e4:ea:5b:66 DHCP setting server from ACK (mscb=0x45e90d90 ip=0x83ac1c43)(server x.x.x6.100, yiaddr x.x.x8.67)
09:20:08.517: 04:f7:e4:ea:5b:66 apfMsRunStateInc
09:20:08.517: 04:f7:e4:ea:5b:66 x.x.x8.67 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7)

From the frame captures you won’t be able to see the data as everything is encrypted using PTK & GTK (unicast & broadcast/multicast frames respectively). So if you really want to see the capture detail you have to decrypt (Using wireshark you can decrypt WPA2-PSK frames). Using that method I have identified the frame number related to those DHCP packet flow.

Here is the frame 2290 capture view which is DHCP Discover sent by client to L2 broadcast address. All frame body is encrypted (note that MAC header frame control field indicated this by setting protected frame to 1)

Here is the rest of DHCP frames (Offer, Request & ACK) in frame capture view. One interesting thing I noticed is Cisco AP set UP value 3 for the Best Effort by default (0 & 3 used for AC_BE. most of the casese vendors set it to 0 by default)

Reference
1. WLC-PSK-debug (debug client 04:f7:e4:ea:5b:66 complete output)

1. WLC Client Debug – Part 1 (Open Authentication)
2. WLC Client Debug- Part 3 (802.1X)

29 thoughts on “WLC Client Debug – Part 2”

Vishweswaran said:

October 18, 2014 at 3:37 am

Thank you so much for this great knowledge sharing 🙂

Reply
- nayarasi said:
  
  October 18, 2014 at 6:37 am
  
  No worries.. good to see it is useful..
  
  Reply
babak said:

October 22, 2014 at 12:51 pm

Thanks so much for this. waiting for the last part 🙂

Reply
Davide Mollica said:

December 16, 2015 at 11:25 am

Very detailed post. Just what the customer ordered!

Reply
- nayarasi said:
  
  December 16, 2015 at 12:15 pm
  
  Good to see you find it useful Davide.
  
  Reply
Juan said:

February 8, 2016 at 10:29 pm

Thanks so much for this. waiting for the last part

Reply
- nayarasi said:
  
  February 9, 2016 at 3:25 pm
  
  I know 🙂 , it is long outstanding & I will do it somehow.
  
  HTH
  Rasika
  
  Reply
mandeep said:

April 17, 2016 at 9:18 pm

It is Grt… pls complete Trilogy 😉

Reply
- nayarasi said:
  
  April 20, 2016 at 9:25 am
  
  Thanks, Will do somehow 🙂
  
  Reply
Harprit said:

July 15, 2016 at 8:14 pm

Hello Mate, Which tool you use to capture wireless packets? Also waiting for 3rd part.Thanks a lot for knowledge sharing.

Reply
- nayarasi said:
  
  July 19, 2016 at 4:04 pm
  
  I used Omnipeek (now – https://www.savvius.com/)
  
  Yes, will find some energy/motivation to part 3 which is long overdue 🙂
  
  HTH
  Rasika
  
  Reply
daoquocsi said:

December 1, 2016 at 2:55 pm

Hope to see part 3 soon. Thanks for your effort making two first part.

Reply
me said:

January 20, 2017 at 9:45 am

Love your first 2 parts, would love to see your post for WLC Client Debug- Part 3 (802.1X).

Thanks for posting.

Reply
- nayarasi said:
  
  January 20, 2017 at 1:22 pm
  
  Yes, it is long due 🙂 will some how complete in this year 🙂
  
  Rasika
  
  Reply
ignacioaraneda said:

June 16, 2017 at 7:29 am

Hiii. i’m ignacio from chile … i have a problem with 802.1x and ap flexconect in peru… i need some help

Reply
- nayarasi said:
  
  June 16, 2017 at 9:58 am
  
  Hi
  Pls post a thread in below CSC forum with more details of your issue. I am sure we will be able to help you
  
  https://supportforums.cisco.com/community/5921/other-wireless-mobility-subjects
  
  Rasika
  
  Reply
Korben Dalas said:

September 7, 2018 at 8:54 pm

Hi do you have a 3th part of this trilogy? i have problem with Motorola/Symbol handheld MC9090/9190/92N0 , when this handhald crash on WPA2 4-way handshake randomly. i set all on WLC5520 by cisco KB , but i have not solved the problem. :-(( I’m desperate. 😦

Reply
- nayarasi said:
  
  September 8, 2018 at 7:12 am
  
  Hi Korben,
  
  I am sorry, it did not come as planned. Will try to complete that post sometime in future
  
  I would suggest you to work with TAC on your case, most probably it may due to current code version you running
  
  HTH
  Rasika
  
  Reply
sids john said:

April 15, 2019 at 3:36 pm

any updates on WLC Client Debug- Part 3 (802.1X) ?
thank you!

Reply
- nayarasi said:
  
  July 11, 2021 at 7:40 am
  
  Here is the link
  https://mrncciew.com/2019/06/03/wlc-client-debug-part-3/
  
  Rasika
  
  Reply
Si Dao said:

July 3, 2019 at 2:53 pm

Do you know what is LOCP: stand for?

Reply
- nayarasi said:
  
  July 18, 2019 at 3:29 pm
  
  Location Protocol. Search LOCP messages in below link
  https://www.cisco.com/c/en/us/td/docs/wireless/controller/8-0/message/guide/sysmsg80/license_locp_log_msgs14.html#pgfId-1008786
  
  Reply
Otiynomed said:

February 7, 2020 at 9:24 am

Would it be possible that a wireless client already associated to an AP would authenticate to a different AP?

Reply
- nayarasi said:
  
  July 11, 2021 at 7:36 am
  
  At the time of roaming, yes they can do it (802.11r – Over the DS method). Prior to 11r there was a method called “pre-authentication” which was not standard based, several vendors supported it. Now a days 11r is the standard method and every AP vendors support it.
  
  HTH
  Rasika
  
  Reply
Bala said:

January 28, 2022 at 2:48 pm

2. WLC Client Debug- Part 3 (802.1X) – seems this is not available

Reply
- nayarasi said:
  
  July 1, 2022 at 6:20 am
  
  Here is the link to part 3. Pls use the search option on the blog to find the content you need.
  https://mrncciew.com/2019/06/03/wlc-client-debug-part-3/
  
  HTH
  Rasika
  
  Reply
Kabeer said:

June 23, 2022 at 9:05 pm

Could you please let me know the debug which i have collected from the 5508 WLC for my clients who are unable to connect to the Wireless shows, sending packet to radius server, succsessfull transmision of authetication packet and then Retransmit the ‘Access-Request to radius server” which is happening, and after that
54 Access-Challenge received from RADIUS server 10.10.10.10 ”

Kindly advice and let me know what i’m suspecting is radius server is the problem here ?

*radiusTransportThread: Jun 23 13:16:49.298: [PA] ec:d0:64:4f:4g:54Retransmit the ‘Access-Request’ (id 56) to 10.10.10.10 (port 1812, qid 2) reached for mobile. msg retx 2 srvr retx 1 srvr evt 0 srvr tried 0
*radiusTransportThread: Jun 23 13:16:49.298: [PA] ec:d0:64:4f:4g:54 Sending the packet to v4 host 10.10.10.10:1812 of length 1619
*radiusTransportThread: Jun 23 13:16:49.298: [PA] ec:d0:64:4f:4g:54 Successful transmission of Authentication Packet (pktId 56) to 10.10.10.10:1812 from server queue 2, proxy state ec:d0:64:4f:4g:54-04:07
*radiusTransportThread: Jun 23 13:16:54.608: [PA] ec:d0:64:4f:4g:54 Retransmit the ‘Access-Request’ (id 56) to 10.10.10.10 (port 1812, qid 2) reached for mobile. msg retx 3 srvr retx 2 srvr evt 0 srvr tried 0
*radiusTransportThread: Jun 23 13:16:54.608: [PA] ec:d0:64:4f:4g:54 Sending the packet to v4 host 10.10.10.10:1812 of length 1619
*radiusTransportThread: Jun 23 13:16:54.608: [PA] ec:d0:64:4f:4g:54 Successful transmission of Authentication Packet (pktId 56) to 10.10.10.10:1812 from server queue 2, proxy state ec:d0:64:4f:4g:54-04:07
*radiusTransportThread: Jun 23 13:16:59.704: [PA] ec:d0:64:4f:4g:54 Retransmit the ‘Access-Request’ (id 56) to 10.10.10.10 (port 1812, qid 2) reached for mobile. msg retx 4 srvr retx 2 srvr evt 0 srvr tried 0
*radiusTransportThread: Jun 23 13:16:59.704: [PA] ec:d0:64:4f:4g:54 Sending the packet to v4 host 10.10.10.10:1812 of length 1619
*radiusTransportThread: Jun 23 13:16:59.704: [PA] ec:d0:64:4f:4g:54 Successful transmission of Authentication Packet (pktId 56) to 10.10.10.10:1812 from server queue 2, proxy state ec:d0:64:4f:4g:54-04:07
*radiusTransportThread: Jun 23 13:17:04.808: [PA] Radius Passive Fallback – Auth server is not ready 10.76.114.74 port 1812
*radiusTransportThread: Jun 23 13:17:04.809: [PA] ec:d0:64:4f:4g:54 Retransmit the ‘Access-Request’ (id 56) to 10.10.10.10 (port 1812, qid 2) reached for mobile. msg retx 5 srvr retx 1 srvr evt 0 srvr tried 0
*radiusTransportThread: Jun 23 13:17:04.809: [PA] ec:d0:64:4f:4g:54 Sending the packet to v4 host 10.10.10.10:1812 of length 1619
*radiusTransportThread: Jun 23 13:17:04.809: [PA] ec:d0:64:4f:4g:54 Successful transmission of Authentication Packet (pktId 56) to 10.10.10.10:1812 from server queue 2, proxy state ec:d0:64:4f:4g:54-04:07
*radiusTransportThread: Jun 23 13:17:04.892: [PA] ec:d0:64:4f:4g:54 Access-Challenge received from RADIUS server 10.10.10.10 (qid:2) with port:1812, pktId:56

Reply
- nayarasi said:
  
  July 1, 2022 at 6:10 am
  
  I hope you know about this debug analyzer tool, if not i would use that to get some insight
  https://cway.cisco.com/wireless-debug-analyzer
  
  HTH
  Rasika
  
  Reply
  - Kabeer said:
    
    July 1, 2022 at 3:38 pm
    
    Thank you so much Nayarasi, i was unaware of this tool and seems it is definitely going to be helpful.