Tags
Here is the debug client <mac-address> output when my C7921 phone while associate to the network.My wireless network is configured for 802.1X + CCKM.
This is a good troubleshooting command to understand what’s wrong in the network if clients are unable to connect to wireless network. The more you familiar with this debug output, faster you can troubleshoot wireless client connectivity issues.
(WLC1) >debug client 00:1b:d4:58:e6:1a (WLC1) >*apfMsConnTask_0: Mar 18 05:54:19.076: 00:1b:d4:58:e6:1a Adding mobile on LWAPP AP 54:75:d0:3e:80:b0(1) *apfMsConnTask_0: Mar 18 05:54:19.076: 00:1b:d4:58:e6:1a Association received from mobile on AP 54:75:d0:3e:80:b0 *apfMsConnTask_0: Mar 18 05:54:19.077: 00:1b:d4:58:e6:1a 0.0.0.0 START (0) Changing ACL 'WLC-ACL' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1621) *apfMsConnTask_0: Mar 18 05:54:19.077: 00:1b:d4:58:e6:1a Applying site-specific IPv6 override for station 00:1b:d4:58:e6:1a - vapId 4, site 'default-group', interface 'vlan14' *apfMsConnTask_0: Mar 18 05:54:19.077: 00:1b:d4:58:e6:1a Applying IPv6 Interface Policy for station 00:1b:d4:58:e6:1a - vlan 14, interface id 11, interface 'vlan14' *apfMsConnTask_0: Mar 18 05:54:19.077: 00:1b:d4:58:e6:1a STA - rates (4): 176 72 96 108 0 0 0 0 0 0 0 0 0 0 0 0 *apfMsConnTask_0: Mar 18 05:54:19.077: 00:1b:d4:58:e6:1a Processing RSN IE type 48, length 22 for mobile 00:1b:d4:58:e6:1a *apfMsConnTask_0: Mar 18 05:54:19.077: 00:1b:d4:58:e6:1a CCKM: Mobile is using CCKM *apfMsConnTask_0: Mar 18 05:54:19.077: 00:1b:d4:58:e6:1a Received RSN IE with 0 PMKIDs from mobile 00:1b:d4:58:e6:1a *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a 0.0.0.0 START (0) Initializing policy *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state AUTHCHECK (2) *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3) *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 54:75:d0:3e:80:b0 vapId 4 apVapId 4for this client *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a Not Using WMM Compliance code qosCap 0f *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 54:75:d0:3e:80:b0 vapId 4 apVapId 4 *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a apfMsAssoStateInc *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 00:1b:d4:58:e6:1a on AP 54:75:d0:3e:80:b0 from Idle to Associated *apfMsConnTask_0: Mar 18 05:54:19.078: 00:1b:d4:58:e6:1a Stopping deletion of Mobile Station: (callerId: 48) *apfMsConnTask_0: Mar 18 05:54:19.079: 00:1b:d4:58:e6:1a Sending Assoc Response to station on BSSID 54:75:d0:3e:80:b0 (status 0) ApVapId 4 Slot 1 *apfMsConnTask_0: Mar 18 05:54:19.079: 00:1b:d4:58:e6:1a apfProcessAssocReq (apf_80211.c:5241) Changing state for mobile 00:1b:d4:58:e6:1a on AP 54:75:d0:3e:80:b0 from Associated to Associated *dot1xMsgTask: Mar 18 05:54:19.081: 00:1b:d4:58:e6:1a Station 00:1b:d4:58:e6:1a setting dot1x reauth timeout = 0 *dot1xMsgTask: Mar 18 05:54:19.081: 00:1b:d4:58:e6:1a Stopping reauth timeout for 00:1b:d4:58:e6:1a *dot1xMsgTask: Mar 18 05:54:19.082: 00:1b:d4:58:e6:1a dot1x - moving mobile 00:1b:d4:58:e6:1a into Connecting state *dot1xMsgTask: Mar 18 05:54:19.082: 00:1b:d4:58:e6:1a Sending EAP-Request/Identity to mobile 00:1b:d4:58:e6:1a (EAP Id 1) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.126: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.126: 00:1b:d4:58:e6:1a Username entry (user2) created for mobile *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.126: 00:1b:d4:58:e6:1a Received Identity Response (count=1) from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.126: 00:1b:d4:58:e6:1a EAP State update from Connecting to Authenticating for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.126: 00:1b:d4:58:e6:1a dot1x - moving mobile 00:1b:d4:58:e6:1a into Authenticating state *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.126: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.135: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.135: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=102) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.135: 00:1b:d4:58:e6:1a WARNING: updated EAP-Identifier 1 ===> 102 for STA 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.135: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 102) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.142: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.142: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 102, EAP Type 3) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.142: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.144: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.144: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=103) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.144: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 103) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.186: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.186: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 103, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.186: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.188: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.188: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=104) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.188: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 104) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.200: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.200: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 104, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.200: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.201: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.201: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=105) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.201: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 105) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.249: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.249: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 105, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.249: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.256: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.256: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=106) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.256: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 106) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.268: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.268: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 106, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.268: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.270: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.270: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=107) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.270: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 107) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.279: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.279: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 107, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.279: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.281: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.281: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=108) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.281: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 108) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.295: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.295: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 108, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.295: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.302: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.302: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=109) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.302: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 109) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.314: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.314: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 109, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.314: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.315: 00:1b:d4:58:e6:1a Processing Access-Challenge for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.315: 00:1b:d4:58:e6:1a Entering Backend Auth Req state (id=110) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.315: 00:1b:d4:58:e6:1a Sending EAP Request from AAA to mobile 00:1b:d4:58:e6:1a (EAP Id 110) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.323: 00:1b:d4:58:e6:1a Received EAPOL EAPPKT from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.323: 00:1b:d4:58:e6:1a Received EAP Response from mobile 00:1b:d4:58:e6:1a (EAP Id 110, EAP Type 25) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.323: 00:1b:d4:58:e6:1a Entering Backend Auth Response state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.325: 00:1b:d4:58:e6:1a Processing Access-Accept for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Resetting web acl from 255 to 255 *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Setting re-auth timeout to 0 seconds, got from WLAN config. *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Station 00:1b:d4:58:e6:1a setting dot1x reauth timeout = 0 *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Stopping reauth timeout for 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Creating a PKC PMKID Cache entry for station 00:1b:d4:58:e6:1a (RSN 2) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Adding BSSID 54:75:d0:3e:80:bc to PMKID cache for station 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: New PMKID: (16) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: [0000] 1a 20 96 10 34 72 68 70 dc 04 1f 31 25 71 c4 6b *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Disabling re-auth since PMK lifetime can take care of same. *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a CCKM: Create a global PMK cache entry *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.326: 00:1b:d4:58:e6:1a Sending EAP-Success to mobile 00:1b:d4:58:e6:1a (EAP Id 110) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.327: Including PMKID in M1 (16) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.327: [0000] 1a 20 96 10 34 72 68 70 dc 04 1f 31 25 71 c4 6b *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.327: 00:1b:d4:58:e6:1a Starting key exchange to mobile 00:1b:d4:58:e6:1a, data packets will be dropped *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.327: 00:1b:d4:58:e6:1a Sending EAPOL-Key Message to mobile 00:1b:d4:58:e6:1a state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.327: 00:1b:d4:58:e6:1a Entering Backend Auth Success state (id=110) for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.327: 00:1b:d4:58:e6:1a Received Auth Success while in Authenticating state for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.327: 00:1b:d4:58:e6:1a dot1x - moving mobile 00:1b:d4:58:e6:1a into Authenticated state *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.344: 00:1b:d4:58:e6:1a Received EAPOL-Key from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.344: 00:1b:d4:58:e6:1a Received EAPOL-key in PTK_START state (message 2) from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.344: 00:1b:d4:58:e6:1a CCKM: Sending cache add *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.345: 00:1b:d4:58:e6:1a Stopping retransmission timer for mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.345: 00:1b:d4:58:e6:1a Sending EAPOL-Key Message to mobile 00:1b:d4:58:e6:1a state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.357: 00:1b:d4:58:e6:1a Received EAPOL-Key from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.357: 00:1b:d4:58:e6:1a Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:1b:d4:58:e6:1a *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.357: 00:1b:d4:58:e6:1a apfMs1xStateInc *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.357: 00:1b:d4:58:e6:1a 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.358: 00:1b:d4:58:e6:1a 0.0.0.0 L2AUTHCOMPLETE (4) DHCP Not required on AP 54:75:d0:3e:80:b0 vapId 4 apVapId 4for this client *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.358: 00:1b:d4:58:e6:1a Not Using WMM Compliance code qosCap 0f *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.358: 00:1b:d4:58:e6:1a 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 54:75:d0:3e:80:b0 vapId 4 apVapId 4 *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.358: 00:1b:d4:58:e6:1a 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state DHCP_REQD (7) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.358: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4755, Adding TMP rule *Dot1x_NW_MsgTask_0: Jan 24 03:35:39.359: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule type = Airespace AP - Learn IP address on AP 54:75:d0:3e:80:b0, slot 1, interface = 1, QOS = 2 ACL Id = 255, Jumbo Fr *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.359: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 6, DSCP = 0, TokenID = 5006 IPv6 Vlan = 14, IPv6 intf id = 11 *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.359: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255) *Dot1x_NW_MsgTask_0: Mar 18 05:54:19.359: 00:1b:d4:58:e6:1a Stopping retransmission timer for mobile 00:1b:d4:58:e6:1a *pemReceiveTask: Mar 18 05:54:19.362: 00:1b:d4:58:e6:1a 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Mar 18 05:54:19.362: 00:1b:d4:58:e6:1a Sent an XID frame *DHCP Proxy DTL Recv Task: Mar 18 05:54:19.667: 00:1b:d4:58:e6:1a DHCP received op BOOTREQUEST (1) (len 556,vlan 0, port 1, encap 0xec03) *DHCP Proxy DTL Recv Task: Mar 18 05:54:19.667: 00:1b:d4:58:e6:1a DHCP dropping packet due to ongoing mobility handshake exchange, (siaddr 0.0.0.0, mobility state = 'apfMsMmQueryRequested' *apfReceiveTask: Mar 18 05:54:21.270: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED *apfReceiveTask: Mar 18 05:54:21.270: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4431, Adding TMP rule *apfReceiveTask: Mar 18 05:54:21.270: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule type = Airespace AP - Learn IP address on AP 54:75:d0:3e:80:b0, slot 1, interface = 1, QOS = 2 ACL Id = 255, Jumbo *apfReceiveTask: Mar 18 05:54:21.270: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 6, DSCP = 0, TokenID = 5006 IPv6 Vlan = 14, IPv6 intf id = 11 *apfReceiveTask: Mar 18 05:54:21.270: 00:1b:d4:58:e6:1a 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255) *pemReceiveTask: Mar 18 05:54:21.273: 00:1b:d4:58:e6:1a 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Mar 18 05:54:21.273: 00:1b:d4:58:e6:1a Sent an XID frame *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP received op BOOTREQUEST (1) (len 556,vlan 0, port 1, encap 0xec03) *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP selecting relay 1 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0 VLAN: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP selected relay 1 - 10.10.14.1 (local address 10.10.14.10, gateway 10.10.14.1, VLAN 14, port 1) *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP transmitting DHCP DISCOVER (1) *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP xid: 0x8cf1c44b (2364654667), secs: 0, flags: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP chaddr: 00:1b:d4:58:e6:1a *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP siaddr: 0.0.0.0, giaddr: 10.10.14.10 *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP requested ip: 10.10.14.54 *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP ARPing for 10.10.14.1 (SPA 10.10.14.10, vlanId 14) *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP selecting relay 2 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 10.10.14.10 VLAN: 14 *DHCP Proxy DTL Recv Task: Mar 18 05:54:21.669: 00:1b:d4:58:e6:1a DHCP selected relay 2 - NONE *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.667: 00:1b:d4:58:e6:1a DHCP received op BOOTREQUEST (1) (len 556,vlan 0, port 1, encap 0xec03) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.667: 00:1b:d4:58:e6:1a DHCP selecting relay 1 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 10.10.14.10 VLAN: 14 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.667: 00:1b:d4:58:e6:1a DHCP selected relay 1 - 10.10.14.1 (local address 10.10.14.10, gateway 10.10.14.1, VLAN 14, port 1) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP transmitting DHCP DISCOVER (1) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP xid: 0x8cf1c44b (2364654667), secs: 0, flags: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP chaddr: 00:1b:d4:58:e6:1a *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP siaddr: 0.0.0.0, giaddr: 10.10.14.10 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP requested ip: 10.10.14.54 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP sending REQUEST to 10.10.14.1 (len 374, port 1, vlan 14) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP selecting relay 2 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 10.10.14.10 VLAN: 14 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.668: 00:1b:d4:58:e6:1a DHCP selected relay 2 - NONE *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.670: 00:1b:d4:58:e6:1a DHCP received op BOOTREPLY (2) (len 308,vlan 14, port 1, encap 0xec00) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.670: 00:1b:d4:58:e6:1a DHCP setting server from OFFER (server 192.168.200.1, yiaddr 10.10.14.54) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.670: 00:1b:d4:58:e6:1a DHCP sending REPLY to STA (len 418, port 1, vlan 111) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.671: 00:1b:d4:58:e6:1a DHCP transmitting DHCP OFFER (2) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.671: 00:1b:d4:58:e6:1a DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.671: 00:1b:d4:58:e6:1a DHCP xid: 0x8cf1c44b (2364654667), secs: 0, flags: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.671: 00:1b:d4:58:e6:1a DHCP chaddr: 00:1b:d4:58:e6:1a *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.671: 00:1b:d4:58:e6:1a DHCP ciaddr: 0.0.0.0, yiaddr: 10.10.14.54 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.671: 00:1b:d4:58:e6:1a DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.671: 00:1b:d4:58:e6:1a DHCP server id: 1.1.1.1 rcvd server id: 192.168.200.1 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP received op BOOTREQUEST (1) (len 556,vlan 0, port 1, encap 0xec03) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP selecting relay 1 - control block settings: dhcpServer: 192.168.200.1, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 10.10.14.10 VLAN: 14 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP selected relay 1 - 192.168.200.1 (local address 10.10.14.10, gateway 10.10.14.1, VLAN 14, port 1) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP transmitting DHCP REQUEST (3) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP xid: 0x8cf1c44b (2364654667), secs: 0, flags: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP chaddr: 00:1b:d4:58:e6:1a *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP siaddr: 0.0.0.0, giaddr: 10.10.14.10 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP requested ip: 10.10.14.54 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP server id: 192.168.200.1 rcvd server id: 1.1.1.1 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP sending REQUEST to 10.10.14.1 (len 382, port 1, vlan 14) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP selecting relay 2 - control block settings: dhcpServer: 192.168.200.1, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 10.10.14.10 VLAN: 14 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.676: 00:1b:d4:58:e6:1a DHCP selected relay 2 - NONE *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.677: 00:1b:d4:58:e6:1a DHCP received op BOOTREPLY (2) (len 308,vlan 14, port 1, encap 0xec00) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a Static IP client associated to interface vlan14 which can support client subnet. *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a apfMsRunStateInc *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a 10.10.14.54 DHCP_REQD (7) Change state to RUN (20) last state RUN (20) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a 10.10.14.54 RUN (20) Reached PLUMBFASTPATH: from line 5273 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a 10.10.14.54 RUN (20) Replacing Fast Path rule type = Airespace AP Client on AP 54:75:d0:3e:80:b0, slot 1, interface = 1, QOS = 2 ACL Id = 255, Jumbo Frames = NO *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a 10.10.14.54 RUN (20) Fast Path rule (contd...) 802.1P = 6, DSCP = 0, TokenID = 5006 IPv6 Vlan = 14, IPv6 intf id = 11 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a 10.10.14.54 RUN (20) Successfully plumbed mobile rule (ACL ID 255) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a Assigning Address 10.10.14.54 to mobile *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a DHCP success event for client. Clearing dhcp failure count for interface vlan14. *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a DHCP sending REPLY to STA (len 418, port 1, vlan 111) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a DHCP transmitting DHCP ACK (5) *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.678: 00:1b:d4:58:e6:1a DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.679: 00:1b:d4:58:e6:1a DHCP xid: 0x8cf1c44b (2364654667), secs: 0, flags: 0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.679: 00:1b:d4:58:e6:1a DHCP chaddr: 00:1b:d4:58:e6:1a *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.679: 00:1b:d4:58:e6:1a DHCP ciaddr: 0.0.0.0, yiaddr: 10.10.14.54 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.679: 00:1b:d4:58:e6:1a DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0 *DHCP Proxy DTL Recv Task: Mar 18 05:54:23.679: 00:1b:d4:58:e6:1a DHCP server id: 1.1.1.1 rcvd server id: 192.168.200.1 *pemReceiveTask: Mar 18 05:54:23.682: 00:1b:d4:58:e6:1a 10.10.14.54 Added NPU entry of type 1, dtlFlags 0x0 *pemReceiveTask: Mar 18 05:54:23.685: 00:1b:d4:58:e6:1a Sending a gratuitous ARP for 10.10.14.54, VLAN Id 53262
Let’s analyze this. From timing perspective WLC see first request from client at 05:54:19.076 & added to NPU entry at 05:54:23.682. So it took around 4s 604ms for whole process of EAP Authentication (~2.5s) & DHCP Address assignment (~2s).
Here is the EAP packet flow
If you look at the above debug output you can clearly identify below states during this client association. You can see DHCP request will be fullfil once 802.1x/EAP process completed.
START(0) to AUTHCHECK (2)
AUTHCHECK (2) to 8021X_REQD (3)
Sending EAP_Request/Identity
Receiving EAP_Identity Response
802.1X_REQD (3) to L2AUTHCOMPLETE (4)
L2AUTHCOMPLETE (4) to DHCP_REQD (7)
DHCP Discover
DHCP Offer
DHCP Request
DHCP ACK
DHCP_REQD (7) to RUN (20)
Typically client will report an issue as “cannot connect on to wireless network”. But you should know what are the probable causes ? It may be dot1X issues, DHCP related issue , etc. If you have the above debug output & you understand how it should work under normal circumstances (as shown in the above) then you can easily point out where would be the possible failure.
Let’s say if you see L2AUTHCOMPLETE state, but no IP assignment to client. That indicate 802.1X/EAP (Radius server) part is ok. You need to look at DHCP side of things.
If you see status as 802.1X_REQD & no any other proper state, then you have to focus on your RADIUS server & check its log for failure reasons.
mrn-cciew 
Sendt fra min HTC-telefon
Hi Kasper,
thanks for viewing this post, Did you make any comment ? I cannot see it.
Rasika
Amazing. Can you please post more of this stuff? How do you narrow down problem with client drop out and connect?
Hi,
One of my user is using mac book.. every alternate day he is complaining like wifi issue … we have WLC 5508 with RADIUS configuration, ACS and WCS
In controller i found “unknown reason code 23” how to troubleshoot for single user.
i found unauthenticate code error IEEE802.1X authentication failed
Did you check the end user wireless drivers ? If not latest, upgrade them to latest & see.
If only single user affected, then most probably client device may causing this
HTH
Rasika
Thanks for this post. I had some users that were not getting on the network from one of the SSIDs and having this helped me see where to troubleshoot further to find the issue.
Nice to hear Doug
Any recommendation of books for helping with understanding wireless?
Hi Rasika
I am trying to troubleshoot a very strange wireless issue in our company. Wireless clients (Windows 7 x64 based) randomly disconnect. In fact, they don’t fully disconnect, but seems like TCP/IP stack looses connectivity? AP/WLC report clients as being connected, but client can’t even ping a gateway.
It starts with an exclamation mark on the wireless bar, after which all apps disconnect form the network. AP/WLC say everything is ok – client is connected, show RSSI, SNR, but from L3 perspective there’s no connectivity.
It happens randomly at different time during the day, affects Windows 7 clients (different HW platforms). We’ve tried to upgrade drivers but it didn’t help. We use dot1x/PEAP to authenticate clients. It also happens with different supplicants (I’ve tried AC, native and Intel PROSet). It affects all offices that use that particular WLC, and our whole CUWN is based on FlexConnect.
The reason I am asking this here is because I believe (although not 100% sure) it may have something with key caching. If you leave client idle without forcing it to reconnect, connectivity is restored automatically when session timeout expires and dot1x kicks in to reauth the client.
Where would you suggest to start?
FYI, this problem existed on 8.0, and we’re now on 8.2 – still the same.
Have you ever faced anything similar to this?
Thank you very much in advance
Hello!
( 00:1b:d4:58:e6:1a Sending a gratuitous ARP for 10.10.14.54, VLAN Id 53262)
Tell me what this means id 53262?
Thank you!
I think that is not a valid vlan ID, may be code issue
Rasika
Hi Rasika, We are running 8.3.143 code and we see clients getting disconnected randomly. L2AUTH is complete and client gets an IP from the DHCP server. The signal strength is good as we recently did a site survey. I have posted my query on Cisco’s support community. Hoping to find a solution.
Please do comment if you see if i’m missing something.
https://community.cisco.com/t5/wireless-and-mobility/random-disconnections-noticed-by-multiple-users-in-the-same/m-p/3699097#M102918
I have responded to that Deepak, I suspect it is 8.3.x code issues as you only noticed it once upgrade from 8.2 -> 8.3
HTH
Rasika