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

From: Tomas Volf <[email-masked]>
Date: Mon, 24 Feb 2025 20:06:33 +0100

Ludovic Courtès <[email-masked]> writes:

> Hi Tomas,
>
> Tomas Volf <[email-masked]> skribis:
>
>> However that did not happen.  Here are the logs:
>>
>> 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.
>>
>>
>> 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.
>
> What architecture is this on?

x86_64-linux, AMD Ryzen 5 5600G with Radeon Graphics

>
> From the excerpt above, the ‘log-rotation’ timer did fire as expected.
> Did it also have “Waiting anew” messages?

No, no such message.  Actually, there are only 2 additional lines in the
log file.  So the following are the last 4 lines of the
shepherd.log.1.zstd (you did already see the first 2 lines):

--8<---------------cut here---------------start------------->8---
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.

2025-02-23 22:00:01 Rotating log.
--8<---------------cut here---------------end--------------->8---

The empty line is in the log, that is not a copy&paste error.  The next
log (shepherd.log) starts with:

--8<---------------cut here---------------start------------->8---
2025-02-23 22:00:01 Rotating '/home/<redacted>/.local/state/shepherd/shepherd.log' to '/home/<redacted>/.local/state/shepherd/shepherd.log.1'.
2025-02-23 22:00:01 Rotated '/home/<redacted>/.local/state/shepherd/shepherd.log'.
--8<---------------cut here---------------end--------------->8---

So there is not much indication what happened.

Tomas

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