screen-locker/screen_locker/tests/test_systemd_units.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

150 lines
6.2 KiB
Python

"""Tests for the systemd unit files that ARM enforcement.
These exist because of a real outage: on 2026-08-04 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*. The Python lock-decision chain was perfectly
healthy the whole time — it simply was never invoked again, so the screen
locker stopped locking for days without a single failing unit or error line.
A timer that is ``WantedBy=timers.target`` must not be ordered ``After=`` a
target that itself comes after ``timers.target``; that closes a dependency
loop and systemd resolves it by silently deleting the job. Parsing is plain
text on purpose: this must run in CI, where no systemd is present. The
complementary *runtime* check ("is it actually enabled and scheduled right
now?") cannot run in a container and lives in
``scripts/check_enforcement_armed.py`` instead.
"""
from __future__ import annotations
from pathlib import Path
import pytest
REPO_ROOT = Path(__file__).resolve().parents[2]
# Targets that are ordered AFTER timers.target. A timer pulled in by
# timers.target may never declare After= on any of these.
_TARGETS_AFTER_TIMERS = frozenset(
{
"graphical-session.target",
"basic.target",
"graphical.target",
"multi-user.target",
"default.target",
}
)
# Every timer unit that schedules the locker, i.e. every file whose breakage
# silently disarms enforcement.
_ENFORCEMENT_TIMERS = ("early-bird-workout-check.timer", "workout-locker.timer")
def _directive_values(unit_text: str, key: str) -> list[str]:
"""Return every value assigned to ``key``, ignoring comments.
systemd allows a directive to repeat (``OnCalendar=`` does, deliberately),
so this returns a list rather than a single value.
"""
values: list[str] = []
for raw_line in unit_text.splitlines():
line = raw_line.strip()
if not line or line.startswith(("#", ";")):
continue
name, sep, value = line.partition("=")
if sep and name.strip() == key:
values.append(value.strip())
return values
@pytest.mark.parametrize("timer_name", _ENFORCEMENT_TIMERS)
class TestEnforcementTimersAreCycleFree:
"""Every locker timer must be installable without an ordering cycle."""
def test_timer_file_exists(self, timer_name: str) -> None:
"""The unit file ships in the repo, so install_systemd.sh can copy it."""
assert (REPO_ROOT / timer_name).is_file(), (
f"{timer_name} is missing; enforcement cannot be scheduled without it"
)
def test_no_ordering_cycle_with_timers_target(self, timer_name: str) -> None:
"""No After= on a target that is itself ordered after timers.target.
This is the exact regression from 2026-08-04. Without this assertion the
failure is invisible: the unit file looks reasonable, nothing errors, and
the timer just quietly never fires.
"""
text = (REPO_ROOT / timer_name).read_text(encoding="utf-8")
wanted_by = set()
for value in _directive_values(text, "WantedBy"):
wanted_by.update(value.split())
if "timers.target" not in wanted_by:
pytest.skip(f"{timer_name} is not pulled in by timers.target")
ordered_after = set()
for value in _directive_values(text, "After"):
ordered_after.update(value.split())
offenders = sorted(ordered_after & _TARGETS_AFTER_TIMERS)
assert not offenders, (
f"{timer_name} declares After={offenders} while being "
f"WantedBy=timers.target. timers.target is ordered before "
f"basic.target before graphical-session.target, so this closes an "
f"ordering cycle and systemd deletes the timer job to break it — "
f"silently disabling enforcement (see 2026-08-04)."
)
def test_triggers_the_locker_service(self, timer_name: str) -> None:
"""The timer must actually start the locker, not some other unit."""
text = (REPO_ROOT / timer_name).read_text(encoding="utf-8")
assert _directive_values(text, "Unit") == ["workout-locker.service"], (
f"{timer_name} must trigger workout-locker.service"
)
def test_survives_a_missed_trigger(self, timer_name: str) -> None:
"""Persistent=true, so a suspend across the trigger still re-checks.
A laptop asleep at 08:30 would otherwise skip the re-check entirely and
leave the early-bird marker banked for the rest of the day.
"""
assert _directive_values(
text := (REPO_ROOT / timer_name).read_text(encoding="utf-8"), "Persistent"
) == ["true"], (
f"{timer_name} must set Persistent=true so a missed trigger is "
f"still run after resume; text was:\n{text}"
)
class TestEarlyBirdTimerWindows:
"""The early-bird timer must keep closing both grace windows."""
def test_covers_normal_and_extended_windows(self) -> None:
"""08:30 closes the normal window; 09:05 closes the extended one."""
text = (REPO_ROOT / "early-bird-workout-check.timer").read_text(
encoding="utf-8"
)
calendars = _directive_values(text, "OnCalendar")
assert "*-*-* 08:30:00" in calendars
assert "*-*-* 09:05:00" in calendars
class TestPeriodicLockerTimer:
"""A day/week boundary crossed mid-session must be re-evaluated."""
def test_repeats_through_the_day(self) -> None:
"""OnCalendar repeats, so enforcement is not login-only.
The 2026-08-16 -> 08-17 rollover was missed precisely because the
service is WantedBy=graphical-session.target (one shot per login) and
the only other trigger was the broken early-bird timer.
"""
text = (REPO_ROOT / "workout-locker.timer").read_text(encoding="utf-8")
calendars = _directive_values(text, "OnCalendar")
assert calendars, "workout-locker.timer must define at least one OnCalendar"