screen-locker/early-bird-workout-check.timer
Krzysztof kuhy Rudnicki e5db25468d
Some checks are pending
pre-commit / pre-commit (push) Waiting to run
Tests / test (3.10) (push) Waiting to run
Tests / test (3.11) (push) Waiting to run
Tests / test (3.12) (push) Waiting to run
Tests / lock-popup-safety (push) Waiting to run
release-apk / release (APK) (push) Waiting to run
Re-arm the locker, and make a disarmed enforcer impossible to miss
The screen locker stopped locking on 2026-08-04 and nobody could tell. Not a
logic bug: every predicate worked the whole time. systemd logged

  timers.target: Found ordering cycle: early-bird-workout-check.timer/start
    after graphical-session.target/start after basic.target/start after
    timers.target/start - after early-bird-workout-check.timer
  timers.target: Job early-bird-workout-check.timer/start deleted to break
    ordering cycle starting with timers.target/start

and left the timer disabled. A timer that is WantedBy=timers.target must not be
ordered After= a target that itself comes after timers.target; systemd resolves
that loop by deleting the job, which is an absence, and absences page nobody.

That timer is the ONLY thing that closes the early-bird window. Each morning a
run inside the window banked early_bird_pending.json, logged "will re-check at
08:30", and exited 0. The re-check never came, so the marker stood all day,
every day, for thirteen days.

It stayed invisible because logging.basicConfig was called only in the
--sync-only branch, never for --production -- the mode systemd actually runs.
Journal proof: zero INFO lines from workout-locker.service since June. Every
early exit logged at INFO into a logger with no handler. Meanwhile the healthy
15-minute sync kept the system looking alive.

The 2026-08-15 Python split is NOT implicated: it was pure code motion, and
basicConfig already sat in that branch before it.

Fixes:

* Drop the After= that closes the cycle; Persistent=true so a machine asleep at
  08:30 still re-checks after resume.
* Add workout-locker.timer (*:00,30). The service is WantedBy=
  graphical-session.target, i.e. one decision per login, so the 08-16 -> 08-17
  day and ISO-week rollover inside one long session was never re-evaluated.
* arm.sh: install units, enable timers, verify -- one command, because
  re-arming was a four-command sequence that was easy to half-do, and
  `systemctl enable` returns 0 while systemd deletes the timer job.
* check_enforcement_armed.py asks systemd what it actually scheduled (enabled
  AND has a next trigger) and fails loudly otherwise. Wired as ExecStartPost on
  workout-sync.service, so a disarmed locker marks that unit failed every 15
  minutes instead of scrolling past. install_systemd.sh now fails on it too.

Logging (the reason this went unnoticed, so treated as a defect in its own
right):

* basicConfig for every mode, never one branch.
* Every enforcement-abandoning exit records a decision instead of an invisible
  INFO: one greppable line -- DECISION lock=no reason=early_bird_window_active
  weekly=0/5 -- at WARNING, since per CLAUDE.md an INFO explanation of a
  non-action is a silent failure with extra steps. The enforced case is logged
  too: "no line at all" was the outage's whole signature.
* A durable JSONL trail outside the repo (~/.local/share/screen_locker/), so
  "when did this last actually enforce?" survives journal rotation. --status
  and --sync-only record lock=n/a; "did not decide" must never look like
  "decided not to lock".
* check_silent_failures.py now also catches sys.exit(0) that explains nothing.
  Verified both directions: it flags 3/3 exits in the pre-fix _auto_upgrade.py
  and passes the repo clean.

Sync noise: four records replayed as WARNINGs every cycle (~384/day), which is
how the actionable lines got tuned out. manual_workout:2026-08-15 is an empty
stub ({date, kind, type}) -- no workout to recover, and that day's credit was
already counted under a different sync_record_id, so no credit was ever lost.
The three "collided" records are dedup working. Both now report at info; a
WARNING from this logger again means something real. 4 -> 0 per cycle.

Verified on the live system: the periodic timer fired at 16:45 and the journal
shows `DECISION lock=no reason=scheduled_skip_day weekly=0/5` -- the line that
did not exist for thirteen days. Both timers report enabled and scheduled, and
no ordering cycle recurs. Today is a scheduled skip so the machine was not
locked mid-session; enforcement resumes tomorrow 08:30. 1007 tests, 100%
coverage, all hooks green.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01F2b6ZjBcdrkSYnMujx4mWd
2026-08-17 16:47:25 +02:00

28 lines
1.3 KiB
SYSTEMD
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

[Unit]
Description=Re-check workout after early bird grace period expires (08:30 normal, 09:05 extended)
# NO After=graphical-session.target here. This timer is WantedBy=timers.target,
# and timers.target is ordered before basic.target before
# graphical-session.target -- so that After= closes a dependency cycle.
# systemd resolves such a cycle by DELETING this timer's job, which is exactly
# what happened on 2026-08-04 ("Job early-bird-workout-check.timer/start deleted
# to break ordering cycle"). The timer went disabled and the locker silently
# stopped enforcing for days. The service it triggers keeps its own
# After=graphical-session.target, which is where that ordering belongs.
[Timer]
# Fires at 08:30 for the normal early-bird window (5:00–8:30).
# Also fires at 09:05 to catch the extended window (5:00–9:00) earned by 5+ workout weeks.
# Both runs are idempotent: the service handles "already logged" and "window still active".
OnCalendar=*-*-* 08:30:00
OnCalendar=*-*-* 09:05:00
Unit=workout-locker.service
# Persistent=true: a machine asleep or off at 08:30 would otherwise skip the
# re-check entirely, leaving the early-bird marker banked and the day
# unenforced. Both runs are idempotent (see above), so a catch-up run is safe.
Persistent=true
AccuracySec=1s
RandomizedDelaySec=0
[Install]
WantedBy=timers.target