ntpd does not restart after failing to start upon boot

[mspanc]

For some reason ntpd failed to start upon boot on my machine:

Jun 16 16:35:56 dokku-ovh1-003 ntpd[1242]: Listening on routing socket on fd #23 for interface updates
Jun 16 16:35:57 dokku-ovh1-003 ntpd[1242]: Soliciting pool server 212.83.160.142
Jun 16 16:35:58 dokku-ovh1-003 ntpd[1242]: Soliciting pool server 5.196.192.58
Jun 16 16:35:58 dokku-ovh1-003 ntpd[1242]: Soliciting pool server 178.33.111.47
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: Soliciting pool server 149.202.200.140
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: Soliciting pool server 91.121.167.54
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: Soliciting pool server 2001:4b98:dc0:43:216:3eff:feb9:5a07
Jun 16 16:35:59 dokku-ovh1-003 ntp[1310]: * Stopping NTP server ntpd
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: ntpd exiting on signal 15 (Terminated)
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: 212.83.160.142 local addr 188.165.207.172 -> <null>
Jun 16 16:35:59 dokku-ovh1-003 ntp[1310]: ...done.
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: 5.196.192.58 local addr 188.165.207.172 -> <null>
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: 178.33.111.47 local addr 188.165.207.172 -> <null>
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: 91.121.167.54 local addr 188.165.207.172 -> <null>
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: 149.202.200.140 local addr 188.165.207.172 -> <null>
Jun 16 16:35:59 dokku-ovh1-003 ntpd[1242]: 2001:4b98:dc0:43:216:3eff:feb9:5a07 local addr 2001:41d0:2:98ac:: -> <null>
Jun 16 16:36:00 dokku-ovh1-003 ntp[1566]: * Starting NTP server ntpd
Jun 16 16:36:00 dokku-ovh1-003 ntpd[1601]: ntpd 4.2.8p4@1.3265-o Wed Apr 5 13:28:07 UTC 2017 (1): Starting
Jun 16 16:36:00 dokku-ovh1-003 ntpd[1601]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 110:118
Jun 16 16:36:00 dokku-ovh1-003 ntp[1566]: ...done.
Jun 16 16:36:00 dokku-ovh1-003 ntpd[1608]: proto: precision = 0.064 usec (-24)
Jun 16 16:36:00 dokku-ovh1-003 ntpd[1608]: unable to bind to wildcard address :: - another process may be running - EXITING
Jun 16 16:36:12 dokku-ovh1-003 ntpdate[1383]: step time server 178.33.227.201 offset -0.000537 sec

but then I have found out that systemd failed to restart it despite being completely aware that there are no running tasks, until I manually did /etc/init.d/ntp stop. There was stale PID file, but removing it didn't helped, until I called /etc/init.d/ntp stop and /etc/init.d/ntp start NTP was dead.

root@dokku-ovh1-003:~# /etc/init.d/ntp start
[ ok ] Starting ntp (via systemctl): ntp.service.
root@dokku-ovh1-003:~# systemctl status ntp.service
● ntp.service - LSB: Start NTP daemon
   Loaded: loaded (/etc/init.d/ntp; bad; vendor preset: enabled)
   Active: active (exited) since Fri 2017-06-16 16:36:00 CEST; 3 weeks 2 days ago
     Docs: man:systemd-sysv-generator(8)
  Process: 1310 ExecStop=/etc/init.d/ntp stop (code=exited, status=0/SUCCESS)
  Process: 1566 ExecStart=/etc/init.d/ntp start (code=exited, status=0/SUCCESS)
    Tasks: 0
   Memory: 0B
      CPU: 0

Jun 16 16:36:00 dokku-ovh1-003 systemd[1]: Starting LSB: Start NTP daemon...
Jun 16 16:36:00 dokku-ovh1-003 ntp[1566]: * Starting NTP server ntpd
Jun 16 16:36:00 dokku-ovh1-003 ntp[1566]: ...done.
Jun 16 16:36:00 dokku-ovh1-003 systemd[1]: Started LSB: Start NTP daemon.
Jun 16 16:36:00 dokku-ovh1-003 ntpd[1608]: proto: precision = 0.064 usec (-24)
Jun 16 16:36:13 dokku-ovh1-003 systemd[1]: Started LSB: Start NTP daemon.
Jul 10 15:36:16 dokku-ovh1-003 systemd[1]: Started LSB: Start NTP daemon.
Jul 10 15:44:46 dokku-ovh1-003 systemd[1]: Started LSB: Start NTP daemon.
Jul 10 15:57:19 dokku-ovh1-003 systemd[1]: Started LSB: Start NTP daemon.
Jul 10 15:59:00 dokku-ovh1-003 systemd[1]: Started LSB: Start NTP daemon.
root@dokku-ovh1-003:~# ps ax | grep ntp
21691 pts/0 S+ 0:00 grep --color=auto ntp
root@dokku-ovh1-003:~# /etc/init.d/ntp stop
[ ok ] Stopping ntp (via systemctl): ntp.service.
root@dokku-ovh1-003:~# /etc/init.d/ntp start
[ ok ] Starting ntp (via systemctl): ntp.service.
root@dokku-ovh1-003:~# systemctl status ntp.service
● ntp.service - LSB: Start NTP daemon
   Loaded: loaded (/etc/init.d/ntp; bad; vendor preset: enabled)
   Active: active (running) since Mon 2017-07-10 15:59:16 CEST; 2s ago
     Docs: man:systemd-sysv-generator(8)
  Process: 21714 ExecStop=/etc/init.d/ntp stop (code=exited, status=0/SUCCESS)
  Process: 21822 ExecStart=/etc/init.d/ntp start (code=exited, status=0/SUCCESS)
    Tasks: 2
   Memory: 756.0K
      CPU: 32ms
   CGroup: /system.slice/ntp.service
           └─21836 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 110:118

Jul 10 15:59:16 dokku-ovh1-003 ntpd[21836]: Listen normally on 54 veth8a7f590 [fe80::206a:e7ff:fe04:9d5d%3508]:123
Jul 10 15:59:16 dokku-ovh1-003 ntpd[21836]: Listen normally on 55 veth1286611 [fe80::284a:87ff:fef9:7ec9%6844]:123
Jul 10 15:59:16 dokku-ovh1-003 ntpd[21836]: Listen normally on 56 veth4200099 [fe80::4405:81ff:fec8:7dfe%204]:123
Jul 10 15:59:16 dokku-ovh1-003 ntpd[21836]: Listen normally on 57 veth4d4460f [fe80::f05d:fff:fe37:e7d%216]:123
Jul 10 15:59:16 dokku-ovh1-003 ntpd[21836]: Listen normally on 58 vethf4265f8 [fe80::acc2:a3ff:fec6:8cc4%6890]:123
Jul 10 15:59:16 dokku-ovh1-003 ntpd[21836]: Listen normally on 59 vethb45cd16 [fe80::44c3:21ff:feb6:7177%7154]:123
Jul 10 15:59:16 dokku-ovh1-003 ntpd[21836]: Listening on routing socket on fd #76 for interface updates
Jul 10 15:59:17 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 149.202.97.123
Jul 10 15:59:18 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 163.172.28.46
Jul 10 15:59:18 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 94.23.0.110
root@dokku-ovh1-003:~# systemctl status ntp.service
● ntp.service - LSB: Start NTP daemon
   Loaded: loaded (/etc/init.d/ntp; bad; vendor preset: enabled)
   Active: active (running) since Mon 2017-07-10 15:59:16 CEST; 4s ago
     Docs: man:systemd-sysv-generator(8)
  Process: 21714 ExecStop=/etc/init.d/ntp stop (code=exited, status=0/SUCCESS)
  Process: 21822 ExecStart=/etc/init.d/ntp start (code=exited, status=0/SUCCESS)
    Tasks: 2
   Memory: 764.0K
      CPU: 37ms
   CGroup: /system.slice/ntp.service
           └─21836 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 110:118

Jul 10 15:59:17 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 149.202.97.123
Jul 10 15:59:18 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 163.172.28.46
Jul 10 15:59:18 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 94.23.0.110
Jul 10 15:59:19 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 37.187.18.4
Jul 10 15:59:19 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 212.83.179.156
Jul 10 15:59:19 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 2001:41d0:8:188d::16
Jul 10 15:59:20 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 2001:bc8:2717:100::1
Jul 10 15:59:20 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 91.121.181.58
Jul 10 15:59:20 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 62.210.244.146
Jul 10 15:59:20 dokku-ovh1-003 ntpd[21836]: Soliciting pool server 212.129.9.36

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: ntp 1:4.2.8p4+dfsg-3ubuntu5.4
ProcVersionSignature: Ubuntu 4.4.0-59.80-generic 4.4.35
Uname: Linux 4.4.0-59-generic x86_64
ApportVersion: 2.20.1-0ubuntu2.6
Architecture: amd64
Date: Mon Jul 10 16:00:37 2017
InstallationDate: Installed on 2016-01-12 (545 days ago)
InstallationMedia:

KernLog:
 [2070085.955078] audit: type=1400 audit(1499693804.041:10): apparmor="DENIED" operation="open" profile="/usr/sbin/ntpd" name="/usr/local/sbin/" pid=19842 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
 [2070085.955101] audit: type=1400 audit(1499693804.041:11): apparmor="DENIED" operation="open" profile="/usr/sbin/ntpd" name="/usr/local/bin/" pid=19842 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
 [2071366.354592] audit: type=1400 audit(1499695101.619:12): apparmor="DENIED" operation="open" profile="/usr/sbin/ntpd" name="/usr/local/sbin/" pid=21398 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
 [2071366.354606] audit: type=1400 audit(1499695101.619:13): apparmor="DENIED" operation="open" profile="/usr/sbin/ntpd" name="/usr/local/bin/" pid=21398 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
ProcEnviron:
 SHELL=/bin/bash
 TERM=xterm-256color
 PATH=(custom, no user)
 LANG=en_GB.UTF-8
 XDG_RUNTIME_DIR=<set>
SourcePackage: ntp
UpgradeStatus: No upgrade log present (probably fresh install)

[Andreas Hasenack (ahasenack)]

Thanks for filing this bug in Ubuntu.

The logs you pasted showed ntp failing to run because something else was listening on its socket already.

In xenial, there is a systemd service that also tries to keep the clock accurate, called systemd-timesyncd.service. It has checks, though, to not try to start if ntp is installed:

# systemctl status systemd-timesyncd
● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /lib/systemd/system/systemd-timesyncd.service.d
           └─disable-with-time-daemon.conf
   Active: inactive (dead)
Condition: start condition failed at Ter 2017-07-11 08:55:03 BRT; 7h ago
     Docs: man:systemd-timesyncd.service(8)

This is what is preventing systemd-timesyncd from running on my system, where I have ntp installed:
# cat /lib/systemd/system/systemd-timesyncd.service.d/disable-with-time-daemon.conf
[Unit]
# don't run timesyncd if we have another NTP daemon installed
ConditionFileIsExecutable=!/usr/sbin/ntpd
ConditionFileIsExecutable=!/usr/sbin/openntpd
ConditionFileIsExecutable=!/usr/sbin/chronyd
ConditionFileIsExecutable=!/usr/sbin/VBoxService

Do you have that file /lib/systemd/system/systemd-timesyncd.service.d/disable-with-time-daemon.conf, and does it have the same content as above?

Can you show the output of "sudo systemctl status systemd-timesyncd.service"?

Assuming you can reproduce the problem at will, could you please run this command right at the time where ntp has failed to start:

sudo fuser -v 123/udp

Thanks!

[mspanc (mspanc)]

Hello,

yes, /lib/systemd/system/systemd-timesyncd.service.d/disable-with-time-daemon.conf has the same contents as you pasted and systemd properly reports condition failed for systemd-timesyncd.

I cannot really reproduce this behaviour. Something was listening upon boot and that is odd.

But anyway that misses the point. Regardless of what caused ntp to fail, in my opinion:

a) systemd should make attempts to restart it - it didn't
b) /etc/init.d/ntp start shouldn't silently fail (that was the behaviour)

However, I will probably revert to systemd-timesyncd and abandon using ntpd.

[Launchpad Janitor (janitor)]

[Expired for ntp (Ubuntu) because there has been no activity for 60 days.]