Bug 814946

Summary: systemd starts ntpdate after ntpd
Product: [Fedora] Fedora Reporter: Ian Dall <ian>
Component: systemdAssignee: systemd-maint
Status: CLOSED DUPLICATE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 16CC: johannbg, metherid, mlichvar, mschmidt, notting, pertusus, plautrba, systemd-maint
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-04-25 07:12:55 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
The output of cat /proc/cmdline
none
Output of dmesg
none
grep ntp /var/log/messages
none
Output from "systemd dump"
none
Output from systemd --test
none
Local /etc/systemd/system/ntpd.service
none
dmesg ouput with increase log_buf_len none

Description Ian Dall 2012-04-21 14:11:53 UTC
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 14:13:11 UTC
Created attachment 579184 [details]
Output of dmesg

Comment 2 Ian Dall 2012-04-21 14:14:08 UTC
Created attachment 579185 [details]
grep ntp /var/log/messages

Comment 3 Ian Dall 2012-04-21 14:15:19 UTC
Created attachment 579186 [details]
Output from "systemd dump"

Comment 4 Ian Dall 2012-04-21 14:16:39 UTC
Created attachment 579187 [details]
Output from systemd --test

Comment 5 Ian Dall 2012-04-21 14:23:33 UTC
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 09:25:09 UTC
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 09:25:57 UTC
s/and ordering requirement/an ordering requirement/

Comment 8 Ian Dall 2012-04-23 22:31:36 UTC
(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 12:46:54 UTC
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/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-25 02:48:36 UTC
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 07:12:55 UTC
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 ***