Bug#933370: chrony won't start

[Vincent Blut]

Control: tags -1 moreinfo


Hello Ross,

On Mon, Jul 29, 2019 at 12:13:16PM -0700, Ross Boylan wrote:

Package: chrony
Version: 3.4-4
Severity: normal

Dear Maintainer,

There's a good chance this is the same problem as bug 826695, but
since I don't know that, and this is on buster, I'm making this a
separate report.

Also, you might want to take a look at #902026.

Some questions before merging (and eventually reassigning to system) those two bug report.

[snip…]

I started the kernel with options
debug systemd.log_level=debug systemd.log_target=kmsg loc_buf_len=1M
printk.devkmsg=on
as advised https://freedesktop.org/wiki/Software/systemd/Debugging/
Oddly, this produced less output than usual: journalctl -u chrony
showed nothing.  However, everything I usually see from journalctl -u
chrony does appear in the overall logs, below.

It looks as if systemd-timesyncd is creating a stop job for chrony
even though the former includes

What’s the status of systemd-timesyncd here? Is it started?

Also, could you attach the output of:
$ systemctl show systemd-timesyncd.service

I would like to see if something is explicitly pulling in systemd-timesyncd
on your system.

# 
/usr/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

which seems to be effective in preventing it from running.
There doesn't seem to be anything in the setup files for
systemd-timesyncd that would cause chrony to stop (no Conflicts
entry); maybe the problem is
Conflicts=systemd-timesyncd.service openntpd.service ntp.service ntpsec.service
in chrony itself.

Looking at [1], you’ll see that, sadly, “Conflicts=” does not prevent service 
from
being started. There’s work being done on the systemd side to improve the
situation, especially regarding NTP services [2].

What annoys me the most it that despite systemd-timesyncd unit file contains “ConditionFileIsExecutable=!/usr/sbin/chronyd”, it will still try to get in the way of chrony.

~# journalctl -b | grep chrony
Jul 29 11:30:43 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:43 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:43 barley systemd[1]: Pulling in chrony.service/start from 
multi-user.target/start
Jul 29 11:30:43 barley systemd[1]: Added job chrony.service/start to 
transaction.
Jul 29 11:30:43 barley systemd[1]: Pulling in sysinit.target/start from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in system.slice/start from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in -.mount/start from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in var.mount/start from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in ntp.service/stop from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in openntpd.service/stop from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in ntpsec.service/stop from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in shutdown.target/stop from 
chrony.service/start
Jul 29 11:30:43 barley systemd[1]: Pulling in systemd-timesyncd.service/stop 
from chrony.service/start
Jul 29 11:30:43 barley systemd[1]: chrony.service: Looking at job 
chrony.service/start conflicted_by=no

Jul 29 11:30:43 barley systemd[1]: chrony.service: Fixing conflicting jobs 
chrony.service/start,chrony.service/stop by deleting job chrony.service/stop
Jul 29 11:30:43 barley systemd[1]: chrony.service: Installed new job 
chrony.service/start as 163
Jul 29 11:30:46 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:46 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:46 barley systemd[1]: chrony.service: chrony.service/stop would 
change existing job.
Jul 29 11:30:46 barley systemd[1]: chrony.service: Deleting chrony.service/stop 
to minimize impact.
Jul 29 11:30:47 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:47 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:47 barley systemd[1]: chrony.service: chrony.service/stop would 
change existing job.
Jul 29 11:30:47 barley systemd[1]: chrony.service: Deleting chrony.service/stop 
to minimize impact.
Jul 29 11:30:47 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:47 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:47 barley systemd[1]: chrony.service: chrony.service/stop would 
change existing job.
Jul 29 11:30:47 barley systemd[1]: chrony.service: Deleting chrony.service/stop 
to minimize impact.
Jul 29 11:30:47 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:47 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:47 barley systemd[1]: chrony.service: chrony.service/stop would 
change existing job.
Jul 29 11:30:47 barley systemd[1]: chrony.service: Deleting chrony.service/stop 
to minimize impact.
Jul 29 11:30:50 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:50 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:50 barley systemd[1]: Keeping job chrony.service/stop because of 
systemd-timesyncd.service/start
Jul 29 11:30:50 barley systemd[1]: chrony.service: Job 163 chrony.service/start 
finished, result=canceled
Jul 29 11:30:50 barley systemd[1]: chrony.service: Installed new job 
chrony.service/stop as 831
Jul 29 11:30:50 barley systemd[1]: chrony.service: Job 831 chrony.service/stop 
finished, result=done
Jul 29 11:30:52 barley systemd[1]: systemd-timesyncd.service: 
ConditionFileIsExecutable=!/usr/sbin/chronyd failed.
Jul 29 11:30:53 barley kernel: audit: type=1400 audit(1564425053.035:8): apparmor="STATUS" 
operation="profile_load" profile="unconfined" name="/usr/sbin/chronyd" pid=1294 
comm="apparmor_parser"
Jul 29 11:30:53 barley audit[1294]: AVC apparmor="STATUS" operation="profile_load" 
profile="unconfined" name="/usr/sbin/chronyd" pid=1294 comm="apparmor_parser"
Jul 29 11:30:53 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:53 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:54 barley systemd[1]: Found redundant job chrony.service/stop, 
dropping from transaction.
Jul 29 11:30:57 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:30:57 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:30:58 barley systemd[1]: Found redundant job chrony.service/stop, 
dropping from transaction.
Jul 29 11:30:58 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:31:00 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:31:00 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:31:12 barley systemd[1]: Found redundant job chrony.service/stop, 
dropping from transaction.
Jul 29 11:31:28 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start
Jul 29 11:31:49 barley systemd[1]: Added job chrony.service/stop to transaction.
Jul 29 11:32:11 barley systemd[1]: Pulling in chrony.service/stop from 
systemd-timesyncd.service/start

I can provide the whole journal if you want.

Jul 29 11:30:43 barley systemd[1]: chrony.service: Looking at job chrony.service/stop conflicted_by=no

$ journalctl -b | grep -E "(chrony|timesync)"

Nevertheless, I would like you to test some things.


Wants=time-sync.target
Before=time-sync.target





Cheers,
Vincent


[1] https://github.com/systemd/systemd/issues/7104
[2] https://github.com/systemd/systemd/pull/13136

Thanks for these logs. To have a bigger picture, could you please show me something like that instead: To begin with, I have an updated chrony unit file in a private git branch targeting a future revision (not the next one) containing: That would be great if you could override the unit file currently provided by chrony to add these two lines. I have no high hopes, but I’m sill curious to see the result in this case. If that does not work, just removing systemd-timesyncd.service from the “Conflicts=” line in the chrony unit file may fix the issue… well I think. ;-)

signature.asc
Description: PGP signature