Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Systemd 238.76-1 breaks systemd-timesyncd on Raspberry Pi #8719

Closed
bulletmark opened this issue Apr 13, 2018 · 9 comments
Closed

Systemd 238.76-1 breaks systemd-timesyncd on Raspberry Pi #8719

bulletmark opened this issue Apr 13, 2018 · 9 comments
Assignees
Labels
bug 🐛 Programming errors, that need preferential fixing timesync

Comments

@bulletmark
Copy link

bulletmark commented Apr 13, 2018

Submission type

  • Bug report

Problem started after this update:

2018-04-13 07:46 libsystemd         238.51-1 -> 238.76-1
2018-04-13 07:46 systemd            238.51-1 -> 238.76-1
2018-04-13 07:46 systemd-sysvcompat 238.51-1 -> 238.76-1

Used distribution

Arch Arm (armv7)

Bug description

Since the above recent Arch ARM package updates, systemd-timesyncd never time syncs after boot. Rolling back the above versions fixes the problem. I rolled back and forward a few times to repeat this and confirmed it on my 2 RPi2 and 1 RPi3. I updated my RPi1 also but the problem does not occur there (may be timing related because RPi1 is much slower). Restarting systemd-timesyncd clears the problem. Note that the RPi does not have a Real Time Clock so must time sync immediately after boot.

It makes no difference which NTP server is used.

Unexpected behaviour

Here are the logs on a RPi with the bad version:

$ journalctl -b -u systemd-timesyncd --no-pager
-- Logs begin at Tue 2018-03-06 09:01:51 AEST, end at Fri 2018-04-13 10:06:36 AEST. --
Apr 12 10:20:18 pi3 systemd[1]: Starting Network Time Synchronization...
Apr 12 10:20:18 pi3 systemd-timesyncd[239]: System clock time unset or jumped backwards, restoring from recorded timestamp: Fri 2018-04-13 09:57:39 AEST
Apr 13 09:57:39 pi3 systemd[1]: Started Network Time Synchronization.

$ timedatectl
                      Local time: Fri 2018-04-13 10:05:59 AEST
                  Universal time: Fri 2018-04-13 00:05:59 UTC
                        RTC time: n/a
                       Time zone: Australia/Brisbane (AEST, +1000)
       System clock synchronized: no
systemd-timesyncd.service active: yes
                 RTC in local TZ: no

Expected behaviour

Here are the logs on a RPi with the previous good version:

$ journalctl -b -u systemd-timesyncd --no-pager
-- Logs begin at Fri 2018-03-23 06:56:58 AEST, end at Fri 2018-04-13 10:28:46 A\
EST. --
Mar 27 22:35:41 pi2 systemd[1]: Starting Network Time Synchronization...
Mar 27 22:35:41 pi2 systemd-timesyncd[233]: System clock time unset or jumped backwards, restoring from recorded timestamp: Fri 2018-04-13 09:47:08 AEST
Apr 13 09:47:08 pi2 systemd[1]: Started Network Time Synchronization.
Apr 13 09:47:09 pi2 systemd-timesyncd[233]: Network configuration changed, trying to establish connection.
Apr 13 09:50:06 pi2 systemd-timesyncd[233]: Synchronized to time server 202.142.142.241:123 (ntp.aussiebroadband.com.au).
Apr 13 09:50:06 pi2 systemd-timesyncd[233]: Network configuration changed, trying to establish connection.
Apr 13 09:50:06 pi2 systemd-timesyncd[233]: Synchronized to time server 202.142.142.241:123 (ntp.aussiebroadband.com.au).

$ timedatectl
                      Local time: Fri 2018-04-13 10:36:08 AEST
                  Universal time: Fri 2018-04-13 00:36:08 UTC
                        RTC time: n/a
                       Time zone: Australia/Brisbane (AEST, +1000)
       System clock synchronized: yes
systemd-timesyncd.service active: yes
                 RTC in local TZ: no

Related Changes

The bug appears to have been introduced by commit 3e85ec0 which is from PR #8611. I compiled systemd for my RPi3 and proved that removing that change variable from the if statement in timesyncd-manager.c stops the fault occurring. I don't know the code well enough to propose the best way to guarantee the sync is forced but I can help with testing any proposed fix. @yuwata

@yuwata
Copy link
Member

yuwata commented Apr 14, 2018

Could you give us the following:

  • .network files, network.conf and its drop-in
  • timesync.conf and its drop-in
  • log of networkd and timesyncd with SYSTEMD_LOG_LEVEL=debug.

@yuwata yuwata self-assigned this Apr 14, 2018
@bulletmark
Copy link
Author

bulletmark commented Apr 14, 2018

This problem occurred on the update I listed above to my 3 x RPi's all configured as generically as you could possibly get with systemd-networkd and simple DHCP clients. The RPi 3 uses a wifi connection, the 2 x RPi 2 use wired connections. Note, after seeing this problem I asked about it on the Arch ARM IRC where somebody else then checked their ARM box and confirmed the same problem. The Arch ARM packager then quickly released an Arch ARM systemd package with that single commit reverted.

I will quote one of the RPi 2 wired configurations:

Configuration

No network.conf file, /etc/systemd/timesyncd.conf empty (all commented out).
/etc/systemd/network/20-wired-network:

[Match]
Name=eth*

[Network]
DHCP=ipv4

Debug log of systemd-timesyncd for failed case:

pi2:~ /usr/bin/journalctl -b -u systemd-timesyncd --no-pager
-- Logs begin at Fri 2018-03-23 06:56:58 AEST, end at Sun 2018-04-15 09:39:09 AEST. --
Apr 12 10:20:20 pi2 systemd[1]: Starting Network Time Synchronization...
Apr 12 10:20:21 pi2 systemd-timesyncd[230]: System clock time unset or jumped backwards, restoring from recorded timestamp: Sun 2018-04-15 09:20:21 AEST
Apr 15 09:20:21 pi2 systemd-timesyncd[230]: Added new server 0.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[230]: Added new server 1.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[230]: Added new server 2.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[230]: Added new server 3.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[230]: systemd-timesyncd running as pid 230
Apr 15 09:20:21 pi2 systemd[1]: Started Network Time Synchronization.

Debug log of systemd-networkd for failed case:

pi2:~ /usr/bin/journalctl -b -u systemd-networkd --no-pager
-- Logs begin at Fri 2018-03-23 06:56:58 AEST, end at Sun 2018-04-15 09:39:09 AEST. --
Apr 12 10:20:19 pi2 systemd[1]: Starting Network Service...
Apr 12 10:20:19 pi2 systemd-networkd[214]: Bus n/a: changing state UNSET → OPENING
Apr 12 10:20:19 pi2 systemd-networkd[214]: Added inotify watch for /run on bus n/a: 2
Apr 12 10:20:19 pi2 systemd-networkd[214]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 12 10:20:19 pi2 systemd-networkd[214]: Bus n/a: changing state OPENING → WATCH_BIND
Apr 12 10:20:19 pi2 systemd-networkd[214]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Apr 12 10:20:19 pi2 systemd-networkd[214]: timestamp of '/etc/systemd/network' changed
Apr 12 10:20:19 pi2 systemd-networkd[214]: Ignoring /etc/systemd/network/20-wired.network, because it's not a regular file with suffix .netdev.
Apr 12 10:20:19 pi2 systemd-networkd[214]: Ignoring /usr/lib/systemd/network/80-container-host0.network, because it's not a regular file with suffix .netdev.
Apr 12 10:20:19 pi2 systemd-networkd[214]: Ignoring /usr/lib/systemd/network/99-default.link, because it's not a regular file with suffix .netdev.
Apr 12 10:20:19 pi2 systemd-networkd[214]: Ignoring /usr/lib/systemd/network/80-container-vz.network, because it's not a regular file with suffix .netdev.
Apr 12 10:20:19 pi2 systemd-networkd[214]: Ignoring /usr/lib/systemd/network/80-container-ve.network, because it's not a regular file with suffix .netdev.
Apr 12 10:20:19 pi2 systemd-networkd[214]: Ignoring /usr/lib/systemd/network/99-default.link, because it's not a regular file with suffix .network.
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Flags change: +MULTICAST +BROADCAST
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Link 2 added
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: link pending udev initialization...
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Saved original MTU: 1500
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Link 1 added
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: link pending udev initialization...
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Saved original MTU: 0
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Adding address: ::1/128 (valid forever)
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Adding address: 127.0.0.1/8 (valid forever)
Apr 12 10:20:20 pi2 systemd-networkd[214]: rtnl: received address with invalid family 129, ignoring
Apr 12 10:20:20 pi2 systemd-networkd[214]: rtnl: received address with invalid family 128, ignoring
Apr 12 10:20:20 pi2 systemd-networkd[214]: Enumeration completed
Apr 12 10:20:20 pi2 systemd[1]: Started Network Service.
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: udev initialized link
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Link state is up-to-date
Apr 12 10:20:20 pi2 systemd-networkd[214]: No virtualization found in DMI
Apr 12 10:20:20 pi2 systemd-networkd[214]: No virtualization found in CPUID
Apr 12 10:20:20 pi2 systemd-networkd[214]: Virtualization XEN not found, /proc/xen does not exist
Apr 12 10:20:20 pi2 systemd-networkd[214]: No virtualization found in /proc/device-tree/*
Apr 12 10:20:20 pi2 systemd-networkd[214]: UML virtualization not found in /proc/cpuinfo.
Apr 12 10:20:20 pi2 systemd-networkd[214]: This platform does not support /proc/sysinfo
Apr 12 10:20:20 pi2 systemd-networkd[214]: Found VM virtualization none
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Unmanaged
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: udev initialized link
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Link state is up-to-date
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: found matching network '/etc/systemd/network/20-wired.network'
Apr 12 10:20:20 pi2 systemd-networkd[214]: lo: Link is not managed by us
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Bringing link up
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: IPv6 successfully enabled
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Flags change: +UP +LOWER_UP +RUNNING
Apr 12 10:20:20 pi2 systemd-networkd[214]: LLDP: Started LLDP client
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Started LLDP.
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Gained carrier
Apr 12 10:20:20 pi2 systemd-networkd[214]: eth0: Acquiring DHCPv4 lease
Apr 12 10:20:20 pi2 systemd-networkd[214]: DHCP CLIENT (0x1982d1d3): STARTED on ifindex 2
Apr 12 10:20:20 pi2 systemd-networkd[214]: DHCP CLIENT (0x1982d1d3): DISCOVER
Apr 12 10:20:20 pi2 systemd-networkd[214]: Got inotify event on bus n/a.
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run on bus n/a: 2
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 12 10:20:20 pi2 systemd-networkd[214]: Got inotify event on bus n/a.
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run on bus n/a: 2
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 12 10:20:20 pi2 systemd-networkd[214]: Got inotify event on bus n/a.
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run on bus n/a: 2
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 12 10:20:20 pi2 systemd-networkd[214]: Got inotify event on bus n/a.
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run on bus n/a: 2
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 12 10:20:20 pi2 systemd-networkd[214]: Got inotify event on bus n/a.
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run on bus n/a: 2
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 12 10:20:20 pi2 systemd-networkd[214]: Got inotify event on bus n/a.
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run on bus n/a: 2
Apr 12 10:20:20 pi2 systemd-networkd[214]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 15 09:20:21 pi2 systemd-networkd[214]: Got inotify event on bus n/a.
Apr 15 09:20:21 pi2 systemd-networkd[214]: Bus n/a: changing state WATCH_BIND → AUTHENTICATING
Apr 15 09:20:21 pi2 systemd-networkd[214]: eth0: Flags change: -LOWER_UP -RUNNING
Apr 15 09:20:21 pi2 systemd-networkd[214]: eth0: Lost carrier
Apr 15 09:20:21 pi2 systemd-networkd[214]: DHCP CLIENT (0x1982d1d3): STOPPED
Apr 15 09:20:21 pi2 systemd-networkd[214]: eth0: State is configuring, dropping config
Apr 15 09:20:21 pi2 systemd-networkd[214]: eth0: Adding address: fe80::ba27:ebff:fe96:19e3/64 (valid forever)
Apr 15 09:20:21 pi2 systemd-networkd[214]: eth0: Gained IPv6LL
Apr 15 09:20:21 pi2 systemd-networkd[214]: eth0: Discovering IPv6 routers
Apr 15 09:20:21 pi2 systemd-networkd[214]: NDISC: Started IPv6 Router Solicitation client
Apr 15 09:20:21 pi2 systemd-networkd[214]: NDISC: Sent Router Solicitation, next solicitation in 4s
Apr 15 09:20:22 pi2 systemd-networkd[214]: Bus n/a: changing state AUTHENTICATING → HELLO
Apr 15 09:20:22 pi2 systemd-networkd[214]: 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
Apr 15 09:20:22 pi2 systemd-networkd[214]: 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
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.1 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Bus n/a: changing state HELLO → RUNNING
Apr 15 09:20:22 pi2 systemd-networkd[214]: 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
Apr 15 09:20:22 pi2 systemd-networkd[214]: Got message type=signal sender=org.freedesktop.DBus destination=:1.1 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
Apr 15 09:20:22 pi2 systemd-networkd[214]: Got message type=signal sender=org.freedesktop.DBus destination=:1.1 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
Apr 15 09:20:22 pi2 systemd-networkd[214]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.1 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=u error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Successfully acquired requested service name.
Apr 15 09:20:22 pi2 systemd-networkd[214]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.1 path=n/a interface=n/a member=n/a cookie=5 reply_cookie=3 signature=n/a error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Match type='signal',sender='org.freedesktop.login1',path='/org/freedesktop/login1',interface='org.freedesktop.login1.Manager',member='PrepareForSleep' successfully installed.
Apr 15 09:20:22 pi2 systemd-networkd[214]: eth0: Flags change: +LOWER_UP +RUNNING
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: eth0: Gained carrier
Apr 15 09:20:22 pi2 systemd-networkd[214]: eth0: Acquiring DHCPv4 lease
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): STARTED on ifindex 2
Apr 15 09:20:22 pi2 systemd-networkd[214]: eth0: Discovering IPv6 routers
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=14 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=15 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=16 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): DISCOVER
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): OFFER
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): REQUEST (requesting)
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): ACK
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): lease expires in 23h 59min 57s
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): T2 expires in 20h 59min 58s
Apr 15 09:20:22 pi2 systemd-networkd[214]: DHCP CLIENT (0x986d3d32): T1 expires in 11h 59min 59s
Apr 15 09:20:22 pi2 systemd-networkd[214]: eth0: DHCPv4 address 192.168.1.99/24 via 192.168.1.254
Apr 15 09:20:22 pi2 systemd-networkd[214]: eth0: Updating address: 192.168.1.99/24 (valid for 1d)
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=17 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=18 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[214]: eth0: DHCP error: could not get routes: No data available
Apr 15 09:20:25 pi2 systemd-networkd[214]: NDISC: Sent Router Solicitation, next solicitation in 8s
Apr 15 09:20:25 pi2 systemd-networkd[214]: NDISC: Received Router Advertisement: flags OTHER preference low lifetime 300 sec
Apr 15 09:20:25 pi2 systemd-networkd[214]: NDISC: Invoking callback for 'r'.
Apr 15 09:20:25 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Started in Information request mode
Apr 15 09:20:25 pi2 systemd-networkd[214]: eth0: Acquiring DHCPv6 lease on NDisc request
Apr 15 09:20:25 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:20:25 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Next retransmission in 1s
Apr 15 09:20:25 pi2 systemd-networkd[214]: eth0: Configured
Apr 15 09:20:25 pi2 systemd-networkd[214]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=19 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:26 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:20:26 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Next retransmission in 1s
Apr 15 09:20:28 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:20:28 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Next retransmission in 4s
Apr 15 09:20:32 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:20:32 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Next retransmission in 8s
Apr 15 09:20:33 pi2 systemd-networkd[214]: NDISC: No RA received before link confirmation timeout
Apr 15 09:20:33 pi2 systemd-networkd[214]: NDISC: Invoking callback for 't'.
Apr 15 09:20:40 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:20:40 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Next retransmission in 16s
Apr 15 09:20:57 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:20:57 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Next retransmission in 34s
Apr 15 09:21:24 pi2 systemd-networkd[214]: NDISC: Received Router Advertisement: flags OTHER preference low lifetime 300 sec
Apr 15 09:21:24 pi2 systemd-networkd[214]: NDISC: Invoking callback for 'r'.
Apr 15 09:21:24 pi2 systemd-networkd[214]: eth0: Acquiring DHCPv6 lease on NDisc request
Apr 15 09:21:31 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:21:31 pi2 systemd-networkd[214]: DHCPv6 CLIENT: Next retransmission in 1min 8s

Debug log of systemd-timesyncd for OK case (with offending commit patched out):

pi2:~ /usr/bin/journalctl -b -u systemd-timesyncd --no-pager
-- Logs begin at Fri 2018-03-23 06:56:58 AEST, end at Sun 2018-04-15 09:43:32 AEST. --
Apr 13 12:27:09 pi2 systemd[1]: Starting Network Time Synchronization...
Apr 13 12:27:10 pi2 systemd-timesyncd[227]: System clock time unset or jumped backwards, restoring from recorded timestamp: Sun 2018-04-15 09:20:21 AEST
Apr 15 09:20:21 pi2 systemd-timesyncd[227]: Added new server 0.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[227]: Added new server 1.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[227]: Added new server 2.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[227]: Added new server 3.arch.pool.ntp.org.
Apr 15 09:20:21 pi2 systemd-timesyncd[227]: systemd-timesyncd running as pid 227
Apr 15 09:20:21 pi2 systemd[1]: Started Network Time Synchronization.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Network configuration changed, trying to establish connection.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Selected server 0.arch.pool.ntp.org.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Resolving 0.arch.pool.ntp.org...
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Resolved address 129.250.35.251:123 for 0.arch.pool.ntp.org.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Resolved address 27.124.125.252:123 for 0.arch.pool.ntp.org.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Resolved address 121.0.0.42:123 for 0.arch.pool.ntp.org.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Resolved address 116.66.161.5:123 for 0.arch.pool.ntp.org.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Selected address 129.250.35.251:123 of server 0.arch.pool.ntp.org.
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Connecting to time server 129.250.35.251:123 (0.arch.pool.ntp.org).
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: Sent NTP request to 129.250.35.251:123 (0.arch.pool.ntp.org).
Apr 15 09:20:22 pi2 systemd-timesyncd[227]: NTP response:
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   leap         : 0
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   version      : 4
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   mode         : 4
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   stratum      : 2
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   precision    : 0.000000 sec (-24)
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   root distance: 0.135826 sec
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   reference    : n/a
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   origin       : 1523748022.783
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   receive      : 1523749398.537
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   transmit     : 1523749398.537
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   dest         : 1523748022.803
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   offset       : +1375.744 sec
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   delay        : +0.019 sec
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   packet count : 1
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   jitter       : 0.000
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   poll interval: 32
Apr 15 09:20:22 pi2 systemd-timesyncd[227]:   adjust (jump): +1375.744 sec
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   status       : 8192 sync
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   time now     : 1523749398.548
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   constant     : 2
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   offset       : +0.000 sec
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   freq offset  : +0 (0 ppm)
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: interval/delta/delay/jitter/drift 32s/+1375.744s/0.019s/0.000s/+0ppm
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: Synchronized to time server 129.250.35.251:123 (0.arch.pool.ntp.org).
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: Network configuration changed, trying to establish connection.
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: Connecting to time server 129.250.35.251:123 (0.arch.pool.ntp.org).
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: Sent NTP request to 129.250.35.251:123 (0.arch.pool.ntp.org).
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: NTP response:
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   leap         : 0
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   version      : 4
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   mode         : 4
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   stratum      : 2
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   precision    : 0.000000 sec (-24)
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   root distance: 0.135826 sec
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   reference    : n/a
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   origin       : 1523749398.757
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   receive      : 1523749398.766
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   transmit     : 1523749398.766
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   dest         : 1523749398.776
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   offset       : -0.000 sec
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   delay        : +0.019 sec
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   packet count : 2
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   jitter       : 0.000
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   poll interval: 64
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   adjust (slew): -0.000 sec
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   status       : 8193 sync
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   time now     : 1523749398.777
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   constant     : 2
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   offset       : -0.000 sec
Apr 15 09:43:18 pi2 systemd-timesyncd[227]:   freq offset  : +0 (0 ppm)
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: interval/delta/delay/jitter/drift 64s/-0.000s/0.019s/0.000s/+0ppm
Apr 15 09:43:18 pi2 systemd-timesyncd[227]: Synchronized to time server 129.250.35.251:123 (0.arch.pool.ntp.org).

Debug log of systemd-networkd for OK case (with offending commit patched out):

pi2:~ /usr/bin/journalctl -b -u systemd-networkd --no-pager
-- Logs begin at Fri 2018-03-23 06:56:58 AEST, end at Sun 2018-04-15 09:43:48 AEST. --
Apr 13 12:27:09 pi2 systemd[1]: Starting Network Service...
Apr 13 12:27:09 pi2 systemd-networkd[210]: Bus n/a: changing state UNSET → OPENING
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run on bus n/a: 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 13 12:27:09 pi2 systemd-networkd[210]: Bus n/a: changing state OPENING → WATCH_BIND
Apr 13 12:27:09 pi2 systemd-networkd[210]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Apr 13 12:27:09 pi2 systemd-networkd[210]: timestamp of '/etc/systemd/network' changed
Apr 13 12:27:09 pi2 systemd-networkd[210]: timestamp of '/usr/lib/systemd/network' changed
Apr 13 12:27:09 pi2 systemd-networkd[210]: Ignoring /etc/systemd/network/20-wired.network, because it's not a regular file with suffix .netdev.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Ignoring /usr/lib/systemd/network/80-container-host0.network, because it's not a regular file with suffix .netdev.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Ignoring /usr/lib/systemd/network/99-default.link, because it's not a regular file with suffix .netdev.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Ignoring /usr/lib/systemd/network/80-container-vz.network, because it's not a regular file with suffix .netdev.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Ignoring /usr/lib/systemd/network/80-container-ve.network, because it's not a regular file with suffix .netdev.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Ignoring /usr/lib/systemd/network/99-default.link, because it's not a regular file with suffix .network.
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Flags change: +MULTICAST +BROADCAST
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Link 2 added
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: link pending udev initialization...
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Saved original MTU: 1500
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Link 1 added
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: link pending udev initialization...
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Saved original MTU: 0
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Adding address: ::1/128 (valid forever)
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Adding address: 127.0.0.1/8 (valid forever)
Apr 13 12:27:09 pi2 systemd-networkd[210]: rtnl: received address with invalid family 129, ignoring
Apr 13 12:27:09 pi2 systemd-networkd[210]: rtnl: received address with invalid family 128, ignoring
Apr 13 12:27:09 pi2 systemd-networkd[210]: Enumeration completed
Apr 13 12:27:09 pi2 systemd[1]: Started Network Service.
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: udev initialized link
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Link state is up-to-date
Apr 13 12:27:09 pi2 systemd-networkd[210]: No virtualization found in DMI
Apr 13 12:27:09 pi2 systemd-networkd[210]: No virtualization found in CPUID
Apr 13 12:27:09 pi2 systemd-networkd[210]: Virtualization XEN not found, /proc/xen does not exist
Apr 13 12:27:09 pi2 systemd-networkd[210]: No virtualization found in /proc/device-tree/*
Apr 13 12:27:09 pi2 systemd-networkd[210]: UML virtualization not found in /proc/cpuinfo.
Apr 13 12:27:09 pi2 systemd-networkd[210]: This platform does not support /proc/sysinfo
Apr 13 12:27:09 pi2 systemd-networkd[210]: Found VM virtualization none
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Unmanaged
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: udev initialized link
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Link state is up-to-date
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: found matching network '/etc/systemd/network/20-wired.network'
Apr 13 12:27:09 pi2 systemd-networkd[210]: lo: Link is not managed by us
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Bringing link up
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: IPv6 successfully enabled
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Flags change: +UP +LOWER_UP +RUNNING
Apr 13 12:27:09 pi2 systemd-networkd[210]: LLDP: Started LLDP client
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Started LLDP.
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Gained carrier
Apr 13 12:27:09 pi2 systemd-networkd[210]: eth0: Acquiring DHCPv4 lease
Apr 13 12:27:09 pi2 systemd-networkd[210]: DHCP CLIENT (0xfa6c707c): STARTED on ifindex 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: DHCP CLIENT (0xfa6c707c): DISCOVER
Apr 13 12:27:09 pi2 systemd-networkd[210]: Got inotify event on bus n/a.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run on bus n/a: 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 13 12:27:09 pi2 systemd-networkd[210]: Got inotify event on bus n/a.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run on bus n/a: 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 13 12:27:09 pi2 systemd-networkd[210]: Got inotify event on bus n/a.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run on bus n/a: 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 13 12:27:09 pi2 systemd-networkd[210]: Got inotify event on bus n/a.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run on bus n/a: 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 13 12:27:09 pi2 systemd-networkd[210]: Got inotify event on bus n/a.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run on bus n/a: 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 13 12:27:09 pi2 systemd-networkd[210]: Got inotify event on bus n/a.
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run on bus n/a: 2
Apr 13 12:27:09 pi2 systemd-networkd[210]: Added inotify watch for /run/dbus on bus n/a: -1
Apr 15 09:20:21 pi2 systemd-networkd[210]: Got inotify event on bus n/a.
Apr 15 09:20:21 pi2 systemd-networkd[210]: Bus n/a: changing state WATCH_BIND → AUTHENTICATING
Apr 15 09:20:21 pi2 systemd-networkd[210]: eth0: Flags change: -LOWER_UP -RUNNING
Apr 15 09:20:21 pi2 systemd-networkd[210]: eth0: Lost carrier
Apr 15 09:20:21 pi2 systemd-networkd[210]: DHCP CLIENT (0xfa6c707c): STOPPED
Apr 15 09:20:21 pi2 systemd-networkd[210]: eth0: State is configuring, dropping config
Apr 15 09:20:22 pi2 systemd-networkd[210]: Bus n/a: changing state AUTHENTICATING → HELLO
Apr 15 09:20:22 pi2 systemd-networkd[210]: 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
Apr 15 09:20:22 pi2 systemd-networkd[210]: 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
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=3 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=4 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_31 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=5 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=6 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=11 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=12 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.1 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Bus n/a: changing state HELLO → RUNNING
Apr 15 09:20:22 pi2 systemd-networkd[210]: 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
Apr 15 09:20:22 pi2 systemd-networkd[210]: Got message type=signal sender=org.freedesktop.DBus destination=:1.1 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
Apr 15 09:20:22 pi2 systemd-networkd[210]: Got message type=signal sender=org.freedesktop.DBus destination=:1.1 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
Apr 15 09:20:22 pi2 systemd-networkd[210]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.1 path=n/a interface=n/a member=n/a cookie=4 reply_cookie=2 signature=u error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Successfully acquired requested service name.
Apr 15 09:20:22 pi2 systemd-networkd[210]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.1 path=n/a interface=n/a member=n/a cookie=5 reply_cookie=3 signature=n/a error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Match type='signal',sender='org.freedesktop.login1',path='/org/freedesktop/login1',interface='org.freedesktop.login1.Manager',member='PrepareForSleep' successfully installed.
Apr 15 09:20:22 pi2 systemd-networkd[210]: eth0: Flags change: +LOWER_UP +RUNNING
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: eth0: Gained carrier
Apr 15 09:20:22 pi2 systemd-networkd[210]: eth0: Acquiring DHCPv4 lease
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): STARTED on ifindex 2
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=14 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=15 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=16 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): DISCOVER
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): OFFER
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): REQUEST (requesting)
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): ACK
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): lease expires in 23h 59min 58s
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): T2 expires in 20h 59min 57s
Apr 15 09:20:22 pi2 systemd-networkd[210]: DHCP CLIENT (0xc7b59186): T1 expires in 11h 59min 59s
Apr 15 09:20:22 pi2 systemd-networkd[210]: eth0: DHCPv4 address 192.168.1.99/24 via 192.168.1.254
Apr 15 09:20:22 pi2 systemd-networkd[210]: eth0: Updating address: 192.168.1.99/24 (valid for 1d)
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=17 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=18 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:20:22 pi2 systemd-networkd[210]: eth0: DHCP error: could not get routes: No data available
Apr 15 09:43:18 pi2 systemd-networkd[210]: eth0: Adding address: fe80::ba27:ebff:fe96:19e3/64 (valid forever)
Apr 15 09:43:18 pi2 systemd-networkd[210]: eth0: Gained IPv6LL
Apr 15 09:43:18 pi2 systemd-networkd[210]: eth0: Discovering IPv6 routers
Apr 15 09:43:18 pi2 systemd-networkd[210]: NDISC: Started IPv6 Router Solicitation client
Apr 15 09:43:18 pi2 systemd-networkd[210]: NDISC: Sent Router Solicitation, next solicitation in 3s
Apr 15 09:43:18 pi2 systemd-networkd[210]: NDISC: Received Router Advertisement: flags OTHER preference low lifetime 300 sec
Apr 15 09:43:18 pi2 systemd-networkd[210]: NDISC: Invoking callback for 'r'.
Apr 15 09:43:18 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Started in Information request mode
Apr 15 09:43:18 pi2 systemd-networkd[210]: eth0: Acquiring DHCPv6 lease on NDisc request
Apr 15 09:43:18 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:43:18 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Next retransmission in 938ms
Apr 15 09:43:18 pi2 systemd-networkd[210]: eth0: Configured
Apr 15 09:43:18 pi2 systemd-networkd[210]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/network1/link/_32 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=19 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Apr 15 09:43:19 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:43:19 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Next retransmission in 1s
Apr 15 09:43:21 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:43:21 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Next retransmission in 3s
Apr 15 09:43:25 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:43:25 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Next retransmission in 7s
Apr 15 09:43:30 pi2 systemd-networkd[210]: NDISC: No RA received before link confirmation timeout
Apr 15 09:43:30 pi2 systemd-networkd[210]: NDISC: Invoking callback for 't'.
Apr 15 09:43:32 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:43:32 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Next retransmission in 15s
Apr 15 09:43:48 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Sent INFORMATION-REQUEST
Apr 15 09:43:48 pi2 systemd-networkd[210]: DHCPv6 CLIENT: Next retransmission in 29s

@bulletmark
Copy link
Author

Note when I first saw this problem I also tried adding an NTP= line to my .network configuration pointing to a completely different NTP server thinking there was something wrong with the default Arch servers but that didn't make any difference.

@bulletmark
Copy link
Author

Have an old Beaglebone Black lying around which I installed Arch ARM with the offending systemd package and confirmed the same problem exists there. I suspect this problem will occur on any system without a RTC.

@yuwata
Copy link
Member

yuwata commented Apr 16, 2018

Thank you for the information. I do not know whether this is related to RTC or not. But now I am preparing a patch which fixes my previous commit. After submitting it as a PR, please test it. Thank you.

yuwata added a commit to yuwata/systemd that referenced this issue Apr 16, 2018
…ager is not connected yet

This also introduces `manager_is_connected()` helper function, which
returns true when the manager is sending a request, resolving a server
name, or in a poll interval.

Follow-up for 3e85ec0.
Fixes systemd#8719.
@yuwata
Copy link
Member

yuwata commented Apr 16, 2018

I've created #8727. If possible, please test it. Thank you.

Note that a simple reproducer for this is,

  1. disconnect all network cable.
  2. restart timesyncd.
  3. connect at least one network cable.

With the above process, I confirm that the timesyncd does not send any request after the network cable is connected. And with #8727, such an issue is fixed.

@yuwata
Copy link
Member

yuwata commented Apr 16, 2018

Also note that a workaround for this is simply restart timesyncd after network is fully configured.

@yuwata yuwata added the bug 🐛 Programming errors, that need preferential fixing label Apr 16, 2018
@bulletmark
Copy link
Author

Applied that PR #8727 to the timesyncd running on my RPi and it did fix the problem.

@yuwata
Copy link
Member

yuwata commented Apr 16, 2018

Thank you for testing.

poettering pushed a commit that referenced this issue Apr 17, 2018
…ager is not connected yet (#8727)

This also introduces `manager_is_connected()` helper function, which
returns true when the manager is sending a request, resolving a server
name, or in a poll interval.

Follow-up for 3e85ec0.
Fixes #8719.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug 🐛 Programming errors, that need preferential fixing timesync
Development

No branches or pull requests

2 participants