[SOLVED] ntpd randomly fails when started at boot

xdegaye · 2024-02-16 15:52:27

ntpd fails to synchronize with the servers randomly and most of the time when started at boot. The following command prints the same result during the ntpd session (not sure if 'remote' is always the same across boots):

$ ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 64:ff9b::3326:7 .INIT.          16 u    -   64    0    0.000   +0.000   0.000
 64:ff9b::5c4:87 .INIT.          16 u    -   64    0    0.000   +0.000   0.000
 time.cloudflare .INIT.          16 u    -   64    0    0.000   +0.000   0.000
 64:ff9b::d9b6:8 .INIT.          16 u    -   64    0    0.000   +0.000   0.000

Internet access:
netctl-auto starts a wireless link to internet with an Android smartphone through hotspot tethering and a weak 4G data connection (smartphone signal strength -110 to -115 dBm - mostly two bars).

If the wifi/hotspot is disabled at boot time and enabled after the boot, then ntpd fails also to synchronize with the servers randomly. It is almost as if the 'wlan0' interface has been blacklisted by ntpd at boot, however upon wake up from sleep ntpd does emit a syslog entry such as 'Listen normally on 7 wlan0 192.168.254.117:123' so it is still scanning that interface.

The synchronization becomes always successful after restarting the ntpd service with systemctl after boot.

When ntpd fails to synchronize, the ntpdate NTP client does succeed as shown by the command: 'ntpdate -d 0.fr.pool.ntp.org'.

Work around

- Disable the systemd ntpd service.
- Add the following two lines to the netctl wireless profile:

    ExecUpPost='systemctl start ntpd || true'
    ExecDownPre='systemctl stop ntpd || true'

Last edited by xdegaye (2024-02-22 10:06:27)

ectospasm · 2024-02-17 00:11:25

Do you have a specific reason why you're not using systemd-timesyncd, and you're using the full ntpd? It may be that systemd-timesyncd is also running, and the two services are conflicting.

systemd-timesyncd is enabled by default in Arch (preset: enabled), so if you haven't explicitly disabled it that may be what's going on.

xdegaye · 2024-02-17 08:15:33

There is no conflict:

# systemctl status systemd-timesyncd
systemd-timesyncd.service - Network Time Synchronization
Loaded: loaded (/usr/lib/systemd/system/systemd-timesyncd.service; disabled; preset: enabled)
Active: inactive (dead)

I remember disabling this service because I adhere to the unix philosophy that there is one program for each task (which is the reverse of what systemd was doing at that time) and because ntpd had worked for me for years.

Thanks for your help.

seth · 2024-02-17 09:47:46

Just to be sure, you've https://wiki.archlinux.org/title/Networ … face_names so there's no chance that ntp listens on wlan0 and that then gets renamed to wlpwhatever?

For more clarification

starts a wireless link to internet with an Android smartphone through hotspot tethering … If the wifi/hotspot is disabled at boot time and enabled after the boot

a) you're using the phone as an AP, there's no usb cable involved to use it as external ethernet provider?
b) "systemctl show ntpd | grep netw" shows that it's supposed to start after the network.target, what provides that when the hotspot is disabled? And by disabled hotspot you mean that you cannot use the AP, it does *not* mean that the network stops at the AP because there's no internet connection in the phone?

Do you configure an updateinterval in ntpd?
It might help to depend ntpd on the network-online.target

ectospasm · 2024-02-17 15:19:05

xdegaye wrote:

There is no conflict:
# systemctl status systemd-timesyncd
systemd-timesyncd.service - Network Time Synchronization
Loaded: loaded (/usr/lib/systemd/system/systemd-timesyncd.service; disabled; preset: enabled)
Active: inactive (dead)
I remember disabling this service because I adhere to the unix philosophy that there is one program for each task (which is the reverse of what systemd was doing at that time) and because ntpd had worked for me for years.
Thanks for your help.

It doesn't look like systemd-timesyncd is enabled by default, despite what the preset says. I think that's a bug, so I filed an issue on GitLab regarding it.

But yeah, if you manually disabled systemd-timesyncd it shouldn't be conflicting. My guess you didn't actually do that, since it appears to be disabled by default (again, despite the preset). It seems on my older Arch systems I had enabled it manually, but that was over two years ago so I had forgotten.

xdegaye · 2024-02-18 11:09:59

> Just to be sure, you've https://wiki.archlinux.org/title/Networ … face_names so there's no chance that ntp listens on wlan0 and that then gets renamed to wlpwhatever?

I did not revert to traditional interface names. But for some reason the wlan interface is not renamed to wlpwhatever.

Today ntpd is working fine (without the workaround), the 'ip link' command prints the wlan0 interface and the boot logs say:

$ journalctl -b | grep ntpd
Feb 18 11:22:13 lillehammer ntpd[503]: ntpd 4.2.8p17@1.4004-o Tue Jun 6 14:05:47 UTC 2023 (1): Starting
Feb 18 11:22:13 lillehammer ntpd[503]: Command line: /usr/bin/ntpd -g -u ntp:ntp
Feb 18 11:22:13 lillehammer ntpd[503]: ----------------------------------------------------
Feb 18 11:22:13 lillehammer ntpd[503]: ntp-4 is maintained by Network Time Foundation,
Feb 18 11:22:13 lillehammer ntpd[503]: Inc. (NTF), a non-profit 501(c)(3) public-benefit
Feb 18 11:22:13 lillehammer ntpd[503]: corporation. Support and training for ntp-4 are
Feb 18 11:22:13 lillehammer ntpd[503]: available at https://www.nwtime.org/support
Feb 18 11:22:13 lillehammer ntpd[503]: ----------------------------------------------------
Feb 18 11:22:13 lillehammer ntpd[503]: DEBUG behavior is enabled - a violation of any
Feb 18 11:22:13 lillehammer ntpd[503]: diagnostic assertion will cause ntpd to abort
Feb 18 11:22:13 lillehammer ntpd[509]: proto: precision = 0.045 usec (-24)
Feb 18 11:22:13 lillehammer ntpd[509]: basedate set to 2023-05-25
Feb 18 11:22:13 lillehammer ntpd[509]: gps base set to 2023-05-28 (week 2264)
Feb 18 11:22:13 lillehammer ntpd[509]: initial drift restored to -11.594000
Feb 18 11:22:13 lillehammer ntpd[509]: Listen and drop on 0 v6wildcard [::]:123
Feb 18 11:22:13 lillehammer ntpd[509]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Feb 18 11:22:13 lillehammer ntpd[509]: Listen normally on 2 lo 127.0.0.1:123
Feb 18 11:22:13 lillehammer ntpd[509]: Listen normally on 3 lo [::1]:123
Feb 18 11:22:13 lillehammer ntpd[509]: Listening on routing socket on fd #20 for interface updates
Feb 18 11:22:13 lillehammer ntpd[509]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Feb 18 11:22:13 lillehammer ntpd[509]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Feb 18 11:22:22 lillehammer ntpd[509]: Listen normally on 4 wlan0 192.168.128.117:123
Feb 18 11:22:22 lillehammer ntpd[509]: Listen normally on 5 wlan0 [fe80::de41:a9ff:fe21:5539%3]:123
Feb 18 11:22:22 lillehammer ntpd[509]: new interface(s) found: waking up resolver
Feb 18 11:22:26 lillehammer ntpd[509]: Listen normally on 6 wlan0 192.168.254.117:123
Feb 18 11:22:26 lillehammer ntpd[509]: new interface(s) found: waking up resolver

The first wlan0 address, 192.168.128.117 has a 32 bits netmask.
I will boot until I get ntpd failing again and check the name of the wlan interface at boot.

> a) you're using the phone as an AP, there's no usb cable involved to use it as external ethernet provider?

No usb cable involved, I stopped using usb tethering and switched to wifi/hotspot about 4 months ago.

> b) "systemctl show ntpd | grep netw" shows that it's supposed to start after the network.target, what provides that when the hotspot is disabled?

Not sure if I understand the question. Here is part of the boot log when the hotspot is disabled:

Feb 18 11:53:54 lillehammer systemd[1]: Finished Save/Restore Sound Card State.
Feb 18 11:53:54 lillehammer systemd[1]: Reached target Sound Card.
Feb 18 11:53:55 lillehammer systemd[1]: Started A basic static ethernet connection.
Feb 18 11:53:55 lillehammer systemd[1]: Reached target Network.
Feb 18 11:53:55 lillehammer systemd[1]: Reached target Network is Online.
Feb 18 11:53:55 lillehammer systemd[1]: Starting Network Time Service...
Feb 18 11:53:55 lillehammer systemd[1]: Started proxy name server.
Feb 18 11:53:55 lillehammer systemd[1]: Starting Shorewall IPv4 firewall...
Feb 18 11:53:55 lillehammer systemd[1]: Started OpenSSH Daemon.
Feb 18 11:53:55 lillehammer systemd[1]: Starting Permit User Sessions...
Feb 18 11:53:55 lillehammer ntpd[407]: ntpd 4.2.8p17@1.4004-o Tue Jun 6 14:05:47 UTC 2023 (1): Starting
Feb 18 11:53:55 lillehammer ntpd[407]: Command line: /usr/bin/ntpd -g -u ntp:ntp
Feb 18 11:53:55 lillehammer ntpd[407]: ----------------------------------------------------
Feb 18 11:53:55 lillehammer ntpd[407]: ntp-4 is maintained by Network Time Foundation,
Feb 18 11:53:55 lillehammer ntpd[407]: Inc. (NTF), a non-profit 501(c)(3) public-benefit
Feb 18 11:53:55 lillehammer ntpd[407]: corporation. Support and training for ntp-4 are
Feb 18 11:53:55 lillehammer ntpd[407]: available at https://www.nwtime.org/support
Feb 18 11:53:55 lillehammer ntpd[407]: ----------------------------------------------------
Feb 18 11:53:55 lillehammer ntpd[407]: DEBUG behavior is enabled - a violation of any
Feb 18 11:53:55 lillehammer ntpd[407]: diagnostic assertion will cause ntpd to abort
Feb 18 11:53:55 lillehammer (horewall)[411]: shorewall.service: Referenced but unset environment variable evaluates to an empty string: OPTIONS, STA>
Feb 18 11:53:55 lillehammer network[377]: Started network profile 'eth-static'
Feb 18 11:53:55 lillehammer ntpd[415]: proto: precision = 0.045 usec (-24)
Feb 18 11:53:55 lillehammer ntpd[415]: basedate set to 2023-05-25
Feb 18 11:53:55 lillehammer ntpd[415]: gps base set to 2023-05-28 (week 2264)
Feb 18 11:53:55 lillehammer ntpd[415]: initial drift restored to -11.594000
Feb 18 11:53:55 lillehammer ntpd[415]: Listen and drop on 0 v6wildcard [::]:123
Feb 18 11:53:55 lillehammer ntpd[415]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Feb 18 11:53:55 lillehammer ntpd[415]: Listen normally on 2 lo 127.0.0.1:123
Feb 18 11:53:55 lillehammer ntpd[415]: Listen normally on 3 lo [::1]:123
Feb 18 11:53:55 lillehammer ntpd[415]: Listening on routing socket on fd #20 for interface updates
Feb 18 11:53:55 lillehammer ntpd[415]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Feb 18 11:53:55 lillehammer ntpd[415]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Feb 18 11:53:55 lillehammer sshd[413]: Server listening on 0.0.0.0 port 22.
Feb 18 11:53:55 lillehammer sshd[413]: Server listening on :: port 22.

> And by disabled hotspot you mean that you cannot use the AP, it does *not* mean that the network stops at the AP because there's no internet connection in the phone?

I mean that the hotspot is disabled on the smartphone, the phone is still connected to the 4G network.

> Do you configure an updateinterval in ntpd?

No.

> It might help to depend ntpd on the network-online.target

I will do that when ntpd starts failing again on boot.

seth · 2024-02-18 13:04:46

Please use [code][/code] tags, not "quote" tags.

I did not revert to traditional interface names. But for some reason the wlan interface is not renamed to wlpwhatever.

iwd implicitly blocks the renaming, if you don't have installed that you might want to explicitly prevent the rename.

I will boot until I get ntpd failing again and check the name of the wlan interface at boot.

You can look up older journals, eg. "sudo journalctl -b -1" for the previous boot.

> Do you configure an updateinterval in ntpd?
No.

You maybe should…

Not sure if I understand the question. Here is part of the boot log when the hotspot is disabled:
…
the hotspot is disabled on the smartphone, the phone is still connected to the 4G network

Feb 18 11:53:55 lillehammer systemd[1]: Started A basic static ethernet connection.
Feb 18 11:53:55 lillehammer systemd[1]: Reached target Network.
Feb 18 11:53:55 lillehammer systemd[1]: Reached target Network is Online.
…
Feb 18 11:53:55 lillehammer network[377]: Started network profile 'eth-static'
…
Feb 18 11:53:55 lillehammer ntpd[415]: Listen normally on 2 lo 127.0.0.1:123
Feb 18 11:53:55 lillehammer ntpd[415]: Listen normally on 3 lo [::1]:123

ntpd is listening on the lo device only - what's eth-static?
You could force ntp.conf to ignore the lo or force it to use wlan0, https://man.archlinux.org/man/extra/ntp … #interface

Lone_Wolf · 2024-02-18 15:41:31

The default minmum interval for polling servers is 64 sec, while the max interval is 1204 seconds (approx 11 minutes ) .

man ntp.conf indicates this can be changed by setting minpoll / maxpoll .
Those variables use a power of 2, you could try minpoll 4 (16 sec) and maxpoll 6 (64 sec) .

xdegaye · 2024-02-18 15:50:40

iwd implicitly blocks the renaming, if you don't have installed that you might want to explicitly prevent the rename.

iwd is installed but it is disabled.

You can look up older journals, eg. "sudo journalctl -b -1" for the previous boot.

ntpd listens to the wlan0 interface in the 20 previous boot logs.

ntpd is listening on the lo device only - what's eth-static?

A netctl profile to setup a static IP address on the ethernet interface. The interface is down.

You could force ntp.conf to ignore the lo or force it to use wlan0

I had already done that.

seth · 2024-02-18 16:07:55

iwd is installed but it is disabled.

That'll disable the rename.

A netctl profile to setup a static IP address on the ethernet interface. The interface is down.

Why is it starting? Why do you reach the network-online.target if there's no active network (hotspot down, ethernet down)?

I had already done that.

Why does ntpd listen on the loopback interface still?
What does your ntp.conf look like?

xdegaye · 2024-02-18 16:11:26

you could try minpoll 4 (16 sec) and maxpoll 6 (64 sec) .

I will try this when ntpd starts failing again.

Upon starting to look into this problem I waited about 17 minutes (1024 secs) before deciding that ntpd was failing. Then I added 'iburst' to the server directives in /etc/ntpconf and changed n.0.arch.pool.ntp.org to 0.fr.pool.ntp.org in order to use servers that are closer. Then ntpd would synchronize within a minute in the following boots (as it does today unfortunately). But the next day ntpd failed in all the boots while ntpdate succeeded.

xdegaye · 2024-02-18 18:45:59

That'll disable the rename.

Thanks !
It is indeed documented in the archwiki.

Why is it starting?

Because the eth-static netctl profile is enabled.

Why do you reach the network-online.target if there's no active network (hotspot down, ethernet down)?

After disabling the eth-static netctl profile and rebooting with the hotspot down:

$ journalctl -b | grep 'Reached target Net'
Feb 18 19:01:52 lillehammer systemd[1]: Reached target Network is Online.
Feb 18 19:01:54 lillehammer systemd[1]: Reached target Network.

The Network Online target is reached right at the start of systemd. It is the 15th systemd log entry.
And ntpd is started before the Network target at Feb 18 19:01:53, although it should be after.

Why does ntpd listen on the loopback interface still?

I removed those directives as nothing changed. And I may be wrong but it seems that the 'interface' directive is rather a security feature for use with ntpd as a server, to protect against DDOS.

What does your ntp.conf look like?

# Associate to Arch's NTP pool
server 0.fr.pool.ntp.org iburst
server 1.fr.pool.ntp.org iburst
server 2.fr.pool.ntp.org iburst
server 3.fr.pool.ntp.org iburst

# By default, the server allows:
# - all queries from the local host
# - only time queries from remote hosts, protected by rate limiting and kod
restrict default kod limited nomodify nopeer noquery notrap
restrict 127.0.0.1
restrict ::1

# Location of drift file
driftfile /var/lib/ntp/ntp.drift

seth · 2024-02-18 20:46:07

And ntpd is started before the Network target at Feb 18 19:01:53, although it should be after.

From that grep, the network-online.target is reached before the network.target.

Please post your complete system journal for the boot:

sudo journalctl -b | curl -F 'file=@-' 0x0.st

so we can see what's going on there.

xdegaye · 2024-02-19 07:44:11

The first boot log of this morning is at https://0x0.st/HnYa.txt.

Booting at 08:02:05.
Sleep mode at 08:13:43.
Waking up and enabling the hotspot at 08:27:07.

seth · 2024-02-19 12:46:52

Feb 19 08:02:05 lillehammer systemd[1]: Reached target Network is Online.
Feb 19 08:02:06 lillehammer systemd[1]: Starting Network Time Service...
Feb 19 08:02:06 lillehammer ntpd[376]: ntpd 4.2.8p17@1.4004-o Tue Jun  6 14:05:47 UTC 2023 (1): Starting
Feb 19 08:02:06 lillehammer ntpd[383]: Listen normally on 3 lo [::1]:123
Feb 19 08:02:06 lillehammer ntpd[383]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Feb 19 08:02:07 lillehammer systemd[1]: Started Automatic wireless network connection using netctl profiles.
Feb 19 08:27:42 lillehammer kernel: wlan0: authenticate with 5a:b7:57:3a:dd:7d
Feb 19 08:27:46 lillehammer ntpd[383]: Listen normally on 4 wlan0 192.168.128.117:123
Feb 19 08:27:46 lillehammer ntpd[383]: new interface(s) found: waking up resolver
Feb 19 08:27:56 lillehammer systemd[1]: Starting Time & Date Service...
Feb 19 08:27:56 lillehammer systemd[1]: Started Time & Date Service.
Feb 19 08:28:26 lillehammer systemd[1]: systemd-timedated.service: Deactivated successfully.

Network status moves "online" immediately, then ntpd starts.
Check

systemctl status netctl-wait-online.service

and try to enable that.

ntpd however responds correctly to the new NIC and systemd-timedated.service starts ~10s later

systemctl status systemd-timedated.service

This doesn't indicate any kind of problem, you're not syncing while there's no network but ~10s after you got an online lease

xdegaye · 2024-02-19 16:29:23

I have been successfully reproducing three times the following sequence of events that allows to have ntpd fail and then ntpd succeed:

1 - Disable pdnsd and reboot (the hotspot is enabled at each of the following boots).
ntpq reports: 'No association ID's returned'.
Start pdnsd: ntpd succeeds.

2 - Enable pdnsd and reboot.
ntpd fails.
Running strace on the ntpd process shows ntpd in a (probably) infinite loop, trying to connect to the ipv6 address that are listed as 'remote' by 'ntpq -p':

connect(4, {sa_family=AF_INET6, sin6_port=htons(123), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "64:ff9b::33c3:68bc", &sin6_addr), sin6_scope_id=0} , 28) = -1 ENETUNREACH (Network is unreachable)

Pinging that address fails also with network unreachable which is expected as shorewall is configured to disable ipv6.
Restarting ntpd succeeds which means that ntpd can fall back on ipv4 when ntpd is started after pdnsd (ntpd is always started before pdnsd on boot).

3 - Enable ipv6 in shorewall and reboot.
ntpd succeeds.
To know if ntpd has used ipv4 or ipv6 for connecting with the servers, look the 'local' column printed by the 'opeers' command when ntpq is run interactively with 'ntpq -i'. when ipv6, each entry is a part of the ipv6 local address being used.

A possible explanation of why pdnsd is involved ?
ntpd starts with ipv6 addresses and uses DNS to find the corresponding ipv4 addresses when ipv6 fails.
Possibly, ntpd fails because it does not fall back to ipv4 due to the boot sequence of events: pdnsd is not started before ntpd as it probably should.

@seth

$ systemctl status systemd-timedated.service
○ systemd-timedated.service - Time & Date Service
     Loaded: loaded (/usr/lib/systemd/system/systemd-timedated.service; static)
     Active: inactive (dead)
       Docs: man:systemd-timedated.service(8)
             man:localtime(5)
             man:org.freedesktop.timedate1(5)

Should I try to enable this service in boot #2 or boot #3 of the above scenario ?

seth · 2024-02-19 16:53:37

Should I try to enable this service in boot #2 or boot #3 of the above scenario ?

No, I just wanted to ensure there're no errors there.

You can use "server -4 0.fr.pool.ntp.org iburst" to force IPv4 resolution.
Otherwise you might want to try to restrict away from link-local IPv6 addresses (fe80:* - you'll get them w/o having a real lease)

xdegaye · 2024-02-19 19:40:02

Actually there is no obvious reason for disabling ipv6 in shorewall except I feel more confident using ipv4 when writing some code (such as pa-dlna). I will run ipv6 from now on and learn how to use it.

After few days of successful boots hopefully, I will mark this thread as resolved.

Thanks for your help.

Last edited by xdegaye (2024-02-19 19:51:47)

Arch Linux

#1 2024-02-16 15:52:27

[SOLVED] ntpd randomly fails when started at boot

#2 2024-02-17 00:11:25

Re: [SOLVED] ntpd randomly fails when started at boot

#3 2024-02-17 08:15:33

Re: [SOLVED] ntpd randomly fails when started at boot

#4 2024-02-17 09:47:46

Re: [SOLVED] ntpd randomly fails when started at boot

#5 2024-02-17 15:19:05

Re: [SOLVED] ntpd randomly fails when started at boot

#6 2024-02-18 11:09:59

Re: [SOLVED] ntpd randomly fails when started at boot

#7 2024-02-18 13:04:46

Re: [SOLVED] ntpd randomly fails when started at boot

#8 2024-02-18 15:41:31

Re: [SOLVED] ntpd randomly fails when started at boot

#9 2024-02-18 15:50:40

Re: [SOLVED] ntpd randomly fails when started at boot

#10 2024-02-18 16:07:55

Re: [SOLVED] ntpd randomly fails when started at boot

#11 2024-02-18 16:11:26

Re: [SOLVED] ntpd randomly fails when started at boot

#12 2024-02-18 18:45:59

Re: [SOLVED] ntpd randomly fails when started at boot

#13 2024-02-18 20:46:07

Re: [SOLVED] ntpd randomly fails when started at boot

#14 2024-02-19 07:44:11

Re: [SOLVED] ntpd randomly fails when started at boot

#15 2024-02-19 12:46:52

Re: [SOLVED] ntpd randomly fails when started at boot

#16 2024-02-19 16:29:23

Re: [SOLVED] ntpd randomly fails when started at boot

#17 2024-02-19 16:53:37

Re: [SOLVED] ntpd randomly fails when started at boot

#18 2024-02-19 19:40:02

Re: [SOLVED] ntpd randomly fails when started at boot

Board footer