kuhyx/screen-locker
1
0
Fork 0
mirror of https://github.com/kuhyx/screen-locker.git synced 2026-11-10 20:27:13 +01:00
Code Issues Actions 6 Packages Projects Releases Wiki Activity

Retry sync past the boot/resume network race, and stop blaming the token

Browse Source 
The morning routine is started by systemd right after boot and right after
resume, so its sync ran seconds before DHCP/DNS were up. Every such run failed
outright — and said this:

    Workout sync push FAILED for 6 workout(s): network error reading
    screen-locker-sync/devices — a 403 here means the token lacks
    contents:write on kuhyx/syncs

Both halves of that were wrong. It was not a 403, and the token was fine: the
same six workouts pushed successfully by hand minutes later on the same token,
which reports push=true on the repo. The message cost a real investigation
chasing a permissions bug that did not exist.

- _sync_retry.with_sync_retry wraps the three sync call sites in a bounded
  retry (4 attempts, 2s/4s/8s backoff — ~14s, enough for the network to come
  up, short enough not to drag the routine). Verified offline in a network
  namespace: three retries, then an honest give-up.
- Any GitHubSyncError retries, deliberately including RepoNotFoundError.
  Classifying transient vs permanent would couple us to which exception
  crdt_sync chains where; a few wasted seconds on a genuinely bad token is the
  cheaper mistake.
- The push failure log now reports what actually happened. The contents:write
  hint survives only for RepoNotFoundError, which is the one error that
  actually implicates the repo or the token.

Retry at the application layer rather than ordering the unit after
network-online.target: the same race hits on resume, where boot ordering does
not apply, and these are user units that cannot depend on a system target.

The tests' autouse no-sleep fixture patches the module-local `sleep` name
rather than `_sync_retry.time.sleep` — the latter mutates the shared time
module object and silently disabled sleep for the whole suite, breaking an
unrelated temperature timeout test.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
Krzysztof Rudnicki 2026-07-20 08:46:37 +02:00
parent 135545ad1e
commit b0d9165a79
8 changed files with 320 additions and 18 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
pyproject.toml
View File

@ -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

11
screen_locker/_constants.py
View File

@ -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

48
screen_locker/_manual_push.py
View File

@ -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(

95
screen_locker/_sync_retry.py Normal file
View File

@ -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

11
screen_locker/_workout_sync.py
View File

@ -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 "

55
screen_locker/tests/test_manual_push.py
View File

@ -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(

14
screen_locker/tests/test_sync_fixtures.py
View File

@ -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

98
screen_locker/tests/test_sync_retry.py Normal file
View File

@ -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