Delayed DHCP at one Ethernet adapter RRS feed

  • Question

  • I have a WEC2013 project for a hardware with 2 Ethernet adapters. One adapter (A) shall be used in a private network to access some devices at a dedicated network. The other adapter (B) shall be used in a normal administered network. For this purpose I have configfure the adapter A for static IP

    "IPAddress"=multi_sz:"" "SubnetMask"=multi_sz:"" "DefaultGateway"=multi_sz:""

    The adapter B keeps the default registry value "EnableDHCP"=dword:1.

    With this setup I see a strange behavior of the adapter B (DHCP enabled) at the network: It starts sending ICMPv6 messages. After 16 seconds an Auto-IP process starts with sending ARP messages for a IP address 169.254.x.y. Finally the DHCP changeds the IP address.

    This is shown in this simplified network log. The timestamp since start of capture is listed in milliseconds in the leftmost colum:

    00000 Multicast Listener Report Message v2
    00077 Router Solicitation
    00579 Neighbor Solicitation for xxxx::xxxx:xxxx:xxx:xxx:xxx
    00582 Multicast Listener Report Message v2
    01585 Neighbor Advertisement xxxx::xxxx:xxxx:xxx:xxx:xxx (ovr) is at XX:XX:XX:XX:XX:XX
    04069 Router Solicitation from xxxx::xxxx:xxxx:xxx:xxx:xxx
    08064 Router Solicitation from xxxx::xxxx:xxxx:xxx:xxx:xxx
    16045 ARP Who has
    17043 ARP Who has
    18041 ARP Who has
    19039 ARP Gratuitous ARP for (Request)
    20037 DHCP Request for previous leased IP configuration

    The DHCP request is answered by the DHCP server and the normal procedure with ARP for the IP address assigned by the DHCP server follows. This behavior is strange because

    1. The DHCP (IPv4) starts very late. It looks like it is delayed until DHCP (IPv6) is finisihed.
    2. The IP stack has no valid configuration and starts 16 seconds after the start the Auto-IP process.

    The Auto-IP process results in a transient state where the IP address of that adapter is different from the DHCP assigned address. This causes sending messages to the network after Auto-IP completion with an address that is not reachable after DHCP (IPv4) is finished.

    The traffic at the adapter B (static IP) is normal. ICMPv6 and ARP for the static IP address are working simultanously. The process is finisehe after 3500 milliseconds.

    The leads to the questions:

    1. Why is the DHCP (IPv4) process delayed by 20 seconds?
    2. Why does the Auto-IP process starts 4 seconds before the DHCP (Ipv4) process?
    3. How can I control the behavior so the the ICMPv6 doesn't cause a delay?

    I have also tried to run the device with DHCP enabled at both adapters. This resulted in a simultanous operation of the processes ICMPv6 and DHCP (vIPv6).

    • Edited by Harper23 Monday, December 19, 2016 4:05 PM
    Monday, December 19, 2016 4:00 PM

All replies

  • I'd capture the serial debug output stream from a Debug build of the operating system. If you don't care about AutoIP, you can disable that (AutoCfg, I think the value is called), before go Debug.

    Post the network portions of the log replicating the error and maybe we can identify something.

    Paul T.

    Wednesday, December 21, 2016 5:35 PM
  • I have set the debug zone mask for the DHPC.dll to 0xFFFF to see as much as possible from that module. I have scanned the output and identified the thread (is it a single thread??) that handles the DHCP process. Then I filtered to huge output of the debug image for that thread. Here is the result:

    [17:55:28.918]  DHCP:DhcpEventWorker: Processing DHCP_EVENT_OBTAIN_LEASE for GEMAC2
    [17:55:28.935]  +DHCP:GetDhcpConfig(GEMAC2):
    [17:55:29.074]  DHCP:StringToAddr: Converted to address 6301A8C0
    [17:55:29.143]  DHCP:StringToAddr: Converted to address FFFFFF
    [17:55:29.213]  -DHCP:GetDhcpConfig(GEMAC2):
    [17:55:29.221]  +DHCP:DhcpInitSock: pDhcp 0XCB310490
    [17:55:29.221]  -DHCP:DhcpInitSock: pDhcp 0xCB310490/0x3 Ret: 0
    [17:55:29.230]  +DHCP:GetDhcpLease: pDhcp 0xCB310490/0x3 (GEMAC2)
    [17:55:35.111]  +BuildDhcpPkt(GEMAC2): REQUEST 0xCB310490
    [17:55:35.115]  DHCP:BuildDhcpPkt(GEMAC2): TX REQUEST
    [17:55:35.126]  -BuildDhcpPkt(GEMAC2): 0x3 Len 267
    [17:55:35.126]  +SendDhcpPkt(GEMAC2): pPkt CB71EE98
    [17:55:35.133]  ### -SendDhcpPkt(GEMAC2): cMinimumTimeout 500d
    [17:55:35.141]  AddFuzz, cFuzz:-182, cTimeout:500, cRet:318
    [17:55:35.150]  SendDhcpPkt(GEMAC2), DhcpSendDown with cBeginTime:4294778318, zero time:4294778318, current:4294778318, last_time:0, interval:4294778318

    The columns with PID: and TID: have been removed since they are all the same for these lines.

    I can see a gap of nearly 6 seconds after the call to GetDhcpLease. This output should be printed in "int GetDhcpLease(struct DhcpInfo *)" of the DHCP.dll. But I have no further information about that function.

    The Registry has these values:

    ;Number of retries before the dialogue box comes up

    ;INIT delay, RFC2131 recommends 10 seconds "DhcpInitDelayInterval"=dword:00002710

    ;DHCP will keep retrying "DhcpMaxRetry"=dword:FFFFFFFF

    ; Yes, we want DHCP "EnableDHCP"=dword:00000001

    ; This should be SZ... If null it means use LAN, else WAN and Interface. "LLInterface"=""

    ; This should be used as we did it last time "DhcpIPAddress"=multi_sz:"", "" "DhcpSubnetMask"=multi_sz:"", ""

    I can't rely on a disabled AutoIP because this should be one option *after* DHCP has failed.

    • Edited by Harper23 Wednesday, December 21, 2016 6:15 PM
    Wednesday, December 21, 2016 6:12 PM
  • Please verify the value of this setting:

    AutoInterval : REG_DWORD Default setting is 300. This value specifies the time interval, in seconds, used to verify if a DHCP server is available to configure adapter settings for a devic, for example, IP Address, SubnetMask, default gateway, DNS and WINS servers.

    Is it possible that you've removed or accidentally changed this value making it smaller than the normal DHCP startup time-out?

    ;INIT delay, RFC2131 recommends 10 seconds

    Do you see the AutoIP "process" running? When does it start and is it in any way you see correlated with an "event" on the DHCP thread?

    Paul T.

    Tuesday, December 27, 2016 8:37 PM