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

Michael Biebl biebl at debian.org
Sun Jan 12 18:57:44 GMT 2020 

Am 12.01.20 um 18:18 schrieb 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:

From a buster system of mine which has chrony and systemd-timesyncd
installed and enabled:

> ● chrony.service - chrony, an NTP client/server
>    Loaded: loaded (/lib/systemd/system/chrony.service; enabled; vendor preset: enabled)
>    Active: active (running) since Sun 2020-01-12 19:48:09 CET; 1min 15s ago
>      Docs: man:chronyd(8)
>            man:chronyc(1)
>            man:chrony.conf(5)
>   Process: 395 ExecStart=/usr/sbin/chronyd $DAEMON_OPTS (code=exited, status=0/SUCCESS)
>   Process: 404 ExecStartPost=/usr/lib/chrony/chrony-helper update-daemon (code=exited, status=0/SUCCESS)
>  Main PID: 401 (chronyd)
>     Tasks: 2 (limit: 1149)
>    Memory: 3.3M
>    CGroup: /system.slice/chrony.service
>            ├─401 /usr/sbin/chronyd -F -1
>            └─403 /usr/sbin/chronyd -F -1
> 
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Control process exited, code=exited, status=0/SUCCESS
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Got final SIGCHLD for state start-post.
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Changed start-post -> running
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Job 75 chrony.service/start finished, result=done
> Jan 12 19:48:09 debian systemd[1]: Started chrony, an NTP client/server.
> Jan 12 19:48:14 debian systemd[1]: chrony.service: chrony.service/stop would stop a running service.
> Jan 12 19:48:14 debian systemd[1]: chrony.service: Deleting chrony.service/stop to minimize impact.
> Jan 12 19:48:17 debian chronyd[401]: Selected source 162.159.200.1
> Jan 12 19:48:18 debian chronyd[401]: Selected source 173.249.58.145
> Jan 12 19:48:19 debian chronyd[401]: Source 129.70.132.37 replaced with 2a01:4f8:110:12c8::123
> 
> ● systemd-timesyncd.service - Network Time Synchronization
>    Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
>   Drop-In: /usr/lib/systemd/system/systemd-timesyncd.service.d
>            └─disable-with-time-daemon.conf
>    Active: inactive (dead)
>      Docs: man:systemd-timesyncd.service(8)



> Jan 12 19:48:08 debian systemd-sysv-generator[232]: Native unit for chrony.service already exists, skipping.
> Jan 12 19:48:09 debian audit[296]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/chronyd" pid=296 comm="apparmor_parser"
> Jan 12 19:48:09 debian kernel: audit: type=1400 audit(1578854889.112:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/chronyd" pid=296 comm="apparmor_parser"
> Jan 12 19:48:09 debian chronyd[401]: chronyd version 3.4 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND +ASYNCDNS +SECHASH +IPV6 -DEBUG)
> Jan 12 19:48:09 debian chronyd[401]: Frequency 0.000 +/- 1000000.000 ppm read from /var/lib/chrony/chrony.drift
> Jan 12 19:48:09 debian chronyd[401]: Loaded seccomp filter
> Jan 12 19:48:09 debian systemd[1]: chrony.service: ConditionCapability=CAP_SYS_TIME succeeded.
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Passing 0 fds to service
> Jan 12 19:48:09 debian systemd[1]: chrony.service: About to execute: /usr/sbin/chronyd $DAEMON_OPTS
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Forked /usr/sbin/chronyd as 395
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Changed dead -> start
> Jan 12 19:48:09 debian systemd[1]: Starting chrony, an NTP client/server...
> Jan 12 19:48:09 debian systemd[395]: Successfully mounted /tmp/systemd-private-c32de5dec7564bdd85daa27163fecfdb-chrony.service-2LqUhJ/tmp to /run/systemd/unit-root/tmp
> Jan 12 19:48:09 debian systemd[395]: Successfully mounted /var/tmp/systemd-private-c32de5dec7564bdd85daa27163fecfdb-chrony.service-aYqukO/tmp to /run/systemd/unit-root/var/tmp
> Jan 12 19:48:09 debian systemd[395]: chrony.service: Executing: /usr/sbin/chronyd -F -1
> Jan 12 19:48:09 debian systemd[1]: Received SIGCHLD from PID 400 (chronyd).
> Jan 12 19:48:09 debian systemd[1]: Child 395 (chronyd) died (code=exited, status=0/SUCCESS)
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Child 395 belongs to chrony.service.
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Control process exited, code=exited, status=0/SUCCESS
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Got final SIGCHLD for state start.
> Jan 12 19:48:09 debian systemd[1]: chrony.service: New main PID 401 belongs to service, we are happy.
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Main PID loaded: 401
> Jan 12 19:48:09 debian systemd[1]: chrony.service: About to execute: /usr/lib/chrony/chrony-helper update-daemon
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Forked /usr/lib/chrony/chrony-helper as 404
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Changed start -> start-post
> Jan 12 19:48:09 debian systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=31 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=32 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd[1]: Child 400 (chronyd) died (code=exited, status=0/SUCCESS)
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Child 400 belongs to chrony.service.
> Jan 12 19:48:09 debian systemd-logind[380]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=31 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd-logind[380]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=32 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd[404]: Successfully mounted /tmp/systemd-private-c32de5dec7564bdd85daa27163fecfdb-chrony.service-2LqUhJ/tmp to /run/systemd/unit-root/tmp
> Jan 12 19:48:09 debian systemd[404]: Successfully mounted /var/tmp/systemd-private-c32de5dec7564bdd85daa27163fecfdb-chrony.service-aYqukO/tmp to /run/systemd/unit-root/var/tmp
> Jan 12 19:48:09 debian systemd[404]: chrony.service: Executing: /usr/lib/chrony/chrony-helper update-daemon
> Jan 12 19:48:09 debian systemd[1]: Received SIGCHLD from PID 404 (chrony-helper).
> Jan 12 19:48:09 debian systemd[1]: Child 404 (chrony-helper) died (code=exited, status=0/SUCCESS)
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Child 404 belongs to chrony.service.
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Control process exited, code=exited, status=0/SUCCESS
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Got final SIGCHLD for state start-post.
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Changed start-post -> running
> Jan 12 19:48:09 debian systemd[1]: chrony.service: Job 75 chrony.service/start finished, result=done
> Jan 12 19:48:09 debian systemd[1]: Started chrony, an NTP client/server.
> Jan 12 19:48:09 debian systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=38 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=39 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=41 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=42 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd-logind[380]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=38 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd-logind[380]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=39 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd-logind[380]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=41 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:09 debian systemd-logind[380]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1/unit/chrony_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=42 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
> Jan 12 19:48:14 debian systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 19:48:14 debian systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 19:48:14 debian systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 19:48:14 debian systemd[1]: Garbage collecting job systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Garbage collecting job chrony.service/stop
> Jan 12 19:48:14 debian systemd[1]: Pulling in systemd-timesyncd.service/start from sysinit.target/start
> Jan 12 19:48:14 debian systemd[1]: Added job systemd-timesyncd.service/start to transaction.
> Jan 12 19:48:14 debian systemd[1]: Pulling in -.mount/start from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in system.slice/start from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in time-sync.target/start from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in shutdown.target/stop from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Pulling in chrony.service/stop from systemd-timesyncd.service/start
> Jan 12 19:48:14 debian systemd[1]: Added job chrony.service/stop to transaction.
> Jan 12 19:48:14 debian systemd[1]: chrony.service: chrony.service/stop would stop a running service.
> Jan 12 19:48:14 debian systemd[1]: chrony.service: Deleting chrony.service/stop to minimize impact.
> Jan 12 19:48:14 debian systemd[1]: Garbage collecting job systemd-timesyncd.service/start
> Jan 12 19:48:17 debian chronyd[401]: Selected source 162.159.200.1
> Jan 12 19:48:18 debian chronyd[401]: Selected source 173.249.58.145
> Jan 12 19:48:19 debian chronyd[401]: Source 129.70.132.37 replaced with 2a01:4f8:110:12c8::123



-------------- 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/728c5468/attachment-0001.sig>

More information about the Pkg-systemd-maintainers mailing list