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

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

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

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

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

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

Fixes:

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

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

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

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

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

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

179 lines
7.3 KiB
Python

"""Mixin: auto-upgrade early_bird/sick_day pending states via phone or RunnerUp.
Neither early_bird (a same-day pending marker, see ``_early_bird.py``) nor
sick_day (tracked in ``sick_history.json`` via ``_sick_tracker.py``) live in
workout_log.json — this module only checks their pending state and, on
success, writes the *real* outcome (phone_verified/runnerup_verified) there.
"""
from __future__ import annotations
import logging
import sys
from screen_locker import _sick_tracker
from screen_locker._decision_log import LockDecision, record_decision
from screen_locker._wake_state import has_workout_skip_today
_logger = logging.getLogger(__name__)
def _skip(reason: str, detail: str, **extra: object) -> None:
"""Record a decision NOT to enforce, then exit.
Every branch that abandons enforcement goes through here. Before this
existed each one just logged at INFO and called ``sys.exit(0)``, which is
how the locker managed to stop enforcing for thirteen days without leaving
a single line saying so.
"""
record_decision(
LockDecision(locked=False, reason=reason, detail=detail, extra=extra)
)
sys.exit(0)
class AutoUpgradeMixin:
"""Handles today-state detection and silent log-entry upgrading.
Relies on methods from EarlyBirdMixin, PhoneVerificationMixin,
RunnerUpVerificationMixin, LogMixin, and ShutdownMixin via MRO.
"""
def _is_sick_day_today(self) -> bool:
"""Check if today is marked as a sick day in sick_history.json."""
return _sick_tracker.is_sick_day(_sick_tracker.load_history())
def _check_early_exits(self, *, verify_only: bool) -> None:
"""Check startup conditions and exit early when appropriate."""
if verify_only:
if not self._is_sick_day_today():
_skip("no_sick_day_to_verify", "No sick day logged today.")
return
self._check_non_verify_exits()
def _check_today_state_exits(self) -> bool:
"""Handle early-bird and today's log states. Return True to stop startup."""
if self._is_early_bird_pending() and not self._is_early_bird_time():
if self._try_auto_upgrade_early_bird():
_skip(
"early_bird_auto_upgraded",
"Auto-upgraded early_bird entry to phone_verified.",
)
return True
return False # Expired early bird, upgrade unavailable — full lock.
if self._is_early_bird_pending():
# The ONLY thing that closes this window is
# early-bird-workout-check.timer. When that timer was disabled by an
# ordering cycle (2026-08-04) this branch silently deferred the lock
# every single day, forever.
_skip(
"early_bird_window_active",
"Early bird window still active — deferring to the 08:30/09:05 "
"re-check timer.",
recheck_by="early-bird-workout-check.timer",
)
elif self._is_sick_day_today():
if self._try_auto_upgrade_sick_day():
_skip(
"sick_day_auto_upgraded",
"Auto-upgraded today's sick_day entry to phone_verified.",
)
else:
_skip("sick_day", "Sick day already logged today.")
elif self.has_logged_today():
_skip("workout_logged_today", "Workout already logged today.")
elif has_workout_skip_today():
_skip("wake_alarm_skip", "Wake alarm earned a workout skip.")
elif self._is_early_bird_time():
self._save_early_bird_pending()
_skip(
"early_bird_banked",
"Early bird time — banked the pending marker, will re-check "
"at 08:30/09:05.",
recheck_by="early-bird-workout-check.timer",
)
else:
return False
return True
def _try_auto_upgrade_sick_day(self) -> bool:
"""Upgrade sick_day entry when phone or RunnerUp detects a valid workout."""
try:
status, message = self._verify_phone_workout()
except (OSError, RuntimeError) as exc:
_logger.warning(
"Sick-day auto-upgrade could not reach the phone (%s) — today's "
"sick_day entry stays unverified; trying RunnerUp next",
exc,
)
status, message = "error", str(exc)
if status == "verified":
self.workout_data["type"] = "phone_verified"
self.workout_data["source"] = message
self.workout_data["after_sick_day"] = "true"
self._adjust_shutdown_time_later()
self.save_workout_log()
return True
_logger.info("Auto-upgrade phone skipped (%s), trying RunnerUp...", status)
try:
runnerup_status, runnerup_msg = self._verify_runnerup_workout()
except (OSError, RuntimeError) as exc:
_logger.warning(
"Sick-day auto-upgrade could not read RunnerUp either (%s) — "
"today stays a sick_day, NOT upgraded to a verified workout",
exc,
)
return False
if runnerup_status != "verified":
_logger.info(
"Auto-upgrade RunnerUp skipped (%s): %s", runnerup_status, runnerup_msg
)
return False
self.workout_data["type"] = "runnerup_verified"
self.workout_data["source"] = runnerup_msg
self.workout_data["after_sick_day"] = "true"
self._adjust_shutdown_time_later()
self.save_workout_log()
return True
def _try_auto_upgrade_early_bird(self) -> bool:
"""Try phone then RunnerUp to upgrade an early_bird log entry."""
try:
status, message = self._verify_phone_workout()
except (OSError, RuntimeError) as exc:
_logger.warning(
"Early-bird auto-upgrade could not reach the phone (%s) — the "
"early_bird entry stays unverified; trying RunnerUp next",
exc,
)
status, message = "error", str(exc)
if status == "verified":
self.workout_data["type"] = "phone_verified"
self.workout_data["source"] = message
self.workout_data["after_early_bird"] = "true"
self._adjust_shutdown_time_later()
self.save_workout_log()
return True
_logger.info("Early bird phone skipped (%s), trying RunnerUp...", status)
try:
runnerup_status, runnerup_msg = self._verify_runnerup_workout()
except (OSError, RuntimeError) as exc:
_logger.warning(
"Early-bird auto-upgrade could not read RunnerUp either (%s) — "
"the expired early_bird entry is NOT upgraded, so the screen "
"will lock",
exc,
)
return False
if runnerup_status != "verified":
_logger.info(
"Early bird RunnerUp skipped (%s): %s", runnerup_status, runnerup_msg
)
return False
self.workout_data["type"] = "runnerup_verified"
self.workout_data["source"] = runnerup_msg
self.workout_data["after_early_bird"] = "true"
self._adjust_shutdown_time_later()
self.save_workout_log()
return True