Troubleshooting DHCP on the 5508 WLC

[Kevin Melton]

What is the best way to debug DHCP activity across this unit.  We have this unit setup as a demo at a client site, and it is having some difficulty with DHCP...

Are there optons for both CLI and the GUI?

Thanks!

[Kevin Melton]

Here is some more output from what I found on the 5508 controller running "debug client "

(Cisco Controller) >debug client 0026c75e3060

(Cisco Controller) >*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 Adding mobile on LWAPP AP f0:25:72:cb:39:70(0)
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 Association received from mobile on AP f0:25:72:cb:39:70
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'Guests' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 Applying site-specific IPv6 override for station 00:26:c7:5e:30:60 - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 Applying IPv6 Interface Policy for station 00:26:c7:5e:30:60 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 STA - rates (8): 130 132 139 150 12 18 24 36 0 0 0 0 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 apfProcessAssocReq (apf_80211.c:4469) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from Idle to AAA Pending

*apfMsConnTask_5: Mar 29 14:53:19.356: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 20) in 10 seconds
*apfReceiveTask: Mar 29 14:53:19.358: 00:26:c7:5e:30:60 Sending Assoc Response to station on BSSID f0:25:72:cb:39:70 (status 1)
*apfReceiveTask: Mar 29 14:53:19.358: 00:26:c7:5e:30:60 apfProcessRadiusAssocResp (apf_80211.c:2104) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from AAA Pending to Authenticated

*apfReceiveTask: Mar 29 14:53:19.358: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 18) in 10 seconds
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 Association received from mobile on AP f0:25:72:cb:39:70
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 Applying site-specific IPv6 override for station 00:26:c7:5e:30:60 - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 Applying IPv6 Interface Policy for station 00:26:c7:5e:30:60 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 STA - rates (8): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:19.573: 00:26:c7:5e:30:60 apfProcessAssocReq (apf_80211.c:4469) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from Authenticated to AAA Pending

*apfMsConnTask_5: Mar 29 14:53:19.574: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 20) in 10 seconds
*apfReceiveTask: Mar 29 14:53:19.574: 00:26:c7:5e:30:60 Sending Assoc Response to station on BSSID f0:25:72:cb:39:70 (status 1)
*apfReceiveTask: Mar 29 14:53:19.574: 00:26:c7:5e:30:60 apfProcessRadiusAssocResp (apf_80211.c:2104) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from AAA Pending to Authenticated

*apfReceiveTask: Mar 29 14:53:19.574: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 18) in 10 seconds
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 Association received from mobile on AP f0:25:72:cb:39:70
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 Applying site-specific IPv6 override for station 00:26:c7:5e:30:60 - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 Applying IPv6 Interface Policy for station 00:26:c7:5e:30:60 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 STA - rates (8): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 apfProcessAssocReq (apf_80211.c:4469) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from Authenticated to AAA Pending

*apfMsConnTask_5: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 20) in 10 seconds
*apfReceiveTask: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 Sending Assoc Response to station on BSSID f0:25:72:cb:39:70 (status 1)
*apfReceiveTask: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 apfProcessRadiusAssocResp (apf_80211.c:2104) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from AAA Pending to Authenticated

*apfReceiveTask: Mar 29 14:53:19.792: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 18) in 10 seconds
*apfMsConnTask_5: Mar 29 14:53:20.011: 00:26:c7:5e:30:60 Association received from mobile on AP f0:25:72:cb:39:70
*apfMsConnTask_5: Mar 29 14:53:20.011: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:20.011: 00:26:c7:5e:30:60 Applying site-specific IPv6 override for station 00:26:c7:5e:30:60 - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_5: Mar 29 14:53:20.011: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:20.011: 00:26:c7:5e:30:60 Applying IPv6 Interface Policy for station 00:26:c7:5e:30:60 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_5: Mar 29 14:53:20.011: 00:26:c7:5e:30:60 STA - rates (8): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:20.011: 00:26:c7:5e:30:60 STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:20.012: 00:26:c7:5e:30:60 apfProcessAssocReq (apf_80211.c:4469) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from Authenticated to AAA Pending

*apfMsConnTask_5: Mar 29 14:53:20.012: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 20) in 10 seconds
*apfReceiveTask: Mar 29 14:53:20.012: 00:26:c7:5e:30:60 Sending Assoc Response to station on BSSID f0:25:72:cb:39:70 (status 1)
*apfReceiveTask: Mar 29 14:53:20.012: 00:26:c7:5e:30:60 apfProcessRadiusAssocResp (apf_80211.c:2104) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from AAA Pending to Authenticated

*apfReceiveTask: Mar 29 14:53:20.012: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 18) in 10 seconds
*apfMsConnTask_5: Mar 29 14:53:20.228: 00:26:c7:5e:30:60 Association received from mobile on AP f0:25:72:cb:39:70
*apfMsConnTask_5: Mar 29 14:53:20.228: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:20.228: 00:26:c7:5e:30:60 Applying site-specific IPv6 override for station 00:26:c7:5e:30:60 - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_5: Mar 29 14:53:20.228: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:20.228: 00:26:c7:5e:30:60 Applying IPv6 Interface Policy for station 00:26:c7:5e:30:60 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_5: Mar 29 14:53:20.229: 00:26:c7:5e:30:60 STA - rates (8): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:20.229: 00:26:c7:5e:30:60 STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:20.229: 00:26:c7:5e:30:60 apfProcessAssocReq (apf_80211.c:4469) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from Authenticated to AAA Pending

*apfMsConnTask_5: Mar 29 14:53:20.229: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 20) in 10 seconds
*apfReceiveTask: Mar 29 14:53:20.229: 00:26:c7:5e:30:60 Sending Assoc Response to station on BSSID f0:25:72:cb:39:70 (status 1)
*apfReceiveTask: Mar 29 14:53:20.229: 00:26:c7:5e:30:60 apfProcessRadiusAssocResp (apf_80211.c:2104) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:39:70 from AAA Pending to Authenticated

*apfReceiveTask: Mar 29 14:53:20.229: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 18) in 10 seconds
*apfMsConnTask_5: Mar 29 14:53:20.448: 00:26:c7:5e:30:60 Association received from mobile on AP f0:25:72:cb:41:90
*apfMsConnTask_5: Mar 29 14:53:20.448: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 Applying site-specific IPv6 override for station 00:26:c7:5e:30:60 - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1393)
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 Applying IPv6 Interface Policy for station 00:26:c7:5e:30:60 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 STA - rates (8): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 0.0.0.0 START (0) Deleted mobile LWAPP rule on AP [f0:25:72:cb:39:70]
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 Updated location for station old AP f0:25:72:cb:39:70-0, new AP f0:25:72:cb:41:90-0
*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 apfProcessAssocReq (apf_80211.c:4469) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:41:90 from Authenticated to AAA Pending

*apfMsConnTask_5: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 20) in 10 seconds
*apfReceiveTask: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 Sending Assoc Response to station on BSSID f0:25:72:cb:41:90 (status 1)
*apfReceiveTask: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 apfBlacklistMobileStationEntry2 (apf_ms.c:4183) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:41:90 from AAA Pending to Exclusion-list (1)

*apfReceiveTask: Mar 29 14:53:20.449: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 44) in 10 seconds
*apfMsConnTask_5: Mar 29 14:53:20.668: 00:26:c7:5e:30:60 Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_5: Mar 29 14:53:21.883: 00:26:c7:5e:30:60 Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_5: Mar 29 14:53:23.100: 00:26:c7:5e:30:60 Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_5: Mar 29 14:53:24.316: 00:26:c7:5e:30:60 Ignoring assoc request due to mobile in exclusion list or marked for deletion
*osapiBsnTimer: Mar 29 14:53:30.410: 00:26:c7:5e:30:60 apfMsExpireCallback (apf_ms.c:599) Expiring Mobile!
*apfReceiveTask: Mar 29 14:53:30.410: 00:26:c7:5e:30:60 Scheduling deletion of Mobile Station:  (callerId: 46) in 60 seconds
*apfReceiveTask: Mar 29 14:53:30.410: 00:26:c7:5e:30:60 apfMsExpireMobileStation (apf_ms.c:5001) Changing state for mobile 00:26:c7:5e:30:60 on AP f0:25:72:cb:41:90 from Exclusion-list (1) to Exclusion-list (2)

*apfReceiveTask: Mar 29 14:53:30.410: 00:26:c7:5e:30:60 0.0.0.0 START (0) Deleted mobile LWAPP rule on AP [f0:25:72:cb:41:90]
*osapiBsnTimer: Mar 29 14:54:30.414: 00:26:c7:5e:30:60 apfMsExpireCallback (apf_ms.c:599) Expiring Mobile!
*apfReceiveTask: Mar 29 14:54:30.414: 00:26:c7:5e:30:60 apfMsAssoStateDec
*apfReceiveTask: Mar 29 14:54:30.414: 00:26:c7:5e:30:60 Deleting mobile on AP f0:25:72:cb:41:90(0)

I have disable security on the WLAN, but still cannot connect.

Thank You

kevin

[Ryan Curry]

What version of code are you running?  There is a known bug with 6.0.199.4 and 7.0.98.0, the following is taken from the release notes:

Upgrading to controller release 6.0.196.0 or 7.0.98.0 can cause client devices to fail to complete DHCP.
To work around this problem, use an external DHCP server, such as a router or a Layer-3 switch. This
defect is described in CSCth68708, which is visible in the Bug Toolkit on Cisco.com.

Hope this helps, we ran into this issue a week ago with our DMZ controller.

[Kevin Melton]

That is the code that we are running on this DEMO unit.  Is this a matter of flashing the co

de?

thx

[Ryan Curry · Accepted solution]

Unfortunately the bug is in the latest code so flashing won't fix the issue, sorry.  Do you have anything else you can offload DHCP to (router or server that can run DHCP services)?  If so, you can point your dynamic interface to that device to provide the DHCP service.  Here's a link for running DHCP on an IOS device:

http://www.cisco.com/en/US/customer/docs/ios/12_0t/12_0t1/feature/guide/Easyip2.html

Hope this helps ya.

[josuvarg · Accepted solution]

The bug is affecting 6.0.199.4 and 7.0.98 which are the latest versions. For now, you should use an external DHCP server.

I thing that there will be a new 7.0 release in a couple of weeks. The bug should be solved there.

[weterry · Accepted solution]

For the record, your client debug shows that this client's association is being rejected. This has nothing to do with DHCP since your client has not successfully associated.

*apfReceiveTask: Mar 29 14:53:19.358: 00:26:c7:5e:30:60 Sending Assoc Response to station on BSSID f0:25:72:cb:39:70 (status 1)

It also indicates you must have Client Exclusion enabled on the WLAN, since after a few rejections the WLC just blacklists your client.

Is every client recieving this same Status 1 Association Response?

[Kevin Melton]

this was a client DEMO unit, as we had been in a competative situation against ARUBA.  There were only 1 WLC, two AP's, and then my laptop.

Thanks for your response.

Kevin

[fbarboza · Accepted solution]

Hi, If you need to use the wlc internal dhcp feature and have code 6.0.199.4 and 7.0.98.0 then you can open a case with Cisco Tac and they can publish a code with the fix for your model of wlc.

Also if you reload the wlc it may start working for an x amount of time

Sent from Cisco Technical Support iPhone App