Ooops… I gave a snatch that show the problem for ntpdate. It exists (or at least existed, as of May this year — it may have been fixed since then) for ntp as well. Here’s a snatch from a different journalctl output file that shows it for ntpd.
> May 18 03:52:22 ultimate kernel: mv643xx_eth_port mv643xx_eth_port.0 eth0: > link up, 1000 Mb/s, full duplex, flow control disable > May 18 03:52:22 ultimate kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link > becomes ready > May 18 03:52:23 ultimate systemd-logind[307]: New seat seat0. > May 18 03:52:23 ultimate systemd[1]: Started Login Service. > May 18 03:52:23 ultimate systemd[1]: Starting Manage, Install and Generate > Color Profiles... > May 18 03:52:23 ultimate systemd[1]: Started Getty on tty1. > May 18 03:52:23 ultimate systemd[1]: Started Serial Getty on ttyS0. > May 18 03:52:23 ultimate systemd[1]: Reached target Login Prompts. > May 18 03:52:23 ultimate ntpd[381]: ntpd 4.2.8p7@1.3265-o Sat Apr 30 11:18:37 > UTC 2016 (1): Starting > May 18 03:52:23 ultimate ntpd[381]: Command line: /usr/sbin/ntpd -p > /var/run/ntpd.pid -g -u 112:120 > May 18 03:52:23 ultimate ntp[315]: Starting NTP server: ntpd. > May 18 03:52:23 ultimate systemd[1]: Started LSB: Start NTP daemon. > May 18 03:52:23 ultimate ntpd[399]: proto: precision = 2.410 usec (-19) > May 18 03:52:23 ultimate ntpd[399]: Listen and drop on 0 v6wildcard [::]:123 > May 18 03:52:23 ultimate ntpd[399]: Listen and drop on 1 v4wildcard > 0.0.0.0:123 > May 18 03:52:23 ultimate ntpd[399]: Listen normally on 2 lo 127.0.0.1:123 > May 18 03:52:23 ultimate ntpd[399]: Listen normally on 3 lo [::1]:123 > May 18 03:52:23 ultimate ntpd[399]: bind(20) AF_INET6 > fe80::f2ad:4eff:fe00:613c%2#123 flags 0x11 failed: Cannot assign requested > May 18 03:52:23 ultimate ntpd[399]: unable to create socket on eth0 (4) for > fe80::f2ad:4eff:fe00:613c%2#123 > May 18 03:52:23 ultimate ntpd[399]: failed to init interface for address > fe80::f2ad:4eff:fe00:613c%2 > May 18 03:52:23 ultimate ntpd[399]: Listening on routing socket on fd #20 for > interface updates > May 18 03:52:23 ultimate dbus[320]: [system] Successfully activated service > 'org.freedesktop.ColorManager' > May 18 03:52:23 ultimate systemd[1]: Started Manage, Install and Generate > Color Profiles. > May 18 03:52:24 ultimate ntpd[399]: error resolving pool pool.rcthomas.org: > Temporary failure in name resolution (-3) > May 18 03:52:24 ultimate avahi-daemon[299]: Joining mDNS multicast group on > interface eth0.IPv6 with address fe80::f2ad:4eff:fe0 > May 18 03:52:24 ultimate avahi-daemon[299]: New relevant interface eth0.IPv6 > for mDNS. > May 18 03:52:24 ultimate avahi-daemon[299]: Registering new address record > for fe80::f2ad:4eff:fe00:613c on eth0.*. > May 18 03:52:24 ultimate apache2[303]: Starting Apache httpd web server: > apache2AH00557: apache2: apr_sockaddr_info_get() failed > May 18 03:52:24 ultimate apache2[303]: AH00558: apache2: Could not reliably > determine the server's fully qualified domain name, > May 18 03:52:25 ultimate ntpd[399]: error resolving pool us.pool.ntp.org: > Temporary failure in name resolution (-3) > May 18 03:52:25 ultimate avahi-daemon[299]: Leaving mDNS multicast group on > interface eth0.IPv6 with address fe80::f2ad:4eff:fe0 > May 18 03:52:25 ultimate avahi-daemon[299]: Joining mDNS multicast group on > interface eth0.IPv6 with address 2001:4978:2d2:1:f2a > May 18 03:52:25 ultimate avahi-daemon[299]: Registering new address record > for 2001:4978:2d2:1:f2ad:4eff:fe00:613c on eth0.*. > May 18 03:52:25 ultimate avahi-daemon[299]: Withdrawing address record for > fe80::f2ad:4eff:fe00:613c on eth0. > May 18 03:52:25 ultimate exim4[296]: Starting MTA: exim4. > May 18 03:52:25 ultimate systemd[1]: Started LSB: exim Mail Transport Agent. > May 18 03:52:25 ultimate apache2[303]: . > May 18 03:52:25 ultimate systemd[1]: Started LSB: Apache2 web server. > May 18 03:52:25 ultimate systemd[1]: Reached target Multi-User System. > May 18 03:52:26 ultimate systemd[1]: Reached target Graphical Interface. > May 18 03:52:26 ultimate systemd[1]: Starting Update UTMP about System > Runlevel Changes... > May 18 03:52:26 ultimate systemd[1]: Started Update UTMP about System > Runlevel Changes. > May 18 03:52:26 ultimate systemd[1]: Startup finished in 7.628s (kernel) + > 22.291s (userspace) = 29.920s. > May 18 03:52:26 ultimate dhclient[247]: DHCPDISCOVER on eth0 to > 255.255.255.255 port 67 interval 10 > May 18 03:52:26 ultimate sh[234]: DHCPDISCOVER on eth0 to 255.255.255.255 > port 67 interval 10 > May 18 03:52:26 ultimate sh[234]: DHCPREQUEST of 192.168.3.4 on eth0 to > 255.255.255.255 port 67 > May 18 03:52:26 ultimate sh[234]: DHCPOFFER of 192.168.3.4 from 192.168.3.111 > May 18 03:52:26 ultimate dhclient[247]: DHCPREQUEST of 192.168.3.4 on eth0 to > 255.255.255.255 port 67 > May 18 03:52:26 ultimate dhclient[247]: DHCPOFFER of 192.168.3.4 from > 192.168.3.111 > May 18 03:52:26 ultimate sh[234]: DHCPACK of 192.168.3.4 from 192.168.3.111 > May 18 03:52:26 ultimate dhclient[247]: DHCPACK of 192.168.3.4 from > 192.168.3.111 > May 18 03:52:26 ultimate avahi-daemon[299]: Joining mDNS multicast group on > interface eth0.IPv4 with address 192.168.3.4. > May 18 03:52:26 ultimate avahi-daemon[299]: New relevant interface eth0.IPv4 > for mDNS. > May 18 03:52:26 ultimate avahi-daemon[299]: Registering new address record > for 192.168.3.4 on eth0.IPv4. > May 18 03:52:26 ultimate dhclient[247]: bound to 192.168.3.4 -- renewal in > 3521 seconds. > May 18 03:52:26 ultimate sh[234]: bound to 192.168.3.4 -- renewal in 3521 > seconds. > May 18 03:52:26 ultimate ntpd[399]: Soliciting pool server > 2001:4978:1:400:202:b3ff:feb4:59cb > May 18 03:52:27 ultimate systemd[1]: Reloading OpenBSD Secure Shell server. > May 18 03:52:27 ultimate sshd[305]: Received SIGHUP; restarting. > May 18 03:52:27 ultimate systemd[1]: Reloaded OpenBSD Secure Shell server. > May 18 03:52:28 ultimate sh[234]: eth0=eth0 > May 18 03:52:28 ultimate sshd[305]: Server listening on 0.0.0.0 port 22. > May 18 03:52:28 ultimate sshd[305]: Server listening on :: port 22. > May 18 03:52:28 ultimate ntpd[399]: Listen normally on 5 eth0 192.168.3.4:123 > May 18 03:52:28 ultimate ntpd[399]: Listen normally on 6 eth0 > [2001:4978:2d2:1:f2ad:4eff:fe00:613c]:123 > May 18 03:52:28 ultimate ntpd[399]: Listen normally on 7 eth0 > [fe80::f2ad:4eff:fe00:613c%2]:123 > May 18 03:52:31 ultimate colord[387]: (colord:387): Cd-WARNING **: failed to > get session [pid 318]: No such device or address > May 18 03:52:32 ultimate kernel: warning: process `colord-sane' used the > deprecated sysctl system call with 8.1.2. > May 18 03:52:40 ultimate ntpd[399]: Soliciting pool server 192.168.3.111 > May 18 03:52:41 ultimate ntpd[399]: Soliciting pool server 192.168.3.207 > May 18 03:52:41 ultimate systemd[1]: Time has been changed > May 18 03:52:41 ultimate systemd[1]: apt-daily.timer: Adding 8h 21min > 54.588061s random time. > May 18 03:52:42 ultimate ntpd[399]: Soliciting pool server 192.168.1.14 > May 18 03:52:57 ultimate sshd[813]: Accepted publickey for rbthomas from > 192.168.3.23 port 52072 ssh2: RSA SHA256:5oYjhr5L23tD0o > May 18 03:52:57 ultimate sshd[813]: pam_unix(sshd:session): session opened > for user rbthomas by (uid=0) > May 18 03:52:57 ultimate systemd-logind[307]: New session 1 of user rbthomas. > May 18 03:52:57 ultimate systemd[1]: Created slice User Slice of rbthomas. > May 18 03:52:57 ultimate systemd[1]: Starting User Manager for UID 1000... > May 18 03:52:57 ultimate systemd[1]: Started Session 1 of user rbthomas. > May 18 03:52:57 ultimate systemd[815]: pam_unix(systemd-user:session): > session opened for user rbthomas by (uid=0) > May 18 03:52:57 ultimate systemd[815]: Reached target Paths. > May 18 03:52:57 ultimate systemd[815]: Reached target Sockets. > May 18 03:52:57 ultimate systemd[815]: Reached target Timers. > May 18 03:52:57 ultimate systemd[815]: Reached target Basic System. > May 18 03:52:57 ultimate systemd[815]: Reached target Default. > May 18 03:52:57 ultimate systemd[815]: Startup finished in 128ms. > May 18 03:52:57 ultimate systemd[1]: Started User Manager for UID 1000. > May 18 03:53:29 ultimate ntpd[399]: Soliciting pool server 199.199.208.25 > May 18 03:53:30 ultimate ntpd[399]: Soliciting pool server 129.250.35.250 > May 18 03:53:31 ultimate ntpd[399]: Soliciting pool server 50.116.55.65 The DHCPACK that assigns the IP address to the interface occurs during the middle of ntpd’s startup, so two of three pool statements get failed DNS. The third one succeeds, so ntpd gets some servers, but not all the servers it’s configured for. On Aug 1, 2016, at 3:53 AM, Rick Thomas <rbtho...@pobox.com> wrote: > First of all, thanks very much for the prompt reply! > > I’ll try it again in sid and stretch, but it was there the last time I looked. > > The problem is not getting dhcpclient to give ntp servers. I’ve put hard > coded ipv4 addresses in /etc/default/ntpdate, so that’s not it. > > The problem is that the network interface is not fully available when ntpdate > runs. I think this is because dhcpclient has not provided an IP address for > the interface yet. > > Here’s a snatch from journalctl that shows the problem in jessie: > >> Aug 01 02:49:46 dillserver kernel: sungem_phy: PHY ID: 206053, addr: 0 >> Aug 01 02:49:46 dillserver kernel: gem 0002:20:0f.0 eth0: Found BCM5401 PHY >> Aug 01 02:49:46 dillserver kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is >> not ready >> Aug 01 02:49:46 dillserver ntpdate[661]: no servers can be used, exiting >> Aug 01 02:49:46 dillserver networking[469]: Configuring network >> interfaces...done. >> Aug 01 02:49:46 dillserver systemd[1]: Started LSB: Raise network >> interfaces.. >> Aug 01 02:49:46 dillserver systemd[1]: Starting ifup for eth0... >> Aug 01 02:49:46 dillserver systemd[1]: Started ifup for eth0. >> Aug 01 02:49:46 dillserver systemd[1]: Starting Network. >> Aug 01 02:49:46 dillserver systemd[1]: Reached target Network. >> Aug 01 02:49:46 dillserver systemd[1]: Starting Network is Online. >> Aug 01 02:49:46 dillserver systemd[1]: Reached target Network is Online. >> Aug 01 02:49:46 dillserver systemd[1]: Starting LSB: RPC portmapper >> replacement... >> Aug 01 02:49:47 dillserver rpcbind[672]: Starting rpcbind daemon.... >> Aug 01 02:49:47 dillserver systemd[1]: Started LSB: RPC portmapper >> replacement. >> Aug 01 02:49:47 dillserver systemd[1]: Starting RPC Port Mapper. >> Aug 01 02:49:47 dillserver systemd[1]: Reached target RPC Port Mapper. >> Aug 01 02:49:47 dillserver systemd[1]: Starting LSB: NFS support files >> common to client and server... >> Aug 01 02:49:47 dillserver dhclient[685]: Internet Systems Consortium DHCP >> Client 4.3.1 >> Aug 01 02:49:47 dillserver dhclient[685]: Copyright 2004-2014 Internet >> Systems Consortium. >> Aug 01 02:49:47 dillserver dhclient[685]: All rights reserved. >> Aug 01 02:49:47 dillserver dhclient[685]: For info, please visit >> https://www.isc.org/software/dhcp/ >> Aug 01 02:49:47 dillserver dhclient[685]: >> Aug 01 02:49:47 dillserver ifup[671]: Internet Systems Consortium DHCP >> Client 4.3.1 >> Aug 01 02:49:47 dillserver ifup[671]: Copyright 2004-2014 Internet Systems >> Consortium. >> Aug 01 02:49:47 dillserver ifup[671]: All rights reserved. >> Aug 01 02:49:47 dillserver ifup[671]: For info, please visit >> https://www.isc.org/software/dhcp/ >> Aug 01 02:49:47 dillserver dhclient[685]: Listening on >> LPF/eth0/00:03:93:3d:bd:bc >> Aug 01 02:49:47 dillserver dhclient[685]: Sending on >> LPF/eth0/00:03:93:3d:bd:bc >> Aug 01 02:49:47 dillserver dhclient[685]: Sending on Socket/fallback >> Aug 01 02:49:47 dillserver dhclient[685]: DHCPDISCOVER on eth0 to >> 255.255.255.255 port 67 interval 4 >> Aug 01 02:49:47 dillserver ifup[671]: Listening on LPF/eth0/00:03:93:3d:bd:bc >> Aug 01 02:49:47 dillserver ifup[671]: Sending on LPF/eth0/00:03:93:3d:bd:bc >> Aug 01 02:49:47 dillserver ifup[671]: Sending on Socket/fallback >> Aug 01 02:49:47 dillserver ifup[671]: DHCPDISCOVER on eth0 to >> 255.255.255.255 port 67 interval 4 >> > > > > > On Aug 1, 2016, at 2:56 AM, Kurt Roeckx <k...@roeckx.be> wrote: > >> On Mon, Aug 01, 2016 at 02:37:58AM -0700, Rick Thomas wrote: >>> This 8 year old bug is still present in jessie and stretch -- the change to >>> systemd did not fix it! >>> >>> Please, somebody pay attention! This bug makes ntpd unreliable tending to >>> useless on systems that get their network config from dhcp. >> >> There are various things broken, but as far as I know in stretch >> things should just work. >> >> You seem to say that this is related to getting the ntp servers >> from dhcp, but that's not making sense to me. The dhcp server >> should give you IP addresses, so it can never be a problem with >> DNS, the peers should always be there. >> >> >> Kurt >> >
