From 1d5965b9a7e19953ac0a3f72630d564f99d254ad Mon Sep 17 00:00:00 2001 From: Krzysztof kuhy Rudnicki Date: Sun, 30 Aug 2026 15:09:42 +0200 Subject: [PATCH] Close the four gaps that let a decided lock never reach the screen Co-Authored-By: Claude Opus 5 (1M context) --- pyproject.toml | 2 +- requirements.txt | 2 +- screen_locker/_armed_state.py | 89 +++++++++-- screen_locker/_compliance_state.py | 10 +- screen_locker/_constants.py | 9 ++ screen_locker/_decision_log.py | 124 ++++++++------- screen_locker/_decision_trail.py | 130 +++++++++++++++ screen_locker/_queue_state.py | 106 +++++++++++++ screen_locker/_queue_wait.py | 46 ++++++ screen_locker/_startup_checks.py | 58 ++++++- screen_locker/_temperature.py | 118 ++++++++++++-- screen_locker/_temperature_status_mixin.py | 13 +- screen_locker/_web_decisions.py | 95 +++++++++++ screen_locker/_web_payload.py | 46 +++--- screen_locker/_web_server.py | 4 +- screen_locker/_window_setup.py | 4 +- screen_locker/screen_lock.py | 32 +++- screen_locker/tests/_isolated_state.py | 16 +- screen_locker/tests/conftest.py | 14 ++ screen_locker/tests/test_armed_state.py | 97 ++++++++++-- .../tests/test_compliance_state_part2.py | 4 +- screen_locker/tests/test_decision_log.py | 17 +- .../tests/test_decision_log_modes.py | 91 +++++++++++ screen_locker/tests/test_decision_trail.py | 128 +++++++++++++++ screen_locker/tests/test_mcp.py | 2 +- screen_locker/tests/test_queue_state.py | 149 ++++++++++++++++++ .../tests/test_screen_lock_coverage_part4.py | 55 +++++++ screen_locker/tests/test_status_data_part2.py | 2 +- .../tests/test_sync_degradation_part2.py | 38 ++++- screen_locker/tests/test_temperature.py | 69 +++++++- screen_locker/tests/test_web_payload.py | 45 +++++- .../tests/test_weekly_logic_part3.py | 35 ++++ web/src/components/NowCard.test.tsx | 56 ++++++- web/src/components/NowCard.tsx | 22 ++- web/src/components/WhyTable.test.tsx | 70 ++++++++ web/src/components/WhyTable.tsx | 14 +- web/src/test/factories.ts | 2 + web/src/types.ts | 19 +++ workout-locker.service | 7 + workout-locker.timer | 10 +- 40 files changed, 1681 insertions(+), 169 deletions(-) create mode 100644 screen_locker/_decision_trail.py create mode 100644 screen_locker/_queue_state.py create mode 100644 screen_locker/_queue_wait.py create mode 100644 screen_locker/_web_decisions.py create mode 100644 screen_locker/tests/test_decision_log_modes.py create mode 100644 screen_locker/tests/test_decision_trail.py create mode 100644 screen_locker/tests/test_queue_state.py diff --git a/pyproject.toml b/pyproject.toml index 57ec04b..5d4b79b 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -7,7 +7,7 @@ requires-python = ">=3.14" # crdt-sync: shared CRDT merge scheme + GitHub-Contents-API sync transport, # also used by diet_guard; here for phone-workout GitHub sync (Workstream C) dependencies = [ - "gatelock @ git+https://github.com/kuhyx/utils@gatelock-v0.7.2#subdirectory=gatelock", + "gatelock @ git+https://github.com/kuhyx/utils@gatelock-v0.7.3#subdirectory=gatelock", "crdt-sync @ git+https://github.com/kuhyx/utils@crdt-sync-v0.9.1#subdirectory=crdt-sync", ] diff --git a/requirements.txt b/requirements.txt index 2745e83..9935e24 100644 --- a/requirements.txt +++ b/requirements.txt @@ -4,7 +4,7 @@ bandit==1.9.4 codespell==2.4.3 coverage==7.16.0 crdt-sync @ git+https://github.com/kuhyx/utils@crdt-sync-v0.9.1#subdirectory=crdt-sync -gatelock @ git+https://github.com/kuhyx/utils@gatelock-v0.7.2#subdirectory=gatelock +gatelock @ git+https://github.com/kuhyx/utils@gatelock-v0.7.3#subdirectory=gatelock mcp==2.1.1 mypy==2.3.1 pre-commit==4.6.2 diff --git a/screen_locker/_armed_state.py b/screen_locker/_armed_state.py index 9b4a8b7..8409c2c 100644 --- a/screen_locker/_armed_state.py +++ b/screen_locker/_armed_state.py @@ -27,13 +27,27 @@ import subprocess _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. +# The timers are what make enforcement recur. REQUIRED_TIMERS = ( "early-bird-workout-check.timer", "workout-locker.timer", ) +# workout-locker.service is WantedBy=graphical-session.target: a login +# one-shot that closes the window between a boot and the next timer tick. +# It is checked here because on 2026-08-30 it had silently drifted to +# `disabled`, the machine rebooted at 14:06, and nothing enforced until +# 14:30 -- while this very module reported "armed" the whole time, because +# it only ever looked at the two timers. +REQUIRED_SERVICES = ("workout-locker.service",) + +# The target the login run hangs off. Checked as well as `is-enabled` +# because ~/.config/i3/config notes that i3 "does not reliably activate +# graphical-session.target" -- an enabled service anchored to an inactive +# target is exactly the correct-looking-but-disarmed state this module was +# written to catch. +_LOGIN_TARGET = "graphical-session.target" + _TIMEOUT_SECONDS = 10 @@ -60,20 +74,34 @@ class TimerState: return self.enabled and self.scheduled def describe(self) -> str: - """Return a one-line human summary of this timer's state. + """Return a one-line human summary of this unit's state. Returns: An ``OK``/``DISARMED`` line naming every reason it is not armed. """ if self.armed: - return f"OK {self.name}: enabled and scheduled" + return f"OK {self.name}: {self._ready_phrase}" 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") + problems.append(self._missing_phrase) return f"DISARMED {self.name}: {', '.join(problems)}" + @property + def _ready_phrase(self) -> str: + """Return the wording for an armed unit of this kind.""" + if self.name.endswith(".timer"): + return "enabled and scheduled" + return f"enabled and anchored to an active {_LOGIN_TARGET}" + + @property + def _missing_phrase(self) -> str: + """Return the wording for the not-scheduled half of this kind.""" + if self.name.endswith(".timer"): + return "no next trigger in list-timers" + return f"{_LOGIN_TARGET} is not active, so the login run cannot fire" + def systemctl_available() -> bool: """Return whether ``systemctl`` can be run at all. @@ -128,15 +156,50 @@ def _scheduled_timers() -> set[str]: return scheduled -def collect_states() -> list[TimerState]: - """Return the current arming state of every required timer. +LOCKER_UNIT = "workout-locker.service" + + +def locker_unit_active() -> bool | None: + """Return whether the locker unit is running right now. + + "The lock would fire" is a statement about the *decision*; it says + nothing about whether anything is currently enforcing it. On 2026-08-30 + the machine had rebooted, no locker process existed, and the status page + read exactly the same as it does with a lock on screen. Returns: - One :class:`TimerState` per entry in :data:`REQUIRED_TIMERS`. + True/False, or None when systemd could not be asked -- which must + never be rendered as "not running". + """ + if not systemctl_available(): + return None + code, out = _run(["systemctl", "--user", "is-active", LOCKER_UNIT]) + if code != 0 and not out.strip(): + return None + return out.strip() == "active" + + +def _login_target_active() -> bool: + """Return whether the target the login run hangs off is active. + + Returns: + True when ``graphical-session.target`` is active. + """ + code, out = _run(["systemctl", "--user", "is-active", _LOGIN_TARGET]) + return code == 0 and out.strip() == "active" + + +def collect_states() -> list[TimerState]: + """Return the current arming state of every unit enforcement depends on. + + Returns: + One :class:`TimerState` per entry in :data:`REQUIRED_TIMERS` and + :data:`REQUIRED_SERVICES`. """ scheduled = _scheduled_timers() + login_target_up = _login_target_active() states = [] - for name in REQUIRED_TIMERS: + for name in (*REQUIRED_TIMERS, *REQUIRED_SERVICES): code, out = _run(["systemctl", "--user", "is-enabled", name]) raw = out.strip() states.append( @@ -144,7 +207,13 @@ def collect_states() -> list[TimerState]: name=name, enabled=code == 0 and raw == "enabled", enabled_raw=raw, - scheduled=name in scheduled, + # For a timer this is "systemd has a next trigger for it"; + # for the login-run service it is "the target it is wanted by + # is actually up". Both answer the same question: would this + # unit really fire? + scheduled=( + name in scheduled if name.endswith(".timer") else login_target_up + ), ) ) return states diff --git a/screen_locker/_compliance_state.py b/screen_locker/_compliance_state.py index 384616a..aa114b2 100644 --- a/screen_locker/_compliance_state.py +++ b/screen_locker/_compliance_state.py @@ -236,13 +236,15 @@ def explain_lock_decision( if result is not None: return result + # Named for the conclusion; "..._pending_heat_check" read as "stuck". return _stage( fired=True, - stage="full_lock_pending_heat_check", + stage="would_lock", reason=( - "No skip condition applies. The real locker still checks live " - "Warsaw temperature before showing the full lock — not " - "evaluated here." + degraded_note + "No skip condition applies, so a locker run starting now would " + "lock. This page re-derives the decision only: no live " + "temperature is checked, and a run may or may not be happening " + "right now (see Health)." + degraded_note ), context=stage_context, ) diff --git a/screen_locker/_constants.py b/screen_locker/_constants.py index f1a666b..475b804 100644 --- a/screen_locker/_constants.py +++ b/screen_locker/_constants.py @@ -178,6 +178,15 @@ SYNC_STATE_FILE: Path = ( ) SYNC_TIMEOUT_SECONDS: float = 10.0 +# Published while the locker has DECIDED to lock but is waiting for a +# higher-ranked holder (wake_alarm) to release the screen. From outside the +# process that state is indistinguishable from a hang: on 2026-08-30 the +# locker sat in gatelock's queue for 2h58m and the only evidence anywhere was +# a single INFO line at the moment it started waiting. +QUEUE_STATE_FILE: Path = ( + Path.home() / ".local" / "share" / "screen_locker" / "queue_state.json" +) + # Sync runs from the morning routine, which is started right after boot and # right after resume — often seconds before networking is actually up. Such a # run used to fail outright, and reported it as a permissions problem diff --git a/screen_locker/_decision_log.py b/screen_locker/_decision_log.py index 09800ab..2f5cf08 100644 --- a/screen_locker/_decision_log.py +++ b/screen_locker/_decision_log.py @@ -30,8 +30,18 @@ from dataclasses import dataclass, field from datetime import UTC, datetime import json import logging -from pathlib import Path -from typing import Final +from typing import TYPE_CHECKING + +from screen_locker._armed_state import locker_unit_active +from screen_locker._decision_trail import ( + DECISION_LOG_FILE, + DECISION_LOG_MAX_ENTRIES, + append_record, +) +from screen_locker._queue_state import read_queue_wait + +if TYPE_CHECKING: + from pathlib import Path __all__ = [ "DECISION_LOG_FILE", @@ -43,17 +53,8 @@ __all__ = [ _logger = logging.getLogger(__name__) -# Outside the repo on purpose -- workout state is private and git-untracked. -DECISION_LOG_FILE: Path = ( - Path.home() / ".local" / "share" / "screen_locker" / "decisions.jsonl" -) - -# Trimmed on write so the recurring timers cannot grow this without bound. -# Writers are the 30-minute locker timer plus the 15-minute sync run (which -# records "made no decision"), i.e. ~100 lines/day -> roughly a month of -# history. That comfortably covers the 13-day blind spot this file exists to -# make impossible. -DECISION_LOG_MAX_ENTRIES: Final[int] = 3000 +# Both live in _decision_trail (which owns the writer) and are re-exported +# here, where every reader already looks for them. @dataclass(frozen=True) @@ -107,13 +108,6 @@ class LockDecision: return record -def _trimmed(lines: list[str], new_line: str) -> list[str]: - """Return the retained history with ``new_line`` appended.""" - if len(lines) >= DECISION_LOG_MAX_ENTRIES: - lines = lines[-(DECISION_LOG_MAX_ENTRIES - 1) :] - return [*lines, new_line] - - def record_decision(decision: LockDecision, *, log_file: Path | None = None) -> None: """Log ``decision`` to the journal and append it to the durable trail. @@ -129,35 +123,7 @@ def record_decision(decision: LockDecision, *, log_file: Path | None = None) -> else: _logger.warning("%s", line) - _append_record(decision.as_record(), log_file=log_file) - - -def _append_record(record: dict[str, object], *, log_file: Path | None = None) -> None: - """Append one record to the durable trail, trimming old history. - - Never raises: failing to *record* why the locker acted must not stop the - locker from acting. A write failure is reported at ``warning`` rather than - swallowed, so the gap in the trail is itself visible. - """ - target = DECISION_LOG_FILE if log_file is None else log_file - try: - target.parent.mkdir(parents=True, exist_ok=True) - existing = ( - target.read_text(encoding="utf-8").splitlines() if target.exists() else [] - ) - kept = _trimmed( - [entry for entry in existing if entry.strip()], - json.dumps(record), - ) - target.write_text("\n".join(kept) + "\n", encoding="utf-8") - except OSError as exc: - _logger.warning( - "Could not append to the decision log at %s (%s) — this run's " - "decision is in the journal only, so the durable trail now has a " - "gap", - target, - exc, - ) + append_record(decision.as_record(), log_file=log_file) def record_no_decision(mode: str, *, log_file: Path | None = None) -> None: @@ -172,17 +138,67 @@ def record_no_decision(mode: str, *, log_file: Path | None = None) -> None: Written at ``info`` because these modes run constantly and are expected; the durable trail is what makes them auditable, not the log level. """ + # What the LOCKER was doing at this moment rides along. systemd cannot + # start a second instance of an already-active Type=simple unit, so on + # 2026-08-30 the 09:30-14:00 timer triggers were silent no-ops and the + # only records in that window were these sync lines -- which said nothing + # about the run that had decided to lock at 09:01 and was still waiting. + # This is the every-15-minutes heartbeat that already exists, so putting + # the observation here needs no new unit in the enforcement path. + locker = locker_unit_active() + waiting = read_queue_wait() _logger.info( - "DECISION lock=n/a reason=mode_makes_no_decision mode=%s — this mode " - "never evaluates the lock", + "DECISION lock=n/a reason=mode_makes_no_decision mode=%s " + "locker_running=%s%s — this mode never evaluates the lock", mode, + "unknown" if locker is None else locker, + ( + f" queued_behind={','.join(waiting.get('blocked_by', []))}" + if waiting + else "" + ), ) - _append_record( + record: dict[str, object] = { + "timestamp": datetime.now(tz=UTC).isoformat(), + "locked": None, + "reason": "mode_makes_no_decision", + "mode": mode, + "locker_running": locker, + } + if waiting: + record["queued_behind"] = waiting.get("blocked_by", []) + append_record(record, log_file=log_file) + + +def record_run_aborted( + reason: str, detail: str, *, log_file: Path | None = None +) -> None: + """Note that a run could not reach the decision ladder at all. + + Distinct from :func:`record_no_decision`, which covers modes that are + *designed* never to decide. This covers a run that meant to decide and + could not -- the case that produced the 2026-08-30 restart loop, where + 1695 runs died before recording anything and the only evidence was a + stack trace in the journal. + + Written at ``warning``: unlike the sync modes, this is never expected. + + Args: + reason: Machine-readable slug for the trail. + detail: One human sentence about what was missing. + log_file: Override for the trail path (for testing). + """ + _logger.warning( + "DECISION lock=n/a reason=%s — %s", + reason, + detail, + ) + append_record( { "timestamp": datetime.now(tz=UTC).isoformat(), "locked": None, - "reason": "mode_makes_no_decision", - "mode": mode, + "reason": reason, + "detail": detail, }, log_file=log_file, ) diff --git a/screen_locker/_decision_trail.py b/screen_locker/_decision_trail.py new file mode 100644 index 0000000..83e5ed3 --- /dev/null +++ b/screen_locker/_decision_trail.py @@ -0,0 +1,130 @@ +"""Writing the durable decision trail, including repeat-collapsing. + +Split out of ``_decision_log.py`` to keep every file under the 250-line cap. +``_decision_log`` owns *what* a decision is and how it reads in the journal; +this module owns how it lands on disk. +""" + +from __future__ import annotations + +import json +import logging +from pathlib import Path +from typing import Final + +_logger = logging.getLogger(__name__) + +# Outside the repo on purpose -- workout state is private and git-untracked. +DECISION_LOG_FILE: Path = ( + Path.home() / ".local" / "share" / "screen_locker" / "decisions.jsonl" +) + +# Trimmed on write so the recurring timers cannot grow this without bound. +# Writers are the 5-minute locker timer plus the 15-minute sync run (which +# records "made no decision"). Consecutive identical records collapse into +# one row, so a restart loop can no longer evict a month of history. +DECISION_LOG_MAX_ENTRIES: Final[int] = 3000 + + +# Fields that differ between two recordings of the *same* event, and so must +# not stop them collapsing into one row. +_COLLAPSE_VOLATILE_KEYS = frozenset({"timestamp", "repeat_count", "last_timestamp"}) + + +def _is_repeat(previous_line: str, record: dict[str, object]) -> bool: + """Return whether ``record`` restates the event on ``previous_line``. + + Everything but the timestamps and the repeat counter must match, so a + change in ``weekly_count`` or ``detail`` still opens a new row -- only a + genuinely identical event collapses. + + Args: + previous_line: The newest line already in the trail. + record: The record about to be written. + + Returns: + True when the two describe the same event. + """ + try: + previous = json.loads(previous_line) + except json.JSONDecodeError as exc: + # An unparsable tail is history we cannot compare against, so we keep + # it and start a new row rather than overwrite it. Said out loud: a + # corrupt trail is exactly the thing that must not stay quiet. + _logger.warning( + "Newest line of the decision trail is unparsable (%s) — starting " + "a new row instead of collapsing into it, so nothing is lost", + exc, + ) + return False + if not isinstance(previous, dict): + return False + return { + key: value + for key, value in previous.items() + if key not in _COLLAPSE_VOLATILE_KEYS + } == { + key: value + for key, value in record.items() + if key not in _COLLAPSE_VOLATILE_KEYS + } + + +def _trimmed(lines: list[str], record: dict[str, object]) -> list[str]: + """Return the retained history with ``record`` folded in. + + Consecutive identical events collapse into one row carrying + ``repeat_count`` and ``last_timestamp`` instead of appending a new line. + On 2026-08-30 a restart loop (no X server at 02:00, ``Restart=on-failure`` + every ~6s) wrote ~1693 identical ``enforced`` records in three hours and + evicted the entire history behind them: the tool built to make blind spots + impossible erased its own. Collapsing bounds any such storm to a single + row, and does the same for the every-15-minutes ``--sync-only`` runs. + + Args: + lines: The existing trail, oldest first. + record: The record to fold in. + + Returns: + The new trail, oldest first. + """ + if lines and _is_repeat(lines[-1], record): + previous = json.loads(lines[-1]) + merged = { + **record, + # The FIRST sighting stays in `timestamp` so the row still says + # when the streak began; readers wanting freshness use + # `last_timestamp` (see _web_payload.decision_age_seconds). + "timestamp": previous.get("timestamp", record["timestamp"]), + "repeat_count": int(previous.get("repeat_count", 1)) + 1, + "last_timestamp": record["timestamp"], + } + return [*lines[:-1], json.dumps(merged)] + if len(lines) >= DECISION_LOG_MAX_ENTRIES: + lines = lines[-(DECISION_LOG_MAX_ENTRIES - 1) :] + return [*lines, json.dumps(record)] + + +def append_record(record: dict[str, object], *, log_file: Path | None = None) -> None: + """Append one record to the durable trail, trimming old history. + + Never raises: failing to *record* why the locker acted must not stop the + locker from acting. A write failure is reported at ``warning`` rather than + swallowed, so the gap in the trail is itself visible. + """ + target = DECISION_LOG_FILE if log_file is None else log_file + try: + target.parent.mkdir(parents=True, exist_ok=True) + existing = ( + target.read_text(encoding="utf-8").splitlines() if target.exists() else [] + ) + kept = _trimmed([entry for entry in existing if entry.strip()], record) + target.write_text("\n".join(kept) + "\n", encoding="utf-8") + except OSError as exc: + _logger.warning( + "Could not append to the decision log at %s (%s) — this run's " + "decision is in the journal only, so the durable trail now has a " + "gap", + target, + exc, + ) diff --git a/screen_locker/_queue_state.py b/screen_locker/_queue_state.py new file mode 100644 index 0000000..c7b85d7 --- /dev/null +++ b/screen_locker/_queue_state.py @@ -0,0 +1,106 @@ +"""Publish the locker's gatelock queue wait so it is visible from outside. + +A locker run that has decided to lock but is waiting for a higher-ranked +holder (``wake_alarm``) to release the screen looks, from any other process, +exactly like a hung one: the unit is ``active``, no window is up, and nothing +is written anywhere. On 2026-08-30 that state lasted 2h58m and the status +page still read a bare "Lock would fire", which is what sent the +investigation to the heat check instead. + +The blocked run cannot answer questions about itself, so it writes this file +before it starts waiting and removes it when it stops. Readers (the web +status payload) treat its absence as "not queued". +""" + +from __future__ import annotations + +from datetime import UTC, datetime +import json +import logging +from typing import Any + +from screen_locker._constants import QUEUE_STATE_FILE + +_logger = logging.getLogger(__name__) + + +def publish_queue_wait(blocked_by: tuple[str, ...], elapsed_seconds: float) -> None: + """Record that this run is queued behind *blocked_by*, or no longer is. + + Args: + blocked_by: Apps holding the screen ahead of us; empty means clear. + elapsed_seconds: How long the wait has lasted so far. + """ + if not blocked_by: + clear_queue_wait() + return + record = { + "blocked_by": list(blocked_by), + "elapsed_seconds": round(elapsed_seconds, 1), + "updated": datetime.now(tz=UTC).isoformat(), + } + try: + QUEUE_STATE_FILE.parent.mkdir(parents=True, exist_ok=True) + QUEUE_STATE_FILE.write_text(json.dumps(record), encoding="utf-8") + except OSError as exc: + _logger.warning( + "Could not publish the queue wait to %s (%s) — the status page " + "will show this run as simply 'would lock' while it is in fact " + "blocked behind %s", + QUEUE_STATE_FILE, + exc, + ", ".join(blocked_by), + ) + + +def clear_queue_wait() -> None: + """Remove the published wait, so readers stop reporting one.""" + try: + QUEUE_STATE_FILE.unlink(missing_ok=True) + except OSError as exc: + _logger.warning( + "Could not clear the queue wait at %s (%s) — the status page may " + "keep claiming this run is queued after it has armed", + QUEUE_STATE_FILE, + exc, + ) + + +def read_queue_wait() -> dict[str, Any] | None: + """Return the currently published wait, or None when there is none. + + Returns: + The published record, or None when nothing is queued or the file + could not be read. + """ + # Absence is the normal case (nothing is queued), so it is tested for + # rather than caught -- an `except FileNotFoundError: return None` here + # would be indistinguishable from swallowing a real read failure. + if not QUEUE_STATE_FILE.exists(): + return None + try: + raw = QUEUE_STATE_FILE.read_text(encoding="utf-8") + except OSError as exc: + _logger.warning( + "Could not read the queue wait at %s (%s) — reporting 'not " + "queued', which may be wrong", + QUEUE_STATE_FILE, + exc, + ) + return None + try: + record = json.loads(raw) + except json.JSONDecodeError as exc: + _logger.warning( + "Queue wait at %s is unparsable (%s) — reporting 'not queued'", + QUEUE_STATE_FILE, + exc, + ) + return None + if not isinstance(record, dict): + _logger.warning( + "Queue wait at %s is not an object — reporting 'not queued'", + QUEUE_STATE_FILE, + ) + return None + return record diff --git a/screen_locker/_queue_wait.py b/screen_locker/_queue_wait.py new file mode 100644 index 0000000..74a7d68 --- /dev/null +++ b/screen_locker/_queue_wait.py @@ -0,0 +1,46 @@ +"""Waiting for the screen in gatelock's queue, observably. + +Separate from ``_queue_state`` on purpose: that module is a pure state-file +reader/writer, which ``_decision_log`` imports to annotate its sync lines. +Putting this function there would close the cycle +``_queue_state -> _decision_log -> _queue_state``. +""" + +from __future__ import annotations + +from typing import TYPE_CHECKING + +from gatelock import wait_for_turn + +from screen_locker._decision_log import record_run_aborted +from screen_locker._queue_state import publish_queue_wait + +if TYPE_CHECKING: + from gatelock import Arbiter + + +def wait_for_screen(arbiter: Arbiter) -> None: + """Wait for the screen, publishing the wait and recording how long it took. + + gatelock's deadline is left at its 6h default on purpose. A higher-ranked + holder means the screen IS locked, just by someone else -- on 2026-08-30 + the 2h58m wait behind ``wake_alarm`` was a real wake-alarm lock held with + the grab and VT, not an unenforced machine. Arming over it early would + draw the workout lock on top of a live alarm, which is the behaviour + gatelock's queue exists to prevent. + + Args: + arbiter: Our own published arbiter. + """ + queued = wait_for_turn(arbiter, on_state=publish_queue_wait) + if not queued.queued: + return + # The decision to lock was recorded when the run started, possibly hours + # earlier; without this the trail shows "enforced" and then silence until + # the window finally appears. + record_run_aborted( + "queued_behind_holder", + f"Waited {queued.waited_seconds:.0f}s behind " + f"{', '.join(queued.blocked_by)} before the screen was free; arming " + f"now{' (deadline hit)' if queued.timed_out else ''}.", + ) diff --git a/screen_locker/_startup_checks.py b/screen_locker/_startup_checks.py index 8984a56..e6cee96 100644 --- a/screen_locker/_startup_checks.py +++ b/screen_locker/_startup_checks.py @@ -13,6 +13,7 @@ from __future__ import annotations import logging import sys +import tkinter as tk from screen_locker._compliance_predicates import is_relaxed_day_skipped_today from screen_locker._constants import ( @@ -30,7 +31,10 @@ from screen_locker._degraded_sources import degraded_sources from screen_locker._extra_benefits import process_week_transition from screen_locker._shutdown_base import reset_to_base_if_new_day from screen_locker._sync_mixin import SyncMixin -from screen_locker._temperature import fetch_current_temp_with_status +from screen_locker._temperature import ( + HARD_TIMEOUT_SECONDS, + fetch_current_temp_with_status, +) from screen_locker._weekly_check import ( WEEKLY_WORKOUT_MINIMUM, count_weekly_workouts, @@ -148,47 +152,85 @@ class StartupChecksMixin(SyncMixin): # "skip a workout" credit — that mechanic works against the goal of # maximizing weekly workouts, so it was removed in favor of a # shutdown-time-only reward (see _apply_weekly_shutdown_bonus). - self._check_heat_skip_exit() + heat = self._check_heat_skip_exit() # Nothing excused today: falling through here means the lock WILL be # built. Recorded explicitly so the trail shows enforcement happening, # not merely the absence of a skip -- "no line at all" was precisely # the signature of the 2026-08 outage. + # + # The heat reading rides along because the check was previously + # invisible on its most common outcome: a grep for "temperat|heat" + # across ~1700 runs returned nothing, so "checked, 27°C, under the + # threshold" and "never got here" looked identical in the trail. self._record_decision( locked=True, reason="enforced", detail="No exemption applied — building the lock screen.", + heat_check=heat, ) - def _check_heat_skip_exit(self) -> None: + def _check_heat_skip_exit(self) -> str: """Exit early if today qualifies for the extreme-heat skip dialog. Fail-closed by construction: a failed or timed-out temperature fetch falls straight through to the lock, same as "not hot enough" — the only difference is this logs *why* explicitly, so a fetch failure is never silently indistinguishable from a normal day in the logs. + + Returns: + A short summary of what the check saw, for the decision record. + Only returns at all when the lock is going ahead; the skip path + exits the process from inside ``_record_skip``. """ check = fetch_current_temp_with_status(HEAT_SKIP_CITY) if check.timed_out: _logger.warning( - "Heat-skip temperature check timed out — defaulting to lock." + "Heat-skip temperature check timed out after %.1fs — " + "defaulting to lock.", + HARD_TIMEOUT_SECONDS, ) - return + return "timed_out" if check.temp_celsius is None: _logger.warning( "Heat-skip temperature check failed (network/API error) — " "defaulting to lock." ) - return + return "fetch_failed" if check.temp_celsius < HEAT_SKIP_TEMP_THRESHOLD: - return + # Logged even though nothing is wrong: this is the check's most + # common outcome and it used to leave no trace at all, so "the + # heat check ran and said no" was indistinguishable from "the + # heat check was never reached". + _logger.info( + "%s is %.0f°C, under the %d°C heat-skip threshold — " + "the lock goes ahead.", + HEAT_SKIP_CITY, + check.temp_celsius, + HEAT_SKIP_TEMP_THRESHOLD, + ) + return f"{check.temp_celsius:.0f}C_under_threshold" _logger.info( "Temperature %.0f°C exceeds threshold — showing heat-skip dialog.", check.temp_celsius, ) - if self._show_heat_skip_dialog(check.temp_celsius): + try: + skipped = self._show_heat_skip_dialog(check.temp_celsius) + except tk.TclError as exc: + # The dialog owns its own tk.Tk(). With no reachable display that + # raises here, and letting it escape would kill the process before + # the "enforced" record below is written -- a lock that silently + # never happened. Offering no skip is the fail-closed answer. + _logger.warning( + "Heat-skip dialog could not be shown (%s) — defaulting to " + "lock rather than skipping the workout.", + exc, + ) + return f"{check.temp_celsius:.0f}C_dialog_unavailable" + if skipped: self._save_heat_skip_log(check.temp_celsius) self._record_skip( "heat_skip", f"User skipped the workout due to heat ({check.temp_celsius:.0f}°C).", temp_celsius=round(check.temp_celsius, 1), ) + return f"{check.temp_celsius:.0f}C_skip_declined" diff --git a/screen_locker/_temperature.py b/screen_locker/_temperature.py index 6058d6e..43d100f 100644 --- a/screen_locker/_temperature.py +++ b/screen_locker/_temperature.py @@ -6,23 +6,51 @@ user claims about the temperature. from __future__ import annotations -from concurrent.futures import ThreadPoolExecutor +from concurrent.futures import Future from concurrent.futures import TimeoutError as _FutureTimeoutError from dataclasses import dataclass +import http.client import json import logging +import threading +from typing import TYPE_CHECKING import urllib.error import urllib.request +if TYPE_CHECKING: + from collections.abc import Callable + _logger = logging.getLogger(__name__) _WTTR_URL = "https://wttr.in/{city}?format=j1" -_TIMEOUT_SECONDS = 5 +_TIMEOUT_SECONDS = 4 # urlopen's `timeout` bounds the socket connect/read, but not necessarily DNS # resolution (`getaddrinfo`) on every platform/resolver — a stalled resolver # can block far past `_TIMEOUT_SECONDS` with no visible failure. This is a # second, hard wall-clock ceiling enforced independently in a worker thread. -HARD_TIMEOUT_SECONDS = 6.0 +# 5.0 is the whole budget the locker is allowed to spend deciding whether it +# is too hot to train; the socket timeout is set below it so the ordinary +# network path fails first and reports *why* rather than just "too slow". +HARD_TIMEOUT_SECONDS = 5.0 + +# Everything `urlopen` + `json.loads` + the subscripting below can raise. +# Spelled out rather than caught as a blind `except Exception`, which ruff +# rejects (BLE001) and which this repo has no escape hatch for. +# `http.client.HTTPException` (IncompleteRead, BadStatusLine, ...) is the +# one that used to be missing: it inherits Exception, *not* OSError, so it +# escaped this function, escaped `future.result()` (which only catches the +# timeout), and killed the locker before it could record its decision — a +# lock that silently never happened. +_FETCH_ERRORS = ( + urllib.error.URLError, + TimeoutError, + OSError, + http.client.HTTPException, + json.JSONDecodeError, + KeyError, + IndexError, + ValueError, +) @dataclass(frozen=True) @@ -33,6 +61,38 @@ class TemperatureCheck: timed_out: bool +def submit_background[T](fn: Callable[[], T]) -> Future[T]: + """Run *fn* on a daemon thread and return a Future for its result. + + Deliberately not a ``ThreadPoolExecutor``. Its worker threads are + non-daemon and joined by an interpreter-exit hook, so a genuinely stuck + DNS lookup kept the locker's process alive past ``sys.exit(0)`` — the + hard timeout below returned on time while the process did not. A daemon + thread is abandoned at exit, which is the correct behaviour for a + fire-and-forget diagnostic read. + + Args: + fn: The zero-argument callable to run off the calling thread. + + Returns: + A Future that resolves when *fn* returns. + """ + future: Future[T] = Future() + + def _run() -> None: + try: + future.set_result(fn()) + except _FETCH_ERRORS as exc: + # Never reachable via _fetch_current_temp_celsius_unbounded, which + # handles these itself; here so a future caller cannot turn a + # background thread into a future that resolves to nothing. + _logger.warning("Background fetch failed: %s", exc) + future.set_exception(exc) + + threading.Thread(target=_run, daemon=True, name="temperature-fetch").start() + return future + + def _fetch_current_temp_celsius_unbounded(city: str) -> float | None: """Return the current temperature in °C for *city*, or None on failure. @@ -41,6 +101,12 @@ def _fetch_current_temp_celsius_unbounded(city: str) -> float | None: May block past `_TIMEOUT_SECONDS` if DNS resolution stalls — callers should go through `fetch_current_temp_with_status` for a hard bound instead of calling this directly. + + Args: + city: The city name to look up, URL-quoted before use. + + Returns: + The temperature in °C, or None if it could not be determined. """ url = _WTTR_URL.format(city=urllib.request.quote(city, safe="")) try: @@ -48,11 +114,13 @@ def _fetch_current_temp_celsius_unbounded(city: str) -> float | None: data = json.loads(resp.read()) temp_str = data["current_condition"][0]["temp_C"] return float(temp_str) - except (urllib.error.URLError, TimeoutError, OSError) as exc: - _logger.warning("Temperature fetch failed (network): %s", exc) - return None - except (KeyError, IndexError, ValueError, json.JSONDecodeError) as exc: - _logger.warning("Temperature fetch failed (parse): %s", exc) + except _FETCH_ERRORS as exc: + _logger.warning( + "Temperature fetch failed (%s: %s) — the caller must fail closed " + "and lock rather than treat this as 'not hot'", + type(exc).__name__, + exc, + ) return None @@ -61,21 +129,37 @@ def fetch_current_temp_with_status( ) -> TemperatureCheck: """Fetch °C for *city*, bounded to *hard_timeout* seconds wall-clock. - Runs the fetch in a worker thread and stops waiting on it after + Runs the fetch on a daemon thread and stops waiting on it after *hard_timeout* regardless of what the network call is doing internally - (DNS, connect, read). The worker thread itself can't be killed and may - keep running in the background after we give up on it — acceptable for - a fire-and-forget diagnostic read. Distinguishes "timed out" from other - failures (network/parse errors) so callers can report which happened. + (DNS, connect, read). The thread itself can't be killed and may keep + running in the background after we give up on it — acceptable for a + fire-and-forget diagnostic read, and harmless at exit because it is a + daemon. Distinguishes "timed out" from other failures (network/parse + errors) so callers can report which happened. + + Args: + city: The city name to look up. + hard_timeout: Wall-clock ceiling in seconds. + + Returns: + The temperature and whether the wall-clock ceiling was hit. """ - executor = ThreadPoolExecutor(max_workers=1) - future = executor.submit(_fetch_current_temp_celsius_unbounded, city) - executor.shutdown(wait=False) + future = submit_background(lambda: _fetch_current_temp_celsius_unbounded(city)) try: temp = future.result(timeout=hard_timeout) except _FutureTimeoutError: _logger.warning( - "Temperature fetch exceeded hard timeout of %.1fs", hard_timeout + "Temperature fetch exceeded hard timeout of %.1fs — the caller " + "must fail closed and lock rather than treat this as 'not hot'", + hard_timeout, ) return TemperatureCheck(temp_celsius=None, timed_out=True) + except _FETCH_ERRORS as exc: + _logger.warning( + "Temperature fetch raised past its own handler (%s: %s) — " + "reporting failure so the caller fails closed and locks", + type(exc).__name__, + exc, + ) + return TemperatureCheck(temp_celsius=None, timed_out=False) return TemperatureCheck(temp_celsius=temp, timed_out=False) diff --git a/screen_locker/_temperature_status_mixin.py b/screen_locker/_temperature_status_mixin.py index 0721427..e9a97b1 100644 --- a/screen_locker/_temperature_status_mixin.py +++ b/screen_locker/_temperature_status_mixin.py @@ -15,11 +15,10 @@ writes to ``log.json``. Host class must provide: from __future__ import annotations -from concurrent.futures import ThreadPoolExecutor # pylint: disable=no-name-in-module from typing import TYPE_CHECKING from screen_locker._constants import HEAT_SKIP_CITY, HEAT_SKIP_TEMP_THRESHOLD -from screen_locker._temperature import HARD_TIMEOUT_SECONDS +from screen_locker._temperature import HARD_TIMEOUT_SECONDS, submit_background if TYPE_CHECKING: import tkinter as tk @@ -83,9 +82,13 @@ class TemperatureStatusMixin: before this call returns would trigger a second, redundant render from within the same call stack that hasn't finished the first one. """ - executor = ThreadPoolExecutor(max_workers=1) - self._temp_future = executor.submit(self.temperature_fetcher, HEAT_SKIP_CITY) - executor.shutdown(wait=False) + # Shares _temperature.submit_background rather than spinning up its + # own ThreadPoolExecutor per open and per refresh: those workers are + # non-daemon and joined at interpreter exit, so one stalled fetch + # held the whole process open past sys.exit(0). + self._temp_future = submit_background( + lambda: self.temperature_fetcher(HEAT_SKIP_CITY) + ) self.root.after(500, self._poll_temperature_check) def _poll_temperature_check(self) -> None: diff --git a/screen_locker/_web_decisions.py b/screen_locker/_web_decisions.py new file mode 100644 index 0000000..0465756 --- /dev/null +++ b/screen_locker/_web_decisions.py @@ -0,0 +1,95 @@ +"""The decision-history payload, with timestamps rendered server-side. + +Split out of ``_web_payload.py`` to keep every file under the 250-line cap. + +The local-time rendering lives here rather than in the browser because +LibreWolf's ``privacy.resistFingerprinting`` pins JavaScript's ``Date`` to +UTC: on 2026-08-30 a 14:00 CEST decision rendered as "12:00 PM" beside a +correct, server-computed "6m ago", and the two-hour disagreement made a live +page look stale. +""" + +from __future__ import annotations + +from datetime import datetime +import logging +from typing import Any + +from screen_locker._decision_log import read_decisions + +_logger = logging.getLogger(__name__) + +# How many decisions the Why view gets by default. The trail holds 3000; +# the browser only ever needs the recent tail to answer "why did nothing +# happen". +DEFAULT_DECISION_LIMIT = 200 + + +def build_decisions_payload( + *, + limit: int = DEFAULT_DECISION_LIMIT, +) -> dict[str, Any]: + """Build the decision-history payload, newest first. + + Args: + limit: Maximum number of decisions to return. + + Returns: + The recent decisions and the total the trail holds. + """ + decisions = read_decisions() + tail = decisions[-limit:] if limit > 0 else decisions + return { + "total": len(decisions), + "returned": len(tail), + "decisions": [_with_local_stamps(entry) for entry in reversed(tail)], + } + + +def _local_stamp(value: object) -> str | None: + """Render one ISO timestamp in this machine's local time. + + Formatted server-side on purpose. The browser used to do it with + ``toLocaleString``, which LibreWolf's ``privacy.resistFingerprinting`` + pins to UTC -- so on 2026-08-30 a 14:00 CEST decision rendered as + "12:00 PM", two hours stale-looking, right next to a correct + server-computed "6m ago". + + Args: + value: The stored ISO-8601 timestamp, if it is one. + + Returns: + A local-time string, or None when there is nothing to render. + """ + if not isinstance(value, str): + return None + try: + moment = datetime.fromisoformat(value) + except ValueError: + _logger.warning( + "Decision timestamp %r is unparsable — leaving it unformatted " + "rather than showing a wrong local time", + value, + ) + return None + return moment.astimezone().strftime("%b %d, %H:%M") + + +def _with_local_stamps(entry: dict[str, object]) -> dict[str, object]: + """Return *entry* with server-rendered local-time fields added. + + Args: + entry: One decision record from the trail. + + Returns: + The record plus ``local_time`` (and ``local_last_time`` for a + collapsed row). + """ + enriched = dict(entry) + local = _local_stamp(entry.get("timestamp")) + if local is not None: + enriched["local_time"] = local + last_local = _local_stamp(entry.get("last_timestamp")) + if last_local is not None: + enriched["local_last_time"] = last_local + return enriched diff --git a/screen_locker/_web_payload.py b/screen_locker/_web_payload.py index 216920e..184adcd 100644 --- a/screen_locker/_web_payload.py +++ b/screen_locker/_web_payload.py @@ -18,9 +18,14 @@ import logging from pathlib import Path from typing import Any -from screen_locker._armed_state import collect_states, systemctl_available +from screen_locker._armed_state import ( + collect_states, + locker_unit_active, + systemctl_available, +) from screen_locker._decision_log import DECISION_LOG_FILE, read_decisions from screen_locker._log_io import load_workout_log +from screen_locker._queue_state import read_queue_wait from screen_locker._status_data import gather_status from screen_locker._status_projection import ( compliance_state_word, @@ -39,10 +44,6 @@ LOG_FILE = Path(__file__).resolve().parent / "log.json" # scripts/disarm_guard.sh, which is the thing that writes it. DISARM_MARKER = Path.home() / ".local" / "share" / "screen_locker" / "DISARMED" -# How many decisions the Why view gets by default. The trail holds 3000; the -# browser only ever needs the recent tail to answer "why did nothing happen". -DEFAULT_DECISION_LIMIT = 200 - def workout_credits_today(*, now: datetime | None = None) -> int: """Return how many workout credits today has earned so far. @@ -77,6 +78,13 @@ def build_status_payload(*, now: datetime | None = None) -> dict[str, Any]: credits_today = workout_credits_today(now=now) return { "snapshot": asdict(snapshot), + # Whether a locker run has decided to lock and is waiting for a + # higher-ranked holder to release the screen. Without this the page + # says "Lock would fire" both when nothing is running and when a run + # is blocked behind wake_alarm -- two very different situations that + # looked identical on 2026-08-30. + "queue_wait": read_queue_wait(), + "locker_running": locker_unit_active(), "summary_line": format_summary_line(snapshot), "compliance_state": compliance_state_word(snapshot), # The gaming budget is decided by steam-backlog-enforcer, which owns the @@ -94,27 +102,6 @@ def build_status_payload(*, now: datetime | None = None) -> dict[str, Any]: } -def build_decisions_payload( - *, - limit: int = DEFAULT_DECISION_LIMIT, -) -> dict[str, Any]: - """Build the decision-history payload, newest first. - - Args: - limit: Maximum number of decisions to return. - - Returns: - The recent decisions and the total the trail holds. - """ - decisions = read_decisions() - tail = decisions[-limit:] if limit > 0 else decisions - return { - "total": len(decisions), - "returned": len(tail), - "decisions": list(reversed(tail)), - } - - def _log_age_seconds(*, now: datetime | None = None) -> float | None: """Return how long ago the workout log was last written. @@ -152,7 +139,12 @@ def _last_decision_age_seconds(*, now: datetime | None = None) -> float | None: decisions = read_decisions() if not decisions: return None - stamp = decisions[-1].get("timestamp") + newest = decisions[-1] + # `timestamp` is when a collapsed row's streak *began*, which for the + # every-15-minutes --sync-only runs would report an hours-old trail as + # stale while it is in fact current. `last_timestamp` is the most recent + # sighting, so it is what freshness must be measured from. + stamp = newest.get("last_timestamp", newest.get("timestamp")) if not isinstance(stamp, str): return None try: diff --git a/screen_locker/_web_server.py b/screen_locker/_web_server.py index 75229b2..2421d4f 100644 --- a/screen_locker/_web_server.py +++ b/screen_locker/_web_server.py @@ -27,9 +27,11 @@ from pathlib import Path from typing import TYPE_CHECKING, Any from urllib.parse import parse_qs, urlsplit -from screen_locker._web_payload import ( +from screen_locker._web_decisions import ( DEFAULT_DECISION_LIMIT, build_decisions_payload, +) +from screen_locker._web_payload import ( build_health_payload, build_status_payload, ) diff --git a/screen_locker/_window_setup.py b/screen_locker/_window_setup.py index 7bf0799..afbcd5b 100644 --- a/screen_locker/_window_setup.py +++ b/screen_locker/_window_setup.py @@ -17,9 +17,9 @@ from gatelock import ( Arbiter, LockWindow, ScrollableSurface, - wait_for_turn, ) +from screen_locker._queue_wait import wait_for_screen from screen_locker._surface_group import FrameGroup if TYPE_CHECKING: @@ -93,7 +93,7 @@ class WindowSetupMixin: # leetcode_guard's own fix for the same grab race (gatelock's own # module docstring: 2026-07-25, and again with diet_guard on # 2026-08-21). - wait_for_turn(arbiter) + wait_for_screen(arbiter) arbiter.acquire_holder() lock = LockWindow(self.root, self._colors, hooks=self, arbiter=arbiter) lock.setup() diff --git a/screen_locker/screen_lock.py b/screen_locker/screen_lock.py index f89f5df..a2f6c05 100755 --- a/screen_locker/screen_lock.py +++ b/screen_locker/screen_lock.py @@ -7,6 +7,7 @@ Requires user to log their workout to unlock the screen. from __future__ import annotations import logging +import os from pathlib import Path import sys import tkinter as tk @@ -33,6 +34,7 @@ from screen_locker._constants import ( SCHEDULED_SKIPS_FILE, SICK_LOCKOUT_SECONDS, ) +from screen_locker._decision_log import record_run_aborted from screen_locker._early_bird import EarlyBirdMixin from screen_locker._heat_skip import HeatSkipMixin from screen_locker._log_mixin import LogMixin @@ -139,7 +141,35 @@ class ScreenLocker( self.workout_data: dict[str, str] = {} self._relaxed_day_mode: bool = False self._check_early_exits(verify_only=verify_only) - self.root = GateRoot() + try: + self.root = GateRoot() + except tk.TclError as exc: + _logger.warning( + "Could not open a window on DISPLAY=%s (%s) — this run cannot " + "enforce anything, so it stops cleanly instead of failing and " + "being restarted in a loop.", + os.environ.get("DISPLAY"), + exc, + ) + # No reachable X server. This used to escape as an unhandled + # TclError and exit 1, which `Restart=on-failure` turned into a + # storm: on 2026-08-30 the display was down from 02:00 and the + # unit restarted ~1695 times in three hours, ~6.3s apart -- just + # slow enough to stay under the default StartLimitBurst=5/10s, and + # fast enough that the identical records evicted the entire + # decision trail behind them. + # + # There is no screen to lock, so there is nothing this run can + # enforce; exiting 0 (which RestartPreventExitStatus=0 honours) + # is the correct answer, and recording it keeps "could not run" + # from looking like "chose not to lock". + record_run_aborted( + "no_display", + f"No usable X display ({exc}) — nothing to lock, so this run " + f"stops instead of restarting. DISPLAY={os.environ.get('DISPLAY')!r}", + ) + self._instance_lock.release() + sys.exit(0) self.root.on_callback_error = self.on_callback_error title_suffix = ( " [VERIFY]" if verify_only else (" [DEMO MODE]" if demo_mode else "") diff --git a/screen_locker/tests/_isolated_state.py b/screen_locker/tests/_isolated_state.py index 4970c97..0b30bed 100644 --- a/screen_locker/tests/_isolated_state.py +++ b/screen_locker/tests/_isolated_state.py @@ -44,7 +44,21 @@ ISOLATED_STATE: tuple[tuple[str, tuple[str, ...]], ...] = ( # The durable lock-decision trail. Written on EVERY locker run, so without # this the suite would append test decisions to the user's real # enforcement history in ~/.local/share/screen_locker/. - ("decisions.jsonl", ("_decision_log.DECISION_LOG_FILE",)), + # BOTH bindings: _decision_trail owns the writer and reads its own + # module global, so patching only _decision_log would silently let + # the suite write into the real enforcement history. + ( + "decisions.jsonl", + ( + "_decision_log.DECISION_LOG_FILE", + "_decision_trail.DECISION_LOG_FILE", + ), + ), + # Written whenever a locker run waits in gatelock's queue. + ( + "queue_state.json", + ("_constants.QUEUE_STATE_FILE", "_queue_state.QUEUE_STATE_FILE"), + ), # Real $XDG_RUNTIME_DIR/gatelock file; unisolated, only the first test in # the whole suite would win it, since it is shared across all of them. ( diff --git a/screen_locker/tests/conftest.py b/screen_locker/tests/conftest.py index 48ad25b..6e09840 100644 --- a/screen_locker/tests/conftest.py +++ b/screen_locker/tests/conftest.py @@ -19,6 +19,7 @@ from unittest.mock import MagicMock, patch import pytest +from screen_locker._degraded_sources import clear_degraded_sources from screen_locker.tests._gatelock_fixtures import ( FAKE_OUTPUTS, TWO_OUTPUTS, @@ -155,6 +156,19 @@ def _isolate_home(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> Iterator[N yield +@pytest.fixture(autouse=True) +def _clear_degraded_sources() -> Iterator[None]: + """Reset the process-scoped degraded-backend registry around every test. + + ``_degraded_sources._degraded`` is a module-level list, so a test that + records a failed Firebase read leaks into every test after it. Invisible + in file order; only ``pytest-randomly`` (which the CI mirror enables and + the local venvs do not) exposes it -- it failed on push and nowhere else. + """ + clear_degraded_sources() + return + + @pytest.fixture(autouse=True) def _isolate_state_files(tmp_path: Path) -> Iterator[None]: """Redirect every on-disk state path to tmp_path for every test. diff --git a/screen_locker/tests/test_armed_state.py b/screen_locker/tests/test_armed_state.py index 187df48..da68dd1 100644 --- a/screen_locker/tests/test_armed_state.py +++ b/screen_locker/tests/test_armed_state.py @@ -11,12 +11,15 @@ import subprocess from unittest.mock import MagicMock, patch from screen_locker._armed_state import ( + REQUIRED_SERVICES, REQUIRED_TIMERS, TimerState, collect_states, + locker_unit_active, systemctl_available, ) +_ALL_UNITS = (*REQUIRED_TIMERS, *REQUIRED_SERVICES) _PKG = "screen_locker._armed_state" _LISTED = """NEXT LEFT LAST PASSED UNIT @@ -46,25 +49,31 @@ class TestTimerState: def test_enabled_and_scheduled_is_armed(self) -> None: """Both halves present means the timer will really fire.""" - state = TimerState("t", enabled=True, enabled_raw="enabled", scheduled=True) + state = TimerState( + "t.timer", enabled=True, enabled_raw="enabled", scheduled=True + ) assert state.armed is True assert "OK" in state.describe() def test_enabled_but_unscheduled_is_not_armed(self) -> None: """The exact 2026-08 failure: enabled, but the job was deleted.""" - state = TimerState("t", enabled=True, enabled_raw="enabled", scheduled=False) + state = TimerState( + "t.timer", enabled=True, enabled_raw="enabled", scheduled=False + ) assert state.armed is False assert "no next trigger" in state.describe() def test_scheduled_but_disabled_is_not_armed(self) -> None: """A transient start does not survive a reboot.""" - state = TimerState("t", enabled=False, enabled_raw="disabled", scheduled=True) + state = TimerState( + "t.timer", enabled=False, enabled_raw="disabled", scheduled=True + ) assert state.armed is False assert "not enabled (is-enabled=disabled)" in state.describe() def test_unknown_enabled_state_is_named(self) -> None: """An empty is-enabled reads as unknown, not as a blank.""" - state = TimerState("t", enabled=False, enabled_raw="", scheduled=False) + state = TimerState("t.timer", enabled=False, enabled_raw="", scheduled=False) assert "is-enabled=unknown" in state.describe() @@ -86,16 +95,50 @@ class TestCollectStates: """collect_states reads systemd's own view, not the unit files.""" def test_all_armed(self) -> None: - """Both timers enabled and listed with a next trigger.""" + """Every timer enabled and listed, and the login run anchored.""" with patch(f"{_PKG}.subprocess.run") as run: run.side_effect = [ _completed(_LISTED), - *[_completed("enabled\n") for _ in REQUIRED_TIMERS], + _completed("active\n"), + *[_completed("enabled\n") for _ in _ALL_UNITS], ] states = collect_states() - assert [s.name for s in states] == list(REQUIRED_TIMERS) + assert [s.name for s in states] == list(_ALL_UNITS) assert all(s.armed for s in states) + def test_the_login_run_is_checked_too(self) -> None: + """The 2026-08-30 gap: timers fine, login run silently disabled. + + Enforcement read "armed" through a 24-minute unenforced window + because only the timers were ever looked at. + """ + with patch(f"{_PKG}.subprocess.run") as run: + run.side_effect = [ + _completed(_LISTED), + _completed("active\n"), + *[_completed("enabled\n") for _ in REQUIRED_TIMERS], + _completed("disabled\n", code=1), + ] + states = collect_states() + service = states[-1] + assert service.name == REQUIRED_SERVICES[0] + assert service.armed is False + assert not all(s.armed for s in states) + + def test_an_inactive_login_target_disarms_the_service(self) -> None: + """Enabled is not enough: i3 may never activate the target.""" + with patch(f"{_PKG}.subprocess.run") as run: + run.side_effect = [ + _completed(_LISTED), + _completed("inactive\n", code=3), + *[_completed("enabled\n") for _ in _ALL_UNITS], + ] + states = collect_states() + service = states[-1] + assert service.enabled is True + assert service.armed is False + assert "is not active" in service.describe() + def test_timer_listed_with_no_next_trigger_is_unscheduled(self) -> None: """An "n/a" NEXT column means systemd will never run it.""" listed = ( @@ -104,7 +147,8 @@ class TestCollectStates: with patch(f"{_PKG}.subprocess.run") as run: run.side_effect = [ _completed(listed), - *[_completed("enabled\n") for _ in REQUIRED_TIMERS], + _completed("inactive\n", code=3), + *[_completed("enabled\n") for _ in _ALL_UNITS], ] states = collect_states() assert all(not s.scheduled for s in states) @@ -114,7 +158,8 @@ class TestCollectStates: with patch(f"{_PKG}.subprocess.run") as run: run.side_effect = [ _completed(_LISTED), - *[_completed("disabled\n", code=1) for _ in REQUIRED_TIMERS], + _completed("active\n"), + *[_completed("disabled\n", code=1) for _ in _ALL_UNITS], ] states = collect_states() assert all(not s.enabled for s in states) @@ -133,3 +178,37 @@ class TestCollectStates: ): states = collect_states() assert all(not s.armed for s in states) + + +class TestLockerUnitActive: + """ "Would lock" says nothing about whether anything is enforcing it.""" + + def test_an_active_unit_reads_as_running(self) -> None: + """The ordinary case while a lock is up.""" + with patch(f"{_PKG}.subprocess.run", return_value=_completed("active\n")): + assert locker_unit_active() is True + + def test_an_inactive_unit_reads_as_not_running(self) -> None: + """The 2026-08-30 screenshot: decided to lock, nothing running.""" + with patch( + f"{_PKG}.subprocess.run", return_value=_completed("inactive\n", code=3) + ): + assert locker_unit_active() is False + + def test_no_systemctl_is_unknown_not_false(self) -> None: + """ "Could not ask" must never render as "not running".""" + with patch(f"{_PKG}.shutil.which", return_value=None): + assert locker_unit_active() is None + + def test_a_failed_probe_is_unknown_not_false(self) -> None: + """A systemctl that cannot run answers nothing, not "no".""" + with patch(f"{_PKG}.subprocess.run", side_effect=OSError("no exec")): + assert locker_unit_active() is None + + def test_an_armed_login_run_says_what_anchors_it(self) -> None: + """The Health row must name the target, since that is what drifts.""" + state = TimerState( + REQUIRED_SERVICES[0], enabled=True, enabled_raw="enabled", scheduled=True + ) + assert state.armed is True + assert "graphical-session.target" in state.describe() diff --git a/screen_locker/tests/test_compliance_state_part2.py b/screen_locker/tests/test_compliance_state_part2.py index 630bbbb..a5bdb6f 100644 --- a/screen_locker/tests/test_compliance_state_part2.py +++ b/screen_locker/tests/test_compliance_state_part2.py @@ -82,7 +82,7 @@ class TestExplainLockDecision: now=now, ) assert result.fired is True - assert result.stage == "full_lock_pending_heat_check" + assert result.stage == "would_lock" assert result.auto_upgrade.via == "early_bird_expired" expired_step = next( t for t in result.trace if t.name == "early_bird_pending_expired" @@ -229,7 +229,7 @@ class TestExplainLockDecision: now=datetime.now(tz=UTC).astimezone().replace(hour=12, minute=0), ) assert result.fired is True - assert result.stage == "full_lock_pending_heat_check" + assert result.stage == "would_lock" assert result.auto_upgrade.via == "none" assert result.heat_skip_evaluated is False diff --git a/screen_locker/tests/test_decision_log.py b/screen_locker/tests/test_decision_log.py index 4fa7bf0..1947f63 100644 --- a/screen_locker/tests/test_decision_log.py +++ b/screen_locker/tests/test_decision_log.py @@ -19,13 +19,15 @@ from screen_locker._decision_log import ( LockDecision, read_decisions, record_decision, - record_no_decision, ) if TYPE_CHECKING: import pytest +_PKG = "screen_locker._decision_log" + + class TestLockDecisionRendering: """The one-line summary must stay greppable and complete.""" @@ -153,19 +155,6 @@ class TestRecordDecision: ) -class TestRecordNoDecision: - """Modes that never evaluate the lock must be distinguishable.""" - - def test_records_mode_and_null_lock(self, tmp_path: Path) -> None: - """'did not decide' must not look like 'decided not to lock'.""" - target = tmp_path / "d.jsonl" - record_no_decision("--sync-only", log_file=target) - (record,) = read_decisions(log_file=target) - assert record["locked"] is None - assert record["reason"] == "mode_makes_no_decision" - assert record["mode"] == "--sync-only" - - class TestReadDecisions: """Reading must degrade gracefully, never crash an investigation.""" diff --git a/screen_locker/tests/test_decision_log_modes.py b/screen_locker/tests/test_decision_log_modes.py new file mode 100644 index 0000000..59492b9 --- /dev/null +++ b/screen_locker/tests/test_decision_log_modes.py @@ -0,0 +1,91 @@ +"""Tests for the run-modes that never reach the lock decision. + +Split out of test_decision_log.py for the 250-line cap. These cover the two +records that keep "this run did not decide" distinguishable from "this run +decided not to lock" -- the confusion that hid a 13-day enforcement outage. +""" + +from __future__ import annotations + +from typing import TYPE_CHECKING +from unittest.mock import patch + +from screen_locker._decision_log import ( + read_decisions, + record_no_decision, + record_run_aborted, +) + +if TYPE_CHECKING: + from pathlib import Path + + import pytest + +_PKG = "screen_locker._decision_log" + + +class TestRecordNoDecision: + """Modes that never evaluate the lock must be distinguishable.""" + + def test_records_mode_and_null_lock(self, tmp_path: Path) -> None: + """'did not decide' must not look like 'decided not to lock'.""" + target = tmp_path / "d.jsonl" + record_no_decision("--sync-only", log_file=target) + (record,) = read_decisions(log_file=target) + assert record["locked"] is None + assert record["reason"] == "mode_makes_no_decision" + assert record["mode"] == "--sync-only" + + def test_it_reports_what_the_locker_was_doing(self, tmp_path: Path) -> None: + """The every-15-minutes heartbeat is where this gets observed. + + systemd cannot start a second instance of an already-active + Type=simple unit, so on 2026-08-30 the 09:30-14:00 timer triggers were + silent no-ops and these sync lines were the only records in the + window -- saying nothing about the run that had decided to lock at + 09:01 and was still waiting behind wake_alarm. + """ + target = tmp_path / "d.jsonl" + with ( + patch(f"{_PKG}.locker_unit_active", return_value=True), + patch( + f"{_PKG}.read_queue_wait", + return_value={"blocked_by": ["wake_alarm"], "elapsed_seconds": 9000}, + ), + ): + record_no_decision("--sync-only", log_file=target) + (record,) = read_decisions(log_file=target) + assert record["locker_running"] is True + assert record["queued_behind"] == ["wake_alarm"] + + def test_an_unqueued_run_omits_the_blocker_field(self, tmp_path: Path) -> None: + """No blocker is the normal case; it must not add noise to every row.""" + target = tmp_path / "d.jsonl" + with ( + patch(f"{_PKG}.locker_unit_active", return_value=False), + patch(f"{_PKG}.read_queue_wait", return_value=None), + ): + record_no_decision("--sync-only", log_file=target) + (record,) = read_decisions(log_file=target) + assert "queued_behind" not in record + assert record["locker_running"] is False + + +class TestRecordRunAborted: + """A run that meant to decide and could not is its own outcome.""" + + def test_it_records_the_reason_and_the_detail(self, tmp_path: Path) -> None: + """1695 runs died at 02:00 leaving only a stack trace behind.""" + target = tmp_path / "d.jsonl" + record_run_aborted("no_display", "No usable X display.", log_file=target) + (record,) = read_decisions(log_file=target) + assert record["locked"] is None + assert record["reason"] == "no_display" + assert record["detail"] == "No usable X display." + + def test_it_is_loud(self, tmp_path: Path, caplog: pytest.LogCaptureFixture) -> None: + """Unlike the sync modes, this is never an expected outcome.""" + record_run_aborted( + "no_display", "No usable X display.", log_file=tmp_path / "d" + ) + assert any(r.levelname == "WARNING" for r in caplog.records) diff --git a/screen_locker/tests/test_decision_trail.py b/screen_locker/tests/test_decision_trail.py new file mode 100644 index 0000000..504539f --- /dev/null +++ b/screen_locker/tests/test_decision_trail.py @@ -0,0 +1,128 @@ +"""Tests for _decision_trail: collapsing repeats so a storm cannot wipe history. + +On 2026-08-30 the locker had no X server at 02:00, crashed, was restarted by +``Restart=on-failure`` every ~6.3s, and wrote ~1693 identical records in three +hours. At ``DECISION_LOG_MAX_ENTRIES = 3000`` that evicted everything behind +them: the tool built to make blind spots impossible erased its own history. +""" + +from __future__ import annotations + +import json +from typing import TYPE_CHECKING +from unittest.mock import MagicMock, patch + +from screen_locker._decision_trail import append_record + +if TYPE_CHECKING: + from pathlib import Path + + +def _rows(target: Path) -> list[dict[str, object]]: + """Return the trail as parsed records. + + Args: + target: The trail file. + + Returns: + One dict per line, oldest first. + """ + return [json.loads(line) for line in target.read_text().splitlines() if line] + + +def _record(index: int, *, reason: str = "enforced") -> dict[str, object]: + """Build one record whose only varying field is its timestamp. + + Args: + index: Distinguishes the timestamps. + reason: The decision reason. + + Returns: + A record ready for append_record. + """ + return { + "timestamp": f"2026-08-30T02:{index:02d}:00+00:00", + "locked": True, + "reason": reason, + } + + +class TestCollapsing: + """Consecutive identical events become one row, not N.""" + + def test_a_storm_of_identical_records_stays_one_row(self, tmp_path: Path) -> None: + """The 1695-restart loop, in miniature.""" + target = tmp_path / "d.jsonl" + for i in range(50): + append_record(_record(i), log_file=target) + rows = _rows(target) + assert len(rows) == 1 + assert rows[0]["repeat_count"] == 50 + + def test_the_row_keeps_both_ends_of_the_streak(self, tmp_path: Path) -> None: + """`timestamp` is when it began; `last_timestamp` is freshness.""" + target = tmp_path / "d.jsonl" + append_record(_record(0), log_file=target) + append_record(_record(7), log_file=target) + row = _rows(target)[0] + assert row["timestamp"] == "2026-08-30T02:00:00+00:00" + assert row["last_timestamp"] == "2026-08-30T02:07:00+00:00" + + def test_a_different_decision_opens_a_new_row(self, tmp_path: Path) -> None: + """Collapsing must never hide a change of outcome.""" + target = tmp_path / "d.jsonl" + append_record(_record(0), log_file=target) + append_record(_record(1, reason="weekly_minimum_met"), log_file=target) + assert len(_rows(target)) == 2 + + def test_only_consecutive_records_collapse(self, tmp_path: Path) -> None: + """An intervening event ends the streak, as the history shows it must.""" + target = tmp_path / "d.jsonl" + append_record(_record(0), log_file=target) + append_record(_record(1, reason="mode_makes_no_decision"), log_file=target) + append_record(_record(2), log_file=target) + rows = _rows(target) + assert len(rows) == 3 + assert all("repeat_count" not in row for row in rows) + + def test_a_changed_field_is_not_a_repeat(self, tmp_path: Path) -> None: + """Everything but the timestamps must match to collapse.""" + target = tmp_path / "d.jsonl" + append_record(_record(0), log_file=target) + append_record({**_record(1), "weekly_count": 4}, log_file=target) + assert len(_rows(target)) == 2 + + +class TestCorruptTrail: + """A trail that cannot be parsed is kept, loudly -- never overwritten.""" + + def test_an_unparsable_tail_starts_a_new_row( + self, tmp_path: Path, caplog: MagicMock + ) -> None: + """Overwriting a line we cannot read would destroy real history.""" + target = tmp_path / "d.jsonl" + target.write_text("{truncated\n", encoding="utf-8") + append_record(_record(0), log_file=target) + lines = target.read_text().splitlines() + assert lines[0] == "{truncated" + assert len(lines) == 2 + assert "unparsable" in caplog.text + + def test_a_non_object_tail_starts_a_new_row(self, tmp_path: Path) -> None: + """Valid JSON of the wrong shape is not a record to merge into.""" + target = tmp_path / "d.jsonl" + target.write_text('["not", "a", "record"]\n', encoding="utf-8") + append_record(_record(0), log_file=target) + assert len(target.read_text().splitlines()) == 2 + + def test_a_write_failure_is_reported( + self, tmp_path: Path, caplog: MagicMock + ) -> None: + """A gap in the trail must itself be visible.""" + target = tmp_path / "nested" / "d.jsonl" + with patch( + "screen_locker._decision_trail.Path.write_text", + side_effect=OSError("full"), + ): + append_record(_record(0), log_file=target) + assert "durable trail now has a gap" in caplog.text diff --git a/screen_locker/tests/test_mcp.py b/screen_locker/tests/test_mcp.py index 613dab1..d910bf7 100644 --- a/screen_locker/tests/test_mcp.py +++ b/screen_locker/tests/test_mcp.py @@ -33,7 +33,7 @@ from screen_locker._status_data import ( def _lock_explanation() -> LockExplanation: return LockExplanation( fired=True, - stage="full_lock_pending_heat_check", + stage="would_lock", reason="No skip condition applies.", trace=(PredicateResult("scheduled_skip", fired=False, reason="not a skip"),), auto_upgrade=AutoUpgradeOpportunity( diff --git a/screen_locker/tests/test_queue_state.py b/screen_locker/tests/test_queue_state.py new file mode 100644 index 0000000..41b02b9 --- /dev/null +++ b/screen_locker/tests/test_queue_state.py @@ -0,0 +1,149 @@ +"""Tests for _queue_state and _queue_wait: making a blocked run visible. + +On 2026-08-30 the locker decided to lock at 09:01, sat in gatelock's queue +behind ``wake_alarm`` until 11:59, and nothing anywhere said so -- the unit +was ``active``, no window was up, and the status page read a bare "Lock would +fire". These cover the file that closes that blind spot. +""" + +from __future__ import annotations + +import json +from pathlib import Path +from unittest.mock import MagicMock, patch + +from gatelock import QueueResult + +from screen_locker._queue_state import ( + clear_queue_wait, + publish_queue_wait, + read_queue_wait, +) +from screen_locker._queue_wait import wait_for_screen + +_PKG = "screen_locker._queue_state" + + +class TestPublishAndRead: + """A blocked run cannot answer for itself, so it writes the answer down.""" + + def test_a_published_wait_reads_back(self) -> None: + """The round trip a status page depends on.""" + publish_queue_wait(("wake_alarm",), 10716.0) + record = read_queue_wait() + assert record is not None + assert record["blocked_by"] == ["wake_alarm"] + assert record["elapsed_seconds"] == 10716.0 + + def test_no_file_means_not_queued(self) -> None: + """Absence is the normal case and must not read as a failure.""" + clear_queue_wait() + assert read_queue_wait() is None + + def test_an_empty_blocker_set_clears_the_wait(self) -> None: + """gatelock signals "clear" with an empty tuple.""" + publish_queue_wait(("wake_alarm",), 5.0) + publish_queue_wait((), 10.0) + assert read_queue_wait() is None + + def test_clearing_twice_is_harmless(self) -> None: + """The locker clears on every exit path, armed or not.""" + clear_queue_wait() + clear_queue_wait() + assert read_queue_wait() is None + + +class TestUnreadableState: + """Every failure says why: a silent None is a lie about enforcement.""" + + def test_an_unwritable_path_warns(self, caplog: MagicMock) -> None: + """A status page that cannot learn of a wait must say so.""" + with patch.object(Path, "write_text", side_effect=OSError("readonly")): + publish_queue_wait(("wake_alarm",), 1.0) + assert "Could not publish the queue wait" in caplog.text + + def test_an_unremovable_path_warns(self, caplog: MagicMock) -> None: + """Otherwise the page keeps claiming a wait that ended.""" + with patch.object(Path, "unlink", side_effect=OSError("busy")): + clear_queue_wait() + assert "Could not clear the queue wait" in caplog.text + + def test_an_unreadable_file_warns(self, caplog: MagicMock) -> None: + """ "Not queued" is a claim, so a failed read cannot make it quietly.""" + publish_queue_wait(("wake_alarm",), 1.0) + with patch.object(Path, "read_text", side_effect=OSError("eio")): + assert read_queue_wait() is None + assert "Could not read the queue wait" in caplog.text + + def test_unparsable_json_warns(self, caplog: MagicMock, tmp_path: Path) -> None: + """A truncated write must not crash the status server.""" + target = tmp_path / "queue_state.json" + target.write_text("{not json", encoding="utf-8") + with patch(f"{_PKG}.QUEUE_STATE_FILE", target): + assert read_queue_wait() is None + assert "unparsable" in caplog.text + + def test_a_non_object_payload_warns( + self, caplog: MagicMock, tmp_path: Path + ) -> None: + """Valid JSON is not automatically the right shape.""" + target = tmp_path / "queue_state.json" + target.write_text(json.dumps([1, 2, 3]), encoding="utf-8") + with patch(f"{_PKG}.QUEUE_STATE_FILE", target): + assert read_queue_wait() is None + assert "not an object" in caplog.text + + +class TestWaitForScreen: + """The wait itself: published while it happens, recorded when it ends.""" + + @staticmethod + def _wait(result: QueueResult) -> MagicMock: + """Run wait_for_screen with a canned queue result. + + Args: + result: What gatelock's wait_for_turn should return. + + Returns: + The patched ``record_run_aborted`` mock. + """ + with ( + patch( + "screen_locker._queue_wait.wait_for_turn", return_value=result + ) as turn, + patch("screen_locker._queue_wait.record_run_aborted") as aborted, + ): + wait_for_screen(MagicMock()) + # The publisher must be handed to gatelock, or the wait stays invisible + # for its whole duration -- only its end would ever be recorded. + assert turn.call_args.kwargs["on_state"] is publish_queue_wait + return aborted + + def test_an_unblocked_run_records_nothing(self) -> None: + """The common case must not add a row to every single locker run.""" + aborted = self._wait( + QueueResult(waited_seconds=0.0, blocked_by=(), timed_out=False) + ) + aborted.assert_not_called() + + def test_a_real_wait_is_recorded_with_its_length(self) -> None: + """The 2h58m gap between "enforced" and a window on screen.""" + aborted = self._wait( + QueueResult( + waited_seconds=10716.0, blocked_by=("wake_alarm",), timed_out=False + ) + ) + reason, detail = aborted.call_args.args + assert reason == "queued_behind_holder" + assert "10716s" in detail + assert "wake_alarm" in detail + assert "deadline hit" not in detail + + def test_hitting_the_deadline_is_named(self) -> None: + """Arming anyway is a different event from the holder standing down.""" + aborted = self._wait( + QueueResult( + waited_seconds=21600.0, blocked_by=("wake_alarm",), timed_out=True + ) + ) + assert "deadline hit" in aborted.call_args.args[1] diff --git a/screen_locker/tests/test_screen_lock_coverage_part4.py b/screen_locker/tests/test_screen_lock_coverage_part4.py index bb246fb..c15a719 100644 --- a/screen_locker/tests/test_screen_lock_coverage_part4.py +++ b/screen_locker/tests/test_screen_lock_coverage_part4.py @@ -6,9 +6,13 @@ halves share the setup_unlock factory in _unlock_helpers.py. from __future__ import annotations +import tkinter as tk from typing import TYPE_CHECKING from unittest.mock import MagicMock, patch +import pytest + +from screen_locker.tests._locker_factories import create_locker from screen_locker.tests._unlock_helpers import setup_unlock if TYPE_CHECKING: @@ -91,3 +95,54 @@ class TestUnlockScreenRewards: patch("screen_locker._log_mixin.compute_entry_hmac", return_value=None), ): locker.unlock_screen() + + +class TestNoDisplayStandsDown: + """The 2026-08-30 restart storm: no X server at 02:00. + + ``GateRoot()`` raised an unhandled ``TclError``, the process exited 1, + ``Restart=on-failure`` restarted it ~6.3s later, and 1695 identical runs + in three hours evicted the entire durable decision trail behind them. + """ + + @staticmethod + def _build_with_no_display(tmp_path: Path) -> tuple[MagicMock, MagicMock]: + """Construct a locker whose GateRoot cannot reach a display. + + Args: + tmp_path: pytest's per-test directory. + + Returns: + The patched ``record_run_aborted`` and ``sys.exit`` mocks. + """ + # conftest stubs sys.exit process-wide, so without a real SystemExit + # here execution would fall through to `self.root`, which was never + # assigned -- and the test would assert on an AttributeError instead + # of on standing down. + with ( + patch( + "screen_locker.screen_lock.GateRoot", + side_effect=tk.TclError('couldn\'t connect to display ":0"'), + ), + patch("screen_locker.screen_lock.record_run_aborted") as aborted, + patch( + "screen_locker.screen_lock.sys.exit", side_effect=SystemExit(0) + ) as exit_mock, + pytest.raises(SystemExit) as raised, + ): + create_locker(MagicMock(), tmp_path, demo_mode=False) + assert raised.value.code == 0 + return aborted, exit_mock + + def test_it_exits_zero_instead_of_failing(self, tmp_path: Path) -> None: + """Exit 0 is what RestartPreventExitStatus=0 honours.""" + _, exit_mock = self._build_with_no_display(tmp_path) + exit_mock.assert_called_once_with(0) + + def test_it_records_why_rather_than_going_quiet(self, tmp_path: Path) -> None: + """ "Could not run" must not look like "chose not to lock".""" + aborted, _ = self._build_with_no_display(tmp_path) + aborted.assert_called_once() + reason, detail = aborted.call_args.args + assert reason == "no_display" + assert "display" in detail.lower() diff --git a/screen_locker/tests/test_status_data_part2.py b/screen_locker/tests/test_status_data_part2.py index a6fd31b..83a2786 100644 --- a/screen_locker/tests/test_status_data_part2.py +++ b/screen_locker/tests/test_status_data_part2.py @@ -47,7 +47,7 @@ class TestGatherStatus: assert snap.streak == 0 assert snap.early_bird_extended is False assert snap.lock_explanation.fired is True - assert snap.lock_explanation.stage == "full_lock_pending_heat_check" + assert snap.lock_explanation.stage == "would_lock" def test_populated_week_counts_workouts(self, tmp_path: Path) -> None: """Populated week counts workouts.""" diff --git a/screen_locker/tests/test_sync_degradation_part2.py b/screen_locker/tests/test_sync_degradation_part2.py index 92e4bf5..17f19c6 100644 --- a/screen_locker/tests/test_sync_degradation_part2.py +++ b/screen_locker/tests/test_sync_degradation_part2.py @@ -12,14 +12,17 @@ with HTTP 401 for weeks behind a warning nobody read. from __future__ import annotations from typing import TYPE_CHECKING +from unittest.mock import MagicMock, patch -from screen_locker import _sync_client, _workout_sync +from screen_locker import _startup_checks, _sync_client, _workout_sync from screen_locker._credential_recovery import RecoveryResult +from screen_locker._degraded_sources import _record_degraded from screen_locker.tests._workout_sync_fixtures import ( ReachableClient, RejectedClient, _firebase_config, ) +from screen_locker.tests.conftest import create_locker if TYPE_CHECKING: from pathlib import Path @@ -89,3 +92,36 @@ class TestRejectedCredentialTriggersRecovery: degraded = _sync_client.degraded_sources() assert degraded, "a credential the server refuses must be recorded" assert "rejected" in degraded[0].reason + + +class TestDecisionNamesUnreadableSources: + """A weekly count taken over a dead backend is a floor, not a count. + + On 2026-08-24 the only trace of a dead Firebase was a warning 90 seconds + earlier, and the DECISION line read ``weekly=0/5`` as though that zero + were a measurement. The decision itself has to say which source it could + not read. + """ + + def test_a_degraded_source_is_named_on_the_decision( + self, mock_tk: MagicMock, mock_sys_exit: MagicMock, tmp_path: Path + ) -> None: + """The annotation exists precisely so the zero cannot mislead.""" + locker = create_locker(mock_tk, tmp_path, has_logged=True) + _record_degraded("firebase", "credential refused") + with patch.object(_startup_checks, "record_decision") as recorded: + locker._record_decision( + locked=True, reason="enforced", detail="No exemption applied." + ) + assert recorded.call_args.args[0].extra["unreadable_sources"] == "firebase" + + def test_a_healthy_run_adds_no_such_note( + self, mock_tk: MagicMock, mock_sys_exit: MagicMock, tmp_path: Path + ) -> None: + """Every decision must not carry an empty caveat.""" + locker = create_locker(mock_tk, tmp_path, has_logged=True) + with patch.object(_startup_checks, "record_decision") as recorded: + locker._record_decision( + locked=True, reason="enforced", detail="No exemption applied." + ) + assert "unreadable_sources" not in recorded.call_args.args[0].extra diff --git a/screen_locker/tests/test_temperature.py b/screen_locker/tests/test_temperature.py index bc57a90..43e4eaf 100644 --- a/screen_locker/tests/test_temperature.py +++ b/screen_locker/tests/test_temperature.py @@ -2,11 +2,17 @@ from __future__ import annotations +import http.client import time from unittest.mock import MagicMock, patch import urllib.error -from screen_locker._temperature import TemperatureCheck, fetch_current_temp_with_status +from screen_locker._temperature import ( + HARD_TIMEOUT_SECONDS, + TemperatureCheck, + fetch_current_temp_with_status, + submit_background, +) def _mock_urlopen_returning(body: bytes) -> MagicMock: @@ -97,3 +103,64 @@ class TestFetchCurrentTempWithStatus: ): result = fetch_current_temp_with_status("Warsaw", hard_timeout=0.05) assert result == TemperatureCheck(temp_celsius=None, timed_out=True) + + +class TestNothingEscapesTheFetch: + """The heat check must never be able to kill the locker. + + `http.client.HTTPException` inherits Exception, not OSError, so it used to + escape the fetch, escape `future.result()` (which catches only the + timeout), and take the process down *before* the "enforced" record was + written -- a lock that never happened and left no line anywhere. + """ + + def test_an_http_exception_is_a_failed_check_not_a_crash(self) -> None: + """The specific gap: IncompleteRead is not an OSError.""" + with patch( + "screen_locker._temperature.urllib.request.urlopen", + side_effect=http.client.IncompleteRead(b"partial"), + ): + result = fetch_current_temp_with_status("Warsaw") + assert result == TemperatureCheck(temp_celsius=None, timed_out=False) + + def test_a_worker_that_raises_still_resolves_the_future(self) -> None: + """A future nobody resolves is a hang, not a failure.""" + with patch( + "screen_locker._temperature._fetch_current_temp_celsius_unbounded", + side_effect=http.client.BadStatusLine("garbage"), + ): + result = fetch_current_temp_with_status("Warsaw") + assert result.temp_celsius is None + assert result.timed_out is False + + def test_the_whole_check_is_bounded_by_the_hard_timeout(self) -> None: + """The user's requirement: at most 5s, then lock regardless.""" + with patch( + "screen_locker._temperature._fetch_current_temp_celsius_unbounded", + side_effect=lambda _city: time.sleep(30), + ): + started = time.monotonic() + result = fetch_current_temp_with_status("Warsaw") + elapsed = time.monotonic() - started + assert result.timed_out is True + assert elapsed <= HARD_TIMEOUT_SECONDS + 0.5 + + +class TestSubmitBackground: + """The daemon thread that replaced ThreadPoolExecutor.""" + + def test_it_resolves_with_the_callables_result(self) -> None: + """The ordinary path every caller depends on.""" + assert submit_background(lambda: 42).result(timeout=5) == 42 + + def test_the_thread_is_a_daemon(self) -> None: + """Non-daemon workers held the process open past sys.exit(0). + + `concurrent.futures` joins its workers in an interpreter-exit hook, so + a stuck DNS lookup outlived the hard timeout it was supposed to be + bounded by. A daemon thread is abandoned at exit instead. + """ + with patch("screen_locker._temperature.threading.Thread") as thread_cls: + submit_background(lambda: 1) + assert thread_cls.call_args.kwargs["daemon"] is True + thread_cls.return_value.start.assert_called_once() diff --git a/screen_locker/tests/test_web_payload.py b/screen_locker/tests/test_web_payload.py index 02e9ee1..529c4dc 100644 --- a/screen_locker/tests/test_web_payload.py +++ b/screen_locker/tests/test_web_payload.py @@ -13,8 +13,8 @@ import json from typing import TYPE_CHECKING, Any from unittest.mock import patch +from screen_locker._web_decisions import build_decisions_payload from screen_locker._web_payload import ( - build_decisions_payload, build_status_payload, workout_credits_today, ) @@ -23,6 +23,7 @@ if TYPE_CHECKING: from pathlib import Path _PKG = "screen_locker._web_payload" +_DECISIONS_PKG = "screen_locker._web_decisions" _SATURDAY = datetime(2026, 8, 29, 21, 0, 0, tzinfo=UTC) @@ -130,7 +131,7 @@ class TestDecisionsPayload: def test_newest_first(self) -> None: """The browser reads top-down; the trail is stored oldest-first.""" trail = [{"timestamp": "1"}, {"timestamp": "2"}, {"timestamp": "3"}] - with patch(f"{_PKG}.read_decisions", return_value=trail): + with patch(f"{_DECISIONS_PKG}.read_decisions", return_value=trail): payload = build_decisions_payload(limit=2) assert [d["timestamp"] for d in payload["decisions"]] == ["3", "2"] assert payload["total"] == 3 @@ -139,6 +140,44 @@ class TestDecisionsPayload: def test_a_non_positive_limit_returns_everything(self) -> None: """Guards the slice: limit=0 must not silently mean "no history".""" trail = [{"timestamp": "1"}, {"timestamp": "2"}] - with patch(f"{_PKG}.read_decisions", return_value=trail): + with patch(f"{_DECISIONS_PKG}.read_decisions", return_value=trail): payload = build_decisions_payload(limit=0) assert payload["returned"] == 2 + + def test_timestamps_are_rendered_server_side_in_local_time(self) -> None: + """The browser cannot be trusted to do this. + + LibreWolf's resistFingerprinting pins JS ``Date`` to UTC, which is how + a 14:00 CEST decision came to render as "12:00 PM" on 2026-08-30. + """ + trail = [{"timestamp": "2026-08-30T12:00:05+00:00"}] + with patch(f"{_DECISIONS_PKG}.read_decisions", return_value=trail): + payload = build_decisions_payload(limit=1) + rendered = payload["decisions"][0]["local_time"] + expected = ( + datetime.fromisoformat("2026-08-30T12:00:05+00:00") + .astimezone() + .strftime("%b %d, %H:%M") + ) + assert rendered == expected + + def test_a_collapsed_row_reports_both_ends(self) -> None: + """A repeat-collapsed row must not look like a gap in history.""" + trail = [ + { + "timestamp": "2026-08-30T12:00:05+00:00", + "last_timestamp": "2026-08-30T12:40:14+00:00", + "repeat_count": 4, + } + ] + with patch(f"{_DECISIONS_PKG}.read_decisions", return_value=trail): + row = build_decisions_payload(limit=1)["decisions"][0] + assert row["local_time"] != row["local_last_time"] + assert row["repeat_count"] == 4 + + def test_an_unparsable_timestamp_is_left_unrendered(self) -> None: + """Better no local time than a confidently wrong one.""" + trail = [{"timestamp": "not-a-timestamp"}] + with patch(f"{_DECISIONS_PKG}.read_decisions", return_value=trail): + row = build_decisions_payload(limit=1)["decisions"][0] + assert "local_time" not in row diff --git a/screen_locker/tests/test_weekly_logic_part3.py b/screen_locker/tests/test_weekly_logic_part3.py index 9911514..0d0831a 100644 --- a/screen_locker/tests/test_weekly_logic_part3.py +++ b/screen_locker/tests/test_weekly_logic_part3.py @@ -2,6 +2,7 @@ from __future__ import annotations +import tkinter as tk from typing import TYPE_CHECKING from unittest.mock import MagicMock, patch @@ -39,6 +40,40 @@ class TestHeatSkipBranch: mock_dialog.assert_not_called() mock_sys_exit.assert_not_called() + def test_a_dialog_that_cannot_be_shown_fails_closed( + self, + mock_tk: MagicMock, + mock_sys_exit: MagicMock, + tmp_path: Path, + ) -> None: + """The heat dialog builds its own tk.Tk(), which can fail. + + With no reachable display that raises here, and letting it escape + would kill the process *before* the "enforced" record is written -- + a lock that silently never happened. Refusing the skip is the only + fail-closed answer. + """ + with ( + patch( + "screen_locker._startup_checks.has_weekly_minimum", return_value=False + ), + patch( + "screen_locker._startup_checks.fetch_current_temp_with_status", + return_value=TemperatureCheck(temp_celsius=35.0, timed_out=False), + ), + patch.object( + ScreenLocker, + "_show_heat_skip_dialog", + side_effect=tk.TclError("no display"), + ), + patch.object(ScreenLocker, "_save_heat_skip_log") as saved, + ): + create_locker(mock_tk, tmp_path, has_logged=False) + + # No skip recorded, and the run continued to build the lock. + saved.assert_not_called() + mock_sys_exit.assert_not_called() + def test_too_hot_and_user_confirms_skip( self, mock_tk: MagicMock, diff --git a/web/src/components/NowCard.test.tsx b/web/src/components/NowCard.test.tsx index bf04979..327858d 100644 --- a/web/src/components/NowCard.test.tsx +++ b/web/src/components/NowCard.test.tsx @@ -2,6 +2,7 @@ import { render, screen } from '@testing-library/react' import { describe, expect, it } from 'vitest' import { NowCard } from './NowCard' import { makeStatus } from '../test/factories' +import type { StatusPayload } from '../types' describe('NowCard', () => { it('shows the cut budget and says why when no workout was logged', () => { @@ -40,7 +41,7 @@ describe('NowCard', () => { lock_explanation: { ...base.snapshot.lock_explanation, fired: true, - stage: 'full_lock_pending_heat_check', + stage: 'would_lock', reason: 'No skip condition applies.', }, }, @@ -89,4 +90,57 @@ describe('NowCard', () => { ) expect(screen.getByText(/degraded/)).toBeInTheDocument() }) + + /** + * "Lock would fire" is a statement about the decision, not about whether + * anything is enforcing it. On 2026-08-30 the page said exactly that while + * the machine had just rebooted and no locker process existed. + */ + const firing = (over: Partial = {}) => { + const base = makeStatus() + return { + ...base, + snapshot: { + ...base.snapshot, + lock_explanation: { ...base.snapshot.lock_explanation, fired: true }, + }, + ...over, + } + } + + it('says when a decided lock is queued behind another holder', () => { + render( + , + ) + expect(screen.getByText(/waiting for/)).toBeInTheDocument() + expect(screen.getByText(/179 min so far/)).toBeInTheDocument() + expect(screen.getByText(/not unlocked/)).toBeInTheDocument() + }) + + it('says when nothing is enforcing a lock it says would fire', () => { + render() + expect( + screen.getByText(/No locker run is in progress right now/), + ).toBeInTheDocument() + }) + + it('stays quiet when a run is up and unblocked', () => { + render() + expect(screen.queryByText(/No locker run is in progress/)).toBeNull() + expect(screen.queryByText(/waiting for/)).toBeNull() + }) + + it('says nothing about enforcement when no lock is due', () => { + render() + expect(screen.queryByText(/No locker run is in progress/)).toBeNull() + }) }) diff --git a/web/src/components/NowCard.tsx b/web/src/components/NowCard.tsx index 93ff7b1..becf712 100644 --- a/web/src/components/NowCard.tsx +++ b/web/src/components/NowCard.tsx @@ -7,7 +7,13 @@ interface Props { /** The decision as it stands right now, in words rather than slugs. */ export function NowCard({ status }: Props) { - const { snapshot, gaming, compliance_state: state } = status + const { + snapshot, + gaming, + compliance_state: state, + queue_wait: queued, + locker_running: running, + } = status const { week, lock_explanation: lock } = snapshot const hours = budgetHours(gaming.workout_today) @@ -18,6 +24,20 @@ export function NowCard({ status }: Props) { {lock.fired ? 'Lock would fire' : 'No lock'}

{lock.reason}

+ {lock.fired && queued !== null && ( +

+ A locker run has already decided to lock and is waiting for{' '} + {queued.blocked_by.join(', ')} to release the screen ( + {Math.round(queued.elapsed_seconds / 60)} min so far). The screen is + held by {queued.blocked_by.join(', ')}, not unlocked. +

+ )} + {lock.fired && queued === null && running === false && ( +

+ No locker run is in progress right now, so nothing is enforcing this. + The next timer tick will start one. +

+ )}
This week diff --git a/web/src/components/WhyTable.test.tsx b/web/src/components/WhyTable.test.tsx index 2a911c2..6930f32 100644 --- a/web/src/components/WhyTable.test.tsx +++ b/web/src/components/WhyTable.test.tsx @@ -76,4 +76,74 @@ describe('WhyTable', () => { // weekly_required missing falls back to 0 rather than rendering undefined. expect(screen.getByText('2/0')).toBeInTheDocument() }) + + /** + * A restart loop wrote ~1693 identical records on 2026-08-30 and evicted + * the whole trail. They now collapse into one row, which must not then + * read as a gap in history. + */ + it('shows how many times a collapsed row repeated, and when it last did', () => { + render( + , + ) + expect(screen.getByText('Aug 30, 02:02')).toBeInTheDocument() + expect(screen.getByText(/×1693, last Aug 30, 05:05/)).toBeInTheDocument() + }) + + it('prefers the server-rendered local time over the browser clock', () => { + // LibreWolf's resistFingerprinting pins JS Date to UTC, which rendered a + // 14:00 CEST decision as "12:00 PM" on 2026-08-30. + render( + , + ) + expect(screen.getByText('Aug 30, 14:00')).toBeInTheDocument() + }) + + it('falls back to formatting the ISO stamp when the server sent none', () => { + render( + , + ) + expect(screen.getByText(/×3, last/)).toBeInTheDocument() + }) + + it('adds no repeat note to a row that happened once', () => { + render() + expect(screen.queryByText(/×/)).toBeNull() + }) }) diff --git a/web/src/components/WhyTable.tsx b/web/src/components/WhyTable.tsx index 5951062..c32f994 100644 --- a/web/src/components/WhyTable.tsx +++ b/web/src/components/WhyTable.tsx @@ -32,7 +32,19 @@ export function WhyTable({ decisions }: Props) { {decisions.decisions.map((decision, index) => ( - {formatStamp(decision.timestamp)} + + {decision.local_time ?? formatStamp(decision.timestamp)} + {decision.repeat_count !== undefined && + decision.repeat_count > 1 && ( +
+ ×{decision.repeat_count}, last{' '} + {decision.local_last_time ?? + formatStamp( + decision.last_timestamp ?? decision.timestamp, + )} +
+ )} + {decision.locked === null ? '—' diff --git a/web/src/test/factories.ts b/web/src/test/factories.ts index 2d5106d..606965d 100644 --- a/web/src/test/factories.ts +++ b/web/src/test/factories.ts @@ -40,6 +40,8 @@ export function makeStatus(over: Partial = {}): StatusPayload { credits_today: 0, reason: 'no counted workout logged today', }, + queue_wait: null, + locker_running: true, ...over, } } diff --git a/web/src/types.ts b/web/src/types.ts index 0af188d..78af083 100644 --- a/web/src/types.ts +++ b/web/src/types.ts @@ -53,11 +53,22 @@ export interface GamingFact { } /** GET /api/status. */ +/** A locker run that has decided to lock but is waiting for the screen. */ +export interface QueueWait { + readonly blocked_by: readonly string[] + readonly elapsed_seconds: number + readonly updated: string +} + export interface StatusPayload { readonly snapshot: StatusSnapshot readonly summary_line: string readonly compliance_state: string readonly gaming: GamingFact + /** Non-null while a run is queued behind a higher-ranked screen holder. */ + readonly queue_wait: QueueWait | null + /** Whether workout-locker.service is running; null means "could not ask". */ + readonly locker_running: boolean | null } /** One recorded decision from decisions.jsonl. */ @@ -70,6 +81,14 @@ export interface Decision { readonly weekly_required?: number readonly also?: string readonly mode?: string + /** Set when consecutive identical decisions were folded into one row. */ + readonly repeat_count?: number + /** The most recent sighting of a collapsed row; `timestamp` is the first. */ + readonly last_timestamp?: string + /** Server-rendered local time. Preferred over formatting `timestamp` here: + * LibreWolf's resistFingerprinting pins the browser's Date to UTC. */ + readonly local_time?: string + readonly local_last_time?: string } /** GET /api/decisions. */ diff --git a/workout-locker.service b/workout-locker.service index df40071..d23f3a0 100644 --- a/workout-locker.service +++ b/workout-locker.service @@ -1,6 +1,13 @@ [Unit] Description=Workout Screen Locker After=graphical-session.target +# Backstop for any crash the code does not turn into a clean exit 0. The +# 2026-08-30 no-display loop restarted ~1695 times in three hours at ~6.3s +# apart -- 1.6 per 10s, which slips under systemd's DEFAULT 5-per-10s limit +# forever. Over five minutes that same rate trips this and the unit stops, +# so a restart storm becomes a visibly failed unit instead of a silent one. +StartLimitIntervalSec=300 +StartLimitBurst=5 [Service] Type=simple diff --git a/workout-locker.timer b/workout-locker.timer index ab54c93..cc7beb5 100644 --- a/workout-locker.timer +++ b/workout-locker.timer @@ -16,12 +16,18 @@ Description=Periodically re-evaluate the workout lock decision # early-exit ladder handles "already logged", "window still active", # "weekly minimum met" and "relaxed day" -- so a re-check costs nothing when # there is nothing to do. -OnCalendar=*-*-* *:00,30:00 +# Every 5 minutes, not every 30. A reboot leaves the machine unenforced +# until the next tick (the login run below is the primary anchor, but i3 has +# been observed not to activate graphical-session.target reliably), and on +# 2026-08-30 that gap was 24 minutes wide with the lock decided and nothing +# on screen. Each run is idempotent, so a shorter period costs only journal +# lines. +OnCalendar=*-*-* *:00/5 # Catch up after suspend/downtime rather than waiting for the next half hour. Persistent=true # A lock that appears at a hard-predictable second feels like a glitch; a small # spread also avoids stacking with workout-sync.timer on the same tick. -RandomizedDelaySec=60 +RandomizedDelaySec=15 Unit=workout-locker.service [Install]