GNU bug report logs - #77390
[Shepherd] Timer spawns many commands on DST change (CET -> CEST)

Previous Next

Full log

View this message in rfc822 format

From: help-debbugs <at> gnu.org (GNU bug Tracking System)
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: tracker <at> debbugs.gnu.org
Subject: bug#77401: closed ([Shepherd] Timer spawns many commands on DST
 change (CET -> CEST))
Date: Mon, 31 Mar 2025 21:23:03 +0000

[Message part 1 (text/plain, inline)]

Your message dated Mon, 31 Mar 2025 23:21:56 +0200
with message-id <87o6xgj3pn.fsf <at> gnu.org>
and subject line Re: bug#77401: [Shepherd] Timer spawns too many commands
has caused the debbugs.gnu.org bug report #77390,
regarding [Shepherd] Timer spawns many commands on DST change (CET -> CEST)
to be marked as done.

(If you believe you have received this mail in error, please contact
help-debbugs <at> gnu.org.)


-- 
77390: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=77390
GNU Bug Tracking System
Contact help-debbugs <at> gnu.org with problems

[Message part 2 (message/rfc822, inline)]

From: Ludovic Courtès <ludo <at> gnu.org>
To: bug-guix <at> gnu.org
Subject: [Shepherd] Timer spawns too many commands
Date: Mon, 31 Mar 2025 09:54:56 +0200

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’.

[Message part 3 (message/rfc822, inline)]

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Timo Wilken" <guix <at> twilken.net>
Cc: 77401-done <at> debbugs.gnu.org, 77390-done <at> debbugs.gnu.org
Subject: Re: bug#77401: [Shepherd] Timer spawns too many commands
Date: Mon, 31 Mar 2025 23:21:56 +0200

Hi Timo,

"Timo Wilken" <guix <at> twilken.net> 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’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.