[bug] systemd 249 (249.4-2-arch) Timesyncd not working

[camerony]

Upgrading from systemd 248 (248.3-2-arch) to systemd 249 (249.4-2-arch) breaks timesync. I'm running on RPI4 over wifi.

$this->bbcode_second_pass_code('', '[root@pikvm kvmd-webterm]# timedatectl status
Local time: Tue 2021-10-05 17:15:02 PDT
Universal time: Wed 2021-10-06 00:15:02 UTC
RTC time: n/a
Time zone: America/Los_Angeles (PDT, -0700)
System clock synchronized: yes
NTP service: active
RTC in local TZ: no
[root@pikvm kvmd-webterm]# timedatectl timesync-status
Server: 196.200.131.160 (1.arch.pool.ntp.org)
Poll interval: 32s (min: 32s; max 34min 8s)
Leap: normal
Version: 4
Stratum: 2
Reference: 60B4CF6D
Precision: 1us (-25)
Root distance: 74.996ms (max: 5s)
Offset: +109.187ms
Delay: 193.073ms
Jitter: 50.929ms
Packet count: 4
[root@pikvm kvmd-webterm]# systemctl --version
systemd 248 (248.3-2-arch)
+PAM +AUDIT -SELINUX -APPARMOR -IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +XKBCOMMON +UTMP -SYSVINIT default-hierarchy=unified
[root@pikvm kvmd-webterm]# ')

Upgrade

$this->bbcode_second_pass_code('', '[root@pikvm kvmd-webterm]# pacman -Syu
:: Synchronizing package databases...
core is up to date
extra is up to date
community is up to date
alarm is up to date
aur is up to date
pikvm is up to date
:: Starting full system upgrade...
resolving dependencies...
looking for conflicting packages...

Packages (1) systemd-249.4-2

Total Download Size: 5.60 MiB
Total Installed Size: 23.75 MiB
Net Upgrade Size: 0.64 MiB

:: Proceed with installation? [Y/n] Y
:: Retrieving packages...
systemd-249.4-2-armv7h 5.6 MiB 3.25 MiB/s 00:02 [##################################################################] 100%
(1/1) checking keys in keyring [##################################################################] 100%
(1/1) checking package integrity [##################################################################] 100%
(1/1) loading package files [##################################################################] 100%
(1/1) checking for file conflicts [##################################################################] 100%
(1/1) checking available disk space [##################################################################] 100%
warning: could not get file information for var/log/journal/
:: Processing package changes...
(1/1) upgrading systemd [##################################################################] 100%
warning: /etc/systemd/resolved.conf installed as /etc/systemd/resolved.conf.pacnew
:: Running post-transaction hooks...
( 1/11) Creating system user accounts...
( 2/11) Updating journal message catalog...
( 3/11) Reloading system manager configuration...
( 4/11) Updating udev hardware database...
( 5/11) Applying kernel sysctl settings...
( 6/11) Creating temporary files...
( 7/11) Reloading device manager configuration...
( 8/11) Arming ConditionNeedsUpdate...
( 9/11) Updating linux-raspberrypi4 initcpios...
==> Building image from preset: /etc/mkinitcpio.d/linux-raspberrypi4.preset: 'default'
-> -k 5.10.52-12-ARCH -c /etc/mkinitcpio.conf -g /boot/initramfs-linux.img
==> Starting build: 5.10.52-12-ARCH
-> Running build hook: [base]
-> Running build hook: [udev]
-> Running build hook: [block]
-> Running build hook: [filesystems]
==> Generating module dependencies
==> Creating gzip-compressed initcpio image: /boot/initramfs-linux.img
==> Image generation successful
(10/11) Updating linux initcpios...
==> Building image from preset: /etc/mkinitcpio.d/linux-raspberrypi4.preset: 'default'
-> -k 5.10.52-12-ARCH -c /etc/mkinitcpio.conf -g /boot/initramfs-linux.img
==> Starting build: 5.10.52-12-ARCH
-> Running build hook: [base]
-> Running build hook: [udev]
-> Running build hook: [block]
-> Running build hook: [filesystems]
==> Generating module dependencies
==> Creating gzip-compressed initcpio image: /boot/initramfs-linux.img
==> Image generation successful
(11/11) Reloading system bus configuration...
[root@pikvm kvmd-webterm]# ')

After upgrade
$this->bbcode_second_pass_code('', '[root@pikvm kvmd-webterm]# timedatectl status
Local time: Mon 2021-10-04 10:37:09 PDT
Universal time: Mon 2021-10-04 17:37:09 UTC
RTC time: n/a
Time zone: America/Los_Angeles (PDT, -0700)
System clock synchronized: no
NTP service: active
RTC in local TZ: no
[root@pikvm kvmd-webterm]# timedatectl timesync-status
Server: n/a (n/a)
Poll interval: 0 (min: 32s; max 34min 8s)
Packet count: 0
[root@pikvm kvmd-webterm]# timedatectl --version
systemd 249 (249.4-2-arch)
+PAM +AUDIT -SELINUX -APPARMOR -IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +XKBCOMMON +UTMP -SYSVINIT default-hierarchy=unified
[root@pikvm kvmd-webterm]# ')

[ufo6000]

Is there something in the logs ?

sudo systemctl status systemd-timesyncd
sudo journalctl -u systemd-timesyncd

[camerony]

Nothing interesting, unfortunately.

$this->bbcode_second_pass_code('', '[root@pikvm kvmd-webterm]# sudo systemctl status systemd-timesyncd
* systemd-timesyncd.service - Network Time Synchronization
Loaded: loaded (/usr/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2021-10-04 10:36:21 PDT; 14h ago
Docs: man:systemd-timesyncd.service(8)
Main PID: 352 (systemd-timesyn)
Status: "Daemon is running"
Tasks: 1 (limit: 4915)
CPU: 274ms
CGroup: /system.slice/systemd-timesyncd.service
`-352 /usr/lib/systemd/systemd-timesyncd

Oct 04 10:36:21 pikvm systemd[1]: Starting Network Time Synchronization...
Oct 04 10:36:21 pikvm systemd[1]: Started Network Time Synchronization.
[root@pikvm kvmd-webterm]# sudo journalctl -u systemd-timesyncd
-- Journal begins at Mon 2021-10-04 10:36:20 PDT, ends at Tue 2021-10-05 01:34:34 PDT. --
Oct 04 10:36:21 pikvm systemd[1]: Starting Network Time Synchronization...
Oct 04 10:36:21 pikvm systemd[1]: Started Network Time Synchronization.
[root@pikvm kvmd-webterm]# ')


Debugging - I restarted networkd a few times during debug, here is the result.

$this->bbcode_second_pass_code('', '[root@pikvm kvmd-webterm]# SYSTEMD_LOG_LEVEL=debug /lib/systemd/systemd-timesyncd
Bus bus-api-timesync: changing state UNSET → OPENING
sd-bus: starting bus bus-api-timesync by connecting to /run/dbus/system_bus_socket...
Bus bus-api-timesync: changing state OPENING → AUTHENTICATING
Registering bus object implementation for path=/org/freedesktop/LogControl1 iface=org.freedesktop.LogControl1
Added new server 0.arch.pool.ntp.org.
Added new server 1.arch.pool.ntp.org.
Added new server 2.arch.pool.ntp.org.
Added new server 3.arch.pool.ntp.org.
Added new server 0.arch.pool.ntp.org.
Added new server 1.arch.pool.ntp.org.
Added new server 2.arch.pool.ntp.org.
Added new server 3.arch.pool.ntp.org.
systemd-timesyncd running as pid 626
Bus bus-api-timesync: changing state AUTHENTICATING → HELLO
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RequestName cookie=2 reply_cookie=0 signature=su error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.13 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Bus bus-api-timesync: changing state HELLO → RUNNING
Got message type=signal sender=org.freedesktop.DBus.Local destination=n/a path=/org/freedesktop/DBus/Local interface=org.freedesktop.DBus.Local member=Connected cookie=4294967295 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.DBus destination=:1.13 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=signal sender=org.freedesktop.DBus destination=:1.13 path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.13 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=u error-name=n/a error-message=n/a
Successfully acquired requested service name.
Got message type=method_call sender=:1.17 destination=org.freedesktop.timesync1 path=/org/freedesktop/timesync1 interface=org.freedesktop.DBus.Properties member=GetAll cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Sent message type=method_return sender=n/a destination=:1.17 path=n/a interface=n/a member=n/a cookie=3 reply_cookie=2 signature=a{sv} error-name=n/a error-message=n/a
Network configuration changed, trying to establish connection.
Selected server 0.arch.pool.ntp.org.
Resolving 0.arch.pool.ntp.org...
varlink: Setting state idle-client
varlink: Sending message: {"method":"io.systemd.Resolve.ResolveHostname","parameters":{"name":"0.arch.pool.ntp.org","flags":0}}
varlink: Changing state idle-client → calling
varlink: New incoming message: {"parameters":{"addresses":[{"ifindex":3,"family":2,"address":[176,9,157,155]},{"ifindex":3,"family":2,"address":[193,150,22,36]},{"ifindex":3,"family":2,"address":[131,234,220,231]},{"ifindex":3,"family":2,"address":[213,231,5,55]}],"name":"0.arch.pool.ntp.org","flags":8388609}}
varlink: Changing state calling → called
varlink: Changing state called → idle-client
Resolved address 176.9.157.155:123 for 0.arch.pool.ntp.org.
Resolved address 193.150.22.36:123 for 0.arch.pool.ntp.org.
Resolved address 131.234.220.231:123 for 0.arch.pool.ntp.org.
Resolved address 213.231.5.55:123 for 0.arch.pool.ntp.org.
Selected address 176.9.157.155:123 of server 0.arch.pool.ntp.org.
Connecting to time server 176.9.157.155:123 (0.arch.pool.ntp.org).
Sent NTP request to 176.9.157.155:123 (0.arch.pool.ntp.org).
No network connectivity, watching for changes.
Got message type=method_call sender=:1.20 destination=org.freedesktop.timesync1 path=/org/freedesktop/timesync1 interface=org.freedesktop.DBus.Properties member=GetAll cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Sent message type=method_return sender=n/a destination=:1.20 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=a{sv} error-name=n/a error-message=n/a
Network configuration changed, trying to establish connection.
Connecting to time server 176.9.157.155:123 (0.arch.pool.ntp.org).
Sent NTP request to 176.9.157.155:123 (0.arch.pool.ntp.org).
No network connectivity, watching for changes.
Got message type=method_call sender=:1.26 destination=org.freedesktop.timesync1 path=/org/freedesktop/timesync1 interface=org.freedesktop.DBus.Properties member=GetAll cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Sent message type=method_return sender=n/a destination=:1.26 path=n/a interface=n/a member=n/a cookie=5 reply_cookie=2 signature=a{sv} error-name=n/a error-message=n/a
Network configuration changed, trying to establish connection.
Connecting to time server 176.9.157.155:123 (0.arch.pool.ntp.org).
Sent NTP request to 176.9.157.155:123 (0.arch.pool.ntp.org).
No network connectivity, watching for changes.
Got message type=method_call sender=:1.28 destination=org.freedesktop.timesync1 path=/org/freedesktop/timesync1 interface=org.freedesktop.DBus.Properties member=GetAll cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Sent message type=method_return sender=n/a destination=:1.28 path=n/a interface=n/a member=n/a cookie=6 reply_cookie=2 signature=a{sv} error-name=n/a error-message=n/a
')

Downgrading to systemd 248 (248.3-2-arch) fixes the issue, then upgrading to systemd 249 (249-3-arch) breaks it.
I couldn't build of 249-2 to test, so I think it narrows it down to 2 commits, on Jul 11, 2021 or Jul 12, 2021

$this->bbcode_second_pass_code('', 'kvmd-webterm@pikvm ~]$ timedatectl
Local time: Mon 2021-07-12 11:31:37 PDT
Universal time: Mon 2021-07-12 18:31:37 UTC
RTC time: n/a
Time zone: America/Los_Angeles (PDT, -0700)
System clock synchronized: no
NTP service: active
RTC in local TZ: no
[kvmd-webterm@pikvm ~]$ systemctl --version
systemd 249 (249-3-arch)
+PAM +AUDIT -SELINUX -APPARMOR -IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +XKBCOMMON +UTMP -SYSVINIT default-hierarchy=unified
[kvmd-webterm@pikvm ~]$

')

[Styglian]

Thank you for posting the logs - finding this thread made this much easier to debug.

I just wanted to link to the other thread here, as it has some other options than downgrading:
https://archlinuxarm.org/forum/viewtopic.php?f=7&t=15574

[jfabernathy]

This still appears to be a problem. Again I was able to get timesyncd to work correctly on an RPI3 with aarch64 by removing en.network and eth.network files from /etc/systemd/network