1479593 – dhclient does not consider time changes

Bug 1479593 - dhclient does not consider time changes

Summary: dhclient does not consider time changes

Keywords:
Status:	CLOSED DUPLICATE of bug 916116
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	dhcp
Sub Component:
Version:	26
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	Pavel Zhukov
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-08-08 23:09 UTC by Kyle Marek
Modified:	2017-08-09 05:37 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2017-08-09 05:37:13 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Description Kyle Marek 2017-08-08 23:09:47 UTC

Description of problem:
dhclient lets leases expire if time dramatically changes backwards from when lease time was recorded.

Version-Release number of selected component (if applicable):
dhcp-client-4.3.5-7.fc26.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Install Fedora 26 in a QEMU VM
2. Configure time zone as America/New_York
3. Configure time source as LOCAL time
4. Reboot

Actual results:
1. VM boots with time that is 4 or 5 hours ahead depending on daylight saving time.
2. dhclient obtains a lease
3. dhclient records renew time as 5 minutes ahead of current time (at least in my 10-minute lease environment)
4. NTP corrects time
5. 10 minutes later: Kernel removes IP address from interface due to dhclient-configured valid_lft counter reaching 0.
6. 4 or 5 hours later: dhclient finally renews lease

Expected results:
dhclient corrects recorded leases upon time shift, and continues to renew leases on expected schedule.

Additional info:
This issue is not specific to Fedora 26. I have also experienced this in Fedora 24 and 25.

This issue may be specific-ish to running Fedora in VMs that do not match expected time settings. Physical machines may only be subject to the issue once as NTP's correction of the time will be retained by CMOS/time circuit, whereas restarting QEMU will reset time presented to VM as whatever is specified (or UTC if unspecified).

Will likely affect anything else that never keep the time such as dead laptops (was observed during testing) or Raspberry Pi boards.

Anaconda usually configures time source to whatever looked more-correct during installation [1]. I was subject to this issue a lot before identifying the source as I left UTC unspecified in my very frequently used kickstart file.

journal to support:
Aug 08 13:00:50 localhost.localdomain NetworkManager[603]: <info>  [1502211650.1064] device (ens3): state change: config -> ip-config (reason 'none', internal state 'managed')
Aug 08 13:00:50 localhost.localdomain NetworkManager[603]: <info>  [1502211650.1080] dhcp4 (ens3): activation: beginning transaction (timeout in 45 seconds)
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.5081] dhcp4 (ens3): dhclient started with pid 761
Aug 08 13:00:54 localhost.localdomain dhclient[761]: DHCPDISCOVER on ens3 to 255.255.255.255 port 67 interval 3 (xid=0xa00fa608)
Aug 08 13:00:54 localhost.localdomain dhclient[761]: DHCPREQUEST on ens3 to 255.255.255.255 port 67 (xid=0xa00fa608)
Aug 08 13:00:54 localhost.localdomain dhclient[761]: DHCPOFFER from 10.42.0.1
Aug 08 13:00:54 localhost.localdomain dhclient[761]: DHCPACK from 10.42.0.1 (xid=0xa00fa608)
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6179] dhcp4 (ens3):   address 10.42.0.225
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6179] dhcp4 (ens3):   plen 24 (255.255.255.0)
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6179] dhcp4 (ens3):   gateway 10.42.0.1
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6180] dhcp4 (ens3):   lease time 505
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6180] dhcp4 (ens3):   nameserver '10.42.0.29'
Aug 08 13:00:54 localhost.localdomain nm-dispatcher[616]: req:2 'pre-up' [ens3]: new request (1 scripts)
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6180] dhcp4 (ens3):   domain name 'internal.gigabyteproductions.net'
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6180] dhcp4 (ens3): state changed unknown -> bound
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6202] device (ens3): state change: ip-config -> ip-check (reason 'none', internal state 'managed')
Aug 08 13:00:54 localhost.localdomain dhclient[761]: bound to 10.42.0.225 -- renewal in 45 seconds.
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6765] device (ens3): state change: ip-check -> secondaries (reason 'none', internal state 'managed')
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6770] device (ens3): state change: secondaries -> activated (reason 'none', internal state 'managed')
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6772] manager: NetworkManager state is now CONNECTED_LOCAL
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6823] manager: NetworkManager state is now CONNECTED_SITE
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6829] policy: set 'ens3' (ens3) as default for IPv4 routing and DNS
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6930] device (ens3): Activation: successful, device activated.
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6944] manager: startup complete
Aug 08 13:00:54 localhost.localdomain NetworkManager[603]: <info>  [1502211654.6954] manager: NetworkManager state is now CONNECTED_GLOBAL
Aug 08 13:00:54 localhost.localdomain nm-dispatcher[616]: req:3 'up' [ens3]: new request (4 scripts)
Aug 08 13:00:54 localhost.localdomain nm-dispatcher[616]: req:3 'up' [ens3]: start running ordered scripts...
Aug 08 13:00:54 localhost.localdomain nm-dispatcher[616]: req:4 'connectivity-change': new request (4 scripts)
Aug 08 13:00:55 localhost.localdomain nm-dispatcher[616]: req:4 'connectivity-change': start running ordered scripts...
Aug 08 13:00:56 localhost.localdomain NetworkManager[603]: <info>  [1502211656.8716] policy: set 'ens3' (ens3) as default for IPv6 routing and DNS
Aug 08 13:01:00 localhost.localdomain chronyd[584]: Selected source 216.218.254.202
Aug 08 13:01:00 localhost.localdomain chronyd[584]: System clock wrong by -14399.260823 seconds, adjustment started
Aug 08 09:01:01 localhost.localdomain chronyd[584]: System clock was stepped by -14399.260823 seconds

[omitted non-jumped progression of time from 09:01:01 to 13:01:39]
(no occurrence of the word "lease" in this omission)

Aug 08 13:01:39 localhost.localdomain dhclient[761]: DHCPREQUEST on ens3 to 10.42.0.1 port 67 (xid=0xa00fa608)
Aug 08 13:01:39 localhost.localdomain dhclient[761]: DHCPACK from 10.42.0.1 (xid=0xa00fa608)
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5943] dhcp4 (ens3):   address 10.42.0.225
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5954] dhcp4 (ens3):   plen 24 (255.255.255.0)
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5954] dhcp4 (ens3):   gateway 10.42.0.1
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5954] dhcp4 (ens3):   lease time 600
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5954] dhcp4 (ens3):   nameserver '10.42.0.29'
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5955] dhcp4 (ens3):   domain name 'internal.gigabyteproductions.net'
Aug 08 13:01:39 localhost.localdomain dbus-daemon[582]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.4' (uid=0 pid=603 comm="/usr/sbin/NetworkManager --no-daemon " label="s
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5955] dhcp4 (ens3): state changed bound -> bound
Aug 08 13:01:39 localhost.localdomain NetworkManager[603]: <info>  [1502211699.5970] policy: set 'ens3' (ens3) as default for IPv4 routing and DNS
Aug 08 13:01:39 localhost.localdomain systemd[1]: Starting Network Manager Script Dispatcher Service...
Aug 08 13:01:39 localhost.localdomain dhclient[761]: bound to 10.42.0.225 -- renewal in 45 seconds.


[1] https://lists.fedorahosted.org/archives/list/anaconda-patches@lists.fedorahosted.org/thread/AIEJ5XXDGE3ICDMVQX5NLGUA52VBO3KU/

Comment 1 Pavel Zhukov 2017-08-09 05:37:13 UTC

Thank you for reporting this.
This is known issue. DHCP code uses gettimeofday and because of that it not stable in case of system time changing. It can cause IP changing or no IP at all because of lifetime.
https://bugzilla.redhat.com/show_bug.cgi?id=916116#c8

and 
https://bugzilla.redhat.com/show_bug.cgi?id=1093803 for RHEL

*** This bug has been marked as a duplicate of bug 916116 ***

Note You need to log in before you can comment on or make changes to this bug.