CSCvq88420 - 3802 AP - Not forwarding DHCP Offer downstream to the client

[devilstide]

Hello,

I have been encountering this issue loosely matching the bug description. We have hundreds of AP's deployed and from time-to-time they "need" a reboot and one of the issues encountered is that the clients never receive a DHCP address from that certain AP.

On the WLC side the relevant debugs look like this:

*DHCP Socket Task: Mar 05 04:14:49.225: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP received op BOOTREQUEST (1) (len 308,vlan 112, port 8, encap 0xec03, xid 0x13c73c7a)
*DHCP Socket Task: Mar 05 04:14:49.225: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP processing DHCP REQUEST (3)
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP xid: 0x7a3cc713 (2050803475), secs: 6, flags: 0
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP chaddr: MAC:OF:ENDPOINT:WIFI:NIC
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP requested ip: requested.ip.address
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP Opt82 bridge mode insertion enabled, inserts opt82 if opt82 is enabled vlan=111, datalen =18, optlen=64
*DHCP Socket Task: Mar 05 04:14:49.226: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP successfully bridged packet to DS
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP received op BOOTREPLY (2) (len 339,vlan 111, port 8, encap 0xec00, xid 0x13c73c7a)
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP processing DHCP ACK (5)
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP xid: 0x7a3cc713 (2050803475), secs: 6, flags: 0
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP chaddr: MAC:OF:ENDPOINT:WIFI:NIC
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP ciaddr: 0.0.0.0, yiaddr: requested.ip.address
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP siaddr: 0.0.0.0, giaddr: gateway.ip.address
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP server id: dhcp.server.nr1 rcvd server id: dhcp.server.nr1
*DHCP Socket Task: Mar 05 04:14:49.239: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP successfully bridged packet to STA
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP received op BOOTREPLY (2) (len 342,vlan 111, port 8, encap 0xec00, xid 0x13c73c7a)
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP processing DHCP ACK (5)
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP xid: 0x7a3cc713 (2050803475), secs: 6, flags: 0
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP chaddr: MAC:OF:ENDPOINT:WIFI:NIC
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP ciaddr: 0.0.0.0, yiaddr: requested.ip.address
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP server id: dhcp.server.nr2 rcvd server id: dhcp.server.nr2
*DHCP Socket Task: Mar 05 04:14:49.305: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP successfully bridged packet to STA
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP received op BOOTREQUEST (1) (len 308,vlan 112, port 8, encap 0xec03, xid 0x92d54e9)
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP processing DHCP REQUEST (3)
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP xid: 0xe9542d09 (3914607881), secs: 0, flags: 80
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP chaddr: MAC:OF:ENDPOINT:WIFI:NIC
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP requested ip: requested.ip.address
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP Opt82 bridge mode insertion enabled, inserts opt82 if opt82 is enabled vlan=111, datalen =18, optlen=64
*DHCP Socket Task: Mar 05 04:14:53.535: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP successfully bridged packet to DS
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP received op BOOTREPLY (2) (len 339,vlan 111, port 8, encap 0xec00, xid 0x92d54e9)
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP processing DHCP ACK (5)
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP xid: 0xe9542d09 (3914607881), secs: 0, flags: 80
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP chaddr: MAC:OF:ENDPOINT:WIFI:NIC
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP ciaddr: 0.0.0.0, yiaddr: requested.ip.address
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP siaddr: 0.0.0.0, giaddr: gateway.ip.address
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP server id: dhcp.server.nr1 rcvd server id: dhcp.server.nr1
*DHCP Socket Task: Mar 05 04:14:53.548: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP successfully bridged packet to STA
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP received op BOOTREPLY (2) (len 342,vlan 111, port 8, encap 0xec00, xid 0x92d54e9)
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP processing DHCP ACK (5)
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP xid: 0xe9542d09 (3914607881), secs: 0, flags: 80
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP chaddr: MAC:OF:ENDPOINT:WIFI:NIC
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP ciaddr: 0.0.0.0, yiaddr: requested.ip.address
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP siaddr: 0.0.0.0, giaddr: gateway.ip.address
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP server id: dhcp.server.nr2 rcvd server id: dhcp.server.nr2
*DHCP Socket Task: Mar 05 04:14:53.615: [PA] MAC:OF:ENDPOINT:WIFI:NIC DHCP successfully bridged packet to STA

Whilst at the same time we see corelated messages on the AP:

Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2855] [1614946488:285516] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] < wifi1> [U:W] DHCP_REQUEST : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2855] [1614946488:285542] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [U:C] DHCP_REQUEST : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2855] [1614946488:285566] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [U:C] DHCP_REQUEST : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2855] [1614946488:285587] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [U:E] DHCP_REQUEST : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2992] [1614946488:299228] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:E] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2992] [1614946488:299251] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2992] [1614946488:299277] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.2993] [1614946488:299305] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [D:W] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.3655] [1614946488:365531] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:E] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.3655] [1614946488:365557] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.3655] [1614946488:365584] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:48 kernel: [*03/05/2021 12:14:48.3656] [1614946488:365617] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [D:W] DHCP_ACK : TransId 0x13c73c7a
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.5952] [1614946492:595217] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] < wifi1> [U:W] DHCP_REQUEST : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.5952] [1614946492:595245] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [U:C] DHCP_REQUEST : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.5952] [1614946492:595271] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [U:C] DHCP_REQUEST : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.5953] [1614946492:595295] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [U:E] DHCP_REQUEST : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6088] [1614946492:608827] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:E] DHCP_ACK : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6088] [1614946492:608855] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6088] [1614946492:608883] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6089] [1614946492:608919] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [D:W] DHCP_ACK : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6753] [1614946492:675330] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:E] DHCP_ACK : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6753] [1614946492:675359] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6753] [1614946492:675387] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <wired0> [D:C] DHCP_ACK : TransId 0x092d54e9
Mar 5 12:14:52 kernel: [*03/05/2021 12:14:52.6754] [1614946492:675421] [AP123] [MAC:OF:ENDPOINT:WIFI:NIC] <apr1v2> [D:W] DHCP_ACK : TransId 0x092d54e9

I don't have visibility of the endpoint, but I know for sure it never gets the ACK message and hence it keeps requesting an IP address(these messages loop). As soon as it connects to another AP - instant connectivity and DHCP address. Several makes and models of endpoints appear to be affected by this issue on that specific AP.

So from the looks of it - the AP is lying to us about it's internal forwarding of DHCP messages - at least as far as these logs and debugs go.

WLC/AP SW is 8.5.161.0

AP Model is AIR-AP3802I-B-K9 - running in local mode

Identical AP(SW, configuration and HW) is connected to a port on the same switch and works fine, it's even been up for the same amount of days.

The AP will likely be rebooted soon - so let me know if anyone has any ideas on additional debugs I can run.

Thanks!

[nick.weber@kumandgo.com]

Did you ever find a solution to this?