Bug#947936: chrony: Does (still) not start properly on boot on buster

[Michael Biebl]

Am 04.01.20 um 20:22 schrieb Santiago Vila:
> Hi. I managed to put the instances in a state where a reboot does not
> make the problem to go away. Please give it a try.

I could reproduce the issue on the system provided by Santiago.

I'm dumping the relevant parts of the log here:

> root at d1:~# journalctl -b | egrep "chrony.service|timesyncd.service"
> Jan 12 17:01:51 d1 systemd-sysv-generator[202]: Native unit for chrony.service already exists, skipping.
> Jan 12 17:02:01 d1 systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 17:02:01 d1 systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 17:02:01 d1 systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 17:02:01 d1 systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 17:02:01 d1 systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 17:02:01 d1 systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 17:02:01 d1 systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 17:02:01 d1 systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 17:02:02 d1 ifup[263]: Executing dbus call org.freedesktop.systemd1.Manager TryRestartUnit(systemd-timesyncd.service, replace)
> Jan 12 17:02:01 d1 systemd[1]: Keeping job systemd-timesyncd.service/start because of sysinit.target/start
> Jan 12 17:02:01 d1 systemd[1]: Keeping job chrony.service/stop because of systemd-timesyncd.service/start
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: Installed new job systemd-timesyncd.service/start as 119
> Jan 12 17:02:01 d1 systemd[1]: chrony.service: Job 82 chrony.service/start finished, result=canceled
> Jan 12 17:02:01 d1 systemd[1]: chrony.service: Installed new job chrony.service/stop as 121
> Jan 12 17:02:01 d1 systemd[1]: chrony.service: Job 121 chrony.service/stop finished, result=done
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: ConditionFileIsExecutable=!/usr/sbin/chronyd failed.
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: Starting requested but condition failed. Not starting unit.
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: Job 119 systemd-timesyncd.service/start finished, result=done
> Jan 12 17:02:02 d1 ifup[263]: Got result done/Success for job systemd-timesyncd.service
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Trying to enqueue job systemd-timesyncd.service/try-restart/replace
> Jan 12 17:02:02 d1 systemd[1]: Added job systemd-timesyncd.service/nop to transaction.
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Installed new job systemd-timesyncd.service/nop as 155
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Enqueued job systemd-timesyncd.service/nop as 155
> Jan 12 17:02:02 d1 systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 17:02:02 d1 systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 17:02:02 d1 systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 17:02:02 d1 systemd[1]: Found redundant job chrony.service/stop, dropping from transaction.
> Jan 12 17:02:02 d1 systemd[1]: Garbage collecting job systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Job 155 systemd-timesyncd.service/nop finished, result=done
> Jan 12 17:02:02 d1 systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 17:02:02 d1 systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 17:02:02 d1 systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 17:02:02 d1 systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 17:02:02 d1 systemd[1]: Found redundant job chrony.service/stop, dropping from transaction.
> Jan 12 17:02:02 d1 systemd[1]: Garbage collecting job systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 17:02:04 d1 systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 17:02:04 d1 systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 17:02:04 d1 systemd[1]: Found redundant job chrony.service/stop, dropping from transaction.
> Jan 12 17:02:04 d1 systemd[1]: Garbage collecting job systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 17:02:04 d1 systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 17:02:04 d1 systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 17:02:04 d1 systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 17:02:04 d1 systemd[1]: Found redundant job chrony.service/stop, dropping from transaction.
> Jan 12 17:02:04 d1 systemd[1]: Garbage collecting job systemd-timesyncd.service/start
> Jan 12 17:02:14 d1 systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 17:02:14 d1 systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 17:02:14 d1 systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 17:02:14 d1 systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 17:02:14 d1 systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 17:02:14 d1 systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 17:02:14 d1 systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 17:02:14 d1 systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 17:02:14 d1 systemd[1]: Found redundant job chrony.service/stop, dropping from transaction.
> Jan 12 17:02:14 d1 systemd[1]: Garbage collecting job systemd-timesyncd.service/start
> Jan 12 17:03:32 d1 systemd[1]: Found unit systemd-timesyncd.service at /lib/systemd/system/systemd-timesyncd.service (regular file)
> Jan 12 17:03:32 d1 systemd[1]: Preset files say enable systemd-timesyncd.service.
> Jan 12 17:03:32 d1 systemd[1]: Found unit chrony.service at /lib/systemd/system/chrony.service (regular file)
> Jan 12 17:03:32 d1 systemd[1]: Preset files don't specify rule for chrony.service. Enabling.

> root at d1:~# systemctl status chrony systemd-timesyncd --no-pager
> ● chrony.service - chrony, an NTP client/server
>    Loaded: loaded (/lib/systemd/system/chrony.service; enabled; vendor preset: enabled)
>    Active: inactive (dead)
>      Docs: man:chronyd(8)
>            man:chronyc(1)
>            man:chrony.conf(5)
> 
> Jan 12 17:02:01 d1 systemd[1]: chrony.service: Job 82 chrony.service/start finished, result=canceled
> Jan 12 17:02:01 d1 systemd[1]: chrony.service: Installed new job chrony.service/stop as 121
> Jan 12 17:02:01 d1 systemd[1]: chrony.service: Job 121 chrony.service/stop finished, result=done
> 
> ● 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 Sun 2020-01-12 17:02:01 UTC; 14min ago
>            └─ ConditionFileIsExecutable=!/usr/sbin/chronyd was not met
>      Docs: man:systemd-timesyncd.service(8)
> 
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: Installed new job systemd-timesyncd.service/start as 119
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: ConditionFileIsExecutable=!/usr/sbin/chronyd failed.
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: Starting requested but condition failed. Not starting unit.
> Jan 12 17:02:01 d1 systemd[1]: systemd-timesyncd.service: Job 119 systemd-timesyncd.service/start finished, result=done
> Jan 12 17:02:01 d1 systemd[1]: Condition check resulted in Network Time Synchronization being skipped.
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Trying to enqueue job systemd-timesyncd.service/try-restart/replace
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Installed new job systemd-timesyncd.service/nop as 155
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Enqueued job systemd-timesyncd.service/nop as 155
> Jan 12 17:02:02 d1 systemd[1]: systemd-timesyncd.service: Job 155 systemd-timesyncd.service/nop finished, result=done

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: OpenPGP digital signature
URL: <http://alioth-lists.debian.net/pipermail/pkg-systemd-maintainers/attachments/20200112/66a70147/attachment-0001.sig>