Re: 2820i AP, 5508 WLCs, DHCP Relay - DHCP NOT working

Sean Haynes · ‎02-21-2018

Morning

We have 2 Cisco 5508 WLCs, we have around 50 1142N APs across the campus, all of which use DHCP and PoE without any issues.

The WLCs are configured as DHCP relay agents which works perfectly well for both the APs and Clients.

We had a need for an additional AP, so we purchased a 2820i, ran a new cable which terminated into a Cisco 3750 switch which is already supporting several of the said 1142n APs.

The 3750 switch does not provided enough power for the newer AP so I also purchased an inline power injector - which works fine.

I have never had to pre-stage an AP before, so as before the new AP was installed and powered on. I was expecting it to mimic what every other AP has done for the last several years - get a DHCP address and join the controller - NOPE!!!

So in summary:

Yes, all other APs joined to that switch are able to get a DHCP address, all other APs tested on the very same port of that same switch are able to get a DHCP address - just not this AP.

If I console into the AP and debug DHCP events I can see that DHCP requests are indeed being sent, but not responded to:

[02/20/2018 23:26:26.7100] wired0 emac 2: link up
[02/20/2018 23:26:26.7600] wired0: link up
[02/20/2018 23:26:26.8100] wired0: started
[*02/20/2018 23:26:26.8635] aptrace_register_sysproc_fn: duplicate registeration for 'wired'
[*02/20/2018 23:26:27.6503] chatter: DHCP-EVT: Sending DHCP discover packet length 346 bytes
[*02/20/2018 23:26:27.6503] chatter: DHCP-PAK: Sent DHCP_DISCOVER pak:
[*02/20/2018 23:26:27.6503] chatter: sent pkt source: 0.0.0.0, destination: 255.255.255.255
[*02/20/2018 23:26:27.6503] chatter: UDP sport: 68, dport: 67, length: 312
[*02/20/2018 23:26:27.6503] chatter: DHCP op: 1, htype: 1, hlen: 6, hops: 0
[*02/20/2018 23:26:27.6503] chatter: xid: 7cd9e03e, secs: 0, flags: 0
[*02/20/2018 23:26:27.6503] chatter: client: 0.0.0.0, your: 0.0.0.0
[*02/20/2018 23:26:27.6504] chatter: srvr: 0.0.0.0, gw: 0.0.0.0
[*02/20/2018 23:26:30.8648] Waiting for uplink IPv4/IPv6 configuration
[*02/20/2018 23:26:35.8657] Waiting for uplink IPv4/IPv6 configuration
[*02/20/2018 23:26:40.8666] Waiting for uplink IPv4/IPv6 configuration
[*02/20/2018 23:26:41.8667] Resetting wired0, if[02/20/2018 23:26:41.9000] wired0: stopped
config down up

If from console I do a 'sho arp', it does just that and returns dozens of IP addresses from across the wireless network, so broadcasts are working, it just can't seem to get it's own IP address via a DHCP broadcast.

I have run 'Wireshark' on both DHCP servers and can see no requests from the AP's MAC address, though I can see other requests from devices on the wireless network being properly relayed through the controllers to the DHCP servers. So it can't be a relay problem.

If from console I enter a static address, subnet mask and the IP of the default gateway on the AP - it will IMMEADIATELY find both controllers and go through the automated process of joining with out issue. Clients are then able to use that AP, again without issue.

[*02/21/2018 10:33:53.4489] AP IPv4 Address updated from 0.0.0.0 to 172.20.255.230
[*02/21/2018 10:33:53.4561] dtls_init: Use MIC device cert
[*02/21/2018 10:33:53.4564] dtls_init: Use MIC device cert private key
[*02/21/2018 10:33:53.4565]
[*02/21/2018 10:33:53.4565] CAPWAP State: Init
[*02/21/2018 10:33:53.4569]
[*02/21/2018 10:33:53.4569] PNP is not required, Starting CAPWAP discovery
[*02/21/2018 10:33:53.4569]
[*02/21/2018 10:33:53.4571]
[*02/21/2018 10:33:53.4571] CAPWAP State: Discovery
[*02/21/2018 10:33:53.4617] Discovery Request sent to 172.20.255.201, discovery type STATIC_CONFIG(1)
[*02/21/2018 10:33:53.4630] Discovery Request sent to 255.255.255.255, discovery type UNKNOWN(0)
[*02/21/2018 10:33:53.4630]
[*02/21/2018 10:33:53.4630] CAPWAP State: Discovery
[*02/21/2018 10:33:53.4635] Discovery Response from 172.20.255.201
[*02/21/2018 11:05:01.0004] Discovery Response from 172.20.255.202
[*02/21/2018 11:05:01.0001] Discovery Response from 172.20.255.201
[*02/21/2018 11:05:01.0000]
[*02/21/2018 11:05:01.0000] CAPWAP State: DTLS Setup
[*02/21/2018 11:05:01.1328] dtls_load_ca_certs: LSC Root Certificate not present
[*02/21/2018 11:05:01.1328]
[*02/21/2018 11:05:01.2326]
[*02/21/2018 11:05:01.2326] CAPWAP State: Join
[*02/21/2018 11:05:01.2339] Sending Join request to 172.20.255.201 through port 5264
[*02/21/2018 11:05:01.2373] Join Response from 172.20.255.201
[*02/21/2018 11:05:01.3126] HW CAPWAP tunnel is ADDED
[*02/21/2018 11:05:01.3258]
[*02/21/2018 11:05:01.3258] CAPWAP State: Image Data
[*02/21/2018 11:05:01.3562] do NO_UPGRADE, part2 is active part
[*02/21/2018 11:05:01.3609]
[*02/21/2018 11:05:01.3609] CAPWAP State: Configure
[*02/21/2018 11:05:01.3640] NO-ENC-PROVIDER for DOT11R_WLC_MAC_IP_PAYLOAD
[*02/21/2018 11:05:02.0198] Started Radio 0
[*02/21/2018 11:05:02.0389] DOT11_DRV[0]: set_channel Channel set to 1
[*02/21/2018 11:05:02.9272] DOT11_DRV[0]: set_channel Channel set to 1
[*02/21/2018 11:05:04.1417] Started Radio 1
[*02/21/2018 11:05:04.1647] DOT11_DRV[1]: set_channel Channel set to 36
[*02/21/2018 11:05:05.0840] DOT11_DRV[1]: set_channel Channel set to 36
[*02/21/2018 11:05:06.3229] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: Configure(8).
[*02/21/2018 11:05:06.3230] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: Configure(8).
[*02/21/2018 11:05:06.3231] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: Configure(8).
[*02/21/2018 11:05:06.3231] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: Configure(8).
[*02/21/2018 11:05:06.3232] Discarding msg CAPWAP_WTP_EVENT_REQUEST(type 9) in CAPWAP state: Configure(8).
[*02/21/2018 11:05:06.4150] DOT11_DRV[0]: set_channel Channel set to 1
[*02/21/2018 11:05:07.4264] DOT11_DRV[1]: set_channel Channel set to 36
[*02/21/2018 11:05:08.3442] DOT11_DRV[1]: set_channel Channel set to 36
[*02/21/2018 11:05:09.4703]
[*02/21/2018 11:05:09.4703] CAPWAP State: Run
[*02/21/2018 11:05:09.5009] CAPWAP HW tunnel params changed, UPDATING the existing
[*02/21/2018 11:05:09.5559] AP has joined controller Cisco5508_WLC_Primary

I have checked the VLAN config which is on the switches, made sure the IP Helper Addresses are correct, basically gone through everything I can think of - still no closer to figuring this out. It has to be said the Cisco literature is pretty base and of no use when troubleshooting this issue.

Anyone else had this problem?

Sandeep Choudhary · ‎02-21-2018

Looks like a proxy issue.

Try to disable DHCP proxy(Controller > Advance > DHCP ) and give a try.

Regards

Dont forget to arte helpful posts

Sean Haynes · ‎02-21-2018

Disabling the DHCP proxy will stop all DHCP relays - so DHCP would not work at all on the Wireless network. I'm not sure I understand what that will prove when clearly the DHCP proxy is working fine for every other device, be that a client or an AP except this particular model.

There must be something specific to this AP, or series of APs that I'm missing.

Rasika Nayanajith · ‎02-21-2018

What is the WLC software version ?

Rasika

Sean Haynes · ‎02-21-2018

Morning the version on both controllers is 8.3.133.0 which according to the Cisco matrix works.

I had to make sure the level of code supported both the 1142Ns and the 2820i - later code if I remember correctly drops the 1142Ns.

Leo Laohoo · ‎02-21-2018

@Sean Haynes wrote:

[*02/21/2018 10:33:53.4489] AP IPv4 Address updated from 0.0.0.0 to 172.20.255.230

AP getting an IP address. I suspect the WLC is running a version that doesn't support the new AP. Kindly post the complete output to the WLC command of "sh sysinfo".

Sean Haynes · ‎02-21-2018

Morning, no it's not getting an address - the .230 is the address I manually configured to bring up a connection. Configured manually it's fine, but it can't get an address via DHCP though it sends and receives ARP packets.

As far as the code is concerned, according to the Cisco matrix this is the correct level of code to support both the 1142N and 2820i APs: 8.3.133.0

Leo Laohoo · ‎02-21-2018

@Sean Haynes wrote:

Morning, no it's not getting an address - the .230 is the address I manually configured to bring up a connection. Configured manually it's fine, but it can't get an address via DHCP though it sends and receives ARP packets.

CSCva34879

Raise a TAC Case and get your name added to the "list".

Tommy Vindvik · ‎03-06-2018

I have the same problem.

Ww are in the progress of expanding our WiFi coverage with around 300 AP's.

Roughly 50% of 3802AP's seems to have a problem with DHCP even running on the same version. These are the two images I have tested on:

Primary Boot Image : 8.5.120.0
Backup Boot Image : 8.2.151.0

8.5 reports "Waiting for uplink IPv4 configuration", and 8.2 "waiting for uplink IP address and reachable default gateway"

Regards, Tommy V

Sean Haynes · ‎03-06-2018

...I feel your pain - from everything I have read, put simply it's a jolly ol bug!

All I can suggest is do what I did and assign fixed IPs to each unti, time consuming I know - for me not such a problem as I wasn't having to deal with such a HUGE number like you are!

Leo Laohoo · ‎03-06-2018

Guys,
One way of fixing this issue is to aggressively reboot the AP. No choice. This is the only workaround we've seen (so far).
The problem I'm seeing (not yet confirm by Cisco) is the DHCP process of the APs keep crashing. Rebooting the AP would help.

Tommy Vindvik · ‎03-06-2018

Hi,

I'm not sure if the DHCP-process are crashing, but there is some kind of problem with it.

Turing on "debug dhcp event", "debug dhcp packet" and "debug dhcp errors" it seems like the AP don't register the DHCP offer from our servers. Then it resets the interface and DHCP client before it tries again and again and again.......

[*03/06/2018 14:41:11.8627] Resetting wired0 and[03/06/2018 14:41:11.8900] wired0: stopped
restart DHCP client
[03/06/2018 14:41:13.9700] wired0 emac 0: link up
[03/06/2018 14:41:14.0300] wired0: link up
[03/06/2018 14:41:14.0700] wired0: started
[*03/06/2018 14:41:14.1299] aptrace_register_sysproc_fn: duplicate registeration for 'wired'
[*03/06/2018 14:41:15.2345] Waiting for uplink IPv4 configuration
[*03/06/2018 14:41:20.2356] Waiting for uplink IPv4 configuration
[*03/06/2018 14:41:25.2366] Waiting for uplink IPv4 configuration
[*03/06/2018 14:41:25.3800] chatter: DHCP-EVT: Sending DHCP discover packet length 346 bytes
[*03/06/2018 14:41:25.3800] chatter: DHCP-PAK: Sent DHCP_DISCOVER pak:
[*03/06/2018 14:41:25.3801] chatter: sent pkt source: 0.0.0.0, destination: 255.255.255.255
[*03/06/2018 14:41:25.3801] chatter: UDP sport: 68, dport: 67, length: 312
[*03/06/2018 14:41:25.3801] chatter: DHCP op: 1, htype: 1, hlen: 6, hops: 0
[*03/06/2018 14:41:25.3801] chatter: xid: 9f76fe5c, secs: 0, flags: 128
[*03/06/2018 14:41:25.3801] chatter: client: 0.0.0.0, your: 0.0.0.0
[*03/06/2018 14:41:25.3801] chatter: srvr: 0.0.0.0, gw: 0.0.0.0
[*03/06/2018 14:41:29.2374] Resetting wired0 and[03/06/2018 14:41:29.2600] wired0: stopped
restart DHCP client

Regards, Tommy V

Tommy Vindvik · ‎03-07-2018

Whats really weird is that *sometimes* it works to change the access port vlan on the switch to another vlan with DHCP. WTF?

No other changes, the AP does not reboot or anything. And we are sure that DHCP works just fine on the original vlan.

And why does the AP complain of "aptrace_register_sysproc_fn: duplicate registeration for 'wired'"? That don't sound right?

[*03/06/2018 14:49:18.3394] Resetting wired0 and[03/06/2018 14:49:18.3700] wired0: stopped
restart DHCP client
[03/06/2018 14:49:20.4500] wired0 emac 0: link up
[03/06/2018 14:49:20.5000] wired0: link up
[03/06/2018 14:49:20.5500] wired0: started
[*03/06/2018 14:49:20.6072] aptrace_register_sysproc_fn: duplicate registeration for 'wired'
[*03/06/2018 14:49:21.7117] Waiting for uplink IPv4 configuration
[*03/06/2018 14:49:25.8597] chatter: DHCP-EVT: Sending DHCP discover packet length 346 bytes
[*03/06/2018 14:49:25.8598] chatter: DHCP-PAK: Sent DHCP_DISCOVER pak:
[*03/06/2018 14:49:25.8598] chatter: sent pkt source: 0.0.0.0, destination: 255.255.255.255
[*03/06/2018 14:49:25.8598] chatter: UDP sport: 68, dport: 67, length: 312
[*03/06/2018 14:49:25.8598] chatter: DHCP op: 1, htype: 1, hlen: 6, hops: 0
[*03/06/2018 14:49:25.8598] chatter: xid: af76fe5c, secs: 0, flags: 128
[*03/06/2018 14:49:25.8598] chatter: client: 0.0.0.0, your: 0.0.0.0
[*03/06/2018 14:49:25.8598] chatter: srvr: 0.0.0.0, gw: 0.0.0.0
[*03/06/2018 14:49:25.8924] chatter: DHCP-EVT: Received DHCP msg type: 2 from server: 172.29.112.1
[*03/06/2018 14:49:25.8924] chatter: DHCP-EVT: DHCP client machine state: init
[*03/06/2018 14:49:25.8925] chatter: DHCP-PAK: Received DHCP_OFFER pak:
[*03/06/2018 14:49:25.8925] chatter: rcvd pkt source: 172.29.112.1, destination: 255.255.255.255
[*03/06/2018 14:49:25.8925] chatter: UDP sport: 67, dport: 68, length: 323
[*03/06/2018 14:49:25.8925] chatter: DHCP op: 2, htype: 1, hlen: 6, hops: 0
[*03/06/2018 14:49:25.8925] chatter: DHCP server identifier: 172.29.48.10
[*03/06/2018 14:49:25.8925] chatter: xid: af76fe5c, secs: 0, flags: 128
[*03/06/2018 14:49:25.8925] chatter: client: 0.0.0.0, your: 172.29.112.10
[*03/06/2018 14:49:25.8925] chatter: srvr: 172.29.48.10, gw: 172.29.112.1
[*03/06/2018 14:49:25.8926] chatter: DHCP-PAK: Sent DHCP_REQUEST pak:
[*03/06/2018 14:49:25.8926] chatter: sent pkt source: 0.0.0.0, destination: 255.255.255.255
[*03/06/2018 14:49:25.8926] chatter: UDP sport: 68, dport: 67, length: 318
[*03/06/2018 14:49:25.8926] chatter: DHCP server identifier: 172.29.48.10
[*03/06/2018 14:49:25.8926] chatter: Request DHCP IP: 172.29.112.10
[*03/06/2018 14:49:25.8926] chatter: DHCP-EVT: Sending DHCP request packet length 352 bytes
[*03/06/2018 14:49:26.0008] chatter: DHCP-EVT: Received DHCP msg type: 5 from server: 172.29.112.1
[*03/06/2018 14:49:26.0008] chatter: DHCP-EVT: DHCP client machine state: requesting
[*03/06/2018 14:49:26.0008] chatter: DHCP-PAK: Received DHCP_ACK pak:
[*03/06/2018 14:49:26.0009] chatter: rcvd pkt source: 172.29.112.1, destination: 255.255.255.255
[*03/06/2018 14:49:26.0009] chatter: UDP sport: 67, dport: 68, length: 323
[*03/06/2018 14:49:26.0009] chatter: DHCP op: 2, htype: 1, hlen: 6, hops: 0
[*03/06/2018 14:49:26.0009] chatter: DHCP server identifier: 172.29.48.10
[*03/06/2018 14:49:26.0009] chatter: xid: af76fe5c, secs: 0, flags: 128
[*03/06/2018 14:49:26.0009] chatter: client: 0.0.0.0, your: 172.29.112.10
[*03/06/2018 14:49:26.0009] chatter: srvr: 0.0.0.0, gw: 172.29.112.1
[*03/06/2018 14:49:26.7128] Waiting for uplink IPv4 configuration
[*03/06/2018 14:49:28.6876] ethernet_port wired0, ip 172.29.112.10, netmask 255.255.255.0, gw 172.29.112.1, mtu 1500, bcast 172.29.112.255, dns1 172.29.48.10, dns2 172.29.48.11, domain xxx.wifi.yyy.noDOT11_CFG[0] Radio Mode is changed from Local to Local
[*03/06/2018 14:49:35.8191] DOT11_CFG[1] Radio Mode is changed from Local to Local
[*03/06/2018 14:49:35.8389] AP IPv4 Address updated from 0.0.0.0 to 172.29.112.10

Regards, Tommy V

Sean Haynes · ‎03-07-2018

..same as you, you can see the requests going out, again and again. I can find no valid reason why it won't work.

Like I said if you do a sho arp it brings up all the neighbours - so data is being sent and received but not DHCP which works perfectly fine on the old 1142Ns and attached wireless devices.

Leo Laohoo · ‎03-07-2018

When I was testing the 2800 I encountered this problem. That's why I know about the "fix". Cisco TAC told me (TWO TAC cases) that this issue could not be reproduced in their lab.

This is not an issue with the DHCP. This is an issue with the AP's DHCP service crashing. The crash can't be seen by "mortals" because you need to be in developers mode (requires a challenge password) to see it.