screen-locker/scripts/check_enforcement_armed.py
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

185 lines
6.2 KiB
Python
Executable File

#!/usr/bin/env python3
"""Fail loudly when the screen locker is not actually armed.
The 2026-08 outage was not a logic bug. Every predicate worked; the timer that
*invokes* them had been disabled by a systemd ordering cycle, and nothing on the
machine considered that worth mentioning. ``systemctl status`` showed no failed
unit, because a job deleted to break a cycle is not a failure -- it is an
absence, and absences do not page anyone.
This script turns that absence into a loud, deterministic failure. It answers
one question -- *would enforcement actually happen?* -- and answers it from
systemd's own view rather than from the unit files on disk, because the files
were correct-looking the entire time the timer sat disabled.
Run it from the periodic sync timer (``workout-sync.service``), so the check
rides along with a unit already proven healthy instead of adding another timer
that could itself silently die.
Output goes through ``sys.stderr.write`` rather than ``print`` to match the
other gate scripts in this directory (see ``check_silent_failures.py``), which
keeps the repo free of T201 waivers.
Usage:
python3 scripts/check_enforcement_armed.py # exit 1 if disarmed
python3 scripts/check_enforcement_armed.py --quiet # only report problems
"""
from __future__ import annotations
import argparse
from dataclasses import dataclass
import logging
import shutil
import subprocess
import sys
_logger = logging.getLogger(__name__)
# Every unit that must be armed for a workout-less day to end in a lock.
# workout-locker.service itself is WantedBy=graphical-session.target and so is
# only ever a login one-shot; the timers are what make enforcement recur.
REQUIRED_TIMERS = (
"early-bird-workout-check.timer",
"workout-locker.timer",
)
_TIMEOUT_SECONDS = 10
@dataclass(frozen=True)
class TimerState:
"""What systemd currently believes about one timer."""
name: str
enabled: bool
enabled_raw: str
scheduled: bool
@property
def armed(self) -> bool:
"""True only when the timer is both enabled and actually scheduled.
Both halves matter. ``is-enabled`` alone passes for a timer whose job
systemd deleted to break an ordering cycle; ``list-timers`` alone passes
for a transient ``start``ed timer that will not survive a reboot.
"""
return self.enabled and self.scheduled
def describe(self) -> str:
"""Return a one-line human summary of this timer's state."""
if self.armed:
return f"OK {self.name}: enabled and scheduled"
problems = []
if not self.enabled:
problems.append(f"not enabled (is-enabled={self.enabled_raw or 'unknown'})")
if not self.scheduled:
problems.append("no next trigger in list-timers")
return f"DISARMED {self.name}: {', '.join(problems)}"
def _report(message: str) -> None:
"""Write one line to stderr, so a disarmed locker is visible in the unit."""
sys.stderr.write(f"{message}\n")
def _run(args: list[str]) -> tuple[int, str]:
"""Run ``args``, returning (returncode, stdout). Never raises."""
try:
# Explicit argument list, never shell=True.
proc = subprocess.run(
args,
capture_output=True,
text=True,
timeout=_TIMEOUT_SECONDS,
check=False,
)
except (OSError, subprocess.SubprocessError):
# A check that cannot run must not look like a check that passed.
_logger.exception("Could not run %s", " ".join(args))
return 1, ""
return proc.returncode, proc.stdout
def _scheduled_timers() -> set[str]:
"""Return the timer names systemd currently has a next trigger for."""
_, out = _run(["systemctl", "--user", "list-timers", "--all", "--no-pager"])
scheduled: set[str] = set()
for line in out.splitlines():
for name in REQUIRED_TIMERS:
# A timer with no next trigger prints "n/a" in the NEXT column.
if name in line and " n/a " not in f" {line} ":
scheduled.add(name)
return scheduled
def collect_states() -> list[TimerState]:
"""Return the current arming state of every required timer."""
scheduled = _scheduled_timers()
states = []
for name in REQUIRED_TIMERS:
code, out = _run(["systemctl", "--user", "is-enabled", name])
raw = out.strip()
states.append(
TimerState(
name=name,
enabled=code == 0 and raw == "enabled",
enabled_raw=raw,
scheduled=name in scheduled,
)
)
return states
def main(argv: list[str] | None = None) -> int:
"""Report arming state; return 1 when enforcement would not happen."""
parser = argparse.ArgumentParser(description=__doc__)
parser.add_argument(
"--quiet",
action="store_true",
help="print only when something is wrong",
)
args = parser.parse_args(argv)
if shutil.which("systemctl") is None:
# Reachable in containers/CI. Say so explicitly rather than passing:
# "could not check" must never be recorded as "checked and fine".
_logger.error("systemctl not found — the arming check could not run")
_report(
"ERROR: systemctl not found — cannot verify that the screen locker "
"is armed. This check did NOT pass; it did not run."
)
return 1
states = collect_states()
disarmed = [state for state in states if not state.armed]
if disarmed:
_logger.error(
"Screen locker is NOT armed: %s",
", ".join(state.name for state in disarmed),
)
_report(
"ERROR: the screen locker is NOT armed — a day without a workout "
"would pass unenforced."
)
for state in states:
_report(f" {state.describe()}")
_report(
"\nRe-arm with:\n"
" systemctl --user daemon-reload\n"
" systemctl --user enable --now "
+ " ".join(state.name for state in disarmed)
)
return 1
if not args.quiet:
for state in states:
_report(f" {state.describe()}")
_report("Screen locker enforcement is armed.")
return 0
if __name__ == "__main__":
sys.exit(main())