[lwip-users] broken DHCP/ARP interaction

I am having an LwIP problem where the local ARP erroneously answers its own who-has request

and by doing that prevents DHCP from working correctly. I would appreciate if anyone

familiar with the ARP code could comment on how this could possibly happen (and of

course help me fix it J).

The setup is an embedded WiFi device running FreeRTOS with LwIP, attempting to obtain

an IP address from the wireless network it just joined. I have a wireshark log I could provide

(it’s big and hard to read) capturing the following:

1. The device associates with the network and requests IP address from the DHCP server

2. The DHCP server gives IP address to the device

3. The device runs an ARP IP check on the address

4. The device erroneously answers its own ARP request

5. The device consequently (ARP answered) rejects the IP address offered by the DHCP server

Obviously, the #4 is wrong, the device should have never answered its own ARP since the IP address

in question is still being validated (by that very ARP transaction).

I am not familiar with the code base so I have no idea how this could happen (appears obviously wrong).

I turned on some debugging in the stack and what I see simply confirms what I had decoded with wireshark.

This is easily reproducible (as in it happens every single time I run it) so I could instrument more of the stack,

if that would help with debugging.

Here is the log:

Aspen firmware: May 13 2014 13:58:05

[2.806917] : etharp_send_ip: sending packet 0x20004b34

[2.811492] : etharp_send_ip: sending packet 0x20004b34

[2.905013] : etharp_send_ip: sending packet 0x20004b34

[3.109013] : etharp_send_ip: sending packet 0x20004b34

[appln] listen: OK

[wlcm] got wifi message: 8 0 0x00000000

[wlcm] got event: scan result

[wlcm] Found better AP iRobot-Guest on channel 11

[wlcm] starting association to "default"

[wlcm] got wifi message: 10 0 0x00000000

[wlcm] got event: association result: success

[wlcm] got wifi message: 12 0 0x00000000

[wlcm] got event: authentication result: success

[net] configuring interface mlan (with DHCP client)

[4.824439] : dhcp_start(netif=0x20012024) ml1

[4.828588] : dhcp_start(): starting new DHCP client

[4.836495] : dhcp_start(): starting DHCP configuration

[4.841152] : dhcp_discover()

[4.843650] : transaction id xid(5542A27)

[4.847158] : dhcp_discover: making request

[4.850809] : dhcp_discover: realloc()ing

[4.854298] : dhcp_discover: sendto(DISCOVER, IP_ADDR_BROADCAST, DHCP_SERVER_PORT)

[4.861214] : etharp_send_ip: sending packet 0x20004b7c

[4.865908] : dhcp_discover: deleting()ing

[4.869444] : dhcp_discover: SELECTING

[4.872686] : dhcp_discover(): set request timeout 2000 msecs

[4.877847] : ethernet_input: dest:ff:ff:ff:ff:ff:ff, src:44:ad:d9:02:a8:cd, type:800

[4.885014] : dhcp_recv(pbuf = 0x2000f7f8) from DHCP server 172.16.16.7 port 67

[4.891654] : pbuf->len = 310

[4.894150] : pbuf->tot_len = 310

[4.896998] : searching DHCP_OPTION_MESSAGE_TYPE

[4.901056] : DHCP_OFFER received in DHCP_SELECTING state

[4.905881] : dhcp_handle_offer(netif=0x20012024) ml1

[4.910375] : dhcp_handle_offer(): server 0x0B02460A

[4.914785] : dhcp_handle_offer(): offer for 0x641110AC

[4.919443] : dhcp_select(netif=0x20012024) ml1

[4.923440] : transaction id xid(169C39E2)

[4.927046] : etharp_send_ip: sending packet 0x20004b7c

[4.931723] : dhcp_select: REQUESTING

[4.934837] : dhcp_select(): set request timeout 2000 msecs

[4.939831] : ethernet_input: dest:ff:ff:ff:ff:ff:ff, src:44:ad:d9:02:a8:cd, type:800

[4.946993] : dhcp_recv(pbuf = 0x2000f1bc) from DHCP server 172.16.16.7 port 67

[4.953638] : pbuf->len = 310

[4.956135] : pbuf->tot_len = 310

[4.958980] : searching DHCP_OPTION_MESSAGE_TYPE

[4.963038] : DHCP_ACK received

[4.965703] : dhcp_check(netif=0x20012024) ml

[4.969530] : dhcp_check(): netif IP: 0x00000000

[4.973606] : etharp_find_entry: found empty entry 0

[4.978017] : etharp_find_entry: selecting empty entry 0

[4.982759] : etharp_request: sending ARP request.

[4.987007] : etharp_raw: sending raw ARP packet.

[4.991203] : dhcp_check(): set request timeout 500 msecs

[4.995991] : ethernet_input: dest:6c:ad:f8:e5:27:fe, src:6c:ad:f8:e5:27:fe, type:806

[5.003142] : etharp_update_arp_entry: 172.16.17.100 - 6C:AD:F8:E5:27:FE

[5.009217] : etharp_find_entry: found matching entry 0

[5.013879] : etharp_update_arp_entry: updating stable entry 0

[5.019116] : etharp_arp_input: incoming ARP reply

[5.023360] : dhcp_arp_reply()

[5.025938] : dhcp_arp_reply(): CHECKING, arp reply for 0x641110AC

[5.031513] : dhcp_arp_reply(): arp reply matched with offered address, declining

[5.038336] : dhcp_decline()

[5.040751] : transaction id xid(2EAB4956)

[5.044358] : etharp_send_ip: sending packet 0x20004b7c

[5.049038] : dhcp_decline: BACKING OFF

[5.052316] : dhcp_decline(): set request timeout 10000 msecs

Thanks for any pointers or help.

-Z

From:	Radouch, Zdenek
Subject:	[lwip-users] broken DHCP/ARP interaction
Date:	Tue, 13 May 2014 19:19:50 +0000