diff --git a/pyproject.toml b/pyproject.toml index da3e27d..b998095 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -63,6 +63,12 @@ unfixable = [] # considered and rejected (it can't ever trigger, so it's just an untested # branch and a crash risk in the lock's startup path for zero real benefit). "screen_locker/_temperature.py" = ["S310"] +# PERF203 (try/except inside a loop) describes a retry loop exactly, and lands +# where its cost is irrelevant: each iteration makes a network call and then +# sleeps for seconds, so handler setup is noise. Hoisting the handler out of +# the loop would mean swallowing the error into a return value, which the +# repo's no-silent-failures rule rightly discourages. +"screen_locker/_sync_retry.py" = ["PERF203"] "screen_locker/_shutdown_base.py" = ["SLF001"] # run_status walks the weekly-status pipeline (weekly logic, RunnerUp scan, # bonus, heat-skip) as a sequence of stages — genuinely branchy by design, same diff --git a/screen_locker/_constants.py b/screen_locker/_constants.py index c799df5..e338028 100644 --- a/screen_locker/_constants.py +++ b/screen_locker/_constants.py @@ -131,3 +131,14 @@ SYNC_PHONE_DEVICE_ID: str = "phone" # this file being absent is a normal, expected state (sync is optional here). SYNC_TOKEN_FILE: Path = Path.home() / ".config" / "screen_locker" / "sync_token" SYNC_TIMEOUT_SECONDS: float = 10.0 + +# 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 +# (2026-07-20: six workouts "FAILED" at 08:04 with the network still down, then +# pushed fine by hand minutes later on the same token). So retry before giving +# up. Exponential backoff from SYNC_RETRY_DELAY_SECONDS gives 2s + 4s + 8s = +# ~14s of patience — enough for DHCP/DNS to come up, without making a genuinely +# offline run drag the whole morning routine. +SYNC_RETRY_ATTEMPTS: int = 4 +SYNC_RETRY_DELAY_SECONDS: float = 2.0 diff --git a/screen_locker/_manual_push.py b/screen_locker/_manual_push.py index 67815bf..0b7bb4c 100644 --- a/screen_locker/_manual_push.py +++ b/screen_locker/_manual_push.py @@ -32,6 +32,7 @@ from crdt_sync import ( GitHubSyncError, Hlc, Record, + RepoNotFoundError, sync_log, ) @@ -43,6 +44,7 @@ from screen_locker._constants import ( ) from screen_locker._log_io import load_workout_log from screen_locker._log_mixin import _derive_workout_id +from screen_locker._sync_retry import with_sync_retry from screen_locker._weekly_check import COUNTED_WORKOUT_TYPES from screen_locker._workout_sync import _DEVICES_PREFIX, read_sync_token @@ -180,24 +182,40 @@ def push_pc_workouts(log_file: Path) -> PushResult: timeout_seconds=SYNC_TIMEOUT_SECONDS, ) try: - sync_log( - client=client, - device_id=_PC_DEVICE_ID, - path_prefix=_DEVICES_PREFIX, - local_log=log, - encode=_encode_log, - decode=_decode_log, + with_sync_retry( + lambda: sync_log( + client=client, + device_id=_PC_DEVICE_ID, + path_prefix=_DEVICES_PREFIX, + local_log=log, + encode=_encode_log, + decode=_decode_log, + ), + description="push PC workouts", ) except GitHubSyncError as exc: reason = f"sync error: {exc}" - _logger.warning( - "Workout sync push FAILED for %d workout(s): %s — a 403 here means " - "the token lacks contents:write on %s/%s", - len(log), - exc, - SYNC_REPO_OWNER, - SYNC_REPO_NAME, - ) + # Report what actually happened. This used to assert "a 403 here means + # the token lacks contents:write" for *every* failure, including a + # plain network error — which sent a 2026-07-20 investigation chasing a + # permissions bug that did not exist (the token could write fine; the + # network was simply not up yet). Only RepoNotFoundError actually + # implicates the repo or the token. + if isinstance(exc, RepoNotFoundError): + _logger.warning( + "Workout sync push FAILED for %d workout(s): %s — check the " + "token has contents:write on %s/%s", + len(log), + exc, + SYNC_REPO_OWNER, + SYNC_REPO_NAME, + ) + else: + _logger.warning( + "Workout sync push FAILED for %d workout(s): %s", + len(log), + exc, + ) return PushResult(pushed=False, record_count=len(log), reason=reason) _logger.info( diff --git a/screen_locker/_sync_retry.py b/screen_locker/_sync_retry.py new file mode 100644 index 0000000..dc4ab02 --- /dev/null +++ b/screen_locker/_sync_retry.py @@ -0,0 +1,95 @@ +"""Bounded retry for sync calls that run before the network is up. + +Every sync entry point here is reached from the morning routine, which systemd +starts immediately after boot and after resume — routinely a few seconds before +DHCP/DNS have settled. A single-shot call in that window fails for a reason +that has nothing to do with the sync itself, and (before this module) reported +it as a token/permissions problem. + +Retrying at the application layer rather than ordering the unit after +``network-online.target``: the same race happens on *resume*, where boot +ordering does not apply, and the user services involved cannot depend on a +system target anyway. + +Any :class:`GitHubSyncError` is retried, deliberately including +:class:`RepoNotFoundError`. Classifying "transient" vs "permanent" would mean +depending on which exception ``crdt_sync`` chains where, which is internal to +that library and has changed before; a few wasted seconds on a genuinely +misconfigured token is a much cheaper mistake than skipping a real retry. +""" + +from __future__ import annotations + +import logging +from time import sleep +from typing import TYPE_CHECKING, TypeVar + +from crdt_sync import GitHubSyncError + +from screen_locker._constants import ( + SYNC_RETRY_ATTEMPTS, + SYNC_RETRY_DELAY_SECONDS, +) + +if TYPE_CHECKING: + from collections.abc import Callable + +_logger = logging.getLogger(__name__) + +T = TypeVar("T") + + +def with_sync_retry( + operation: Callable[[], T], + *, + description: str, + attempts: int = SYNC_RETRY_ATTEMPTS, + delay_seconds: float = SYNC_RETRY_DELAY_SECONDS, +) -> T: + """Run *operation*, retrying a failed sync with exponential backoff. + + Args: + operation: The zero-argument sync call to run. + description: Human phrase naming the operation, used in the retry + logs (e.g. ``"push PC workouts"``). + attempts: Total tries, including the first. Values below 1 still run + the operation exactly once. + delay_seconds: Base backoff; attempt *n* waits ``delay * 2**(n-1)``. + + Returns: + Whatever *operation* returns. + + Raises: + GitHubSyncError: If every attempt failed. The caller keeps its own + handling — this only buys time, it never hides the outcome. + """ + last_attempt = max(attempts, 1) + # Every attempt but the last swallows-and-waits; the last one is run + # outside the loop so its failure propagates with no unreachable branch. + for attempt in range(1, last_attempt): + try: + return operation() + except GitHubSyncError as exc: + wait = delay_seconds * (2 ** (attempt - 1)) + _logger.warning( + "Could not %s (attempt %d/%d): %s — retrying in %.0fs; " + "this is normal right after boot or resume, when the " + "network is not up yet", + description, + attempt, + last_attempt, + exc, + wait, + ) + sleep(wait) + + try: + return operation() + except GitHubSyncError as exc: + _logger.warning( + "Could not %s after %d attempt(s): %s — giving up", + description, + last_attempt, + exc, + ) + raise diff --git a/screen_locker/_workout_sync.py b/screen_locker/_workout_sync.py index 9cdfded..f5aa703 100644 --- a/screen_locker/_workout_sync.py +++ b/screen_locker/_workout_sync.py @@ -23,6 +23,7 @@ from screen_locker._constants import ( SYNC_TOKEN_FILE, ) from screen_locker._manual_workout import MANUAL_WORKOUT_SYNC_KIND +from screen_locker._sync_retry import with_sync_retry _logger = logging.getLogger(__name__) @@ -113,7 +114,10 @@ def pull_synced_workout() -> tuple[dict | None, str | None]: timeout_seconds=SYNC_TIMEOUT_SECONDS, ) try: - text = client.get_file_text(_LOG_PATH) + text = with_sync_retry( + lambda: client.get_file_text(_LOG_PATH), + description="fetch the phone's workout log", + ) except GitHubSyncError as exc: _logger.warning( "Could not fetch the phone's workout log %s from %s/%s: %s — " @@ -189,7 +193,10 @@ def pull_all_manual_records() -> list[tuple[str, dict]]: timeout_seconds=SYNC_TIMEOUT_SECONDS, ) try: - devices = client.list_directory(_DEVICES_PREFIX) + devices = with_sync_retry( + lambda: client.list_directory(_DEVICES_PREFIX), + description="list synced device logs", + ) except GitHubSyncError as exc: _logger.warning( "Could not list device logs under %s in %s/%s: %s — pulling NO " diff --git a/screen_locker/tests/test_manual_push.py b/screen_locker/tests/test_manual_push.py index 078a9e3..d640459 100644 --- a/screen_locker/tests/test_manual_push.py +++ b/screen_locker/tests/test_manual_push.py @@ -8,7 +8,7 @@ import json from typing import TYPE_CHECKING from unittest.mock import MagicMock, patch -from crdt_sync import GitHubSyncError +from crdt_sync import GitHubSyncError, RepoNotFoundError from screen_locker import _manual_push from screen_locker._manual_push import ( @@ -23,6 +23,8 @@ from screen_locker._manual_push import ( if TYPE_CHECKING: from pathlib import Path + import pytest + _MANUAL = { "type": "manual_workout", "source": "table tennis at Solec", @@ -204,6 +206,57 @@ class TestPushPcWorkouts: assert result.record_count == 1 assert "403 forbidden" in result.reason + def test_network_error_is_not_blamed_on_the_token( + self, tmp_path: Path, caplog: pytest.LogCaptureFixture + ) -> None: + """A network failure must not be reported as a permissions problem. + + Regression guard for 2026-07-20: the morning routine runs seconds after + boot/resume, so its pushes failed with the network still down — and the + log asserted "a 403 here means the token lacks contents:write", which + sent an investigation chasing a permissions bug that did not exist. + """ + log_file = tmp_path / "workout_log.json" + _write_log( + log_file, {"2026-07-13": [_entry(_RUN, "2026-07-13T10:00:00+00:00")]} + ) + with ( + patch.object(_manual_push, "read_sync_token", return_value="t"), + patch.object(_manual_push, "GitHubSyncClient", MagicMock()), + patch.object( + _manual_push, + "sync_log", + side_effect=GitHubSyncError("network error reading x"), + ), + caplog.at_level("WARNING"), + ): + result = push_pc_workouts(log_file) + assert result.pushed is False + assert "network error reading x" in caplog.text + assert "contents:write" not in caplog.text + + def test_repo_not_found_still_points_at_the_token( + self, tmp_path: Path, caplog: pytest.LogCaptureFixture + ) -> None: + """The permission hint survives for the error that actually implies it.""" + log_file = tmp_path / "workout_log.json" + _write_log( + log_file, {"2026-07-13": [_entry(_RUN, "2026-07-13T10:00:00+00:00")]} + ) + with ( + patch.object(_manual_push, "read_sync_token", return_value="t"), + patch.object(_manual_push, "GitHubSyncClient", MagicMock()), + patch.object( + _manual_push, + "sync_log", + side_effect=RepoNotFoundError("no access"), + ), + caplog.at_level("WARNING"), + ): + result = push_pc_workouts(log_file) + assert result.pushed is False + assert "contents:write" in caplog.text + def test_successful_push_reports_count(self, tmp_path: Path) -> None: log_file = tmp_path / "workout_log.json" _write_log( diff --git a/screen_locker/tests/test_sync_fixtures.py b/screen_locker/tests/test_sync_fixtures.py index 644d9de..8a7a177 100644 --- a/screen_locker/tests/test_sync_fixtures.py +++ b/screen_locker/tests/test_sync_fixtures.py @@ -33,3 +33,17 @@ def isolate_sync_token(tmp_path: Path) -> Iterator[None]: tmp_path / "sync_token", ): yield + + +@pytest.fixture(autouse=True) +def no_sync_retry_sleep() -> Iterator[None]: + """Make the sync retry's backoff instant for every test. + + ``with_sync_retry`` waits 2s + 4s + 8s before giving up, which is right in + production (it covers the network coming up after boot/resume) but would + add ~14s to every test that exercises a sync failure. Tests that care about + the backoff assert on the patched ``sleep`` calls instead -- see + ``test_sync_retry.py``. + """ + with patch("screen_locker._sync_retry.sleep"): + yield diff --git a/screen_locker/tests/test_sync_retry.py b/screen_locker/tests/test_sync_retry.py new file mode 100644 index 0000000..f117211 --- /dev/null +++ b/screen_locker/tests/test_sync_retry.py @@ -0,0 +1,98 @@ +"""Tests for the bounded sync retry that covers the boot/resume network race.""" + +from __future__ import annotations + +from unittest.mock import MagicMock, patch + +from crdt_sync import GitHubSyncError, RepoNotFoundError +import pytest + +from screen_locker._sync_retry import with_sync_retry + + +class TestWithSyncRetry: + """Tests for :func:`with_sync_retry`.""" + + def test_returns_result_without_retrying_on_success(self) -> None: + """A working call runs exactly once and returns its value.""" + operation = MagicMock(return_value="ok") + with patch("screen_locker._sync_retry.sleep") as sleep: + assert with_sync_retry(operation, description="do the thing") == "ok" + assert operation.call_count == 1 + sleep.assert_not_called() + + def test_recovers_when_a_later_attempt_succeeds(self) -> None: + """The boot case: the network comes up mid-retry and the sync lands.""" + operation = MagicMock(side_effect=[GitHubSyncError("network error"), "ok"]) + with patch("screen_locker._sync_retry.sleep") as sleep: + assert with_sync_retry(operation, description="do the thing") == "ok" + assert operation.call_count == 2 + sleep.assert_called_once_with(2.0) + + def test_gives_up_after_the_attempt_budget(self) -> None: + """A genuinely offline run stops after the configured attempts.""" + operation = MagicMock(side_effect=GitHubSyncError("network error")) + with ( + patch("screen_locker._sync_retry.sleep"), + pytest.raises(GitHubSyncError), + ): + with_sync_retry(operation, description="do the thing", attempts=3) + assert operation.call_count == 3 + + def test_backoff_is_exponential(self) -> None: + """Waits double each time, so ~14s covers DHCP/DNS without dragging.""" + operation = MagicMock(side_effect=GitHubSyncError("network error")) + with ( + patch("screen_locker._sync_retry.sleep") as sleep, + pytest.raises(GitHubSyncError), + ): + with_sync_retry( + operation, + description="do the thing", + attempts=4, + delay_seconds=2.0, + ) + assert [call.args[0] for call in sleep.call_args_list] == [2.0, 4.0, 8.0] + + def test_retries_repo_not_found_too(self) -> None: + """Permission-shaped errors retry as well — see the module docstring. + + Classifying transient vs permanent would couple us to which exception + crdt_sync chains where; a few wasted seconds is the cheaper mistake. + """ + operation = MagicMock(side_effect=RepoNotFoundError("no access")) + with ( + patch("screen_locker._sync_retry.sleep"), + pytest.raises(RepoNotFoundError), + ): + with_sync_retry(operation, description="do the thing", attempts=2) + assert operation.call_count == 2 + + @pytest.mark.parametrize("attempts", [1, 0, -1]) + def test_never_runs_fewer_than_once(self, attempts: int) -> None: + """A nonsensical budget still runs the operation exactly once.""" + operation = MagicMock(side_effect=GitHubSyncError("network error")) + with ( + patch("screen_locker._sync_retry.sleep") as sleep, + pytest.raises(GitHubSyncError), + ): + with_sync_retry(operation, description="do the thing", attempts=attempts) + assert operation.call_count == 1 + sleep.assert_not_called() + + def test_logs_each_retry_and_the_final_give_up( + self, caplog: pytest.LogCaptureFixture + ) -> None: + """Never fails silently: every swallowed attempt says why, at WARNING.""" + operation = MagicMock(side_effect=GitHubSyncError("network error")) + with ( + patch("screen_locker._sync_retry.sleep"), + caplog.at_level("WARNING"), + pytest.raises(GitHubSyncError), + ): + with_sync_retry(operation, description="push things", attempts=3) + assert "attempt 1/3" in caplog.text + assert "attempt 2/3" in caplog.text + assert "after 3 attempt(s)" in caplog.text + assert "giving up" in caplog.text + assert "push things" in caplog.text