search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.09k stars 4.97k forks source link

systemd-timesyncd: Address family not supported by protocol #2987

Open brubbel opened 5 years ago

brubbel commented 5 years ago

Prerequisites: ipv6.disable=1 is set in /boot/cmdline.txt

Issue: As of lately, systemd-timesyncd sometimes gets stuck trying to connect to an ipv6 NTP server, while ipv6 is disabled at boot.

● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /lib/systemd/system/systemd-timesyncd.service.d
           └─disable-with-time-daemon.conf
   Active: active (running) since Thu 2019-04-11 16:24:00 BST; 1 months 8 days ago
     Docs: man:systemd-timesyncd.service(8)
 Main PID: 260 (systemd-timesyn)
   Status: "Connecting to time server [2a03:b0c0:0:1010::3:4001]:123 (2.debian.pool.ntp.org)."
      CPU: 7.937s
   CGroup: /system.slice/systemd-timesyncd.service
           └─260 /lib/systemd/systemd-timesyncd

syslog: systemd-timesyncd[260]: Failed to setup connection socket: Address family not supported by protocol

Restarting the systemd service solves the issue, but I've never experienced this in the last years, while it regularly pops up since a few weeks.

I'll update this report when I can pinpoint some more data or find a way to reproduce this.

brubbel commented 5 years ago

More info: the connection to ipv6 is suddenly initiated after a few days, even with ipv6.disable=1 set. The systemd-timesyncd service does not recover after that.

journalctl:

May 12 13:07:03  systemd[1]: Starting Network Time Synchronization...
May 12 13:07:04  systemd[1]: Started Network Time Synchronization.
May 12 13:07:42  systemd-timesyncd[277]: Synchronized to time server 193.190.147.153:123 (2.debian.pool.ntp.org).
May 15 09:31:28  systemd-timesyncd[277]: Timed out waiting for reply from 193.190.147.153:123 (2.debian.pool.ntp.org).
May 15 09:31:28  systemd-timesyncd[277]: Synchronized to time server 194.78.244.172:123 (2.debian.pool.ntp.org).
May 18 16:06:45  systemd-timesyncd[277]: Failed to setup connection socket: Address family not supported by protocol

https://github.com/systemd/systemd/blob/2fc1afca5917b9ef4fe293fe6fd75615ca364a5d/src/timesync/timesyncd-manager.c#L878 It seems that, even when ipv6 is disabled, 2.debian.pool.ntp.org (supporting both ipv4 and ipv6) sometimes resolves to an AAAA record (dig 2.debian.pool.ntp.org AAAA). Then, for some reason, a connection to this address does not timeout as it should. Possibly this results in systemd-timesyncd waiting forever and failing to switch to the next address.

Maybe it is appropriate to transfer this issue to https://github.com/systemd/systemd/issues ?

brubbel commented 5 years ago

I could not find a reliable way to reproduce the 2.debian.pool.ntp.org -> AAAA record. However, one can verify that systemd-timesyncd does not rotate between servers by manually adding the ipv6 address to /etc/systemd/timesyncd.conf:

[Time]
NTP=2001:470:1f15:1360::123 0.debian.pool.ntp.org

then sudo systemctl restart systemd-timesyncd and one can verify that timesyncd does not switch to the next address.

If ipv6 support is enabled in the kernel, timesyncd immediately switches to 0.debian.pool.ntp.org, which is the expected behaviour.

LaRodraga commented 3 years ago

Hey there, I'm using Debian Bullseye

As brubbel mentioned, I have the IPv6 disabled but the timesyncd still tries to resolve IPv6 address which makes the desktop GUI wait until this situation is solved to initialize. So screen is frozen in the login until the synchronization is made. (logs taken from /var/log/syslog)

Oct 28 15:47:41 systemd-timesyncd[690]: Timed out waiting for reply from [2001:720:1014:a202::2]:123 (2.debian.pool.ntp.org). Oct 28 15:47:51 systemd-timesyncd[690]: Timed out waiting for reply from [2001:720:1014:a201::2]:123 (2.debian.pool.ntp.org). Oct 28 15:48:01 systemd-timesyncd[690]: Timed out waiting for reply from [2606:4700:f1::1]:123 (2.debian.pool.ntp.org). Oct 28 15:48:12 systemd-timesyncd[690]: Timed out waiting for reply from [2606:4700:f1::123]:123 (2.debian.pool.ntp.org). Oct 28 15:48:11 systemd-timesyncd[690]: Initial synchronization to time server 5.56.160.3:123 (2.debian.pool.ntp.org).

jobenvil commented 3 years ago

Having same issue with worst results. My both systems where I disabled IPv6 via /boot/cmdline.txt are getting isolated after a cascade of events clearly trackable in the syslog events:

5695 Sep 15 11:32:09 "myhostname" systemd[1]: Reloading.
 5696 Sep 15 11:32:10 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5697 Sep 15 11:32:10 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5698 Sep 15 11:32:11 "myhostname" systemd[1]: Stopping LSB: automatic crash report generation...
 5699 Sep 15 11:32:11 "myhostname" apport[30941]:  * Stopping automatic crash report generation: apport
 5700 Sep 15 11:32:11 "myhostname" apport[30941]:    ...done.
 5701 Sep 15 11:32:11 "myhostname" systemd[1]: apport.service: Succeeded.
 5702 Sep 15 11:32:11 "myhostname" systemd[1]: Stopped LSB: automatic crash report generation.
 5703 Sep 15 11:32:11 "myhostname" systemd[1]: Reloading.
 5704 Sep 15 11:32:12 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5705 Sep 15 11:32:12 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5706 Sep 15 11:32:14 "myhostname" systemd[1]: Reloading.
 5707 Sep 15 11:32:15 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5708 Sep 15 11:32:15 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5709 Sep 15 11:32:16 "myhostname" systemd[1]: Condition check resulted in Process error reports when automatic reporting is enabled (file watch) being skipped.
 5710 Sep 15 11:32:16 "myhostname" systemd[1]: Condition check resulted in Unix socket for apport crash forwarding being skipped.
 5711 Sep 15 11:32:16 "myhostname" systemd[1]: Reloading.
 5712 Sep 15 11:32:17 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5713 Sep 15 11:32:17 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5714 Sep 15 11:32:18 "myhostname" systemd[1]: Reloading.
 5715 Sep 15 11:32:19 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5716 Sep 15 11:32:19 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5717 Sep 15 11:32:20 "myhostname" systemd[1]: Starting LSB: automatic crash report generation...
 5718 Sep 15 11:32:20 "myhostname" apport[31130]:  * Starting automatic crash report generation: apport
 5719 Sep 15 11:32:20 "myhostname" apport[31130]:    ...done.
 5720 Sep 15 11:32:20 "myhostname" systemd[1]: Started LSB: automatic crash report generation.
 5721 Sep 15 11:32:20 "myhostname" systemd[1]: Reloading.
 5722 Sep 15 11:32:20 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5723 Sep 15 11:32:20 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5724 Sep 15 11:32:22 "myhostname" watchdog[3020]: device eth0 received 1567273101 bytes
 5725 Sep 15 11:32:22 "myhostname" watchdog[3020]: got answer on ping=1 from target 192.168.178.50  time=0.024ms
 5726 Sep 15 11:32:23 "myhostname" watchdog[3020]: still alive after 1775520 interval(s)
 5727 Sep 15 11:32:26 "myhostname" dbus-daemon[588]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by       ':1.178729' (uid=0 pid=31523 comm="/usr/bin/gdbus call --system --dest org.freedeskto")
 5728 Sep 15 11:32:26 "myhostname" systemd[1]: Starting PackageKit Daemon...
 5729 Sep 15 11:32:26 "myhostname" PackageKit: daemon start
 5730 Sep 15 11:32:26 "myhostname" dbus-daemon[588]: [system] Successfully activated service 'org.freedesktop.PackageKit'
 5731 Sep 15 11:32:26 "myhostname" systemd[1]: Started PackageKit Daemon.
 5732 Sep 15 11:32:52 "myhostname" watchdog[3020]: device eth0 received 1585711681 bytes
 5733 Sep 15 11:32:52 "myhostname" watchdog[3020]: got answer on ping=1 from target 192.168.178.50  time=0.020ms
 5734 Sep 15 11:32:53 "myhostname" watchdog[3020]: still alive after 1775550 interval(s)
 5735 Sep 15 11:33:00 "myhostname" dbus-daemon[588]: [system] Reloaded configuration
 5736 Sep 15 11:33:00 "myhostname" systemd[1]: Reloading.
 5737 Sep 15 11:33:01 "myhostname" CRON[31874]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
 5738 Sep 15 11:33:01 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5739 Sep 15 11:33:01 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5740 Sep 15 11:33:02 "myhostname" dbus-daemon[588]: [system] Reloaded configuration
 5741 Sep 15 11:33:04 "myhostname" dbus-daemon[588]: message repeated 9 times: [ [system] Reloaded configuration]
 5742 Sep 15 11:33:06 "myhostname" systemd[1]: Reexecuting.
 5743 Sep 15 11:33:06 "myhostname" kernel: [1783921.277887] systemd[1]: systemd 245.4-4ubuntu3.13 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +      SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
 5744 Sep 15 11:33:06 "myhostname" kernel: [1783921.278368] systemd[1]: Detected architecture arm.
 5745 Sep 15 11:33:06 "myhostname" kernel: [1783921.605983] systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5746 Sep 15 11:33:06 "myhostname" kernel: [1783921.606026] systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5747 Sep 15 11:33:07 "myhostname" systemd[1]: Condition check resulted in OpenVSwitch configuration for cleanup being skipped.
 5748 Sep 15 11:33:07 "myhostname" systemd[1]: systemd-networkd-wait-online.service: Succeeded.
 5749 Sep 15 11:33:07 "myhostname" systemd[1]: Stopped Wait for Network to be Configured.
 5750 Sep 15 11:33:07 "myhostname" systemd[1]: Stopping Wait for Network to be Configured...
 5751 Sep 15 11:33:07 "myhostname" systemd[1]: Stopping Network Service...
 5752 Sep 15 11:33:07 "myhostname" systemd-timesyncd[571]: Network configuration changed, trying to establish connection.
 5753 Sep 15 11:33:07 "myhostname" systemd-timesyncd[571]: Failed to set up connection socket: Address family not supported by protocol
 5754 Sep 15 11:33:07 "myhostname" systemd[1]: systemd-networkd.service: Succeeded.
 5755 Sep 15 11:33:07 "myhostname" systemd[1]: Stopped Network Service.
 5755 Sep 15 11:33:07 "myhostname" systemd[1]: Stopped Network Service.
 5756 Sep 15 11:33:07 "myhostname" systemd[1]: Starting Network Service...
 5757 Sep 15 11:33:08 "myhostname" systemd-networkd[32089]: Enumeration completed
 5758 Sep 15 11:33:08 "myhostname" systemd[1]: Started Network Service.
 5759 Sep 15 11:33:08 "myhostname" systemd[1]: Starting Wait for Network to be Configured...
 5760 Sep 15 11:33:08 "myhostname" systemd[1]: Stopping Network Name Resolution...
 5761 Sep 15 11:33:08 "myhostname" dhcpcd[669]: eth0: deleted route to 192.168.178.0/24
 5762 Sep 15 11:33:08 "myhostname" dhcpcd[669]: eth0: deleted default route via 192.168.178.1
 5763 Sep 15 11:33:08 "myhostname" systemd-networkd[32089]: eth0: Could not set route: Nexthop has invalid gateway. Network is unreachable
 5764 Sep 15 11:33:08 "myhostname" systemd-networkd[32089]: eth0: Failed
 5765 Sep 15 11:33:08 "myhostname" systemd-networkd-wait-online[32093]: managing: eth0
 5766 Sep 15 11:33:08 "myhostname" systemd[1]: systemd-resolved.service: Succeeded.
 5767 Sep 15 11:33:08 "myhostname" systemd[1]: Stopped Network Name Resolution.
 5768 Sep 15 11:33:08 "myhostname" systemd[1]: Finished Wait for Network to be Configured.
 5769 Sep 15 11:33:08 "myhostname" systemd[1]: Starting Network Name Resolution...
 5770 Sep 15 11:33:08 "myhostname" systemd-resolved[32096]: Positive Trust Anchors:
 5771 Sep 15 11:33:08 "myhostname" systemd-resolved[32096]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
 5772 Sep 15 11:33:08 "myhostname" systemd-resolved[32096]: Negative trust anchors: 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.      in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172      .in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa corp home internal intranet lan       local private test
 5773 Sep 15 11:33:08 "myhostname" systemd-resolved[32096]: Using system hostname '"myhostname"'.
 5774 Sep 15 11:33:08 "myhostname" systemd[1]: Started Network Name Resolution.
 5775 Sep 15 11:33:08 "myhostname" systemd[1]: Stopping Flush Journal to Persistent Storage...
 5776 Sep 15 11:33:08 "myhostname" systemd[1]: systemd-journal-flush.service: Succeeded.
 5777 Sep 15 11:33:08 "myhostname" systemd[1]: Stopped Flush Journal to Persistent Storage.
 5778 Sep 15 11:33:08 "myhostname" kernel: [1783923.324769] systemd-journald[338]: Received SIGTERM from PID 1 (systemd).
 5779 Sep 15 11:33:08 "myhostname" kernel: [1783923.325335] systemd[1]: Stopping Journal Service...
 5780 Sep 15 11:33:08 "myhostname" kernel: [1783923.355325] systemd[1]: systemd-journald.service: Succeeded.
 5781 Sep 15 11:33:08 "myhostname" kernel: [1783923.357146] systemd[1]: Stopped Journal Service.
 5782 Sep 15 11:33:08 "myhostname" kernel: [1783923.364444] systemd[1]: Starting Journal Service...
 5783 Sep 15 11:33:08 "myhostname" kernel: [1783923.480703] systemd[1]: Started Journal Service.
 5784 Sep 15 11:33:08 "myhostname" systemd[1]: Starting Flush Journal to Persistent Storage...
 5785 Sep 15 11:33:08 "myhostname" kernel: [1783923.519688] systemd-journald[32099]: Received client request to flush runtime journal.
 5786 Sep 15 11:33:08 "myhostname" systemd[1]: Finished Flush Journal to Persistent Storage.
 5787 Sep 15 11:33:09 "myhostname" systemd[1]: Reloading.
 5788 Sep 15 11:33:09 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5789 Sep 15 11:33:09 "myhostname" systemd[1]: Binding to IPv6 address not available since kernel does not support IPv6.
 5790 Sep 15 11:33:11 "myhostname" systemd[1]: Stopping Network Time Synchronization...
 5791 Sep 15 11:33:11 "myhostname" systemd[1]: systemd-timesyncd.service: Succeeded.
 5792 Sep 15 11:33:11 "myhostname" systemd[1]: Stopped Network Time Synchronization.
 5793 Sep 15 11:33:11 "myhostname" systemd[1]: Starting Network Time Synchronization...
 5794 Sep 15 11:33:11 "myhostname" systemd[1]: Started Network Time Synchronization.
 Sep 15 11:33:11 "myhostname" cloudflared[28977]: 2021-09-15T09:33:11Z ERR failed to connect to an HTTPS backend "https://1.1.1.1/dns-query" error="failed to perf      orm an HTTPS request: Post \"https://1.1.1.1/dns-query\": dial tcp 1.1.1.1:443: connect: network is unreachable"
 5796 Sep 15 11:33:11 "myhostname" cloudflared[28977]: 2021-09-15T09:33:11Z ERR failed to connect to an HTTPS backend "https://1.0.0.1/dns-query" error="failed to perf      orm an HTTPS request: Post \"https://1.0.0.1/dns-query\": dial tcp 1.0.0.1:443: connect: network is unreachable"
 5797 Sep 15 11:33:11 "myhostname" cloudflared[28977]: 2021-09-15T09:33:11Z ERR failed to connect to an HTTPS backend "https://1.1.1.1/dns-query" error="failed to perf      orm an HTTPS request: Post \"https://1.1.1.1/dns-query\": dial tcp 1.1.1.1:443: connect: network is unreachable"
 5798 Sep 15 11:33:11 "myhostname" cloudflared[28977]: 2021-09-15T09:33:11Z ERR failed to connect to an HTTPS backend "https://1.0.0.1/dns-query" error="failed to perf      orm an HTTPS request: Post \"https://1.0.0.1/dns-query\": dial tcp 1.0.0.1:443: connect: network is unreachable"
 5799 Sep 15 11:33:11 "myhostname" cloudflared[28977]: 2021-09-15T09:33:11Z ERR failed to connect to an HTTPS backend "https://1.1.1.1/dns-query" error="failed to perf      orm an HTTPS request: Post \"https://1.1.1.1/dns-query\": dial tcp 1.1.1.1:443: connect: network is unreachable"
 5800 Sep 15 11:33:11 "myhostname" cloudflared[28977]: 2021-09-15T09:33:11Z ERR failed to connect to an HTTPS backend "https://1.0.0.1/dns-query" error="failed to perf      orm an HTTPS request: Post \"https://1.0.0.1/dns-query\": dial tcp 1.0.0.1:443: connect: network is unreachable"

that's an ugly end. From 5 system, in two of them in which I have disabled IPv6, its happening the same:

Ubuntu 20.04.3 LTS - "focal" (GNU/Linux 5.4.142-228 armv7l)

pelwell commented 3 years ago

Try disabling IPv6 a different way:

  1. $ sudo nano /etc/sysctl.conf
  2. Add the following lines at the end of the file: 
    net.ipv6.conf.all.disable_ipv6=1
net.ipv6.conf.default.disable_ipv6=1
net.ipv6.conf.lo.disable_ipv6=1
  3. Save and reboot.
skymal4ik commented 2 years ago

Could be great to have option for timesyncd to disable ipv6, e.g.: vim /etc/systemd/timesyncd.conf

[Time]
DisableIPv6 = true
3cl1ps commented 2 years ago

hey, any update on this ? what's the correct way to resolve this ?

3cl1ps commented 2 years ago

ended up using chrony -4 https://serverfault.com/questions/992844/chronyd-on-debian-could-not-open-ipv6-ntp-socket

popy2k14 commented 2 years ago

same issue here. also with newest system updates until today on an pi4. Did you guys found an reliable, non third party, workaround for this?

@pelwell does your workaround actually work? Asking because reproducing this in an short period of time is not so easy.

thx

popy2k14 commented 2 years ago

guys, maybe found a solution here: https://wiki.archlinux.org/title/IPv6 Look at "10.2.6 systemd-timesyncd". You have to configure /etc/systemd/timesyncd.conf and remove the "2." pool servers, because just this are using ipv6. Example to remove:

2.arch.pool.ntp.org
2.debian.pool.ntp.org
2.pool.ntp.org
2. ....

So i had not configured any NTP servers and now changed the file to:

#  This file is part of systemd.
#
#  systemd is free software; you can redistribute it and/or modify it
#  under the terms of the GNU Lesser General Public License as published by
#  the Free Software Foundation; either version 2.1 of the License, or
#  (at your option) any later version.
#
# Entries in this file show the compile time defaults.
# You can change settings by editing this file.
# Defaults can be restored by simply deleting this file.
#
# See timesyncd.conf(5) for details.

[Time]
NTP=0.debian.pool.ntp.org 1.debian.pool.ntp.org 3.debian.pool.ntp.org
#FallbackNTP=0.debian.pool.ntp.org 1.debian.pool.ntp.org 2.debian.pool.ntp.org 3.debian.pool.ntp.org
#RootDistanceMaxSec=5
#PollIntervalMinSec=32
#PollIntervalMaxSec=2048

Hope this helps.

pelwell commented 2 years ago

The instructions I gave do disable IPv6 - ifconfig won't show any inet6 information. I don't know if disabling IPv6 is enough to solve the problem.

popy2k14 commented 2 years ago

ok, thx. have done my change from above in file /etc/systemd/timesyncd.conf will see how it goes and come back here if it fixes the issue.

popy2k14 commented 2 years ago

The solution above works!