Tags

,

When you are troubleshooting wireless client connectivity issues there is a one command you always need to use. “debug client <client_mac_address>” output will tells you what’s going on. To identify the issues, you have to know how this output looks like when it is working. So in this post we will have a look on this debug output for an open authentication SSID & in a different post we will look at similar output for WPA2-PSK & 802.1X-EAP authentication in used.

In Open Auth SSID connection steps are as follows.

1. Open System Authentication (Request)
2. Open System Authentication (Response)
3. Association Request
4. Association Response
5. Client send DHCP Discovery
6. Client receive DHCP Offer
7. Client send DHCP Request
8. Client receive DHCP ACK

In this post I have taken wireless packet capture to compare it with the debug output. But once you are familiar with the process you should be able to identify any abnormalities just look at the debug output.

Here is the Open System Authentication frame exchange between client & AP. Note that first authentication frame sent by client (with auth seq#1) & then AP respond with second authentication frame with (auth seq#2 & status code=0 successful).

WLC-debug-07WLC-debug-08Once Open System Authentication completes client send the Association Request frame to the AP. Here is the Association Request frame where client specify the SSID to join & other capabilities like data rates, power capability,etc

WLC-debug-06Here is my “debug client 04:f7:e4:ea:5b:66” output from my WLC related to the above steps. I am using WLC code 8.0.100.0 & if you are using other codes output may be different depend on the code capability. You will see the AP name, BSSID, details where the client send Association Request frame.

Client state is moved from “START(0)” to “AUTHCHECK(2)” to “L2AUTHCOMPLETE(4)”

12:42:25.393: 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
12:42:25.393: 04:f7:e4:ea:5b:66 Adding mobile on LWAPP AP 1c:6a:7a:bc:4d:60(1) 
12:42:25.393: 04:f7:e4:ea:5b:66 Association received from mobile on BSSID 1c:6a:7a:bc:4d:5d AP TEST-AP
12:42:25.393: 04:f7:e4:ea:5b:66 Global 200 Clients are allowed to AP radio
12:42:25.394: 04:f7:e4:ea:5b:66 Max Client Trap Threshold: 0  cur: 1
12:42:25.394: 04:f7:e4:ea:5b:66 Rf profile 600 Clients are allowed to AP wlan
12:42:25.394: 04:f7:e4:ea:5b:66 override for default ap group, marking intgrp NULL
12:42:25.394: 04:f7:e4:ea:5b:66 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0
12:42:25.394: 04:f7:e4:ea:5b:66 Re-applying interface policy for client 
12:42:25.394: 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)
12:42:25.394: 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)
12:42:25.394: 04:f7:e4:ea:5b:66 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
12:42:25.394: 04:f7:e4:ea:5b:66 In processSsidIE:5680 setting Central switched to TRUE
12:42:25.394: 04:f7:e4:ea:5b:66 In processSsidIE:5683 apVapId = 2 and Split Acl Id = 65535
12:42:25.394: 04:f7:e4:ea:5b:66 Applying site-specific Local Bridging override for station 04:f7:e4:ea:5b:66 - vapId 19, site 'LTU-APG1', interface 'vlan1422'
12:42:25.394: 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'
12:42:25.394: 04:f7:e4:ea:5b:66 override from ap group, removing intf group from mscb
12:42:25.394: 04:f7:e4:ea:5b:66 Applying site-specific override for station 04:f7:e4:ea:5b:66 - vapId 19, site 'LTU-APG1', interface 'vlan1422'
12:42:25.394: 04:f7:e4:ea:5b:66 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 1422
12:42:25.394: 04:f7:e4:ea:5b:66 Re-applying interface policy for client 
12:42:25.394: 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)
12:42:25.394: 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)
12:42:25.394: 04:f7:e4:ea:5b:66 processSsidIE  statusCode is 0 and status is 0 
12:42:25.394: 04:f7:e4:ea:5b:66 processSsidIE  ssid_done_flag is 0 finish_flag is 0
12:42:25.394: 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
12:42:25.394: 04:f7:e4:ea:5b:66 suppRates  statusCode is 0 and gotSuppRatesElement is 1 
12:42:25.394: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Initializing policy
12:42:25.394: 04:f7:e4:ea:5b:66 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)
12:42:25.395: 04:f7:e4:ea:5b:66 0.0.0.0 AUTHCHECK (2) Change state to L2AUTHCOMPLETE (4) last state AUTHCHECK (2)
12:42:25.395: 04:f7:e4:ea:5b:66 Not Using WMM Compliance code qosCap 00

Then AP will send Association Response to the client with status code 0 (successful) Once client associated to the network they move onto “DHCP_REQD (7)” state. Note that AP will give AID (Association ID) to each client uniquely identify them within the cell. In my client got AID of 2.

WLC-debug-01Here is the WLC debug output where you can see the Association Response frame send to client.

12:42:25.395: 04:f7:e4:ea:5b:66 Sending 11w Flag 0 for Client 04:F7:E4:EA:5B:66 
12:42:25.395: 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 19 apVapId 2 flex-acl-name: 
12:42:25.395: 04:f7:e4:ea:5b:66 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)
12:42:25.395: 04:f7:e4:ea:5b:66 apfMsAssoStateInc
12:42:25.395: 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
12:42:25.395: 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 
12:42:25.395: 04:f7:e4:ea:5b:66 Stopping deletion of Mobile Station: (callerId: 48)
12:42:25.395: 04:f7:e4:ea:5b:66 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0
12:42:25.395: 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 2
12:42:25.395: 04:f7:e4:ea:5b:66 Sending Assoc Response to station on BSSID 1c:6a:7a:bc:4d:6e (status 0) ApVapId 2 Slot 1
12:42:25.395: 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

Once Association complted you would see the client try to get an IP address. In 802.1X/EAP you would see EAP Authentication process & 4-Way handshake prior to this. But in this case we use no 802.1X authentication & once client completes Open System Authentication/Association they move to this.

Here is the DHCP Discovery message coming from client. This is destined to L2 broadcast address (ff:ff:ff:ff:ff:ff) with client MAC address used as Client Identifier.

WLC-debug-02Here is the debug output section related to it. If WLC proxy enabled, then WLC will use its dynamic interface (in my case vlan 1422) assigned to WLAN to relay this Discovery msg to DHCP server. This is how DHCP server get to know which subnet IP to be allocated to this client.

12:42:30.290: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP DISCOVER (1)
12:42:30.290: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
12:42:30.290: 04:f7:e4:ea:5b:66 DHCP   xid: 0x6dc433f2 (1841574898), secs: 0, flags: 0
12:42:30.290: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
12:42:30.290: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
12:42:30.291: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: x.x.x8.120
12:42:30.291: 04:f7:e4:ea:5b:66 DHCP sending REQUEST to x.x.x8.125 (len 350, port 1, vlan 1422)
12:42:30.291: 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
12:42:30.291: 04:f7:e4:ea:5b:66 DHCP selected relay 2 - x.x.x.200 (local address x.x.x8.120, gateway x.x.x8.125, VLAN 1422, port 1)
12:42:30.291: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP DISCOVER (1)

Once WLC hear from WLC (DHCP Offer) then it will pass that to the client. Note that WLC use its virtual address as source IP when passing it to client (DHCP proxy). This will provide the offered IP detail & other DHCP option to client.

WLC-debug-03Here is the  WLC debug output show these frame exchange. In my case x.x.x8.67 IP offered by DHCP server to the client.

12:42:31.294: 04:f7:e4:ea:5b:66 DHCP setting server from OFFER (server x.x.x.100, yiaddr x.x.x8.67)
12:42:31.294: 04:f7:e4:ea:5b:66 DHCP sending REPLY to STA (len 418, port 1, vlan 1600)
12:42:31.295: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP OFFER (2)
12:42:31.295: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
12:42:31.295: 04:f7:e4:ea:5b:66 DHCP   xid: 0x6dc433f2 (1841574898), secs: 0, flags: 0
12:42:31.295: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
12:42:31.295: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: x.x.x8.67
12:42:31.295: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: 0.0.0.0
12:42:31.295: 04:f7:e4:ea:5b:66 DHCP   server id: 192.0.2.1  rcvd server id: x.x.x.100
12:42:32.432: 04:f7:e4:ea:5b:66 DHCP received op BOOTREQUEST (1) (len 308,vlan 1600, port 1, encap 0xec03)
12:42:32.432: 04:f7:e4:ea:5b:66 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
12:42:32.432: 04:f7:e4:ea:5b:66 DHCP selecting relay 1 - control block settings:
                        dhcpServer: x.x.x.100, dhcpNetmask: 0.0.0.0,
                        dhcpGateway: 0.0.0.0, dhcpRelay: x.x.x8.120  VLAN: 1422
12:42:32.432: 04:f7:e4:ea:5b:66 DHCP mscbVapLocalAddr=x.x.x8.120 mscbVapLocalNetMask= 255.255.255.128 mscbdhcpRelay=x.x.x8.120
12:42:32.432: 04:f7:e4:ea:5b:66 DHCP selected relay 1 - x.x.x.100 (local address x.x.x8.120, gateway x.x.x8.125, VLAN 1422, port 1)

Then client will send the DHCP Request frame. As you can see it is destined to L2 broadcast (ff:ff:ff:ff:ff:ff) requesting previously offered IP from the DHCP server.

WLC-debug-04Here is the debug output related to this.

 12:42:32.432: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP REQUEST (3)
 12:42:32.432: 04:f7:e4:ea:5b:66 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
 12:42:32.432: 04:f7:e4:ea:5b:66 DHCP   xid: 0x6dc433f2 (1841574898), secs: 2, flags: 0
 12:42:32.432: 04:f7:e4:ea:5b:66 DHCP   chaddr: 04:f7:e4:ea:5b:66
 12:42:32.433: 04:f7:e4:ea:5b:66 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
 12:42:32.433: 04:f7:e4:ea:5b:66 DHCP   siaddr: 0.0.0.0,  giaddr: x.x.x8.120
 12:42:32.433: 04:f7:e4:ea:5b:66 DHCP   requested ip: x.x.x8.67
 12:42:32.433: 04:f7:e4:ea:5b:66 DHCP   server id: x.x.x.100  rcvd server id: 192.0.2.1
 12:42:32.433: 04:f7:e4:ea:5b:66 DHCP sending REQUEST to x.x.x8.125 (len 350, port 1, vlan 1422)
 12:42:32.433: 04:f7:e4:ea:5b:66 DHCP selecting relay 2 - control block settings:
 dhcpServer: x.x.x.100, dhcpNetmask: 0.0.0.0,
 dhcpGateway: 0.0.0.0, dhcpRelay: x.x.x8.120  VLAN: 1422
 12:42:32.433: 04:f7:e4:ea:5b:66 DHCP selected relay 2 - NONE
 12:42:32.434: 04:f7:e4:ea:5b:66 DHCP received op BOOTREPLY (2) (len 308,vlan 1422, port 1, encap 0xec00)

Finally DHCP server will send DHCP ACK frame to client confirming  successful address allocation. Again WLC will proxy this & use its virtual IP address (192.0.2.1) as the source IP of this packet.

WLC-debug-05Here is the debug output related to this. As you can see DHCP_REQD(7) state move to “RUN” state which is the final & operational state of a working wireless client.

 12:42:32.435: 04:f7:e4:ea:5b:66 DHCP setting server from ACK (mscb=0x45e778c0 ip=0x83ac1c43)(server x.x.x.100, yiaddr x.x.x8.67)
 12:42:32.435: 04:f7:e4:ea:5b:66 apfMsRunStateInc
 12:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7)
 12:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 RUN (20) Reached PLUMBFASTPATH: from line 7148
 12:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 RUN (20) Replacing Fast Path rule
 type = Airespace AP Client
 on AP 1c:6a:7a:bc:4d:60, slot 1, interface = 1, QOS = 2
 IPv4 ACL ID = 255, IPv6 ACL ID
 12:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 RUN (20) Fast Path rule (contd...) 802.1P = 6, DSCP = 0, TokenID = 15206, IntfId = 13  Local Bridging Vlan = 1422, Local Bridging intf id = 13
 12:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 RUN (20) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0
 12:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 RUN (20) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 0
 12:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 RUN (20) Fast Path rule (contd...) AVC Ratelimit:  AppID = 0 ,AppAction = 0, AppToken = 15206  AverageRate = 0, BurstRate = 012:42:32.435: 04:f7:e4:ea:5b:66 x.x.x8.67 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
 12:42:32.435: 04:f7:e4:ea:5b:66 Assigning Address x.x.x8.67 to mobile
 12:42:32.435: 04:f7:e4:ea:5b:66 DHCP success event for client. Clearing dhcp failure count for interface vlan1422.
 12:42:32.435: 04:f7:e4:ea:5b:66 DHCP sending REPLY to STA (len 418, port 1, vlan 1600)
 12:42:32.436: 04:f7:e4:ea:5b:66 DHCP transmitting DHCP ACK (5)

Note that I have excluded the mobility messages just to make it simple. Once you familiar with above steps you can go into mobility related details where when a client associate to a WLC, first it will announce to rest of the WLCs in the mobility group to see whether this client previously associated to any other controllers.

 Related Posts

1. WLC Client Debug – Part 2 (PSK)
2. WLC Client Debug – Part 3 (802.1X)