Subject: bug#77401: closed (Re: bug#77401: [Shepherd] Timer spawns too many commands)

From: [email-masked] (GNU bug Tracking System)
Date: Mon, 31 Mar 2025 21:23:03 +0000

Your bug report

#77390: [Shepherd] Timer spawns many commands on DST change (CET -> CEST)

which was filed against the guix package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to [email-masked].

-- 
77390: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=77390
GNU Bug Tracking System
Contact [email-masked] with problems

Subject: Re: bug#77401: [Shepherd] Timer spawns too many commands
From: Ludovic Courtès <[email-masked]>
To: "Timo Wilken" <[email-masked]>
Cc: [email-masked], [email-masked]
Date: Mon, 31 Mar 2025 23:21:56 +0200
List-Id: <debbugs-submit.debbugs.gnu.org>

Hi Timo,

"Timo Wilken" <[email-masked]> skribis:

> Last night, this hit the exact moment of the CET/CEST change and seems to have
> confused the Shepherd a lot, to the point where it kept spamming the same
> message to /var/log/messages, and used up 80% of my system's total memory,
> according to htop. (This led to various things getting oom-killed, and the
> system grinding to a halt until I had a look at it in the afternoon.)
>
> First, at 01:00, the Shepherd spawned about 30 processes for this one timer:

This is now fixed:

  https://git.savannah.gnu.org/cgit/shepherd.git/commit/?id=b36e97a730596dbf3c376f940150d5fd1f08ecf1

Let me know if you find something fishy.

The irony is that the work I did for <https://issues.guix.gnu.org/75622>
helped, but the one test that would have caught this issue was wrong: it
was looking at the wrong date when testing the CET->CEST change.

Setting #:wait-for-termination? #true would have mitigated this bug (it
wouldn’t have triggered).

Thanks,
Ludo’.

Subject: [Shepherd] Timer spawns too many commands
From: Ludovic Courtès <[email-masked]>
To: [email-masked]
Date: Mon, 31 Mar 2025 09:54:56 +0200
List-Id: <debbugs-submit.debbugs.gnu.org>

Something went wrong on berlin (Shepherd 1.0.3):

--8<---------------cut here---------------start------------->8---
2025-03-29 22:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 45159.
2025-03-29 22:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-29 22:15:04 localhost shepherd[1]: Process 45159 of timer 'update-guix.gnu.org' terminated with status 0 after 4 seconds.
[...]
2025-03-29 23:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 38952.
2025-03-29 23:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-29 23:15:03 localhost shepherd[1]: Process 38952 of timer 'update-guix.gnu.org' terminated with status 0 after 3 seconds.
[...]
2025-03-30 00:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 32759.
2025-03-30 00:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 00:15:04 localhost shepherd[1]: Process 32759 of timer 'update-guix.gnu.org' terminated with status 0 after 4 seconds.
[...]
2025-03-30 01:14:12 localhost ntpd[1829]: Soliciting pool server 185.197.135.21
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51571.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51572.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51579.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51605.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51622.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51639.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51650.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51673.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51690.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51707.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51725.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51728.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51760.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51778.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51795.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51798.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 01:15:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 51830.
2025-03-30 01:15:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
[...]
2025-03-30 01:15:01 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 03:00:00 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 53303.
2025-03-30 03:00:00 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
[...]
2025-03-30 03:00:06 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 53334.
2025-03-30 03:00:07 localhost shepherd[1]: Registering new logger for update-guix.gnu.org.
2025-03-30 03:00:07 localhost shepherd[1]: Timer 'update-guix.gnu.org' spawned process 53351.
2025-03-30 03:00:07 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:07 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:09 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:09 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:10 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:10 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
2025-03-30 03:00:10 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).
[...]
2025-03-30 03:01:23 localhost shepherd[1]: Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep st
2025-03-30 03:01:23 localhost shepherd[1]: ate?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sl
2025-03-30 03:01:23 localhost shepherd[1]: eep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming f
2025-03-30 03:01:23 localhost shepherd[1]: rom sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resuming from sleep state?).Waiting anew for timer 'update-guix.gnu.org' (resu
--8<---------------cut here---------------end--------------->8---

The “waiting anew” bit could be related to the DST change, but things
went wrong before the DST change, at 1:15AM.

FWIW, the service had #:wait-for-termination? #false.

Ludo’.