Subject: bug#76516: [shepherd] Timer not executed

From: Tomas Volf <[email-masked]>
Date: Sun, 23 Feb 2025 23:05:08 +0100

Hi,

I might have find a bug in shepherd timers.  I have a timer scheduled to
run every 24 hours, the definition is as follow:

--8<---------------cut here---------------start------------->8---
(define %kerberos-log-in-refresh-service
  (let ((name 'kerberos-log-in-refresh))
    (simple-service
     name
     home-shepherd-service-type
     (list (shepherd-service
            (documentation "Refresh the kerberos ticket.")
            (provision (list name))
            (requirement '(kerberos-reachable?))
            (start #~(make-timer-constructor
                      (calendar-event #:hours '(12) #:minutes '(0))
                      (command (list #$%kerberos-log-in))))
            (stop #~(make-timer-destructor))
            (modules (cons '(shepherd service timer)
                           %default-modules))
            (actions (list (shepherd-action
                            (name 'trigger)
                            (documentation "Immediately refresh the ticket.")
                            (procedure #~trigger-timer)))))))))
--8<---------------cut here---------------end--------------->8---

This should run every 24 hours (at noon) and execute the
%kerberos-log-in script (simple guile program that authenticates against
kerberos).

However that did not happen.  Here are the logs:

--8<---------------cut here---------------start------------->8---
2025-02-22 19:17:00 Service kerberos-log-in running with value #<<process> id: 730 command: ("/gnu/store/8m21cnqnllk6g1kcgyj91i5h05s7c0c4-krb-log-in")>.
2025-02-22 19:17:00 [8m21cnqnllk6g1kcgyj91i5h05s7c0c4-krb-log-in] <redacted>
2025-02-22 19:17:00 [8m21cnqnllk6g1kcgyj91i5h05s7c0c4-krb-log-in] <redacted>
2025-02-22 19:17:00 [8m21cnqnllk6g1kcgyj91i5h05s7c0c4-krb-log-in] <redacted>
2025-02-22 19:17:00 [8m21cnqnllk6g1kcgyj91i5h05s7c0c4-krb-log-in] <redacted>
2025-02-23 12:00:02 Waiting anew for timer 'kerberos-log-in-refresh' (resuming from sleep state?).
2025-02-23 22:00:01 Not rotating '/home/<redacted>/.local/state/shepherd/dbus.log', which is below the 8192 B threshold.
--8<---------------cut here---------------end--------------->8---

The ones from 19:17:00 are from 'kerberos-log-in service, which is
one-shot executed upon login.  That went fine.

However the 'kerberos-log-in-refresh is only at 12:00:02, and only as
"Waiting anew ...".  The message indicates that the computer might be
resuming from sleep, however that was not the case here.  It is a
desktop machine, and it was left running over night.

Here is herd status:

--8<---------------cut here---------------start------------->8---
$ herd status kerberos-log-in-refresh
● Status of kerberos-log-in-refresh:
  It is running since Sat 22 Feb 2025 07:17:00 PM CET (28 hours ago).
  Timed service.
  Periodically running: /gnu/store/8m21cnqnllk6g1kcgyj91i5h05s7c0c4-krb-log-in
  It is enabled.
  Provides: kerberos-log-in-refresh
  Requires: kerberos-reachable?
  Custom action: trigger
  Will be respawned.

Upcoming timer alarms:
  Mon 24 Feb 2025 12:00:00 PM CET (in 13 hours)
  Tue 25 Feb 2025 12:00:00 PM CET (in 37 hours)
  Wed 26 Feb 2025 12:00:00 PM CET (in 3 days)
  Thu 27 Feb 2025 12:00:00 PM CET (in 4 days)
  Fri 28 Feb 2025 12:00:00 PM CET (in 5 days)
--8<---------------cut here---------------end--------------->8---

Have a nice day,
Tomas

-- 
There are only two hard things in Computer Science:
cache invalidation, naming things and off-by-one errors.