Re: Warning "Supervising process..." due to SIGCHLD from grand-parent

[Lennart Poettering <lennart@xxxxxxxxxxxxxx>]

On Mo, 31.10.22 08:04, Christopher Wong (Christopher.Wong@xxxxxxxx) wrote:

> Hi,
>
>
> We have during boot received the "Supervising process..." warning
> from systemd related to chronyd.service. This is not always
> happening, but when it happens systemd receives SIGCHLD from
> grand-parent (22955) before the parent (22956). See logs below:

grand-parent? do you mean grand-child? I am a bit confusing what you
are trying to say?

> Oct 25 10:34:55.104980 axis-accc8ed1c728 systemd[22955]: chronyd.service: Executing: /usr/sbin/chronyd -u chronyd -f /run/chrony/chronyd.conf
> Oct 25 10:34:55.117999 axis-accc8ed1c728 chronyd[22957]: chronyd version 4.2 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP -SCFILTER -SIGND +ASYNCDNS +NTS -SECHASH +IPV6 +DEBUG)
> Oct 25 10:34:55.120781 axis-accc8ed1c728 chronyd[22957]: Frequency -8.172 +/- 1.366 ppm read from /var/lib/chrony/drift
> Oct 25 10:34:55.124304 axis-accc8ed1c728 systemd[1]: systemd-journald.service: Received EPOLLHUP on stored fd 82 (stored), closing.
> Oct 25 10:34:55.126460 axis-accc8ed1c728 systemd[1]: Received SIGCHLD from PID 22955 (chronyd).
> Oct 25 10:34:55.126708 axis-accc8ed1c728 systemd[1]: Child 22955 (chronyd) died (code=exited, status=0/SUCCESS)
> Oct 25 10:34:55.126920 axis-accc8ed1c728 systemd[1]: chronyd.service: Child 22955 belongs to chronyd.service.
> Oct 25 10:34:55.127000 axis-accc8ed1c728 systemd[1]: chronyd.service: Control process exited, code=exited, status=0/SUCCESS (success)
> Oct 25 10:34:55.127027 axis-accc8ed1c728 systemd[1]: chronyd.service: Got final SIGCHLD for state start.
> Oct 25 10:34:55.127160 axis-accc8ed1c728 systemd[1]: chronyd.service: Potentially unsafe symlink chain, will now retry with relaxed checks: /run/chrony/chronyd.pid
> Oct 25 10:34:55.127571 axis-accc8ed1c728 systemd[1]: chronyd.service: New main PID 22957 belongs to service, we are happy.
> Oct 25 10:34:55.127598 axis-accc8ed1c728 systemd[1]: chronyd.service: Main PID loaded: 22957
> Oct 25 10:34:55.127759 axis-accc8ed1c728 systemd[1]: Custom log in process-util.c fnc pid_is_my_child(): pid: 22957, ppid: 22956, cached_pid: 1.
> Oct 25 10:34:55.127785 axis-accc8ed1c728 systemd[1]: chronyd.service: Supervising process 22957 which is not our child. We'll most likely not notice when it exits.
> Oct 25 10:34:55.127964 axis-accc8ed1c728 systemd[1]: chronyd.service: Changed start -> running
> Oct 25 10:34:55.128006 axis-accc8ed1c728 systemd[1]: chronyd.service: Job 117032 chronyd.service/start finished, result=done
> Oct 25 10:34:55.128053 axis-accc8ed1c728 systemd[1]: Started NTP client/server.
> ...
> Oct 25 10:34:55.158173 axis-accc8ed1c728 systemd[1]: Received SIGCHLD from PID 22956 (chronyd).
> Oct 25 10:34:55.158436 axis-accc8ed1c728 systemd[1]: Child 22956 (chronyd) died (code=exited, status=0/SUCCESS)
> Oct 25 10:34:55.158679 axis-accc8ed1c728 systemd[1]: chronyd.service: Child 22956 belongs to chronyd.service.
>
>
> The chronyd does two forks. In the normal case the parent will die
> first and then the grand-parent will die. This behavior is according
> to the SysV Daemons implementation
> https://www.freedesktop.org/software/systemd/man/daemon.html
> However, it seems scheduling for parent and grand-parent can vary
> and result in a different behavior.

This is almost certainly a bug in chrony. If you use Type=forking,
then the process that systemd forks off (let's call it "P") should
wait until all of the below holds:

1. The middle child P' has exited
2. The grandchild (and main daemon process) P'' is running
3. The PID file has been successfully written to contain the PID of P''.

That all said, it's 2022, maybe chrony should just use Type=notify and
sd_notify() like any modern code?

Lennart

--
Lennart Poettering, Berlin