[pkg-ntp-maintainers] Bug#766838: ntpdate runs before dhcp-client has configured the network interface

[Hartmut Buhrmester]

I recently noticed a similar problem with ntpdate on Debian 8 Jessie. 
ntpdate is called before dhclient (isc-dhcp-client) has configured the 
network interface. Then ntpdate fails, because the dns resolution 
doesn't work yet.

The versions of ntpdate and isc-dhcp-client are:

ntpdate 1:4.2.6.p5+dfsg-7+deb8u2
isc-dhcp-client 4.3.1-6+deb8u2


A relevant part of /var/log/syslog looks like:

Nov 29 08:18:17 debian systemd[1]: Starting ifup for eth0...
Nov 29 08:18:17 debian systemd[1]: Started ifup for eth0.
Nov 29 08:18:17 debian systemd[1]: Starting Network.
Nov 29 08:18:17 debian systemd[1]: Reached target Network.
Nov 29 08:18:17 debian systemd[1]: Starting Network is Online.
Nov 29 08:18:17 debian systemd[1]: Reached target Network is Online.
Nov 29 08:18:17 debian systemd[1]: Starting LSB: RPC portmapper 
replacement...
Nov 29 08:18:17 debian ntpdate[517]: Can't find host 
0.debian.pool.ntp.org: Name or service not known (-2)
Nov 29 08:18:17 debian ntpdate[517]: Can't find host 
1.debian.pool.ntp.org: Name or service not known (-2)
Nov 29 08:18:17 debian ntpdate[517]: Can't find host 
2.debian.pool.ntp.org: Name or service not known (-2)
Nov 29 08:18:17 debian ntpdate[517]: Can't find host 
3.debian.pool.ntp.org: Name or service not known (-2)
Nov 29 08:18:17 debian ntpdate[517]: no servers can be used, exiting
Nov 29 08:18:17 debian dhclient: Internet Systems Consortium DHCP Client 
4.3.1
Nov 29 08:18:17 debian ifup[518]: Internet Systems Consortium DHCP 
Client 4.3.1
Nov 29 08:18:17 debian dhclient: Copyright 2004-2014 Internet Systems 
Consortium.
Nov 29 08:18:17 debian ifup[518]: Copyright 2004-2014 Internet Systems 
Consortium.
Nov 29 08:18:17 debian dhclient: All rights reserved.
Nov 29 08:18:17 debian dhclient: For info, please visit 
https://www.isc.org/software/dhcp/
Nov 29 08:18:17 debian dhclient:
Nov 29 08:18:17 debian ifup[518]: All rights reserved.
Nov 29 08:18:17 debian ifup[518]: For info, please visit 
https://www.isc.org/software/dhcp/
Nov 29 08:18:17 debian rpcbind[519]: Starting rpcbind daemon....
Nov 29 08:18:17 debian systemd[1]: Started LSB: RPC portmapper replacement.
Nov 29 08:18:17 debian systemd[1]: Starting RPC Port Mapper.
Nov 29 08:18:17 debian systemd[1]: Reached target RPC Port Mapper.
Nov 29 08:18:17 debian systemd[1]: Starting LSB: NFS support files 
common to client and server...
Nov 29 08:18:17 debian dhclient: Listening on LPF/eth0/00:11:50:9b:ef:be
Nov 29 08:18:17 debian dhclient: Sending on   LPF/eth0/00:11:50:9b:ef:be
Nov 29 08:18:17 debian dhclient: Sending on   Socket/fallback
Nov 29 08:18:17 debian dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 
port 67 interval 5
Nov 29 08:18:17 debian ifup[518]: Listening on LPF/eth0/00:11:50:9b:ef:be
Nov 29 08:18:17 debian ifup[518]: Sending on   LPF/eth0/00:11:50:9b:ef:be
Nov 29 08:18:17 debian ifup[518]: Sending on   Socket/fallback
Nov 29 08:18:17 debian ifup[518]: DHCPDISCOVER on eth0 to 
255.255.255.255 port 67 interval 5
Nov 29 08:18:17 debian dhclient: DHCPREQUEST on eth0 to 255.255.255.255 
port 67
Nov 29 08:18:17 debian dhclient: DHCPOFFER from 192.168.2.1
Nov 29 08:18:17 debian ifup[518]: DHCPREQUEST on eth0 to 255.255.255.255 
port 67
Nov 29 08:18:17 debian ifup[518]: DHCPOFFER from 192.168.2.1
Nov 29 08:18:17 debian dhclient: DHCPACK from 192.168.2.1
Nov 29 08:18:17 debian ifup[518]: DHCPACK from 192.168.2.1
Nov 29 08:18:17 debian rpc.statd[554]: Version 1.2.8 starting
Nov 29 08:18:17 debian sm-notify[555]: Version 1.2.8 starting
Nov 29 08:18:17 debian dhclient: bound to 192.168.2.100 -- renewal in 
667079753 seconds.
Nov 29 08:18:17 debian ifup[518]: bound to 192.168.2.100 -- renewal in 
667079753 seconds.

There are three steps recognizable:

1) systemd thinks the network is ready and prints "Reached target 
Network is Online".

2) ntpdate is called but fails to connect to any servers, because the 
dns resolution does not work.

3) dhclient is called and configures the network interface.

This is certainly the wrong order. The network is not yet ready, when 
systemd thinks it is. The network is ready, when dhclient has configured 
the network interface with a local IP address, gateway and DNS servers.


As a workaround, I created a small shell script /etc/cron.daily/ntpdate

#!/bin/sh
ntpdate-debian


Then I find another call of ntpdate, after the system has fully started 
up, and this time it succeeds:

Nov 29 08:18:24 debian systemd[1]: Starting Multi-User System.
Nov 29 08:18:24 debian systemd[1]: Reached target Multi-User System.
Nov 29 08:18:24 debian systemd[1]: Starting Graphical Interface.
Nov 29 08:18:24 debian systemd[1]: Reached target Graphical Interface.
Nov 29 08:18:24 debian systemd[1]: Starting Update UTMP about System 
Runlevel Changes...
Nov 29 08:18:24 debian systemd[1]: Started Update UTMP about System 
Runlevel Changes.
Nov 29 08:18:24 debian systemd[1]: Startup finished in 8.050s (kernel) + 
21.945s (userspace) = 29.995s.
Nov 29 08:18:26 debian ntpdate[581]: step time server 193.175.73.151 
offset -5.518937 sec
Nov 29 08:18:26 debian systemd[1]: Time has been changed

-- 
Hartmut Buhrmester