Systemd user timer: "next" run is blank, since last boot

Help
1

Hi, just thought I’d start a thread here about a case of: systemd “user” timer and service pairing are no longer scheduled (and thus the service hasn’t run since dec 1st apparently).

My current hypothesis is this is related to this bug (found here) but I haven’t gone digging to prove one way or another. Apparently there’s a recent commit to that bug, so perhaps I picked up some bleeding edge behavior that broke things for me.

context on my timer/service: they’ve been working for over a year without being touched, so I really don’t think there’s an error in my user units here.

expand for some debugging details and shell output here...

Dec 1st, when my timer last ran successfully, was my previous boot. Unfortunately I don’t know which nixos build that was (I’m sure there’s a way to look it up though…).

$ systemctl --user list-dependencies timers.target
timers.target
● ├─borgmatic.timer
● └─logrotate.timer

$ systemctl --all --user list-timers borgmatic.timer
NEXT LEFT LAST                                   PASSED UNIT            ACTIVATES
-       - Fri 2023-12-01 19:49:41 CST 1 week 3 days ago borgmatic.timer borgmatic.service

1 timers listed.

$ systemctl --user status borgmatic.service
● borgmatic.service - borgmatic backup
     Loaded: loaded (/home/myuser/.config/systemd/user/borgmatic.service; linked; preset: enabled)
     Active: activating (start) since Fri 2023-12-01 19:49:41 CST; 1 week 3 days ago
TriggeredBy: ● borgmatic.timer
   Main PID: 147109 (systemd-inhibit)
      Tasks: 4 (limit: 38241)
     Memory: 48.1M
        CPU: 1min 18.719s
     CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/borgmatic.service
             ├─147109 systemd-inhibit --who=borgmatic "--why=Prevent interrupting scheduled backup" /run/current-system/sw/bin/borgmatic --syslog-verbosity 2
             ├─147112 /nix/store/qp5zys77biz7imbk6yy85q5pdv7qk84j-python3-3.11.6/bin/python3.11 /nix/store/7djjsv3gj2j52r5cmjwx3bzvqkv5q4ga-borgmatic-1.8.1/bin/.borgmatic-wrapped --syslog-verbosity 2
             ├─155107 /nix/store/qp5zys77biz7imbk6yy85q5pdv7qk84j-python3-3.11.6/bin/python3.11 /nix/store/5rnsi8kx3bawizpj7k78vy075vl9lxxl-borgbackup-1.2.6/bin/.borg-wrapped compact --debug --show-rc ssh://user@borgserver.tld/./repo
             └─155122 ssh -i /home/myuser/.ssh/borgkey user@borgserver.tld borg serve --debug

Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id b8d2aa88cf73250d1727d7b588ae05edf8d9e104480df15dacea537196212c47 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id f4ec914db7f3c55ac4022b7d89b1ed88900e787246fe84b21c8362b7260e40b6 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id 3590ddbaa073a151aa3ab90a29067542b4118f72e388fcc31ddb24d505cb31f6 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id 81c977165c1e20d3275d722f57e61049df8e1930e850366f314a96f4d848f80c - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id a93abeab04b11c71c47462ca057a4e1633c1ad7015ebd0df7e2d004a7d848b46 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id 39714a25953f44cbc44250020ad3b26818b51c644189134bf6efd2f5c029c402 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id fd3c21eaa1980f750d3c333e5c7876902fd8d1f8dce17bd706d30f72c1d5992d - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id 96965a79f143430db8e0f41bea40a01bd70d31a58ae88020a5868086e54f3760 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id 9cb240c0941fab371ccb3b17f0a15cb45a3081cb6074d070dcdd4076d5b36c20 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO RemoteRepository: 4.79 kB bytes sent, 403.85 kB bytes received, 5 messages sent

$ systemctl --user status borgmatic.timer
● borgmatic.timer - Scheduler of borgmatic backups
     Loaded: loaded (/home/myuser/.config/systemd/user/borgmatic.timer; enabled; preset: enabled)
     Active: active (running) since Wed 2023-11-29 14:00:43 CST; 1 week 5 days ago
    Trigger: n/a
   Triggers: ● borgmatic.service

Nov 29 14:00:43 mymachine systemd[1450]: Started Scheduler of borgmatic backups.

Just thought I’d start this thread to keep notes in a public place in case it’s useful to someone else.

2

The service status is listed as activating. Is the backup service stuck? Have your tried restarting the service? The timer won’t trigger another run if the service is still active.

3

oh wow thanks so much! sytemctl restart --user borgmatic.service fixed it; I’m guessing it’s systemd that somehow erroneously thought it was running, since there would’ve at least been one error log line in journalctl from the time since my last boot.

Thanks for catching my Active: line didn’t match what I was reporting! I must’ve glossed right over it myself since the first thing I did was journalctl to view the service’s status and there was nothing since Dec 1st, so I was confident it hadn’t even been invoked.

Anyway, interesting output I'll save for later pondering: what happened when I poked the service

Here’s journalctl output running the whole time. In another terminal, I run systemctl --user restart borgmatic.service (at 18:46:33) which hung, so I ^C to interrupt and ran systemctl --user stop borgmatic.service (at 18:46:56) which finally gave my shell’s PS1 back at 18:47:13:

Dec 01 20:03:22 mymachine borgmatic[147112]: INFO Remote: dropping DEL for id 9cb240c0941fab371ccb3b17f0a15cb45a3081cb6074d070dcdd4076d5b36c20 - seg 12487, iti 12490, knisi False, spe False, dins False, si []
Dec 01 20:03:22 mymachine borgmatic[147112]: INFO RemoteRepository: 4.79 kB bytes sent, 403.85 kB bytes received, 5 messages sent
Dec 12 18:46:40 mymachine systemd-inhibit[147112]: Exiting due to TERM signal
Dec 12 18:46:40 mymachine systemd-inhibit[147112]: Exception ignored in: <function Popen.__del__ at 0x7f6e8f0ecae0>
Dec 12 18:46:40 mymachine systemd-inhibit[147112]: Traceback (most recent call last):
Dec 12 18:46:40 mymachine systemd-inhibit[147112]:   File "/nix/store/qp5zys77biz7imbk6yy85q5pdv7qk84j-python3-3.11.6/lib/python3.11/subprocess.py", line 1127, in __del__
Dec 12 18:46:40 mymachine systemd-inhibit[147112]:     _warn("subprocess %s is still running" % self.pid,
Dec 12 18:46:40 mymachine systemd-inhibit[147112]:   File "/nix/store/7djjsv3gj2j52r5cmjwx3bzvqkv5q4ga-borgmatic-1.8.1/lib/python3.11/site-packages/borgmatic/signals.py", line 18, in handle_signal
Dec 12 18:46:40 mymachine systemd-inhibit[147112]:     if frame.f_back.f_code.co_name == handle_signal.__name__:
Dec 12 18:46:40 mymachine systemd-inhibit[147112]:        ^^^^^^^^^^^^^^^^^^^
Dec 12 18:46:40 mymachine systemd-inhibit[147112]: AttributeError: 'NoneType' object has no attribute 'f_code'
Dec 12 18:46:40 mymachine systemd[1450]: borgmatic.service: Main process exited, code=killed, status=15/TERM
░░ Subject: Unit process exited
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░
░░ An ExecStart= process belonging to unit UNIT has exited.
░░
░░ The process' exit code is 'killed' and its exit status is 15.
Dec 12 18:46:40 mymachine borgmatic[147112]: CRITICAL Exiting due to TERM signal
Dec 12 18:48:10 mymachine systemd[1450]: borgmatic.service: State 'final-sigterm' timed out. Killing.
Dec 12 18:48:10 mymachine systemd[1450]: borgmatic.service: Killing process 155107 (.borg-wrapped) with signal SIGKILL.
Dec 12 18:48:10 mymachine systemd[1450]: borgmatic.service: Killing process 155122 (ssh) with signal SIGKILL.
Dec 12 18:48:10 mymachine systemd[1450]: borgmatic.service: Failed with result 'signal'.

Here’s the line of code from that stack trace: https://projects.torsion.org/borgmatic-collective/borgmatic/src/commit/72587a3b7281807794b5451209c17776183c2d7d/borgmatic/signals.py#L18 which is the function referred to as handler here: signal — Set handlers for asynchronous events — Python 3.12.2 documentation

The handler is called with two arguments: the signal number and the current stack frame (None or a frame object; for a description of frame objects, see the description in the type hierarchy or see the attribute descriptions in the inspect module).

To be fair to the borgmatic source: that python API doesn’t really expand on why/when a frame would be None (and as such isn’t really encouraging handling such a case).

tl;dr probably a patch is needed to borgmatic to have it handle resurrecting from the dead a little smoother? I’m still not 100% though.