Focal Fossa : chronyd unable to sync system clock

Tested on armv7l and aarch64.

Hello Cryolithe and thanks for filing this bug report. In order to understand if what you observe is actually a bug or the expected behavior of chrony we need to know two things:

1. What is the exact version of the package you have installed?
2. Are you running Focal on bare metal, in a virtual machine, or in a container?

If you are running it in a (unprivileged) container and you have installed the latest version of the chrony package (currently 3.5-5ubuntu1), then you should see these warnings:

chronyd-starter.sh[1813]: Warning: Missing cap_sys_time, syncing the system clock will fail
chronyd-starter.sh[1813]: Warning: Running in a container, likely impossible and unintended to sync system clock
chronyd-starter.sh[1813]: Adding -x as fallback disabling control of the system clock, see /usr/share/doc/chrony/README.container to override this behavior

and chrony should start but only serve time, without setting the system clock. This is expected.

I'm setting the status of this bug report to Incomplete for the moment. Please change it back to New after commenting back, and we'll look at it again. Thanks!

Hello, the version is :

||/ Name Version Architecture Description
+++-==============-============-============-=====================================================
ii chrony 3.5-5ubuntu1 arm64 Versatile implementation of the Network Time Protocol

And yes, on bare metal, on Raspberry Pi 2 and Raspberry Pi 4.

I know it act like this in a VM or container, but it's bare metal and I just installed the package in a "normal" way.

I can precise that it was working until recently, it doesn't work anymore since about a week, after an "apt upgrade".

Answer

And it happened after a reboot, then maybe since the last kernel update.

Hi Cryolithe,
I know that glibc changed things in 2.31 but I thought that is in proposed still.
I was working (I thought just for test/build issues) on an update in bug 1866753.
It does internal syscall filtering and that changed in glibc.
Out of that I already have PPA: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/3968
Soon that will show up in focal-proposed anyway, but still.

@Cryolithe - would you mind trying if that PPA resolves it for you and report back here?
- Also are you running -proposed enabled?
- And anyway the report lacks some data - which Ubuntu release are you running atm?
  $ cat /etc/os-release
  $ apt-cache policy chrony
It would also be great to run apport to get the package upgrade history and all that right away.
 $ apport-collect 1867036

Finally maybe we should check and compare caps in your system
  $ apt install libcap-ng-utils
  $ pscap -a
  # if the service didn't fail but keeps running with reduced caps

Example output on a container:
root@f:~# pscap -a | grep chrony
1 26441 _chrony chronyd net_bind_service
26441 26442 _chrony chronyd net_bind_service
Example output on a VM:
@f $ pscap -a | grep chrony
1 1707 _chrony chronyd net_bind_service, sys_time +
1707 1708 _chrony chronyd net_bind_service, sys_time +

Hello,
no I'm not using -proposed.

$ cat /etc/os-release
NAME="Ubuntu"
VERSION="20.04 LTS (Focal Fossa)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu Focal Fossa (development branch)"
VERSION_ID="20.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal

$ apt-cache policy chrony
chrony:
  Installed: 3.5-6ubuntu1
  Candidate: 3.5-6ubuntu1
  Version table:
 *** 3.5-6ubuntu1 500
        500 http://ports.ubuntu.com/ubuntu-ports focal/main arm64 Packages
        100 /var/lib/dpkg/status

then I added -proposed and your PPA, nothing changed.

apt-cache policy chrony
chrony:
  Installed: 3.5-6ubuntu1
  Candidate: 3.5-6ubuntu1
  Version table:
 *** 3.5-6ubuntu1 500
        500 http://ports.ubuntu.com/ubuntu-ports focal/main arm64 Packages
        100 /var/lib/dpkg/status
     3.5-6ubuntu1~ppa1 500
        500 http://ppa.launchpad.net/ci-train-ppa-service/3968/ubuntu focal/main arm64 Packages

then I edited /etc/default/chrony to add SYNC_IN_CONTAINER="yes"
now service status says:

chronyd-starter.sh[50743]: Warning: Missing cap_sys_time, syncing the system clock will fail
chronyd-starter.sh[50743]: Not falling back to disable control of the system clock

Now I have to try your libcap-ng-utils stuff.

$ pscap -a | grep chrony
1 50749 _chrony chronyd net_bind_service, sys_time +
50749 50750 _chrony chronyd net_bind_service, sys_time +

With SYNC_IN_CONTAINER="yes" in /etc/default/chrony it works.

$ timedatectl
               Local time: Fri 2020-03-13 21:51:42 CET
           Universal time: Fri 2020-03-13 20:51:42 UTC
                 RTC time: n/a
                Time zone: Europe/Paris (CET, +0100)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

But it isn't normal to have to do this as I'm on bare metal. By the way, the -X workaround for VM/container is very bad because chronyd serve the (wrong) system time and not the NTP time.

Confirmed on amd64 (vmware vm without docker, lxd, ...)

# systemctl restart chrony
# systemctl status chrony
● chrony.service - chrony, an NTP client/server
     Loaded: loaded (/lib/systemd/system/chrony.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2020-03-27 11:17:47 CET; 1s ago
       Docs: man:chronyd(8)
             man:chronyc(1)
             man:chrony.conf(5)
    Process: 15193 ExecStart=/usr/lib/systemd/scripts/chronyd-starter.sh $DAEMON_OPTS (code=exited, status=0/SUCCESS)
    Process: 15213 ExecStartPost=/usr/lib/chrony/chrony-helper update-daemon (code=exited, status=0/SUCCESS)
   Main PID: 15209 (chronyd)
      Tasks: 2 (limit: 2249)
     Memory: 1.7M
     CGroup: /system.slice/chrony.service
             ├─15209 /usr/sbin/chronyd -F -1 -4 -x
             └─15210 /usr/sbin/chronyd -F -1 -4 -x

Mar 27 11:17:47 ld3ubu001t systemd[1]: Starting chrony, an NTP client/server...
Mar 27 11:17:47 ld3ubu001t chronyd-starter.sh[15193]: Warning: Missing cap_sys_time, syncing the system clock will fail
Mar 27 11:17:47 ld3ubu001t chronyd-starter.sh[15193]: Adding -x as fallback disabling control of the system clock, see /usr/shar>
Mar 27 11:17:47 ld3ubu001t chronyd[15209]: chronyd version 3.5 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND >
Mar 27 11:17:47 ld3ubu001t chronyd[15209]: Disabled control of system clock
Mar 27 11:17:47 ld3ubu001t chronyd[15209]: Frequency 0.707 +/- 6.210 ppm read from /var/lib/chrony/chrony.drift
Mar 27 11:17:47 ld3ubu001t chronyd[15209]: Loaded seccomp filter
Mar 27 11:17:47 ld3ubu001t systemd[1]: Started chrony, an NTP client/server.

# dpkg -l chrony
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-==============-============-============-===================================================
ii chrony 3.5-6ubuntu1 amd64 Versatile implementation of the Network Time Protocol

# pscap -a |grep chrony
1 15209 _chrony chronyd net_bind_service +
15209 15210 _chrony chronyd net_bind_service +

# cat /etc/apparmor.d/usr.sbin.chronyd | grep capa
  capability sys_time,
  capability net_bind_service,
  capability setuid,
  capability setgid,
  capability sys_nice,
  capability sys_resource,
  capability chown,
  capability net_admin,

For me chrony 3.5-6ubuntu1 gets happier when I tell systemd to hand it the CAP_SYS_TIME capability.

# cat /etc/systemd/system/chrony.service.d/cap_sys_time.conf
[Service]
AmbientCapabilities=CAP_SYS_TIME
#

Status changed to 'Confirmed' because the bug affects multiple users.

Looking into this, it seems the problem is that /usr/lib/systemd/scripts/chronyd-starter.sh expects to be able to check for the cap_sys_time capability by grepping the output of "capsh --print" for "^Current.*cap_sys_time". However, in Focal the output of "capsh --print" for a root process is just "Current: =ep". I suspect this is a linux kernel tools change, as on an eoan system with linux 5.3.0, "sudo capsh --print" has all the capabilities listed in Current:, which is what the starter script expects.

andol's dropin makes capsh output "Current: =ep cap_sys_time+i" which the grep matches so all is fine. Not sure that's the right fix, though. (It would help if I knew what "Current: =ep" is supposed to mean.

Thanks Rich for that hint, I've seen this issue of the changed output hit LXD and yes that might be the issue here.

If indeed that is a false positive it will add -x which isn't intended for cases where it would be fine to run without (only wanted to too hard isolation breaking chrony).

Confirmed on a normal install in a VM:

ubuntu@f-chrony:~$ journalctl -u chrony
-- Logs begin at Mon 2020-03-30 13:21:33 UTC, end at Mon 2020-03-30 14:26:38 UTC. --
Mar 30 14:26:34 f-chrony systemd[1]: Starting chrony, an NTP client/server...
Mar 30 14:26:34 f-chrony chronyd-starter.sh[7534]: Warning: Missing cap_sys_time, syncing the system clock will fail
Mar 30 14:26:34 f-chrony chronyd-starter.sh[7534]: Adding -x as fallback disabling control of the system clock, see /usr/share/doc/chrony/README.container to override this behavior
Mar 30 14:26:34 f-chrony chronyd[7545]: chronyd version 3.5 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND +ASYNCDNS +SECHASH +IPV6 -DEBUG)
Mar 30 14:26:34 f-chrony chronyd[7545]: Disabled control of system clock
Mar 30 14:26:34 f-chrony chronyd[7545]: Loaded seccomp filter
Mar 30 14:26:34 f-chrony systemd[1]: Started chrony, an NTP client/server.

ubuntu@e-chrony:~$ journalctl -u chrony
-- Logs begin at Mon 2020-03-30 12:14:05 UTC, end at Mon 2020-03-30 14:18:48 UTC. --
Mar 30 14:18:39 e-chrony systemd[1]: Starting chrony, an NTP client/server...
Mar 30 14:18:39 e-chrony chronyd[15659]: chronyd version 3.5 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND +ASYNCDNS +SECHASH +IPV6 -DEBUG)
Mar 30 14:18:39 e-chrony chronyd[15659]: Initial frequency -5.143 ppm
Mar 30 14:18:39 e-chrony chronyd[15659]: Loaded seccomp filter
Mar 30 14:18:39 e-chrony systemd[1]: Started chrony, an NTP client/server.
Mar 30 14:18:48 e-chrony chronyd[15659]: Selected source 162.159.200.123

Just as Rich reported (but here in full detail):

Old (eoan):
Current: = cap_chown,cap_dac_override,cap_dac_read_search,cap_fowner,cap_fsetid,cap_kill,cap_setgid,cap_setuid,cap_setpcap,cap_linux_immutable,cap_net_bind_service,cap_net_broadcast,cap_net_admin,cap_net_raw,cap_ipc_lock,cap_ipc_owner,cap_sys_module,cap_sys_rawio,cap_sys_chroot,cap_sys_ptrace,cap_sys_pacct,cap_sys_admin,cap_sys_boot,cap_sys_nice,cap_sys_resource,cap_sys_time,cap_sys_tty_config,cap_mknod,cap_lease,cap_audit_write,cap_audit_control,cap_setfcap,cap_mac_override,cap_mac_admin,cap_syslog,cap_wake_alarm,cap_block_suspend,cap_audit_read+ep
Bounding set =cap_chown,cap_dac_override,cap_dac_read_search,cap_fowner,cap_fsetid,cap_kill,cap_setgid,cap_setuid,cap_setpcap,cap_linux_immutable,cap_net_bind_service,cap_net_broadcast,cap_net_admin,cap_net_raw,cap_ipc_lock,cap_ipc_owner,cap_sys_module,cap_sys_rawio,cap_sys_chroot,cap_sys_ptrace,cap_sys_pacct,cap_sys_admin,cap_sys_boot,cap_sys_nice,cap_sys_resource,cap_sys_time,cap_sys_tty_config,cap_mknod,cap_lease,cap_audit_write,cap_audit_control,cap_setfcap,cap_mac_override,cap_mac_admin,cap_syslog,cap_wake_alarm,cap_block_suspend,cap_audit_read
Securebits: 00/0x0/1'b0
 secure-noroot: no (unlocked)
 secure-no-suid-fixup: no (unlocked)
 secure-keep-caps: no (unlocked)
uid=0(root)
gid=0(root)
groups=

New (Focal):
Current: =ep
Bounding set =cap_chown,cap_dac_override,cap_dac_read_search,cap_fowner,cap_fsetid,cap_kill,cap_setgid,cap_setuid,cap_setpcap,cap_linux_immutable,cap_net_bind_service,cap_net_broadcast,cap_net_admin,cap_net_raw,cap_ipc_lock,cap_ipc_owner,cap_sys_module,cap_sys_rawio,cap_sys_chroot,cap_sys_ptrace,cap_sys_pacct,cap_sys_admin,cap_sys_boot,cap_sys_nice,cap_sys_resource,cap_sys_time,cap_sys_tty_config,cap_mknod,cap_lease,cap_audit_write,cap_audit_control,cap_setfcap,cap_mac_override,cap_mac_admin,cap_syslog,cap_wake_alarm,cap_block_suspend,cap_audit_read
Ambient set =
Securebits: 00/0x0/1'b0
 secure-noroot: no (unlocked)
 secure-no-suid-fixup: no (unlocked)
 secure-keep-caps: no (unlocked)
 secure-no-ambient-raise: no (unlocked)
uid=0(root) euid=0(root)
gid=0(root)
groups=
Guessed mode: UNCERTAIN (0)

The new versions didn't only change output, it also added an option to much better check if this would be allowed (better than output + grep):
  capsh --has-p="cap_sys_time"

libcap change was:
=> https://git.kernel.org/pub/scm/libs/libcap/libcap.git/commit/?id=588d0439cb6495b03f0ab9f213f0b6b339e7d4b7
That is in 2.32 and later.

Lets add a versioned dependency to ensure upgraders don't get awkward issues (missing --has-p) on service restarts before the right things are in place.

Test PPA builds at:
https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/4000

MP with the fix:
https://code.launchpad.net/~paelzer/ubuntu/+source/chrony/+git/chrony/+merge/381424

Testing with the PPA confirms the issue is fixes:
It now looks like this:

bare-metal/VMs:
ar 31 10:17:51 f-chrony systemd[1]: Starting chrony, an NTP client/server...
Mar 31 10:17:51 f-chrony chronyd[10780]: chronyd version 3.5 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND +ASYNCDNS +SECHASH +IPV6 -DEBUG)
Mar 31 10:17:51 f-chrony chronyd[10780]: Frequency -0.027 +/- 0.117 ppm read from /var/lib/chrony/chrony.drift
Mar 31 10:17:51 f-chrony chronyd[10780]: Loaded seccomp filter
Mar 31 10:17:51 f-chrony systemd[1]: Started chrony, an NTP client/server.

Containers:
Mar 31 10:17:42 f2 systemd[1]: Starting chrony, an NTP client/server...
Mar 31 10:17:42 f2 chronyd-starter.sh[3934]: cap[cap_sys_time] not permitted
Mar 31 10:17:42 f2 chronyd-starter.sh[3932]: Warning: Missing cap_sys_time, syncing the system clock will fail
Mar 31 10:17:42 f2 chronyd-starter.sh[3932]: Warning: Running in a container, likely impossible and unintended to sync system clock
Mar 31 10:17:42 f2 chronyd-starter.sh[3932]: Adding -x as fallback disabling control of the system clock, see /usr/share/doc/chrony/README.container to override this behavior
Mar 31 10:17:42 f2 chronyd[3937]: chronyd version 3.5 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND +ASYNCDNS +SECHASH +IPV6 -DEBUG)
Mar 31 10:17:42 f2 chronyd[3937]: Disabled control of system clock
Mar 31 10:17:42 f2 chronyd[3937]: Frequency -0.137 +/- 0.196 ppm read from /var/lib/chrony/chrony.drift
Mar 31 10:17:42 f2 chronyd[3937]: Loaded seccomp filter
Mar 31 10:17:42 f2 systemd[1]: Started chrony, an NTP client/server.

The extra message of "cap[cap_sys_time] not permitted" isn't too bad.
In fact if down the road this would change behavior again and throw other errors (like cap[cap_sys_time] not recognized by library or anything else) we'd immediately see it which is a good aspect.

Fix uploaded, will need to be reviewed and approved by the release team (beta freeze)

Of course when things should be fast they are accompanied by a bunch of test errors.

I'm seeing these two:

amd64 & s390x
autopkgtest [14:27:33]: test run_destructive_system_tests: [-----------------------
100-clockupdate Testing update of system clock:
...
  checking system clock BAD

ppc64:
007-cmdmon Testing chronyc commands:
...
  running chronyc shutdown OK
  stopping chronyd ERROR

There were issues with HW specific clocks e.g. in VMs before - I'll have to revisit.
But the chrony upload didn't really change anything so it must be other components that trigger this now.

Liiking for other packages if any then IMHO it might be due to the new glibc, but I'll need to run some tests to prove that. That at least caused such issues in the past and would have been bumped at the right time.

Liiking should have been Looking :-)

Ok, the following confirms what I have assumed about glibc.
The reset let glibc pass but now we are just as broken. I remember having a discussion about that before, maybe now all changes are ready to be added.

revno: 4655
committer: Steve Langasek <email address hidden>
branch nick: hints-ubuntu
timestamp: Mon 2020-03-09 20:48:22 -0700
message:
  badtest chrony
diff:
+## external testsuite downloaded at test time is incompatible with glibc 2.31
+force-reset-test chrony/3.5-5ubuntu1
+##

But that particular failure was in the sub-test "upstream-simulation-testsuite" and fixed in:
chrony/3.5-6ubuntu1 via
      * debian/tests/upstream-simulation-test-suite:
        - Update clknetsim version. This new version supports glibc >= 2.31 headers.
        (LP: #1866753

So this is some new issue and I'll need to find what it is now.
Furthermore the PPC64 test issue seems to be a different one, that needs an extra check.

Running in a autopkgtest-VM (x86):
- 2x all-proposed
- 1x just the new chrony from proposed

All these tests worked fine

At the same time I've prepped tests on s390x (KVM) and ppc64 (canonistack) - with all proposed.
There all tests ran successfully on both architectures.

x86(1-3):
SUMMARY:
  TOTAL 5
  PASSED 4
  FAILED 0 ()
  SKIPPED 1 (102-hwtimestamp)
ppc:
SUMMARY:
  TOTAL 5
  PASSED 4
  FAILED 0 ()
  SKIPPED 1 (102-hwtimestamp)
s390x:
SUMMARY:
  TOTAL 5
  PASSED 3
  FAILED 0 ()
  SKIPPED 2 (101-rtc 102-hwtimestamp)

With so much (probably false) confidence I re-ran the tests on the autopkgtest infrastructure.
Once as-is and once with all-proposed:
http://autopkgtest.ubuntu.com/packages/c/chrony/focal/amd64
http://autopkgtest.ubuntu.com/packages/c/chrony/focal/ppc64el
http://autopkgtest.ubuntu.com/packages/c/chrony/focal/s390x

PPC64/S390X were fixed just by these retry.
Both runs (all-proposed and just chrony from proposed) worked.

Furthermore in case this only triggers on LP to be able to iterate I put a new version to
https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/4000/+packages
With tests triggered from:
https://bileto.ubuntu.com/#/ticket/4000

This bug was fixed in the package chrony - 3.5-6ubuntu2

---------------
chrony (3.5-6ubuntu2) focal; urgency=medium

  * fix capsh usage in focal avoiding to always fall back to -x (LP: #1867036)
    - d/control: add versioned dependency to libcap2-bin new enough to
      support --has-p
    - d/chronyd-starter.sh: update capsh usage to use --has-p

 -- Christian Ehrhardt <email address hidden> Tue, 31 Mar 2020 10:19:20 +0200

x86 working on a retry as well now :-/
Due to that the package migrated.

I'm glad it worked as that matches what my 7 local retries all confirm.
But I'm slightly scared if this might randomly come back.

It might stay one of those "happened only on autopkgtest infrastructure" issues :-/
If it does not come back I'm ok with that.

It seems to be racy/flaky and the comparison is on second granularity.
I was adding debug to check the values it fails on.

It was somewhat reproducible in the bileto ticket (again autopkgtest infrastructure).
Therefore I inserted some debug code and re-ran it there.

Ha - my assumption was right. Our test environment is too fast (sometimes) and hence the flakyness.

  checking chronyc output OK
    DEBUG before 1585747433
    DEBUG before 1585747433
  checking system clock BAD

That is checked with "lt" and here the results are ==.
I'll need to discuss if there is a strict reason for these to be non-equal.
Otherwise the fix might be as easy as using "-le" instead

Also the original bug is closed, time to move to a new bug with the test issue.