Bug 814946 - systemd starts ntpdate after ntpd
systemd starts ntpdate after ntpd
Status: CLOSED DUPLICATE of bug 753586
Product: Fedora
Classification: Fedora
Component: systemd (Show other bugs)
16
Unspecified Linux
unspecified Severity medium
: ---
: ---
Assigned To: systemd-maint
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-04-21 10:11 EDT by Ian Dall
Modified: 2012-04-25 03:12 EDT (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-04-25 03:12:55 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
The output of cat /proc/cmdline (237 bytes, application/octet-stream)
2012-04-21 10:11 EDT, Ian Dall
no flags Details
Output of dmesg (121.86 KB, text/plain)
2012-04-21 10:13 EDT, Ian Dall
no flags Details
grep ntp /var/log/messages (1.66 KB, text/plain)
2012-04-21 10:14 EDT, Ian Dall
no flags Details
Output from "systemd dump" (588.90 KB, text/plain)
2012-04-21 10:15 EDT, Ian Dall
no flags Details
Output from systemd --test (618.72 KB, text/plain)
2012-04-21 10:16 EDT, Ian Dall
no flags Details
Local /etc/systemd/system/ntpd.service (101 bytes, application/octet-stream)
2012-04-21 10:23 EDT, Ian Dall
no flags Details
dmesg ouput with increase log_buf_len (189.13 KB, text/plain)
2012-04-24 22:48 EDT, Ian Dall
no flags Details

  None (edit)
Description Ian Dall 2012-04-21 10:11:53 EDT
Created attachment 579183 [details]
The output of cat /proc/cmdline

Description of problem:
I find that time is not synchronised (especially on a reboot after daylight saving change) due to ntpdate failing.

Version-Release number of selected component (if applicable):
ntpdate-4.2.6p4-1.fc16.i686

How reproducible:
Always

Steps to Reproduce:
1.grep /var/log/messages for ntpdate
2.
3.
  
Actual results:
ntpdate[nnn]: the NTP socket is in use, exiting

Expected results:
ntpdate should run successfully

Additional info:
I booted with systemd.log_level=debug and saved the output of dmesg (attached).
ntpd is clearly being started before ntpdate but I can't see why.

If I manually stop ntpd.service, start ntpdate.service and start ntpd.service things work as expected. As this seems to be a problem with the systemctl configuration I have attached the appropriate files.
Comment 1 Ian Dall 2012-04-21 10:13:11 EDT
Created attachment 579184 [details]
Output of dmesg
Comment 2 Ian Dall 2012-04-21 10:14:08 EDT
Created attachment 579185 [details]
grep ntp /var/log/messages
Comment 3 Ian Dall 2012-04-21 10:15:19 EDT
Created attachment 579186 [details]
Output from "systemd dump"
Comment 4 Ian Dall 2012-04-21 10:16:39 EDT
Created attachment 579187 [details]
Output from systemd --test
Comment 5 Ian Dall 2012-04-21 10:23:33 EDT
Created attachment 579188 [details]
Local /etc/systemd/system/ntpd.service

There is a local modification to ntpd.service (attached) which serves to ensure that ntpd doesn't start until the network is up, even if ntpdate has been disabled.

I can't see how this could cause a problem, but it is attached just in case.
Comment 6 Michal Schmidt 2012-04-23 05:25:09 EDT
ntpd.service and ntpdate.service are both owned by the "ntp" source package. If there exists and ordering requirement, it should be expressed in the unit file. Reassigning.
Comment 7 Michal Schmidt 2012-04-23 05:25:57 EDT
s/and ordering requirement/an ordering requirement/
Comment 8 Ian Dall 2012-04-23 18:31:36 EDT
(In reply to comment #6)
> ntpd.service and ntpdate.service are both owned by the "ntp" source package. If
> there exists and ordering requirement, it should be expressed in the unit file.
> Reassigning.

Except that, as far as I can see, the unit files for ntpd and ntpdate already have the ordering relationship. ntpd.service has:

After=syslog.target ntpdate.service


It just doesn't seem to take effect.
Comment 9 Michal Schmidt 2012-04-24 08:46:54 EDT
hm, I see.
I wonder what causes the following jobs to be enqueued:

[   40.786960] systemd[1]: Trying to enqueue job systemd-update-utmp-runlevel.service/start/ignore-requirements
[   40.787212] systemd[1]: Trying to enqueue job multi-user.target/start/ignore-requirements
[   40.787272] systemd[1]: Trying to enqueue job getty@tty1.service/start/ignore-requirements
[   40.787551] systemd[1]: Trying to enqueue job getty.target/start/ignore-requirements
[   40.787799] systemd[1]: Trying to enqueue job ntpdate.service/start/ignore-requirements
[   41.641098] systemd[1]: Trying to enqueue job systemd-update-utmp-runlevel.service/start/ignore-requirements
[   41.641137] systemd[1]: Trying to enqueue job multi-user.target/start/ignore-requirements
[   41.641401] systemd[1]: Trying to enqueue job ntpdate.service/start/ignore-requirements

It could come from unit deserialization, but I see no indication in the log of that happening.

In case we're missing some log items... Could you please boot with:
  systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
and attach the new output of dmesg. Thanks.
Comment 10 Ian Dall 2012-04-24 22:48:36 EDT
Created attachment 580044 [details]
dmesg ouput with increase log_buf_len

OK. Here is the new dmesg output corresponding to the /proc/cmdline:

root=nfs:fs.beware.dropbear.id.au:/export/NFSroots/Fedora16 initrd=/images/Fedora16/initramfs-3.1.6-1.fc16.i686.img selinux=0 systemd.unit=multi-user.target systemd.log_level=debug systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M BOOT_IMAGE=/images/Fedora16/vmlinuz-3.1.6-1.fc16.i686

The "ignore-requirements" lines seems to have gone away but the mis-ordering of ntpdate remains.
Comment 11 Michal Schmidt 2012-04-25 03:12:55 EDT
Thanks.

[   29.919074] systemd[1]: Accepted connection on private bus.
[   29.919963] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.TryRestartUnit() on /org/freedesktop/systemd1
[   29.920036] systemd[1]: Trying to enqueue job ntpd.service/try-restart/replace
[   29.920135] systemd[1]: Installed new job ntpd.service/restart as 131
[   29.920153] systemd[1]: Enqueued job ntpd.service/try-restart as 131
[   29.921607] systemd[1]: About to execute: /usr/sbin/ntpd -n -u ntp:ntp $OPTIONS

This is probably /etc/dhcp/dhclient.d/ntp.sh calling "systemctl try-restart ntpd.service". It exposes a bug in systemd that we previously encountered with ypbind.

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

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