chrony: Hotplug race condition

[wagnerflo]

Package Name

chrony

Maintainer

@mlichvar

OpenWrt Version

24.10.4

OpenWrt Target/Subtarget

lantiq/xrx200

Steps to Reproduce

1. Start the device
2. Check if the hotplug.ntp event has been recieved through udev. For example by placing a script in /etc/hotplug.d/ntp to log something.

Actual Behaviour

chrony's init script starts chronyd as well as /usr/sbin/chrony-hotplug in short succession (through procd). The latter then proceeds to immediately call /usr/bin/chronyc waitsync .... On my device (Fritzbox 7490; but I'd assume this is bound to happen on any not-so-fast hardware) the chronyd process doesn't come up fast enough most of the times. So chronyc will fail with "Could not open connection to daemon" and the stratum notification event never get's sent.

This for example breaks the DNSSEC after NTP for unbound.

I fixed it locally with a sleep 10 at the top of /usr/sbin/chrony-hotplug but that obviously is just a hack and no guarantee whatsoever.

Confirmation Checklist

• The package is maintained in this repository.
• I understand that issues related to the base OpenWrt repository or LuCI repository will be closed.
• I am reporting an issue for OpenWrt, not an unsupported fork.

[mlichvar]

It's not clear to me what exactly is wrong.

Is the chrony version 4.6.1? If you stop the chronyd service and run the /usr/bin/chronyc waitsync 300 1 0.0 1 command, what do you see? For me, it's printing 506 Cannot talk to daemon in a loop, for up to 5 minutes as requested.

[wagnerflo]

Yes, it's version 4.6.1 and yes if I stop the chronyd and run the command I get the same behavior as you described.

Basically what I did to find the root of the behavior (why unbound wouldn't restart after getting correct time) is I modified /usr/sbin/chrony-hotplug to run /usr/bin/chronyc waitsync >/tmp/chrony-hotplug.log 2>&1 600 1 0.0 1 || exit 0 instead of what's in there.

This gave me the Could not open connection to daemon error in my logfile which is from here https://github.com/mlichvar/chrony/blob/007a1ae4fef36cec10742e2bb05e37acd02f2b96/client.c#L3710 I think. Wild guessing (without reading code; no time for that currently): Maybe it's catching chronyd in a half-initialized state?

[mlichvar]

If you can install strace and modify the hotplug script to run chronyc in strace, that might give us a clue what is failing.

[wagnerflo]

Good idea but no dice. Adding strace makes the issue go away reliably. I guess its load times act like the sleep 10 from my workaround. I'll add some debug output to open_io() and see...

[mlichvar]

chrony already has some debug messages, but they are not enabled in the openwrt build. You can add --enable-debug to the configure options in the Makefile and then add -d option to the chronyc command.

[wagnerflo]

Calling open_io() at startup.
open_io(): START OF FUNCTION CALL
open_io(): looking at address_index=0
           PATH=/var/run/chrony/chronyd.sock
open_io(): looking at address_index=1
           IP=127.0.0.1, PORT=323
Could not connect socket to 127.0.0.1:323 : Network is unreachable
open_ip_socket(): connect_ip_address() failed
open_io(): looking at address_index=2
           IP=::1, PORT=323
Could not connect socket to [::1]:323 : Network is unreachable
open_ip_socket(): connect_ip_address() failed
open_io(): no connection found; return 0

Could not open connection to daemon

That's in contrast to later where chronyc can always open the UDP socket. Looking at /etc/rc.d that makes sense though: S15chronyd and the S20network. So with out an IP address assigned to localhost even that "network is unreachable".

I guess a less hacky fix would be to move chronyd to a later point in the startup order or move chrony-hotplug into a separate init script and make that start after network

[mlichvar]

Another potential fix is to create the /var/run/chrony directory before starting chronyd, so chronyc can always bind its socket there.

--- a/net/chrony/files/chronyd.init
+++ b/net/chrony/files/chronyd.init
@@ -144,4 +144,7 @@ start_service() {
                config_foreach handle_nts nts
                config_foreach handle_logging logging
        ) > $INCLUDEFILE
+
+       mkdir -p -m 0700 /var/run/chrony
+       chown chrony:chrony /var/run/chrony
 }

[wagnerflo]

Why would it be able to connect to a unix socket that has not been created yet?

Calling open_io() at startup.
open_io(): START OF FUNCTION CALL
open_io(): looking at address_index=0
           PATH=/var/run/chrony/chronyd.sock
Could not remove /var/run/chrony/chronyc.1165.sock : No such file or directory
Could not connect Unix socket to /var/run/chrony/chronyd.sock : No such file or directory
open_io(): looking at address_index=1
           IP=127.0.0.1, PORT=323
[... as before ...]
Could not open connection to daemon

(That's with your suggested patch to the init script.)

[mlichvar]

Hm, ok. I remembered a similar case which was solved by creating a directory containing client sockets, but that might have been with linuxptp, not chrony.

Does ordering after S20network guarantees the loopback interface will already be up, or is there still a race (just less likely to happen)?

Ideally, chronyd should be started without -n, so the parent process can see when the daemon is ready to receive client requests, and only then start chronyc, but I'm not sure how to do that with the openwrt procd.

[wagnerflo]

I guess even reordering the startup sequence will be no perfect fix. Looking at S20network that also uses procd to start /sbin/netifd which takes care of configuring networking.

What could be a more robust solution is waiting for the loopback interface like this:

--- a/net/chrony/files/chrony.ntp-hotplug
+++ b/net/chrony/files/chrony.ntp-hotplug
@@ -1,6 +1,8 @@
 #!/bin/sh
 # Wait for sync for up to 5 minutes and notify other services
 
+ubus -t 30 wait_for network.interface.loopback
+
 /usr/bin/chronyc waitsync 300 1 0.0 1 || exit 0
 
 ubus call hotplug.ntp call '{ "env": [ "ACTION=stratum" ] }'

The network.interface.loopback ubus object is being added by netifd and (based on a very quick look at the flow of code in netifd) it seems that is only being done after IP addresses have been configured on the interface.

Obviously the loopback part of network.interface.loopback depends on the uci configured name of that interface section. loopback is the OpenWRT default but (as far as I know) there's no reason it has to be like that (uci rename network.loopback=foo won't break the system). Going through uci output to find the name of the interface that will have 127.0.0.1 or ::1 assigned to is maybe a bit excessive, though.

[mlichvar]

Thanks. That looks like a good solution to me. Can you please submit a PR?

[wagnerflo]

I'm off to vacation today and was super busy the days before. I'll hope to get back to this and make a PR when I'm back end of next week. Feel free to remind me.