From 0435b712863b3f3ee5f2ce7513098abd820aa12f Mon Sep 17 00:00:00 2001 From: Ankush Kapoor <50513804+kapoorankush@users.noreply.github.com> Date: Tue, 22 Sep 2026 15:43:26 -0500 Subject: [PATCH] Port the post-v0.229.0 development train MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Boundary confirmed by content: litclock-dev `7438f611` <-> public `49083e3d` (tag v0.229.0). Eight non-stats commits, seven files. Seven of eight files are tests or documentation. The entire runtime delta is a degradation arm in `_runtime_render_enabled()` (`src/literary_clock.py`). ### The runtime change (litclock-dev#886) A validation marker that is not valid UTF-8 used to kill the painter instead of falling back to the pre-rendered images. `open(..., encoding="utf-8")` defers decoding to `.read()`, and a `UnicodeDecodeError` is a `ValueError`, so the `except OSError` beside it never caught one and the exception propagated out of a guard whose whole contract is to return True or False. Every other input to that guard already degraded: a missing marker, an unusable freetype-py wheel, a stale FreeType version, a digest that no longer matches. A corrupt one was the exception, and it is the shape a power loss mid-stamp or a damaged card leaves. Reachable only where `LITCLOCK_RUNTIME_RENDER` is true, which is not nobody: the fielded clock runs with it on, so this was live in production rather than latent. Reproduced on the bench against the code this release replaces (`UnicodeDecodeError` at `literary_clock.py:600`, exit 1) and confirmed to degrade to the PNG tier at exit 0 with the fix. ### Tests - litclock-dev#881 — unit tests can no longer resolve a hostname. `conftest.py` wraps `socket.getaddrinfo` at import, refuses anything but loopback, and fails the run from `pytest_sessionfinish`. New file `tests/test_network_guard.py`. - litclock-dev#883 — the self-test record's `duration_s` had no value coverage; the old `0 <= duration_s < 5` band was satisfied by a hardcoded `0.0`. ### Not in this train litclock-dev#871 Stage B (the runtime-render migration) is held. ### Checks `ruff check .` clean. `pytest tests/ --ignore=tests/test_eink_display.py`: 4697 passed, 66 skipped. Issue refs requalified on ported lines only and validated by `tests/test_issue_ref_namespace.py`. No shell scripts touched. CHANGELOG gets one line: the other seven commits are test infrastructure and engineering-record corrections that an owner cannot see. --- CHANGELOG.md | 4 + CLAUDE.md | 83 +++++ src/literary_clock.py | 32 ++ tests/conftest.py | 260 +++++++++++++++ tests/test_literary_clock.py | 59 ++++ tests/test_network_guard.py | 426 +++++++++++++++++++++++++ tests/test_runtime_render_autostamp.py | 256 ++++++++++++++- tests/test_update_sh.py | 15 +- 8 files changed, 1124 insertions(+), 11 deletions(-) create mode 100644 tests/test_network_guard.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 8782be8..796c0d2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,10 @@ All notable changes to LitClock are documented here. Format loosely follows [Kee ## [Unreleased] +### Fixed + +- A damaged validation file no longer stops the clock painting; it falls back to the pre-rendered quotes until the file is rebuilt. + ## [v0.229.0] - 2026-09-21 ### Fixed diff --git a/CLAUDE.md b/CLAUDE.md index f82485c..fdd5db0 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -504,9 +504,92 @@ sudo systemctl start litclock-update.service && journalctl -fu litclock-update **First field measurement, 2026-09-20 (`dev-20260920-512c291`, Pi Zero 2 W):** the self-test recorded **3.8s** during the update; five hand-run repeats on an idle system gave **3.4 / 3.5 / 3.5 / 3.5 / 3.7s**. The gap is update-time load, not instrument bias, and it errs the safe way. + **Confirmed in PRODUCTION, 2026-09-21** — a real weekly-tick OTA onto + v0.229.0 on the fielded clock recorded **3.5s**, and the bench measured + **3.4s** against an INDEPENDENTLY timed 3497ms (`date +%s%N` around the + run, not the function's own claim). Two runs moved together, and the + control — the strip replaced by a no-op — returned an EMPTY duration + against a real 3558ms, which is what makes the 3.4s evidence rather than + a number the function asserts about itself. Same figure across a dev + image, a public image and production, so the expansion widening in + litclock-dev#879/litclock-dev#881 did not move it. + + **The field IS tested now — litclock-dev#883, closed 2026-09-22.** It was not: the + only assertion on the real record was `0 <= duration_s < 5`, which a + hardcoded `0.0` satisfies, and mutating `_runtime_selftest_record_write` + to `local duration="0.0"` left it green. Three executed tests replaced it + (`TestSelfTestDurationReachesTheRecord`), and the bound is no longer a + tolerance: the painter really did sleep `S`, so an honest reading is never + below `S`, and the whole subprocess is strictly longer than the painter + inside it, so it is never above the measured wall clock — both move with + load, and both sides are timed on the SAME clock the value comes from + (`time.time()`, since `EPOCHREALTIME` is CLOCK_REALTIME). + + **What that does NOT give you, before Stage B builds a gate on it.** An + eleven-mutation battery is red, but the accuracy window is `[sleep, wall]` + — its WIDTH is however much the box stalled, so a coarse mutation such as + `floor` fits inside it under a second of load and passes (measured). The + degradation is one-way, costing catching power rather than producing a + false red. More importantly `duration_s` is WHOLE-PROCESS wall time — + env.sh sourcing, interpreter start, the PIL import, then the render — so + it is not comparable to the 4s render lead, and the painter pays that same + startup BEFORE it computes its target instant, so the lead does not cover + it either. A "renders inside the lead" threshold built on this number + would be measuring the wrong thing. Stage B as written gates on the + record's `result` and `sha`, not its duration, deliberately. + + **A release that touches any of the six proof inputs revokes the marker + fleet-wide.** v0.229.0 changed `src/quote_renderer.py`, so the fielded + clock revoked and re-validated (179s, 568044/568044 exact) inside its + update — a ~3.5 min longer tick for every marker-bearing device, and a + window where a device with `LITCLOCK_RUNTIME_RENDER=true` has no marker + and silently paints PNGs. Expected per litclock-dev#604, self-heals on re-stamp. + **Fresh flashes are unaffected**: the image stamps the marker at build + time against the new renderer — verified on the public v0.229.0 image, + digest `c09ebeaf…`, identical to the bench dev card and the fielded + clock. Check that digest on any new image; an ABSENT marker there would + ship devices that never render text and say nothing about it. + **Read what `duration_s` actually contains before you build a threshold on it** (litclock-dev#878 review). It is WHOLE-PROCESS wall time: `t0` is stamped before the subshell, so it includes sourcing `env.sh`, spawning the interpreter, and importing PIL — a material share of 3.5s on a Zero 2 W — and only then the render. It is **not** render time, and it is **not** comparable to a frame-settle figure, which includes a panel refresh the dry-run never performs (it exits before `epd.init()`). Worse for a naive gate: the painter pays that same startup BEFORE it computes its target instant, so that share is not covered by the 4.0s lead at all. The lead is not a render budget. What actually makes a frame late — timer fire through `epd.display()` returning, panel included — is measured by neither this number nor the lead, so Stage B needs to decide what it is really gating before picking a value. Two things that ARE settled: render duration cannot change WHICH minute is painted, because the target is computed once and threaded through the quote pick, masthead, status file and clear gate; but a stall BEFORE that computation (a hanging weather fetch, say) can push the target into the next minute and leave one unpainted, so "slow is harmless" is true only on the render side. +- **A CORRUPT validation marker must degrade, not kill the paint (litclock-dev#886).** + The marker's other failure modes — absent, stale FreeType, wrong digest — all + return False and fall back. A marker that is not valid UTF-8 used to propagate + `UnicodeDecodeError` out of `_runtime_render_enabled()` and take the painter + with it, because `open(..., encoding="utf-8")` defers decoding to `.read()` + and a `UnicodeDecodeError` is a `ValueError`, so the `except OSError` beside it + never caught one. Reachable only where `LITCLOCK_RUNTIME_RENDER=true`. + + Run it on a device with the flag ON, offscreen so it cannot race the minute + tick for GPIO: + + ```bash + cd ~/litclock && cp .runtime-render-validated /tmp/marker.bak + printf 'freetype=2.13.2 digest=\xff\xfe\xfd broken\n' > .runtime-render-validated + mkdir -p /tmp/rr && LITCLOCK_RUNTIME_RENDER=true LITCLOCK_RUNTIME_RENDER_DIR=/tmp/rr \ + WEATHER_ENABLED=false timeout 60 ./venv/bin/python3 src/literary_clock.py --dry-run; echo "EXIT=$?" + cp /tmp/marker.bak .runtime-render-validated # or `validate_measurement.py check --stamp` + ``` + + PASS is a warning naming the file and the re-stamp command, then + `dry-run: rendered 800x480 image, render_mode=image`, **exit 0**. A FAIL is a + `UnicodeDecodeError` traceback and **exit 1**. + + **The asymmetry is measured, not assumed** (bench device, 2026-09-22; + address deliberately not recorded here — this file is public). + The bench tracks the PUBLIC repo, so at v0.229.0 it was fleet code WITHOUT the + fix and reproduced the crash — `UnicodeDecodeError ... position 23` at + `literary_clock.py:600`, exit 1 — while the same corrupt marker with + `src/literary_clock.py` from dev degraded to the PNG tier at exit 0. That + public-tracking bench is the cheapest control you have for any fix whose bug is + live on the fleet: reproduce on it first, then rsync the single changed file. + Full record is kept with the maintainer's QA notes, off-repo. + + **What this does NOT cover:** the SPI write. `--dry-run` exits before + `epd.init()`, so it proves the render path and the fallback decision, not the + panel. + - **`catalog-count` is stdout-compared, so check its contract directly.** On the device: `sudo -u pi /home/pi/litclock/venv/bin/python3 src/eink_display.py catalog-count` must print an integer and **exit 0**. Break the bundle diff --git a/src/literary_clock.py b/src/literary_clock.py index 5446933..d090ab9 100644 --- a/src/literary_clock.py +++ b/src/literary_clock.py @@ -606,6 +606,38 @@ def _runtime_render_enabled() -> bool: "first; using pre-rendered images" ) return False + except UnicodeDecodeError: + # A CORRUPT marker, which is not the same as a missing one and used to + # be the one input to this function that could not degrade: `open(..., + # encoding="utf-8")` defers decoding to `.read()`, and a + # UnicodeDecodeError is a ValueError, so `except OSError` did not catch + # it. It propagated out of the guard whose entire contract is to return + # False, and the painter died instead of falling back to the PNG tier. + # + # NOT latent: this line is unreachable only where + # `LITCLOCK_RUNTIME_RENDER` is false, and the fielded clock is not one + # of those — checked directly on 2026-09-21, flag true and + # `render_mode: runtime` in its live status file. The gifted clocks and + # the internet flashers are on images and are not exposed yet; + # litclock-dev#871 Stage B would have exposed all of them in one weekly + # tick, which is how this was found (in that PR's review, before it + # shipped). + # + # It matters more than a stray traceback because nothing catches the + # aftermath: `litclock-bootcheck` asks whether the heartbeat exists at + # all since boot, not whether it is RECENT, so a clock that painted all + # week and stopped after a Sunday update still looks healthy to it. + # + # Rejected rather than salvaged with errors="replace": a marker is a + # proof, and a proof that did not survive the disk is not one. One + # re-stamp re-earns it, and until then the device paints PNGs. + logging.warning( + f"runtime-render validation marker at {RUNTIME_VALIDATED_MARKER} is not valid " + "UTF-8 — treating this device as unvalidated and using pre-rendered images. " + "Re-run `venv/bin/python3 tools/validate_measurement.py check --stamp` to " + "replace it (litclock-dev#871 review)" + ) + return False # The marker records which FreeType it validated. A freetype-py bump # (OTA venv rebuild) must invalidate it — hinted metrics are version- # sensitive and a stale marker would keep the flag honored in a diff --git a/tests/conftest.py b/tests/conftest.py index e019103..dcb23d6 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -1,10 +1,13 @@ """Shared fixtures for LitClock tests.""" +import ipaddress import json import os import shlex +import socket import subprocess import textwrap +import threading import warnings from dataclasses import dataclass from pathlib import Path @@ -26,6 +29,205 @@ os.environ.setdefault("LITCLOCK_SYSTEMCTL", str(REPO_ROOT / "tests" / ".no-such-systemctl")) +# --- litclock-dev#881: no unit test may touch the network ------------------- +# +# Installed at IMPORT, not as a fixture, and that is the whole point. The bug +# this closes is fixture-ORDERING: `_reset_setup_server_state` below does not +# request `monkeypatch`, so it is set up first and finalized LAST — its +# `reset_state()` drain therefore runs AFTER monkeypatch has restored the real +# `setup_server._resolve_location_from_ip`. A connect thread still draining at +# that moment reaches the LIVE resolver, whatever the test stubbed. A guard that +# is itself a function-scoped fixture would be subject to the same ordering it +# exists to defend against. (A SESSION-scoped one would outlive monkeypatch and +# would also work; import-time simply has no ordering to reason about at all.) +# +# What that late call does is why this is not tidiness. The resolver's success +# path calls `set_system_timezone()` BEFORE the env write, which shells out to +# `sudo /usr/local/lib/litclock/litclock-set-timezone`. That sudo call is +# sandboxed by nothing, so on a Pi — or any box where the installer has run — a +# `pytest tests/` reaching this window can change the SYSTEM TIMEZONE. (It needs +# `setup_server.ENV_FILE` to be set for the resolver to get that far, which a +# fully-restored teardown may not have; the hazard is real but conditional.) It +# is also a live call on a 1/3/9s ladder with a 5s socket timeout — ~33s of +# nominal ladder, not an enforced deadline — against a rate-limited free tier, +# which is the CI-flake mechanism from litclock-dev#876. +# +# litclock-dev#879's finding was that a per-class list of stubs is a list of the +# classes somebody remembered. This is the structural half. It is deliberately +# NOT a replacement for those stubs: a stub says what a test MEANS, this says +# only that no DNS left the process. +# +# SCOPE, stated exactly, because the first draft of this comment got it backwards +# in both halves (review). It covers IN-PROCESS DNS. `socket.create_connection`, +# `http.client`, `urllib` and `requests` all resolve through here — INCLUDING for +# a literal IP, which `create_connection` still passes to `getaddrinfo`, so +# literals do NOT slip past on those paths. What genuinely bypasses it is a raw +# `socket.connect` to a literal, and this tree has two: +# `src/literary_clock.py::_resolve_lan_ip` and `src/control_server/handoff.py` +# both `sock.connect(("1.1.1.1", 80))` on a UDP socket to pick a route. No packet +# leaves for those, and the literary_clock tests stub `socket.socket` — but the +# shape exists, and the earlier claim that "nothing in this tree does that" was +# false. Also outside the guard: SUBPROCESSES. `ScriptSandbox` and every +# bash-script test inherit no Python patch, so a script that shells out to `curl` +# egresses normally. Widening to `socket.connect` would have to tell the loopback +# servers the control-server tests bind apart from real egress, trading a live +# risk of false failures for a hypothetical leak. +# +# Proxies are neutralised rather than left as a hole: with `http_proxy` pointing +# at a loopback address, the only name resolved is the PROXY's, which is +# allowlisted, and the request for `ip-api.com` goes out through it with no +# refusal recorded at all (reproduced in review, on a box with a corporate, +# mitmproxy or Docker proxy variable set). So the vars are cleared here. +for _var in ("http_proxy", "https_proxy", "ftp_proxy", "all_proxy", "no_proxy"): + os.environ.pop(_var, None) + os.environ.pop(_var.upper(), None) +os.environ["no_proxy"] = os.environ["NO_PROXY"] = "*" + +_REAL_GETADDRINFO = socket.getaddrinfo + +# Names that mean this machine. Numeric forms are NOT listed: they are classified +# by `ipaddress` below, because a frozenset of spellings refused `127.0.0.2`, +# `::ffff:127.0.0.1` and `::1%0` — all genuinely loopback here — and would have +# turned any future test using one into a false red (review). +_LOOPBACK_NAMES = frozenset({"localhost", "localhost.localdomain", "ip6-localhost", "ip6-loopback"}) + + +def _is_loopback_host(host) -> bool: + """True when `host` cannot leave this machine. + + `None` and `""` are the wildcard-bind forms. Bytes are a valid `getaddrinfo` + host. On the NAME path a trailing dot is a legal FQDN and case is not + significant, so both are normalised away there — but not before the numeric + parse, for the reason given inline below. + + Two forms are refused although they would resolve to loopback, both + deliberately: `inet_aton` shorthand such as `127.1`, and unicode spellings + such as a unicode look-alike of `localhost` that the resolver NFKC-folds back + to the ASCII spelling. Refusing + is the safe direction — it costs a false red that nothing in this tree + triggers, where accepting would cost the guarantee. + """ + if host is None: + return True + if isinstance(host, (bytes, bytearray)): + try: + host = host.decode("ascii") + except UnicodeDecodeError: + return False + if not isinstance(host, str): + return False + raw = host.strip() + if not raw: + return True + try: + addr = ipaddress.ip_address(raw.split("%", 1)[0]) + except ValueError: + # The trailing dot is stripped ONLY here, on the name path. Doing it + # before the numeric parse made `"127.0.0.1."` classify as a numeric + # loopback while the resolver still treats that exact spelling as a NAME + # needing DNS — approved, forwarded, and resolved with no ledger entry + # (reproduced in review). The guard forwards the ORIGINAL host, so the + # numeric path must judge the original. + return raw.rstrip(".").casefold() in _LOOPBACK_NAMES + # `::ffff:127.0.0.1` is loopback but `IPv6Address.is_loopback` is False for + # it, so unmap first. + if addr.version == 6 and addr.ipv4_mapped is not None: + addr = addr.ipv4_mapped + return addr.is_loopback or addr.is_unspecified + + +class _NetworkAttemptState: + """Resolutions the guard refused (litclock-dev#881). + + ``attempts`` is ``(test nodeid, host, thread name)`` per occurrence. The + thread name is carried because it narrows the diagnosis: a refusal from + ``MainThread`` is usually an unstubbed call in the test body, while one from + a background thread is usually the litclock-dev#881 teardown window. Neither + is proof — an unstubbed worker thread looks the same — so read it as a + pointer, not a verdict. + """ + + def __init__(self) -> None: + self.attempts: list[tuple[str, str, str]] = [] + + +_NETWORK_ATTEMPTS = _NetworkAttemptState() + +# The nodeid a refusal is attributed to: the last test to START, which is the +# test ACTIVE WHEN OBSERVED and not necessarily the one that spawned the thread. +# For a leak that drains inside its own teardown those coincide, which is the +# common case; for a thread that outlives its test — the shape `_ESCAPED_THREADS` +# below exists to track — the name printed is whichever test started next. The +# earlier version of this comment claimed the spawning test, which is wrong. +_CURRENT_NODEID = "" + + +class NetworkAccessAttempted(BaseException): + """Raised in whichever thread tried to leave the box. + + `BaseException`, not `Exception`, and that is load-bearing: the callers this + guard is aimed at swallow broadly. `geocoding.ip_geolocate` and + `location_resolver.resolve_location_from_ip` both wrap their work in + `except Exception`, so an `AssertionError` subclass was caught, logged as + "IP geolocation failed" and RETRIED down the 1/3/9s ladder — the refusal + downgraded to a soft failure that fails nothing (measured in review). + Deriving from `BaseException` means a main-thread refusal really does fail + its own test instead of being absorbed by the code under test. + """ + + +def _guarded_getaddrinfo(host, *args, **kwargs): + if _is_loopback_host(host): + return _REAL_GETADDRINFO(host, *args, **kwargs) + _NETWORK_ATTEMPTS.attempts.append( + (_CURRENT_NODEID, str(host), threading.current_thread().name) + ) + raise NetworkAccessAttempted( + f"a unit test tried to resolve {host!r} (thread {threading.current_thread().name}). " + "Unit tests must not touch the network: stub the caller. If this came from a " + "background thread during teardown, it is litclock-dev#881 — the stub was already " + "restored by monkeypatch while the thread was still draining." + ) + + +socket.getaddrinfo = _guarded_getaddrinfo + + +def foreign_attempts(attempts, expected): + """The refusals in ``attempts`` a quarantining test did NOT ask for. + + Split out as a pure function for the same reason + ``network_attempts_summary_line`` is: a test can hand it its own lists + instead of exercising it through a fixture whose whole job is to leave no + trace, which made the round trip impossible to assert from inside. + + ``expected`` holds hosts the test deliberately tripped; those are its own + business. Everything else — a different host, or the same host from another + thread — belongs to the run and is migrated back to the real ledger. + """ + return [a for a in attempts if a[1] not in expected or a[2] != "MainThread"] + + +def network_attempts_summary_line(state: _NetworkAttemptState) -> str | None: + """The reported text for ``state``, or None when nothing was refused. + + A pure function of the state, matching ``escaped_threads_summary_line`` + below and for the same reason: tests call it with their OWN state object + rather than mutating the module singleton. + """ + if not state.attempts: + return None + shown = state.attempts[:_ESCAPE_REPORT_LIMIT] + hidden = len(state.attempts) - len(shown) + detail = "; ".join(f"{nodeid} -> {host} ({thread})" for nodeid, host, thread in shown) + more = f" (+{hidden} more)" if hidden else "" + return ( + f"[litclock-dev#881] {len(state.attempts)} network resolution(s) REFUSED during the " + f"run: {detail}{more}. A call from a non-main thread points at the litclock-dev#881 " + "teardown window; one from MainThread points at a missing stub. The run has been failed." + ) + + @pytest.fixture def tmp_env_file(tmp_path): """Create a temporary env.sh file with typical content.""" @@ -382,6 +584,59 @@ def absorber_summary_line(state): ) +def pytest_runtest_logstart(nodeid, location): + """Attribute later refusals to the test that is starting (litclock-dev#881).""" + global _CURRENT_NODEID + _CURRENT_NODEID = nodeid + + +def pytest_sessionstart(session): + """Start each session with an empty ledger (litclock-dev#881). + + Process-lifetime state outlives a session when pytest is driven in-process + (`pytest.main()` twice, some IDE runners), and a refusal from run 1 would + then redden run 2 — a self-inflicted version of the poisoning this guard is + meant to detect (found in review). + + xdist is refused outright rather than silently tolerated. A worker's + `exitstatus` is snapshotted before ordinary hooks run and the controller does + not treat a worker's exit status as a failed test, so under `-n` the backstop + below is disarmed while still printing its red line — the exact + looks-like-it-works shape litclock-dev#860/litclock-dev#864 catalogued. Wire + worker-to-controller reporting before removing this. + """ + _NETWORK_ATTEMPTS.attempts.clear() + if session.config.pluginmanager.hasplugin("xdist") and session.config.getoption("numprocesses", None): + raise pytest.UsageError( + "litclock-dev#881: the network guard's run-failing backstop does not survive " + "xdist workers. Wire worker-to-controller reporting before using -n." + ) + + +@pytest.hookimpl(trylast=True) +def pytest_sessionfinish(session, exitstatus): + """Fail the run if anything was refused (litclock-dev#881). + + A refusal raised in a BACKGROUND thread cannot fail the test it came from: + the exception dies with the thread and the test passes. Reporting alone + would therefore be the silent-allow shape this repo keeps getting bitten by + (litclock-dev#860/litclock-dev#864), so the exit status is set here as well. A MAIN + thread refusal fails its own test on its own — `NetworkAccessAttempted` + derives from `BaseException` precisely so the code under test cannot swallow + it. This only converts a green run to red, never the reverse. + + `trylast` so it samples the ledger after other plugins' session hooks have + run. The residual is honest and unfixable from inside the process: a refusal + recorded AFTER this hook — a thread that outlives the whole session, or a + later rung of the 1/3/9s retry ladder spilling past the final test — is + recorded and then dropped, and the run exits 0. The FIRST refusal of any + leak is prompt, which is why the common case is caught; a leak starting in + the session's last test is the one that can escape. + """ + if _NETWORK_ATTEMPTS.attempts and exitstatus == 0: + session.exitstatus = 1 + + def pytest_terminal_summary(terminalreporter): """Surface the absorber's findings where they survive capture. @@ -399,3 +654,8 @@ def pytest_terminal_summary(terminalreporter): escaped_line = escaped_threads_summary_line(_ESCAPED_THREADS) if escaped_line is not None: terminalreporter.write_line(escaped_line, yellow=True, bold=True) + # litclock-dev#881 — red, not yellow: unlike the two above, this one has + # already failed the run in pytest_sessionfinish. + network_line = network_attempts_summary_line(_NETWORK_ATTEMPTS) + if network_line is not None: + terminalreporter.write_line(network_line, red=True, bold=True) diff --git a/tests/test_literary_clock.py b/tests/test_literary_clock.py index 00a58ed..2eb32f9 100644 --- a/tests/test_literary_clock.py +++ b/tests/test_literary_clock.py @@ -654,6 +654,65 @@ def test_flag_requires_validation_marker(self, monkeypatch, tmp_path) -> None: monkeypatch.setattr(literary_clock, "RUNTIME_VALIDATED_MARKER", str(tmp_path / "missing-marker")) assert literary_clock._runtime_render_enabled() is False + def test_a_corrupt_marker_degrades_instead_of_raising(self, monkeypatch, tmp_path, caplog) -> None: + """A marker that is not valid UTF-8 must be treated as unvalidated. + + The one input to this guard that could not degrade. `open(..., + encoding="utf-8")` defers decoding to `.read()`, and a + UnicodeDecodeError is a ValueError — so `except OSError` missed it and + it propagated out of the function whose whole contract is to return + False, killing the paint rather than falling back to the PNG tier. + + Reachable only where the flag is on, which is why it survived this + long — but that is not nobody: the fielded clock runs with it true + (checked 2026-09-21, `render_mode: runtime`), so the crash path is live + in production rather than latent. litclock-dev#871 Stage B would have + made it reachable on every migrated device at once, which is how it was + found. It is worse than a stray traceback because nothing catches the + aftermath: `litclock-bootcheck` asks whether a heartbeat exists since + boot, not whether it is recent, so a clock that stops painting after a + Sunday update still reads as healthy. + """ + marker = tmp_path / ".runtime-render-validated" + marker.write_bytes(b"freetype=2.13.2 digest=\xff\xfe not-utf8\n") + monkeypatch.setenv("LITCLOCK_RUNTIME_RENDER", "true") + monkeypatch.setattr(literary_clock, "RUNTIME_VALIDATED_MARKER", str(marker)) + assert literary_clock._runtime_render_enabled() is False + assert "not valid UTF-8" in caplog.text + + def test_the_corrupt_marker_control_a_valid_one_is_accepted_this_far(self, monkeypatch, tmp_path) -> None: + """The control for the test above. + + `False` is also what a VALID marker returns here once the freetype or + digest check declines, so "returns False" on its own proves nothing + about the decode. This asserts the corrupt marker is rejected at the + READ — by the message it logs — while a well-formed one gets past the + read and is refused later, for a different and stated reason. + """ + marker = tmp_path / ".runtime-render-validated" + marker.write_text("freetype=0.0.0 digest=deadbeef\n") + monkeypatch.setenv("LITCLOCK_RUNTIME_RENDER", "true") + monkeypatch.setattr(literary_clock, "RUNTIME_VALIDATED_MARKER", str(marker)) + import logging as _logging + + with monkeypatch.context(): + records = [] + handler = _logging.Handler() + handler.emit = records.append + _logging.getLogger().addHandler(handler) + try: + assert literary_clock._runtime_render_enabled() is False + finally: + _logging.getLogger().removeHandler(handler) + text = " ".join(r.getMessage() for r in records) + assert "not valid UTF-8" not in text, "a well-formed marker must get past the read" + # Which later check declines depends on the box: a dev machine has no + # freetype-py wheel at all, a validated Pi gets as far as the digest. + # Any of them proves the read succeeded, which is the point. + assert any( + phrase in text for phrase in ("freetype-py unusable", "FreeType", "proof inputs", "digest") + ), text + def _blank_frame(self): from PIL import Image diff --git a/tests/test_network_guard.py b/tests/test_network_guard.py new file mode 100644 index 0000000..a525122 --- /dev/null +++ b/tests/test_network_guard.py @@ -0,0 +1,426 @@ +"""The conftest network guard refuses, records and FAILS (litclock-dev#881). + +A guard that only ever sees clean runs is indistinguishable from one that is +broken: it never fires, so it never proves anything. These force the condition. + +The load-bearing one is `test_a_background_thread_refusal_fails_an_otherwise_green_run`. +A refusal raised inside a background thread cannot fail the test it came from — +the exception dies with the thread and the test passes — so without the +`pytest_sessionfinish` backstop the whole guard would be a yellow line under a +green run, which is the silent-allow shape litclock-dev#860/litclock-dev#864 catalogued. +That test runs a child pytest whose only test PASSES and asserts the child still +exits non-zero. +""" + +from __future__ import annotations + +import os +import socket +import subprocess +import sys +import textwrap +from pathlib import Path + +import pytest + +from tests import conftest +from tests.conftest import ( + _ESCAPE_REPORT_LIMIT, + NetworkAccessAttempted, + _guarded_getaddrinfo, + _is_loopback_host, + _NetworkAttemptState, + foreign_attempts, + network_attempts_summary_line, + pytest_sessionstart, +) + +REPO_ROOT = Path(__file__).resolve().parent.parent + +# The child source for `test_a_refusal_in_teardown_survives_into_the_next_test`, +# held at module level so its own triple quotes do not nest inside the method's +# docstring. +# Child source for the proxy test. The child inherits `http_proxy`; conftest's +# import-time clearing is what must remove it. +CHILD_ASSERTS_NO_PROXY = """ + import os + + def test_the_conftest_cleared_the_inherited_proxy(): + for var in ("http_proxy", "https_proxy", "ftp_proxy", "all_proxy"): + assert var not in os.environ, var + assert var.upper() not in os.environ, var.upper() + assert os.environ.get("no_proxy") == "*" +""" + + +CHILD_LEAKS_IN_TEARDOWN = """ + import socket, pytest + + @pytest.fixture + def leaks_on_teardown(): + yield + try: + socket.getaddrinfo("ip-api.com", 80) # the teardown window + except BaseException: + pass # swallowed, as the real caller does + + def test_a_leaks_during_its_own_teardown(leaks_on_teardown): + assert True + + def test_b_runs_after_and_passes(): + assert True +""" + + + + +@pytest.fixture +def quarantined_attempts(monkeypatch): + """Let a test trip the REAL guard without touching the real ledger. + + The guard and both session hooks look `_NETWORK_ATTEMPTS` up on the conftest + module at call time, so pointing that name at a throwaway state redirects + every write a quarantined test causes — including `pytest_sessionstart`'s + `clear()`, which the hook tests below call for real. + + Two earlier versions were wrong in the same direction, both found by review. + Snapshot-and-restore overwrote the ledger wholesale, discarding any refusal + an unrelated escaped thread recorded meanwhile. Filtering the restore by + nodeid did not help: the guard attributes to the test CURRENTLY RUNNING, so a + foreign thread's refusal during a quarantined test carries this test's nodeid + too and was deleted just the same. Redirecting the destination removes the + class — nothing is ever deleted from the real ledger. + + Anything the test did not `expect()` is migrated back afterwards, so a + genuine leak that lands in the throwaway still reaches session finish. + """ + real = conftest._NETWORK_ATTEMPTS + fresh = _NetworkAttemptState() + expected: set[str] = set() + fresh.expect = expected.add + fresh.real = real # the live ledger, reachable while it is shadowed + monkeypatch.setattr(conftest, "_NETWORK_ATTEMPTS", fresh) + yield fresh + real.attempts.extend(foreign_attempts(fresh.attempts, expected)) + + +class TestTheGuardIsInstalledAndDiscriminates: + def test_it_is_installed_on_the_socket_module(self): + """Not a fixture, so it is not subject to the finalizer ordering that + causes litclock-dev#881 in the first place.""" + assert socket.getaddrinfo is _guarded_getaddrinfo + + def test_loopback_still_resolves(self): + """The control-server tests bind local servers; blocking these would + trade a real regression for the one being prevented.""" + assert socket.getaddrinfo("127.0.0.1", 80) + assert socket.getaddrinfo("localhost", 80) + + @pytest.mark.parametrize( + "host", + [ + None, "", "localhost", "LOCALHOST", "localhost.", b"localhost", + "localhost.localdomain", "ip6-localhost", + "127.0.0.1", "127.0.0.2", "::1", "0:0:0:0:0:0:0:1", "::1%0", + "::ffff:127.0.0.1", "0.0.0.0", "::", + ], + ) + def test_every_loopback_spelling_is_allowed(self, host): + """Each of these resolves to this machine, and each would have been + REFUSED by the frozenset-of-strings the guard first shipped as — a false + red waiting for the first test that used one (review measured all of + them). The classifier is `ipaddress`, so the numeric forms are decided + rather than listed.""" + assert _is_loopback_host(host) is True + + @pytest.mark.parametrize( + "host", ["8.8.8.8", "1.1.1.1", "ip-api.com", "example.com", "127.1", "127.0.0.1."] + ) + def test_non_loopback_is_refused_including_literals(self, host): + """The negative half. Literals matter: `socket.create_connection` passes + one to `getaddrinfo` too, so a hardcoded IP does NOT slip past on that + path. `127.1` is `inet_aton` shorthand that IS loopback on this box but + is deliberately refused — the classifier sticks to forms `ipaddress` + understands, and refusing is the safe direction. + + `127.0.0.1.` is the one that bit: stripping the trailing dot BEFORE the + numeric parse made it classify as a numeric loopback, while the resolver + treats that exact spelling as a NAME needing DNS — approved, forwarded, + resolved, no ledger entry (review). The guard forwards the original host, + so the numeric path has to judge the original. + """ + assert _is_loopback_host(host) is False + + def test_the_guard_writes_to_the_quarantined_state_not_the_real_ledger(self, quarantined_attempts): + """Redirection, not restoration. The real ledger is never written to and + so can never be corrupted by a test that trips the guard on purpose.""" + quarantined_attempts.expect("ip-api.com") + before = len(quarantined_attempts.real.attempts) + with pytest.raises(NetworkAccessAttempted): + socket.getaddrinfo("ip-api.com", 80) + assert len(quarantined_attempts.attempts) == 1, "the refusal went to the throwaway" + assert len(quarantined_attempts.real.attempts) == before, "the real ledger was not written to" + + def test_the_refusal_is_not_swallowed_by_except_exception(self, quarantined_attempts): + """`NetworkAccessAttempted` derives from `BaseException` for this reason. + + `geocoding.ip_geolocate` and `location_resolver.resolve_location_from_ip` + both wrap their work in `except Exception`. As an `AssertionError` + subclass the refusal was caught, logged "IP geolocation failed" and + retried down the 1/3/9s ladder — a refusal that failed nothing. + """ + quarantined_attempts.expect("ip-api.com") + with pytest.raises(NetworkAccessAttempted): + try: + socket.getaddrinfo("ip-api.com", 80) + except Exception: # noqa: BLE001 - the swallow being defended against + pytest.fail("a broad `except Exception` swallowed the refusal") + + def test_no_proxy_is_forced_in_this_process(self): + """Weak on its own — this box sets no proxy, so it would pass with the + clearing deleted. `TestItActuallyFailsTheRun` has the one that can fail.""" + assert os.environ.get("no_proxy") == "*" + + def test_a_remote_host_is_refused_and_recorded(self, quarantined_attempts): + quarantined_attempts.expect("ip-api.com") + with pytest.raises(NetworkAccessAttempted) as exc: + socket.getaddrinfo("ip-api.com", 80) + assert "ip-api.com" in str(exc.value) + assert len(quarantined_attempts.attempts) == 1 + nodeid, host, thread = quarantined_attempts.attempts[0] + assert host == "ip-api.com" + assert "test_a_remote_host_is_refused_and_recorded" in nodeid + assert thread == "MainThread" + + def test_the_refusal_names_litclock_dev_881_for_the_teardown_case(self, quarantined_attempts): + """The message has to tell the two shapes apart, because the fix differs: + a MainThread call is a missing stub, a thread call is the ordering bug.""" + quarantined_attempts.expect("example.invalid") + with pytest.raises(NetworkAccessAttempted) as exc: + socket.getaddrinfo("example.invalid", 443) + assert "litclock-dev#881" in str(exc.value) + assert "background thread" in str(exc.value) + + +class TestTheSummaryLine: + """A pure function of its own state object, like `escaped_threads_summary_line` + beside it — these pass their OWN state rather than mutating the singleton.""" + + def test_it_is_silent_when_nothing_was_refused(self): + assert network_attempts_summary_line(_NetworkAttemptState()) is None + + def test_it_names_the_test_the_host_and_the_thread(self): + state = _NetworkAttemptState() + state.attempts.append(("tests/test_x.py::test_y", "ip-api.com", "setup-wifi-connect")) + line = network_attempts_summary_line(state) + assert "tests/test_x.py::test_y" in line + assert "ip-api.com" in line + assert "setup-wifi-connect" in line + assert "The run has been failed." in line + + def test_it_does_not_say_more_at_exactly_the_limit(self): + """The `hidden == 0` boundary: an off-by-one producing "(+0 more)" would + otherwise go unnoticed.""" + state = _NetworkAttemptState() + for i in range(_ESCAPE_REPORT_LIMIT): + state.attempts.append((f"tests/test_x.py::test_{i}", "ip-api.com", "t")) + line = network_attempts_summary_line(state) + assert "more)" not in line + assert all(f"test_{i}" in line for i in range(_ESCAPE_REPORT_LIMIT)) + + def test_it_truncates_a_flood(self): + state = _NetworkAttemptState() + for i in range(_ESCAPE_REPORT_LIMIT + 3): + state.attempts.append((f"tests/test_x.py::test_{i}", "ip-api.com", "t")) + line = network_attempts_summary_line(state) + assert "(+3 more)" in line + assert f"test_{_ESCAPE_REPORT_LIMIT}" not in line + + +class TestItActuallyFailsTheRun: + """Forced-condition child runs. `-p tests.conftest` loads the repo's conftest + as a plugin, so the child gets the import-time patch and the hooks without + the test file having to live in `tests/`. Verified load-bearing: dropping the + flag makes the child exit 0, so these cannot pass for the wrong reason. + + The child runs CONFIG-LESS — rootdir is the tmp dir, so `pyproject.toml`'s + `pythonpath`, `required_plugins` and `timeout` do not apply. That means + `import setup_server` fails there and the autouse `_reset_setup_server_state` + early-returns, so no child test may depend on that fixture (review).""" + + @staticmethod + def _child(tmp_path, body, env=None): + test_file = tmp_path / "test_child.py" + test_file.write_text(textwrap.dedent(body)) + child_env = dict(os.environ) + child_env.update(env or {}) + return subprocess.run( + [sys.executable, "-m", "pytest", str(test_file), "-p", "tests.conftest", "-q", "-p", "no:cacheprovider"], + cwd=REPO_ROOT, + capture_output=True, + text=True, + timeout=120, + env=child_env, + ) + + def test_a_background_thread_refusal_fails_an_otherwise_green_run(self, tmp_path): + """THE test. The child's only test passes; the run must still be red. + + This is the litclock-dev#881 shape exactly: the resolution happens off + the main thread, so nothing can fail the test itself. + """ + r = self._child(tmp_path, ''' + import socket, threading + + def test_passes_while_a_thread_resolves(): + def go(): + try: + socket.getaddrinfo("ip-api.com", 80) + except Exception: + pass # swallowed, exactly as the real connect thread does + t = threading.Thread(target=go) + t.start() + t.join() + assert True + ''') + assert "1 passed" in r.stdout, f"the child's test should PASS:\n{r.stdout}\n{r.stderr}" + assert r.returncode != 0, ( + "the run must be FAILED by the refusal even though every test passed — " + f"without that backstop the guard is a yellow line under a green suite:\n{r.stdout}" + ) + assert "litclock-dev#881" in r.stdout and "ip-api.com" in r.stdout + + def test_a_refusal_in_teardown_survives_into_the_next_test(self, tmp_path): + """THE litclock-dev#881 timing, which the two child runs above cannot reach. + + Both of those resolve inside a single test body, so a regression that + merely DROPS the ledger between tests keeps them green. Proven in review: + adding `_NETWORK_ATTEMPTS.attempts.clear()` to `_reset_setup_server_state` + — the same kind of between-test isolation reset this conftest does + everywhere else — left the whole file passing while silently allowing + exactly the leak the guard exists to catch. + + So this child has TWO tests: the first leaks from a fixture FINALIZER, + which is the teardown window itself, and the second is a trivial pass + that follows it. Both must pass and the run must still be red. + + Written not to depend on `_reset_setup_server_state`: the child runs + config-less (see `_child`), so `pythonpath` is unset, `import + setup_server` raises ModuleNotFoundError and that fixture early-returns. + """ + r = self._child(tmp_path, CHILD_LEAKS_IN_TEARDOWN) + assert "2 passed" in r.stdout, f"both child tests should PASS:\n{r.stdout}\n{r.stderr}" + assert r.returncode != 0, ( + "a refusal recorded in test A's teardown must still fail the run after test B " + f"has come and gone — otherwise a per-test ledger reset would go unnoticed:\n{r.stdout}" + ) + assert "litclock-dev#881" in r.stdout and "ip-api.com" in r.stdout + + def test_a_proxy_variable_in_the_environment_is_cleared(self, tmp_path): + """The proxy bypass, tested where it can actually fail. + + With `http_proxy` pointing at a loopback address, the only name resolved + is the PROXY's — which is allowlisted — and the request for `ip-api.com` + goes out through it with no refusal recorded at all. That is the guard's + whole property defeated by an environment variable, reproduced in review + on the shape a corporate proxy, mitmproxy or Docker leaves behind. + + The in-process assertion above cannot catch a regression here, because + this box sets no proxy to begin with. This child is given one. + """ + r = self._child( + tmp_path, + CHILD_ASSERTS_NO_PROXY, + env={"http_proxy": "http://127.0.0.1:3128", "HTTPS_PROXY": "http://127.0.0.1:3128"}, + ) + assert "1 passed" in r.stdout, f"{r.stdout}\n{r.stderr}" + assert r.returncode == 0, f"{r.stdout}" + + def test_a_clean_child_run_stays_green(self, tmp_path): + """The control for the test above: the backstop must not fail runs that + did not touch the network, or it would be a permanent red.""" + r = self._child(tmp_path, ''' + import socket + + def test_touches_only_loopback(): + assert socket.getaddrinfo("127.0.0.1", 80) + ''') + assert "1 passed" in r.stdout, f"{r.stdout}\n{r.stderr}" + assert r.returncode == 0, f"a clean run must stay green:\n{r.stdout}" + assert "litclock-dev#881" not in r.stdout + + +class TestTheSessionStartHook: + """`pytest_sessionstart` clears the ledger and refuses xdist. + + Both are invisible to every other test here: the ledger only matters across + two in-process sessions, and xdist is not installed. Called directly with a + stub session for that reason. + """ + + class _StubPM: + def __init__(self, xdist): + self._xdist = xdist + + def hasplugin(self, name): + return name == "xdist" and self._xdist + + class _StubConfig: + def __init__(self, xdist, nprocs): + self.pluginmanager = TestTheSessionStartHook._StubPM(xdist) + self._nprocs = nprocs + + def getoption(self, name, default=None): + return self._nprocs if name == "numprocesses" else default + + class _StubSession: + def __init__(self, xdist=False, nprocs=None): + self.config = TestTheSessionStartHook._StubConfig(xdist, nprocs) + + def test_it_clears_a_previous_sessions_ledger(self, quarantined_attempts): + """Process-lifetime state outlives a session when pytest is driven + in-process, and a refusal from run 1 would otherwise redden run 2 — + reproduced in review with two `pytest.main()` calls.""" + quarantined_attempts.attempts.append(("stale::test", "ip-api.com", "MainThread")) + pytest_sessionstart(self._StubSession()) + assert quarantined_attempts.attempts == [] + + def test_it_refuses_xdist(self, quarantined_attempts): + """Under `-n` a worker's exitstatus is snapshotted before ordinary hooks + run and the controller ignores it, so the backstop is disarmed while the + red line still prints — the looks-like-it-works shape. Loud beats that.""" + with pytest.raises(pytest.UsageError, match="litclock-dev#881"): + pytest_sessionstart(self._StubSession(xdist=True, nprocs=4)) + + def test_it_allows_a_plain_run(self, quarantined_attempts): + pytest_sessionstart(self._StubSession(xdist=True, nprocs=None)) + pytest_sessionstart(self._StubSession(xdist=False, nprocs=None)) + + +class TestTheQuarantinePartition: + """`foreign_attempts` decides what a quarantining test may swallow. + + Tested as a pure function, because the fixture's whole job is to leave no + trace — asserting the round trip from inside a test that uses it would + require observing after its own teardown. + """ + + def test_an_expected_main_thread_refusal_is_the_tests_own(self): + attempts = [("t::a", "ip-api.com", "MainThread")] + assert foreign_attempts(attempts, {"ip-api.com"}) == [] + + def test_a_different_host_belongs_to_the_run(self): + attempts = [("t::a", "elsewhere.example", "MainThread")] + assert foreign_attempts(attempts, {"ip-api.com"}) == attempts + + def test_the_same_host_from_another_thread_belongs_to_the_run(self): + """The case a nodeid filter could not see: the guard attributes to the + test CURRENTLY RUNNING, so an escaped `setup-wifi-connect` thread + resolving during a quarantined test carries that test's nodeid too, and + the earlier filter deleted it (review reproduced the loss).""" + attempts = [("t::a", "ip-api.com", "setup-wifi-connect")] + assert foreign_attempts(attempts, {"ip-api.com"}) == attempts + + def test_nothing_expected_means_everything_is_the_runs(self): + attempts = [("t::a", "ip-api.com", "MainThread")] + assert foreign_attempts(attempts, set()) == attempts diff --git a/tests/test_runtime_render_autostamp.py b/tests/test_runtime_render_autostamp.py index 5681a6c..b2f0996 100644 --- a/tests/test_runtime_render_autostamp.py +++ b/tests/test_runtime_render_autostamp.py @@ -14,6 +14,7 @@ from __future__ import annotations +import ast import json import os import re @@ -51,6 +52,42 @@ # tests; the same trap litclock-dev#782 catalogued and this session has hit twice. STAMP_CALL = re.compile(r'(?:"\$PYTHON"|\./venv/bin/python3)\s+tools/validate_measurement\.py\s+check\s+--stamp') +# The self-test arm's two bounds, NAMED because more than one thing computes +# against them (litclock-dev#883): `_run`'s default and +# `test_the_boundary_is_exact`'s arithmetic. They were bare literals in both, +# linked only by a comment — so the boundary test could silently stop tracking +# the default it claims to follow. Only the RESERVE mirrors `scripts/update.sh`; +# the 2s timeout is a harness choice that keeps the rc-124 test fast, and +# production ships 60s (update.sh:1724). +SELFTEST_TIMEOUT_DEFAULT_S = 2 +SELFTEST_BUDGET_RESERVE_S = 120 + +def render_lead_s(): + """The render lead Stage B will gate `duration_s` against, read from the + source of truth so a change to the lead moves the test with it (litclock-dev#883). + + Read by AST, not by regex, and called from the test rather than at import. + A regex over the assignment was the first version and it is wrong three + ways the review found by trying them: `RENDER_LEAD_DEFAULT_S: float = 4.0` + and `= (4.0)` both report the constant "gone", `= 40e-1` reads FORTY, and + an import-time assert on any of those stops the whole FILE collecting — + including the pi-gen tests, which have nothing to do with this. `ast` + handles the annotation and the parens, `literal_eval` handles the exponent, + and a computed value raises here instead of being silently misread. + `src/literary_clock.py` is still not IMPORTED: these are bash-harness tests + and pulling PIL in for one float would be the heaviest import in the module. + """ + tree = ast.parse((REPO_ROOT / "src" / "literary_clock.py").read_text()) + for node in tree.body: + targets = [node.target] if isinstance(node, ast.AnnAssign) else getattr(node, "targets", []) + for t in targets: + if isinstance(t, ast.Name) and t.id == "RENDER_LEAD_DEFAULT_S": + return float(ast.literal_eval(node.value)) + raise AssertionError( + "RENDER_LEAD_DEFAULT_S is gone from src/literary_clock.py — " + "litclock-dev#883's gate-boundary test has no boundary to sit above" + ) + class TestSomethingActuallyWritesTheMarker: """The regression itself: a tree where nothing stamps.""" @@ -965,6 +1002,7 @@ def _run( installed_budget_s=None, language="xx", sleep=0, + selftest_timeout_s=SELFTEST_TIMEOUT_DEFAULT_S, mktemp_fails=False, pass_record_exists=False, ): @@ -982,7 +1020,11 @@ def _run( f'"${{LITCLOCK_RUNTIME_RENDER_DIR:-unset}}" >> {log}\n' f'if [ -d "${{LITCLOCK_RUNTIME_RENDER_DIR:-}}" ]; then echo exists=yes >> {log}; ' f': > "$LITCLOCK_RUNTIME_RENDER_DIR/current-quote.png"; else echo exists=no >> {log}; fi\n' - f"sleep {sleep}\n" + # `|| exit 97`: the duration tests are the first to depend on the + # painter actually SLEEPING, and a swallowed failure here reports as + # a defect in the shipped writer. 97 is outside every arm the + # self-test distinguishes (0/3/124), so it reads as the harness. + f"sleep {sleep} || exit 97\n" "echo painter-says-hello\n" f"exit {painter_rc}\n" ) @@ -1019,9 +1061,10 @@ def _run( f"RUNTIME_SELFTEST_RECORD_FILE={tmp_path / 'selftest.json'}\n" f"{h._budget_helpers()}" # AFTER the lifted helpers, which carry the script's own constants: - # a 2s bound keeps the timeout case fast, and the boundary tests - # compute against it. - "SELFTEST_TIMEOUT_S=2\nVALIDATOR_BUDGET_RESERVE_S=120\n" + # the 2s default keeps the timeout case fast, and the boundary + # tests compute against it. The duration tests raise it, because + # they need a painter that runs LONGER than the default bound. + f"SELFTEST_TIMEOUT_S={selftest_timeout_s}\nVALIDATOR_BUDGET_RESERVE_S={SELFTEST_BUDGET_RESERVE_S}\n" f"{stub}" + ("mktemp() { return 1; }\n" if mktemp_fails else "") + f"{self._record_fn()}" @@ -1065,6 +1108,9 @@ def test_a_pass_forces_the_renderer_on_with_the_devices_language_and_writes_no_m assert memo is None rec = self._record(tmp_path) assert rec is not None and rec["result"] == "passed", "a pass must leave a DURABLE record for Stage B" + # SHAPE only: any constant in [0, 5) satisfies this, `0.0` included, + # which is what litclock-dev#883 was filed about. The VALUE is asserted + # by TestSelfTestDurationReachesTheRecord below. assert isinstance(rec["duration_s"], (int, float)) and 0 <= rec["duration_s"] < 5, rec assert rec["sha"] and rec["at_unix"] > 0 @@ -1134,11 +1180,16 @@ def test_enough_budget_runs_it(self, tmp_path): assert "argv=" in painter and memo is None def test_the_boundary_is_exact(self, tmp_path): - # elapsed + 2 (timeout) + 120 (reserve) > budget defers; == does not. - _, painter, _ = self._run(tmp_path, painter_rc=0, elapsed_s=1678, installed_budget_s=1800) - assert "argv=" in painter, "1678+2+120 == 1800 fits" - _, painter, _ = self._run(tmp_path, painter_rc=0, elapsed_s=1679, installed_budget_s=1800) - assert painter == "", "1679+2+120 > 1800 defers" + # elapsed + timeout + reserve > budget defers; == does not. DERIVED from + # the two constants rather than the hand-computed 1678/1679 this used to + # carry (litclock-dev#883): the bound became a defaulted parameter, and a + # literal here would track it only by comment. + budget = 1800 + fits = budget - SELFTEST_BUDGET_RESERVE_S - SELFTEST_TIMEOUT_DEFAULT_S + _, painter, _ = self._run(tmp_path, painter_rc=0, elapsed_s=fits, installed_budget_s=budget) + assert "argv=" in painter, f"{fits}+{SELFTEST_TIMEOUT_DEFAULT_S}+{SELFTEST_BUDGET_RESERVE_S} == {budget} fits" + _, painter, _ = self._run(tmp_path, painter_rc=0, elapsed_s=fits + 1, installed_budget_s=budget) + assert painter == "", f"{fits + 1}+{SELFTEST_TIMEOUT_DEFAULT_S}+{SELFTEST_BUDGET_RESERVE_S} > {budget} defers" def test_an_unknown_budget_defers_an_unlimited_one_runs(self, tmp_path): _, painter, memo = self._run(tmp_path, painter_rc=0, elapsed_s="unknown") @@ -1149,3 +1200,190 @@ def test_an_unknown_budget_defers_an_unlimited_one_runs(self, tmp_path): def test_outside_systemd_there_is_no_budget_to_respect(self, tmp_path): _, painter, memo = self._run(tmp_path, painter_rc=0, elapsed_s=None) assert "argv=" in painter and memo is None + + +class TestSelfTestDurationReachesTheRecord: + """litclock-dev#883 — `duration_s` in the REAL record, the field litclock-dev#871 + Stage B is designed to gate on ("does this device render inside the render lead"). + + `TestRuntimeRenderSelftestExecutes` is the only place the real + `_runtime_selftest_record_write` executes, and every duration assertion it + made was `0 <= duration_s < 5` — a band any constant in it satisfies, `0.0` + included. `TestSelfTestDurationSurvivesToTheRecord` in test_update_sh.py + covers the layer above and cannot see this one: it STUBS the writer, so it is + scoped to what `_runtime_render_selftest` HANDS the writer. The boundary + between the two classes is the writer itself, which is why these live here. + Measured: `local duration="0.0"` in the writer is red here and GREEN there. + + Three shapes, because the first draft of this class was one band plus one + movement control and four independent review passes each defeated it. + MEASURED against an eleven-mutation battery on a quiet box (x = caught): + + mutation accuracy control lead + writer: hardcoded 0.0 x x x + writer: constant 1.5 - x x + writer: epoch x - x + writer: floor x - x + writer: +0.9 x - x + writer: *0.7 / *1.5 x - x + writer: *0.98 x - x + writer: clamp at 3 - - x + selftest: dropped decisecond x - x + selftest: $SECONDS revert x - x + + Read that honestly, in three parts. + + The lead test catches all eleven and the other two are dominated on THIS + battery. They stay for their diagnosis, not their coverage: "below the + sleep", "not tracking the clock" and "Stage B would pass a device that + cannot make it" send the next reader to three different places. The control + also holds the one RELATIONAL property — compared between two records rather + than against a computed bound — so it survives any future loosening of the + bounds below. + + The battery is a measurement, not a guarantee. The accuracy window is + `[sleep, wall]`, so its WIDTH is however much the box stalled: ~0.05s idle, + and a second wide under a second of stall, where a coarse mutation such as + `floor` fits inside it and passes (measured, by injecting the delay). The + degradation is one-way — load widens the window, so it costs catching power + and never produces a false red — which is the right direction for CI, and + the reason to run the battery on a quiet box when it matters. + + The one genuinely unqualified claim is the LOWER bound: a reading below the + sleep cannot be the elapsed time. Its only escape is a backward + CLOCK_REALTIME step inside the painter's window, which reds it. The upper + bound is now measured on the same clock as the value (see `_timed_run`), so + a step moves both together and cannot break the nesting. + + Total cost 8.8s of sleeping in a suite that runs ~330s. + + **The accuracy bound is the painter's own sleep and the subprocess's measured + wall clock, not a fixed tolerance.** The first draft used `abs(d - 1.5) <= 1.0` + and four imprecision mutations stayed green under it, the sharpest being + `t0=$SECONDS` / `dur_ms=$(( (SECONDS-t0)*1000 ))` — a literal revert of the + decision recorded four lines above the code it mutates ("whole-second + $SECONDS is ±1s on it", the litclock-dev#875 red team), because a ±1.0s tolerance is + exactly what that revert costs. `floor`, `+0.9` and a dropped decisecond + survived it too. A tighter fixed tolerance would trade that for flake, so the + bound is not fixed: the painter really did sleep `S`, so an honest reading is + never below `S`; and the whole subprocess is strictly longer than the painter + inside it, so an honest reading is never above the wall clock. Neither side + is a number anybody had to guess at, and the failure direction under load is + one-way — see the third part of the battery note below for what that does + and does not buy. + + What these do NOT cover, stated so it is not re-derived: a mutation that + keeps the value honest at every sleep used here. The locale layer + (`TestSelfTestDurationIsLocaleProof`, test_update_sh.py) covers the separator + class, which no amount of sleeping reaches. + """ + + # Must exceed every sleep below: the painter is wrapped in `timeout + # "$SELFTEST_TIMEOUT_S"`, and exceeding it takes the rc-124 arm, which + # deletes the record and surfaces as "no record" rather than "bound too low". + TIMEOUT_S = 30 + # Every sleep sits on a decisecond BOUNDARY, which is what lets the lower + # bound be the sleep exactly rather than the sleep minus a quantum + # (litclock-dev#883, second review round). `duration` is formatted `S.d` by + # truncation, and truncating an elapsed time of at least 1.5s cannot yield + # 1.4s — so subtracting a quantum "for safety" admits values the shipped + # formatter cannot honestly produce. It cost a real mutation: `d * 0.98` + # passed all three tests, recording a 4.05s paint as 3.92s — inside the lead. + SLEEP_S = 1.5 # deliberately mid-second: whole-second arithmetic + # lands 0.5s away whichever way it rounds + CONTROL_SHORT_S = 0.3 + CONTROL_LONG_S = 2.5 + MIN_MOVE_S = 1.5 # true movement 2.2s; ~0.7s of slack + SLOW_MARGIN_S = 0.5 # the slow painter runs this far ABOVE the lead + + H = TestRuntimeRenderSelftestExecutes + + def _timed_run(self, tmp_path, **kw): + """Run the real self-test and time the whole subprocess. + + The elapsed wall clock is an UPPER bound on what the painter inside it + can honestly have taken — it also carries bash startup, the lifted + helpers and the writer's own `jq`/`git`. + """ + # time.time(), NOT time.monotonic(): the value under test comes from + # EPOCHREALTIME, which is CLOCK_REALTIME. Timing the outside on the + # monotonic clock compares two clocks that step differently, and an NTP + # step or a suspend then breaks the nesting this bound rests on (review + # replayed both directions). Reading the SAME clock on both sides means + # a step moves the inner and outer measurement together. + t0 = time.time() + r, _painter, memo = self.H()._run(tmp_path, selftest_timeout_s=self.TIMEOUT_S, **kw) + wall = time.time() - t0 + assert "self-test PASSED" in r.stdout, ( + f"the run did not take the PASS arm, so there is no duration to judge — " + f"rc 97 here means the HARNESS's `sleep` failed, not the writer:\n{r.stdout}\n{r.stderr}" + ) + assert memo is None, f"a pass writes no memo, got {memo}" + rec = self.H._record(tmp_path) + assert rec is not None, "the pass arm must have written the record" + return rec, wall + + def _assert_honest(self, rec, slept, wall): + d = rec["duration_s"] + assert d >= slept, ( + f"the record says {d}s for a painter that slept {slept}s — a reading BELOW the " + f"sleep cannot be the elapsed time, whatever the machine was doing" + ) + assert d <= wall, ( + f"the record says {d}s but the whole subprocess took {wall:.2f}s — the painter " + f"is strictly inside that, so the value is not the elapsed time" + ) + + def test_the_recorded_duration_is_the_real_elapsed_time(self, tmp_path): + """A painter that sleeps a known time must put THAT time in the record.""" + rec, wall = self._timed_run(tmp_path, painter_rc=0, sleep=self.SLEEP_S) + self._assert_honest(rec, self.SLEEP_S, wall) + + def test_a_slower_painter_records_a_longer_duration(self, tmp_path): + """The movement control. + + A constant INSIDE the accuracy bounds passes them exactly as the real + clock does; only a second measurement at a different paint time + separates the two. The reverse also holds, which is the part worth + recording: an epoch-valued duration MOVES between the two runs and + passes this test, while failing accuracy — measured, and the inverse of + what this docstring claimed in its first draft. So accuracy and movement + each catch something the other does not, even though the lead test above + happens to catch both. + """ + short, _ = self._timed_run(tmp_path, painter_rc=0, sleep=self.CONTROL_SHORT_S) + long, _ = self._timed_run(tmp_path, painter_rc=0, sleep=self.CONTROL_LONG_S) + moved = long["duration_s"] - short["duration_s"] + asked = self.CONTROL_LONG_S - self.CONTROL_SHORT_S + assert moved >= self.MIN_MOVE_S, ( + f"a painter asked to run {asked:.1f}s longer moved the recorded duration by only " + f"{moved}s ({short['duration_s']} -> {long['duration_s']}) — duration_s is not " + f"tracking the clock (or this box stalled the short run by ~{asked - self.MIN_MOVE_S:.1f}s)" + ) + + def test_a_paint_slower_than_the_lead_is_recorded_as_slower(self, tmp_path): + """The gate boundary — the shape the other two cannot see. + + Stage B's question is "did this device render inside the lead", so the + value has to be honest AT that boundary, not merely somewhere near 1.5s. + Measured: a writer that CLAMPS the duration (`min(d, 3)`) passes both + tests above and would report every slow device as comfortably inside the + lead — the exact "falsely SMALL value sailing through a threshold" + hazard `update.sh`'s own litclock-dev#879 comment names. (A scale-down + like `d * 0.7` is caught by accuracy as well; only the clamp reaches + here alone.) + + The lead assertion runs BEFORE the accuracy bounds on purpose. It is the + weaker of the two — the lower bound already implies it — so behind them + it could never fail, and the clamp would report as "below the sleep" + rather than as the Stage B consequence, which is the diagnosis worth + reading. + """ + lead = render_lead_s() + slept = lead + self.SLOW_MARGIN_S + rec, wall = self._timed_run(tmp_path, painter_rc=0, sleep=slept) + assert rec["duration_s"] >= lead, ( + f"a paint that took {slept}s was recorded as {rec['duration_s']}s, inside " + f"the {lead}s lead — Stage B would pass a device that cannot make it" + ) + self._assert_honest(rec, slept, wall) diff --git a/tests/test_update_sh.py b/tests/test_update_sh.py index e5fab31..3aae082 100644 --- a/tests/test_update_sh.py +++ b/tests/test_update_sh.py @@ -4305,9 +4305,20 @@ def test_the_recorded_duration_is_the_real_elapsed_time(self, tmp_path): def test_a_longer_paint_records_a_longer_duration(self, tmp_path): """The CONTROL for the test above. - A hardcoded constant, a zero, or an epoch would satisfy a single + A hardcoded constant INSIDE the tolerance band above satisfies a single measurement just as well; this one only passes if the recorded value - actually TRACKS how long the painter ran. + actually TRACKS how long the painter ran. Corrected in litclock-dev#883: + this used to say "a constant, a zero, or an epoch", and neither a zero + nor an epoch satisfies the measurement above — both land further than + TOLERANCE_S from SLEEP_S. An epoch does pass THIS one, by moving between + the two runs, so the overbroad version named as the control's reason the + one example where the control is the test that is fooled. + + The twin of this pair, one layer down, is + `TestSelfTestDurationReachesTheRecord` in + tests/test_runtime_render_autostamp.py: it executes the REAL writer, + where this class stubs it. Retuning the sleeps or the tolerance here + should check there too. """ short = self._run_real_function(tmp_path, sleep_s=0.3) long = self._run_real_function(tmp_path, sleep_s=2.5)