dhclient fails to assign IP address during system boot inspite of valid DHCP Offer when time change is performed by systemd-timesyncd.service

[J.D.]

System Information:
Description: Ubuntu 16.04.2 LTS
Release: 16.04

Package Information:
network-manager:
  Installed: (none)
  Candidate: 1.2.6-0ubuntu0.16.04.1
  Version table:
     1.2.6-0ubuntu0.16.04.1 500
        500 http://us.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
     1.2.2-0ubuntu0.16.04.4 500
        500 http://security.ubuntu.com/ubuntu xenial-security/main amd64 Packages
     1.1.93-0ubuntu4 500
        500 http://us.archive.ubuntu.com/ubuntu xenial/main amd64 Packages

Expected Behavior:
The system has one ethernet interface ens160 that is expected to be assigned an IPv4 address using DHCP as part of the bootup process so that services that depends on presence of IPv4 address do not fail to initialize during the boot process.

Problem Behavior:
The ethernet interface ens160 was UP but no IPv4 address was assigned inspite of correct response from the DHCP server, thereby causing the services that depends on presence of IPv4 address to fail during the boot process.

Problem Details:
The default 16.04.2 LTS server installed in a VMWare virtual machine running on SuperMicro server using ESXi 6 fails to obtain an IP address from a DHCP server during system startup when there is a simultaneous time change as evidenced by "systemd[1]: Time has been changed" entry in syslog. The system successfully obtains the IP address after significant delay (ranging from 2 - 5 minutes) after system startup.

Note that the system has open-vmware-tools package and the VMWare tools settings are set to NOT synchronize the guest time, thereby eliminating any scope of interference from virtualization host (The host itself is set to use NTP synchronization and has correct timing).

Wireshark was used to sniff the BOOTP messages. When system is rebooted, system sends a DHCP Release to the DHCP server. When system starts, it broadcasts a valid DHCP Discover to network and received a valid DHCP Offer from the network within 4 secs. Note that a "Time has been changed" log appears just before dhclient logs "No DHCPOFFERS received" in syslog. (The time appears to be moved ahead by around 6 mins.)

After about 4 minutes, system broadcasts a valid DHCP Discover to which DHCP server responds with DHCP Offer, system responds with DHCP Request and DHCP server responds with DHCP Ack and the system is assigned its IP address. The dhclient logs in syslog concurs with the wireshark trace:

Apr 6 18:39:05 etCorgServer dhclient[1071]: DHCPDISCOVER on ens160 to 255.255.255.255 port 67 interval 3 (xid=0x92322e17)
Apr 6 18:39:08 etCorgServer dhclient[1071]: DHCPDISCOVER on ens160 to 255.255.255.255 port 67 interval 8 (xid=0x92322e17)
Apr 6 18:39:08 etCorgServer dhclient[1071]: DHCPREQUEST of 192.168.1.161 on ens160 to 255.255.255.255 port 67 (xid=0x172e3292)
Apr 6 18:39:08 etCorgServer dhclient[1071]: DHCPOFFER of 192.168.1.161 from 192.168.1.1
Apr 6 18:39:09 etCorgServer dhclient[1071]: DHCPACK of 192.168.1.161 from 192.168.1.1
Apr 6 18:39:09 etCorgServer dhclient[1071]: bound to 192.168.1.161 -- renewal in 33171 seconds.

An attempt to release and reacquire the IP address after the system is up and running always succeeds immediately with the aforesaid "happy" usecase.

Workaround Attempted:
Turning off systemd-timesyncd.service always allows dhclient to immediately assign the IP address during the boot process. Turning it on leads to the above problem usecase with very high probability. Based on this observation, an assumption can be made that the time synchronization happens to overlap the DHCP processing performed by dhclient. There is a time-change which causes the DHCP Offer sent by the DHCP server to be ignored and dhclient to snooze for a long time before attempting another DHCP Discover message to the server. Under such circumstances, the services that depend on presence of an IP address fail.

Attempted Workaround:
Above assumption was further used to create a delayNetwork.service patch one-shot systemd service that causes the networking service to delay networking.service until time-sync.target is reached by the systemd-timesyncd.service. Such patch seems to cause dhclient to always assign IP address during boot process. However, it would be desirable to ensure that dhclient and/or the networking.service take correct steps to protect itself against race conditions that may arise due to time changes affected by the systemd-timesyncd.service. At the very least, possibility of time change during such critical and vulnerable system component initialization must be minimized by isolating the time change to occur during a bootup phase when such components are not being initialized.

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: network-manager (not installed)
ProcVersionSignature: Ubuntu 4.4.0-62.83-generic 4.4.40
Uname: Linux 4.4.0-62-generic x86_64
ApportVersion: 2.20.1-0ubuntu2.5
Architecture: amd64
Date: Fri Apr 7 22:50:11 2017
InstallationDate: Installed on 2017-04-06 (1 days ago)
InstallationMedia: Ubuntu-Server 16.04.2 LTS "Xenial Xerus" - Release amd64 (20170215.8)
ProcEnviron:
 SHELL=/bin/bash
 TERM=linux
 PATH=(custom, user)
 LANG=en_US.UTF-8
 XDG_RUNTIME_DIR=<set>
SourcePackage: network-manager
UpgradeStatus: No upgrade log present (probably fresh install)

[J.D. (j1234d2003)]

Please find the attached wireshark trace of the BOOTP messages for problem usecase, whereby the system was rebooted.

[J.D. (j1234d2003)]

Please find the attached patch service that was used to delay the network initialization so that it is not affected by the time-change by systemd-timesyncd.service. This may not exactly be an acceptable solution but demonstrates how equivalent changes can be performed to arrive at the solution.