From 58f8f13445f0252bca59c7801ec9c2d429e41e88 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 10:48:03 -0500 Subject: [PATCH 1/5] fix(tests): a swallowed SQL Server lock-timeout stranded an ADR 0070 lane in terminal IDLE (BACKLOG #344 instance 2) The intermittent sqlserver-only `assert False` in test_stage_dispatcher.py was never the 8.0s bound. Proven, not argued. MECHANISM. claim_fifo_heads runs under SET LOCK_TIMEOUT 0, so a momentarily contended head raises native error 1222 instantly -- and the store CATCHES 1222 and returns a normal EMPTY result (store/sqlserver.py, the _is_lock_timeout branch; deliberate, the "never-block" yield, logged only at DEBUG). The dispatcher's EMPTY branch then takes T12: phase=IDLE with NO timer armed. Production's periodic sweep re-readies exactly such a lane; the ADR 0070 tests set sweep_interval=3600 with an empty lane_provider ON PURPOSE, so IDLE is TERMINAL there and the lane can never be re-claimed. No budget would have helped: the poll cannot succeed at any size. PROOF. Holding a conflicting row lock across the post-unpark re-claim on a live SQL Server reproduces it deterministically -- empty_claims (0,0,0) -> (1,0,1), lane IDLE, park_until=None, no armed timer, head still `pending` and DUE -- and releasing the lock does NOT recover it. The same stranding then appeared UNFORCED on a local full-file run (test_adr0070_1_retry_forever_never_stops_alerts_stuck[sqlserver]). So this is a test-rig gap, not an engine defect. SQLite's immunity is structural (in-process, no lock-timeout translation); Postgres's 119 observations are too few to exonerate it, so read "SQL Server-only" as "server-backed store". FIX, two halves. 1. _wait_until now RAISES on expiry (BACKLOG #344 proposal 6) with the lane's phase, park deadline, streak, task liveness/exception, the store row's status and next_attempt_at, the clock, and empty_claims -- plus a one-line VERDICT naming which hypothesis the reading proves, so no future occurrence is re-diagnosed from scratch. All 60 bare-assert call sites convert for free (the two that legitimately tolerate a timeout pass required=False; the one that carried a message passes note=). 2. The ADR 0070 phase waits go through _wait_lane, which stands in for the sweep those tests disable -- re-readying a lane found in TERMINAL IDLE, but COUNTED and capped at one, and warned about, so a genuine contention regression still fails loudly rather than being absorbed. The stand-in is disabled when IDLE is itself the target phase. FALSIFIED. With the stand-in budget forced to 0, the same injected EMPTY reproduces the original failure -- now carrying the full diagnostic instead of a bare `assert False`. A guard that passes against unpatched code would have measured nothing. Verified: ruff format + check, mypy strict, and the full file green on all three backends (sqlite + a live SQL Server 2022 container + a live Postgres 16), 76 passed per server leg. NOTE for the merge: PR #138 (claude/ci-margin-correction) also edits #344 instance 2 -- it ADDS a "RE-DIAGNOSED" block recording the mechanism as unresolved. That block is superseded by this one and the two will need a one-time reconciliation. --- docs/BACKLOG.md | 10 +- tests/test_stage_dispatcher.py | 247 +++++++++++++++++++++++++++++---- 2 files changed, 229 insertions(+), 28 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 38cd5981..6678ac0a 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8325,7 +8325,7 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme ## 344. Fixed wall-clock bounds have drifted out of proportion to the work they bound -> πŸ”’ **Filed 2026-08-01 β€” not started.** Value **6/10** Β· Difficulty **4/10** Β· _fill-in_. Hardcoded real-time budgets β€” a CI `step_timeout`, a test helper's poll deadline β€” were sized when the work was smaller or the machine faster, and nothing re-derives them. Two confirmed instances; each presents as an unrelated flake. +> 🚧 **Status OPEN (filed 2026-08-01; both named instances now closed, the generic remedy is not).** Value **6/10** Β· Difficulty **4/10** Β· _fill-in_. Hardcoded real-time budgets β€” a CI `step_timeout`, a test helper's poll deadline β€” were sized when the work was smaller or the machine faster, and nothing re-derives them. Instance 1 (the Windows `step_timeout`) was fixed on filing; **instance 2 was resolved 2026-08-02 and turned out not to be a bound problem at all** β€” a swallowed SQL Server lock-timeout stranded a lane in a terminal IDLE, and no budget would have helped. What remains open is the mechanical margin check (proposal 1) and the sweep of the remaining bounds (proposal 2). The item's real lesson is now instance 2's: **a timeout with zero failing assertions is a diagnosis to be made, not a number to be raised.** **Cluster:** Developer Experience & CI. **Priority:** P2. **Verdict:** build. **Severity:** medium. @@ -8333,7 +8333,11 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme *Instance 1 (fixed 2026-08-01, this filing).* `ci.yml`'s Windows `step_timeout: 26`. windows-2025's max PASSING `Tests (pytest)` step was **24:35** over 11 runs β€” 1.06x margin β€” and PR #119 was killed at 26:07 with zero test failures after #74 added a 1,506-line test file. The comment beside the cap asserted "~2x headroom", a figure that matched no leg. Raised to 36:00 (1.46x) with the measurement and its date recorded in place of the multiple. -*Instance 2 (open).* `tests/test_stage_dispatcher.py`'s `_wait_until` (:356) polls `loop.time()` against a hardcoded **8.0s** budget while the dispatcher under test is driven by an injected `ManualClock`. On PR #129 β€” whose diff is provably AST-identical to main, docstrings only β€” `test_adr0070_9_content_retry_is_not_an_infra_fault[sqlserver]` failed on that bound alone against a Dockerised SQL Server; every logic assertion in the same loop passed. A real-time deadline gating a virtual-clock system has no principled value. +*Instance 2 (**RESOLVED 2026-08-02 β€” and it was never a bound problem**).* Presented as `tests/test_stage_dispatcher.py`'s `_wait_until` 8.0s budget expiring on the SQL Server leg with zero logic assertions failing (two occurrences in 21 days: `test_adr0070_1_stop_policy_bounds_deterministic_infra_head`, run 30733129076; `test_adr0070_9_content_retry_is_not_an_infra_fault`, run 30716979773 attempt 1 β€” ~0.4%/test over ~479 observations, zero on Postgres/119 and zero on SQLite/1,105). **The bound was never the cause and must not be raised**: the test passes in max 0.204s on green SQL Server jobs and 0.576s at worst across 241 runs, so 8.0s is 14–39Γ— the worst passing run and both failures sit ~7Γ— beyond the *entire* passing distribution β€” a gap, not a tail. Past ~31s a raise would convert a real 30-second store hang into a silent PASS. + +The actual mechanism, **proven by forcing it on a live SQL Server** rather than argued: `claim_fifo_heads` runs under `SET LOCK_TIMEOUT 0`, so a momentarily contended head raises native error **1222** instantly; the store **catches 1222 and returns a normal EMPTY result** (`store/sqlserver.py`, the `_is_lock_timeout` branch β€” deliberate, the "never-block" yield, logged only at DEBUG). The dispatcher's EMPTY branch then takes **T12**: `phase=IDLE` with **no timer armed**. In production the periodic sweep re-readies exactly such a lane; the ADR 0070 tests set `sweep_interval=3600` with an empty `lane_provider` **on purpose**, so IDLE is **terminal** there and the lane can never be re-claimed β€” the poll then cannot succeed at any budget. Holding a conflicting row lock across the post-unpark re-claim reproduces it deterministically: `empty_claims` goes `(0,0,0)` β†’ `(1,0,1)`, the lane sits `IDLE` with `park_until=None` and no armed timer, the head is still `pending` and **due**, and releasing the lock does *not* recover it. The same stranding was then observed **unforced** on a local full-file run (`test_adr0070_1_retry_forever_never_stops_alerts_stuck[sqlserver]`). This is a **test-rig gap, not an engine defect** β€” production's backstop is intact; SQLite's immunity is structural (in-process, no lock-timeout translation), and Postgres's 119 observations are too few to exonerate it, so "SQL Server-only" should be read as "server-backed store". + +Fixed two ways in [`tests/test_stage_dispatcher.py`](../tests/test_stage_dispatcher.py): `_wait_until` now **raises on expiry** carrying the lane's phase, park deadline, streak, task state, the store row's status/`next_attempt_at`, the clock, and `empty_claims` β€” plus a one-line **verdict** naming which hypothesis the reading proves, so no future occurrence needs re-diagnosing from scratch; and the ADR 0070 waits now stand in for the sweep those tests disable β€” re-readying a lane found in terminal IDLE, but **counted and capped at one**, so a genuine contention regression still fails loudly instead of being absorbed. Both halves are falsification-tested: with the stand-in disabled the same injected EMPTY reproduces the original failure, now carrying the full diagnostic instead of a bare `assert False`. **Why:** these fail *individually blameless*. The remaining CI margin is a **shared budget nobody accounts for** β€” three PRs each adding a minute of Windows time reproduce #119's death, with no single PR at fault. And this repo has twice mislabelled such a failure: the two famous "flakes" turned out to be a livelock and a test that was right. A timeout with no failing assertion is the exact signature that invites the wrong diagnosis. @@ -8343,7 +8347,7 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme 3. Where a virtual clock drives the system under test, the poll deadline should follow that clock, not `loop.time()` β€” instance 2 is the worked example. 4. Prefer bounds expressed as a measured ratio with a date over round multiples, per instance 1's post-mortem. -**Related:** [`.github/workflows/ci.yml`](../.github/workflows/ci.yml) Β§*Tests (pytest)* (instance 1 and its measurement table); `tests/test_stage_dispatcher.py`:356 (instance 2); #320 (windows-2025 slowness β€” the capacity fact that shrinks every Windows margin); #340 (the other half of this triage); [`Secure_Development_Standards`](Secure_Development_Standards.md) Β§3 (prose asserting a margin the numbers do not support β€” five instances found on 2026-08-01 alone). +**Related:** [`.github/workflows/ci.yml`](../.github/workflows/ci.yml) Β§*Tests (pytest)* (instance 1 and its measurement table); [`tests/test_stage_dispatcher.py`](../tests/test_stage_dispatcher.py) (instance 2 β€” `_wait_until`'s raising expiry report and the counted `_wait_lane` sweep stand-in); [`store/sqlserver.py`](../messagefoundry/store/sqlserver.py) (`_is_lock_timeout` β€” the 1222-as-EMPTY yield that instance 2 turned on); ADR 0070 (the infra-fault machinery the affected tests cover); #320 (windows-2025 slowness β€” the capacity fact that shrinks every Windows margin); #340 (the other half of this triage); [`Secure_Development_Standards`](Secure_Development_Standards.md) Β§3 (prose asserting a margin the numbers do not support β€” five instances found on 2026-08-01 alone). **Source:** stuck-CI triage, 2026-08-01. Instance 1 measured across 11 windows-2025 runs; instance 2 reported and diagnosed by the HA-construct-recheck session from PR #129's sqlserver leg. diff --git a/tests/test_stage_dispatcher.py b/tests/test_stage_dispatcher.py index bdd4f0d2..b5c567dc 100644 --- a/tests/test_stage_dispatcher.py +++ b/tests/test_stage_dispatcher.py @@ -32,7 +32,8 @@ import asyncio import os import random -from collections.abc import AsyncIterator, Callable +import warnings +from collections.abc import AsyncIterator, Callable, Iterator from dataclasses import dataclass from pathlib import Path from typing import Any, cast @@ -188,6 +189,9 @@ class ManualClock: def __init__(self, start: float = 0.0) -> None: self.now = start self._armed: list[_ManualHandle] = [] + _LIVE_CLOCKS.append( + self + ) # so a `_wait_until` expiry can report virtual time (BACKLOG #344) def time(self) -> float: return self.now @@ -353,16 +357,138 @@ async def _settle(rounds: int = 8) -> None: await asyncio.sleep(0.005) -async def _wait_until(pred: Callable[[], bool], timeout: float = 8.0) -> bool: +# --- expiry diagnostics (BACKLOG #344 proposal 6) ------------------------------------------------- +# +# A bare `assert await _wait_until(...)` reports `assert False` and NOTHING else, so every occurrence +# gets re-diagnosed from scratch β€” BACKLOG #344 instance 2 was read as latency for a day on exactly +# that basis. `_wait_until` therefore RAISES on expiry, carrying the state a reader needs. +# +# The dispatcher/clock are not passed in (the predicate is an opaque closure): they register +# themselves on construction and `_reset_wait_registry` clears them per test, so every call site gets +# the diagnostic for free with no per-site argument. + +_LIVE_DISPATCHERS: list[StageDispatcher] = [] +_LIVE_CLOCKS: list[ManualClock] = [] + + +class _WaitTimeout(AssertionError): + """A `_wait_until` poll expired. AssertionError so pytest reports it as a test failure, not an + error, and so the historical `assert await _wait_until(...)` form reads unchanged.""" + + +@pytest.fixture(autouse=True) +def _reset_wait_registry() -> Iterator[None]: + """Scope the diagnostic registries to one test (they are module-level by necessity).""" + _LIVE_DISPATCHERS.clear() + _LIVE_CLOCKS.clear() + _SWEEP_STANDINS.clear() + yield + _LIVE_DISPATCHERS.clear() + _LIVE_CLOCKS.clear() + _SWEEP_STANDINS.clear() + + +def _lane_report(d: StageDispatcher, lane: str) -> str: + task = d._lane_tasks.get(lane) + if task is None: + task_state = "none" + elif not task.done(): + task_state = "ALIVE" + elif task.cancelled(): + task_state = "cancelled" + else: + exc = task.exception() + task_state = f"raised {exc!r}" if exc is not None else "finished" + return ( + f" {lane}: phase={getattr(d.phase(lane), 'name', None)}" + f" park_until={d.park_until(lane)} streak={d.infra_error_streak(lane)}" + f" dirty={d.is_dirty(lane)} timer_armed={d._timer_deadline.get(lane)}" + f" lane_task={task_state}" + ) + + +def _verdict(d: StageDispatcher) -> str: + """State which #344 hypothesis this expiry is, so the next reader need not know the theory. + + `empty_claims` is the discriminator (`StageDispatcher.empty_claims`, fed only by the EMPTY branch + of `_claim_and_dispatch`): under the ADR 0070 topology a clean run reads (0, 0, 0). + """ + if d.empty_claims[0] > 0: + return ( + "VERDICT: a claim came back EMPTY (empty_claims[0] > 0) and T12 dropped the lane to a" + " TERMINAL IDLE β€” no timer armed, and these tests disable the sweep that would re-ready" + " it. On SQL Server the usual cause is a swallowed lock-timeout (native 1222 under" + " SET LOCK_TIMEOUT 0, reported by the store as a normal empty result). BACKLOG #344" + " instance 2." + ) + return ( + "VERDICT: NO empty claim was recorded (empty_claims[0] == 0), so the claim never returned at" + " all β€” a stalled statement or a lost wakeup. This is NOT the #344 instance-2 stranding and" + " must not be papered over with a re-nudge; check the lane/claimer task state below." + ) + + +async def _expiry_report(pred: Callable[[], bool] | None = None) -> str: + """Everything a reader needs to tell the two #344 hypotheses apart, without a second CI round-trip.""" + lines = ["_wait_until expired."] + if pred is not None: + try: + lines.append(f" predicate re-read after expiry: {pred()!r}") + except Exception as exc: # noqa: BLE001 β€” a raising predicate must not hide the report + lines.append(f" predicate re-read RAISED: {exc!r}") + for i, d in enumerate(_LIVE_DISPATCHERS): + lines.append(f" {_verdict(d)}") + lines.append( + f" dispatcher[{i}] stage={d._stage.value}" + f" empty_claims(total,wake_fanout,idle_poll)={d.empty_claims}" + f" busy_violations={d.busy_violations} processing_lanes={d.processing_lanes}" + f" slots_free={d._slots_free}" + ) + lines.extend(_lane_report(d, lane) for lane in d._states) + # The store row is the other half: status + next_attempt_at say whether the head was even + # claimable. Bounded and swallowed β€” a diagnostic that hangs or raises would MASK the failure + # it is meant to explain. + try: + for lane in list(d._states): + rows = await asyncio.wait_for(_lane_rows(d._store, lane), timeout=5.0) + lines.append( + f" {lane} rows=" + + str([(r["status"], r["attempts"], r["next_attempt_at"]) for r in rows]) + ) + except Exception as exc: # noqa: BLE001 β€” a diagnostic must never mask the real failure + lines.append(f" ") + for i, mc in enumerate(_LIVE_CLOCKS): + lines.append(f" clock[{i}].now={mc.now} armed={[h.fire_at for h in mc.armed]}") + return "\n".join(lines) + + +async def _wait_until( + pred: Callable[[], bool], + timeout: float = 8.0, + *, + required: bool = True, + note: str | None = None, +) -> bool: """Poll ``pred`` (letting async work run) until true or ``timeout``. Robust against aiosqlite thread - latency without fixed-iteration flakiness.""" + latency without fixed-iteration flakiness. + + On expiry this RAISES :class:`_WaitTimeout` with a full dispatcher/store dump (BACKLOG #344 + proposal 6) instead of returning False β€” a bare ``assert False`` is what made instance 2 cost a day + of re-diagnosis. Pass ``required=False`` for the handful of call sites that legitimately treat a + timeout as a value rather than a failure. + """ loop = asyncio.get_running_loop() deadline = loop.time() + timeout while loop.time() < deadline: if pred(): return True await asyncio.sleep(0.003) - return pred() + if pred(): + return True + if not required: + return False + report = await _expiry_report(pred) + raise _WaitTimeout(f"{note}\n{report}" if note else report) def _make( @@ -381,7 +507,7 @@ def _make( infra_fault_stop_after: int = 10, infra_fault_backoff_cap: float = 60.0, ) -> StageDispatcher: - return StageDispatcher( + d = StageDispatcher( Stage.INGRESS, store, process_item=stub, @@ -399,6 +525,8 @@ def _make( infra_fault_stop_after=infra_fault_stop_after, infra_fault_backoff_cap=infra_fault_backoff_cap, ) + _LIVE_DISPATCHERS.append(d) # so a `_wait_until` expiry can dump it (BACKLOG #344 proposal 6) + return d def _first_occurrence_order( @@ -795,7 +923,7 @@ def _quiescent() -> bool: d.notify_work() mc.advance(1_000_000.0) await d._run_sweep_once() - if await _wait_until(_quiescent, timeout=3.0): + if await _wait_until(_quiescent, timeout=3.0, required=False): drained = True break assert drained, "soak did not reach quiescence" @@ -968,6 +1096,72 @@ def _always_raise(lane: str, item: OutboxItem) -> str: return "RAISE" +# How many times a lane may be re-readied by the sweep stand-in below before the test fails outright. +# 1 covers the observed rate (a swallowed 1222 is a rare, independent event); a lane needing more than +# that is a contention REGRESSION, not the transient this stands in for β€” so it must still fail. +_MAX_SWEEP_STANDINS = 1 +_SWEEP_STANDINS: dict[str, int] = {} + + +async def _wait_lane( + d: StageDispatcher, lane: str, *phases: _LanePhase, timeout: float = 8.0 +) -> None: + """Wait for ``lane`` to reach any of ``phases``, standing in for the periodic sweep that the ADR + 0070 tests deliberately disable. + + A claim can come back EMPTY even though the lane's head is PENDING and due: on SQL Server + ``claim_fifo_heads`` runs under ``SET LOCK_TIMEOUT 0``, so a momentarily contended head raises + native error 1222, which the store CATCHES and reports as a normal empty result + ([`store/sqlserver.py`] ``_is_lock_timeout`` branch) β€” by design, the "never-block" yield. The + dispatcher's EMPTY branch then takes T12: ``phase=IDLE`` with **no timer armed**. In production the + periodic sweep re-readies exactly that lane; these tests set ``sweep_interval=_HUGE_SWEEP`` with an + empty ``lane_provider`` on purpose, so IDLE is TERMINAL here and the lane can never be re-claimed β€” + which is the whole of BACKLOG #344 instance 2 (proven by forcing a real 1222 mid-re-claim). + + So re-ready a stranded lane, but COUNT it and cap it at ``_MAX_SWEEP_STANDINS``: absorbing this + silently would hide a genuine contention regression, which is the failure mode the cap exists for. + + When IDLE is itself an expected outcome the stand-in is disabled β€” a test that WANTS the lane idle + must never have it re-readied underneath its assertion. + """ + loop = asyncio.get_running_loop() + deadline = loop.time() + timeout + idle_is_a_target = _LanePhase.IDLE in phases + while loop.time() < deadline: + phase = d.phase(lane) + if phase in phases: + return + # TERMINAL IDLE: no timer armed and (in this topology) no sweep to re-arm one. + if not idle_is_a_target and phase is _LanePhase.IDLE and lane not in d._timer_deadline: + used = _SWEEP_STANDINS.get(lane, 0) + if used >= _MAX_SWEEP_STANDINS: + raise _WaitTimeout( + f"{lane} stranded in terminal IDLE {used + 1} times β€” past the" + f" {_MAX_SWEEP_STANDINS} allowed sweep stand-in(s). That is a contention" + f" regression, not the transient 1222 this stands in for.\n" + + await _expiry_report() + ) + _SWEEP_STANDINS[lane] = used + 1 + # LOUD, but not fatal: surfaced in pytest's warnings summary so the real-world rate of the + # swallowed 1222 stays visible (and reviewable) instead of being silently absorbed here. + warnings.warn( + f"sweep stand-in: {lane} was stranded in terminal IDLE after an EMPTY claim" + f" (empty_claims={d.empty_claims}) β€” re-readied ({used + 1}/{_MAX_SWEEP_STANDINS})." + " See BACKLOG #344 instance 2.", + stacklevel=2, + ) + # woken=False: a sweep-class readiness, not a producer wake (books EMPTY as idle_poll). + d.mark_ready(lane, woken=False) + await asyncio.sleep(0.003) + want = "/".join(p.name for p in phases) + raise _WaitTimeout(f"{lane} never reached {want}\n" + await _expiry_report()) + + +def _sweep_standins(lane: str) -> int: + """How many times `_wait_park_or_stop` had to stand in for the disabled sweep on ``lane``.""" + return _SWEEP_STANDINS.get(lane, 0) + + async def _advance_past_park(d: StageDispatcher, mc: ManualClock, lane: str) -> None: """Advance the ManualClock just past ``lane``'s current park deadline so its park timer fires, re-claiming the (not-due) faulting head β†’ the next infra fault. Settles the async work after.""" @@ -983,7 +1177,7 @@ async def _drive_infra_faults_until_stop( """Drive an always-faulting lane to STOPPED by repeatedly firing its park timer, bounded by ``budget`` iterations (a guard against a non-terminating loop if the bound regressed).""" for _ in range(budget): - assert await _wait_until(lambda: d.phase(lane) in (_LanePhase.PARKED, _LanePhase.STOPPED)) + await _wait_lane(d, lane, _LanePhase.PARKED, _LanePhase.STOPPED) if d.phase(lane) == _LanePhase.STOPPED: return await _advance_past_park(d, mc, lane) @@ -1048,7 +1242,7 @@ async def test_adr0070_1_retry_forever_never_stops_alerts_stuck(store: Any) -> N try: d.mark_ready(lane) for _ in range(7): # well past the horizon - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.phase(lane) != _LanePhase.STOPPED # never terminal await _advance_past_park(d, mc, lane) # WAIT for the post-advance retry cycle (unpark β†’ claim β†’ re-fault β†’ re-park) to settle back to @@ -1056,7 +1250,7 @@ async def test_adr0070_1_retry_forever_never_stops_alerts_stuck(store: Any) -> N # outlasts _advance_past_park's fixed _settle() and catches the lane mid-cycle in PROCESSING # (mirrors test 9's post-loop _wait_until). The invariant under test is unchanged: still PARKED, # never STOPPED. - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) >= 7 # streak keeps accruing (drives the backoff) assert alert.stopped == [] # never STOPs assert len(alert.stuck) == 1 # throttled: emitted ONCE at the horizon crossing @@ -1081,13 +1275,13 @@ async def test_adr0070_2_transient_infra_fault_self_heals(store: Any) -> None: await d.start() try: d.mark_ready(lane) # fault 1 - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 1 await _advance_past_park(d, mc, lane) # fault 2 - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 2 await _advance_past_park(d, mc, lane) # resolves β†’ clean drain - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.IDLE) + await _wait_lane(d, lane, _LanePhase.IDLE) assert d.infra_error_streak(lane) == 0 # streak reset on the resolving pass assert alert.stopped == [] # never STOPped assert [r.message_id for r in stub.records] == [mid, mid, mid] # head retried head-first @@ -1110,15 +1304,15 @@ async def test_adr0070_3_streak_reset_scoping_sharp_edge(store: Any) -> None: await d.start() try: d.mark_ready(lane) # fault 1 - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 1 await _advance_past_park(d, mc, lane) # park-timer unpark β†’ fault 2 - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 2 # ACCRUED across the park-timer unpark (not reset) await _advance_past_park(d, mc, lane) # park-timer unpark β†’ fault 3 == threshold β†’ STOP - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.STOPPED) + await _wait_lane(d, lane, _LanePhase.STOPPED) assert d.infra_error_streak(lane) == 3 d.notify_work() # STOPPEDβ†’READY reload resume β€” the ONLY reset path for a stopped lane @@ -1144,11 +1338,11 @@ async def test_adr0070_3b_streak_resets_on_forward_progress(store: Any) -> None: await d.start() try: d.mark_ready(lane) # round 1: i==0 head fault - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 1 # zero-progress fault accrued await _advance_past_park(d, mc, lane) # round 2: head RESOLVES, row1 raises at i==1 - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 0 # forward-progress fault RESET the streak assert mids[0] in {r.message_id for r in stub.records} finally: @@ -1191,7 +1385,7 @@ def policy(lane_: str, item: OutboxItem) -> str: n_before = len(stub.records) d.notify_work() await _settle() - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.IDLE) + await _wait_lane(d, lane, _LanePhase.IDLE) resumed = [r.message_id for r in stub.records[n_before:]] assert resumed == mids # head first, then the tail β€” strict FIFO, no overtake assert d.busy_violations == 0 @@ -1240,7 +1434,7 @@ async def test_adr0070_6_spin_collapses_to_backoff(store: Any) -> None: await d.start() try: d.mark_ready(lane) # one infra fault β†’ head re-pended not-due - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) park_until = d.park_until(lane) assert park_until is not None and park_until > mc.now # future deadline @@ -1303,7 +1497,7 @@ async def test_adr0070_7_reload_resumes_idempotently(store: Any) -> None: mc.advance((rows[0]["next_attempt_at"] - mc.now) + 1.0) d.notify_work() await _settle() - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.IDLE) + await _wait_lane(d, lane, _LanePhase.IDLE) assert mid in { r.message_id for r in stub.records } # the SAME preserved head, finally delivered @@ -1382,13 +1576,13 @@ async def test_adr0070_9_content_retry_is_not_an_infra_fault(store: Any) -> None try: d.mark_ready(lane) # content retry 1 for n in range(6): # drive 6 content retries β€” twice past stop_after=3 - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 0, ( f"content retry accrued the infra streak after retry {n + 1}" ) assert d.phase(lane) != _LanePhase.STOPPED await _advance_past_park(d, mc, lane) # park-timer unpark β†’ next content retry - assert await _wait_until(lambda: d.phase(lane) == _LanePhase.PARKED) + await _wait_lane(d, lane, _LanePhase.PARKED) assert d.infra_error_streak(lane) == 0 assert d.phase(lane) != _LanePhase.STOPPED assert alert.stopped == [] # the infra STOP never fired on message-content poison @@ -1420,12 +1614,15 @@ async def test_wakeless_backlog_drains_greedily_not_sweep_gated(store: Any) -> N sweep_interval=5.0, # LARGE: sweep-gated draining would need ~nΓ—5s; greedy T13b ignores it clock=mc.time, ) + _LIVE_DISPATCHERS.append(d) # built without _make β€” register for the #344 expiry dump await d.start() # seed-all-READY (woken=False), NO explicit producer wake try: # 8s budget << the ~100s a sweep-gated (1 row / 5s) drain would take: only the greedy re-arm passes. # (RESOLVED leaves each claimed row INFLIGHT, so the stub records exactly one dispatch per row.) - assert await _wait_until(lambda: len(stub.records) >= n, timeout=8.0), ( - "wake-less backlog did not drain greedily" + await _wait_until( + lambda: len(stub.records) >= n, + timeout=8.0, + note="wake-less backlog did not drain greedily", ) assert [ r.message_id for r in stub.records if r.lane == lane @@ -1865,7 +2062,7 @@ def _quiescent() -> bool: d.notify_work() mc.advance(1_000_000.0) await d._run_sweep_once() - if await _wait_until(_quiescent, timeout=3.0): + if await _wait_until(_quiescent, timeout=3.0, required=False): drained = True break assert drained, "pause/resume soak did not reach quiescence" From e42f0ae350d5f6ff55b7ad4ae4f4110196d39024 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 10:55:22 -0500 Subject: [PATCH 2/5] fix(tests): three corrections from the adversarial review of the #344 fix Adversarial verification of the mechanism (30 agents, 23 candidates, 20 refuted) converged on the same diagnosis, but surfaced three things the first pass had wrong or incomplete. All three verified against the source before being written down. 1. empty_claims is NOT a complete discriminator on its own. `> 0` is biconditional with the T12 stranding only because the other EMPTY consumer (T11, EMPTY-with-dirty) is unreachable under this topology; and `== 0` covers at least three distinct stuck states -- CLAIMING (stalled claim), PROCESSING (hung serializer) and READY (claimer not picking it up) -- which only the PHASE separates. _verdict now reads phase alongside empty_claims and names what each combination means, including the previously unhandled "EMPTY recorded but the lane is not IDLE" case. 2. There is a SECOND, quieter route to the same spurious EMPTY on SQL Server. The batch claim's lock probe runs WITH (UPDLOCK, ROWLOCK, READPAST), so a contended head is SKIPPED, and the head-pinned contiguity step then drops the whole lane ("rn=1 missing drops the whole lane => EMPTY") -- with NO log line at all, not even the DEBUG one. Same observable, strictly harder to see. The fix already covers it (identical T12 stranding); the ledger and the verdict now name it. 3. Postgres is NOT structurally immune, and saying "too few observations" understated it. Its claim uses FOR UPDATE SKIP LOCKED (store/postgres.py) -- the same head-of-line skip. Only SQLite's 0/1,105 is structural. The ledger now says so instead of leaning on the sample size. Also fixes a real shadowing bug introduced by the first commit: the store-row loop used `for lane in ...`, rebinding the `lane` PARAMETER, so with two live dispatchers the second one's verdict would have named a stale lane. Measured while here: 12 consecutive full-file runs against a live SQL Server produced ZERO sweep stand-ins (the one failing run was a concurrently-running experiment of mine stealing DB time -- 56s vs the usual 27s), so the cap of 1 has comfortable margin. Re-verified: ruff format + check, mypy strict, the full file green on sqlite + live SQL Server + live Postgres, and both falsification arms still hold. --- docs/BACKLOG.md | 4 ++- tests/test_stage_dispatcher.py | 57 +++++++++++++++++++++++----------- 2 files changed, 42 insertions(+), 19 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 6678ac0a..97c5d02c 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8335,7 +8335,9 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme *Instance 2 (**RESOLVED 2026-08-02 β€” and it was never a bound problem**).* Presented as `tests/test_stage_dispatcher.py`'s `_wait_until` 8.0s budget expiring on the SQL Server leg with zero logic assertions failing (two occurrences in 21 days: `test_adr0070_1_stop_policy_bounds_deterministic_infra_head`, run 30733129076; `test_adr0070_9_content_retry_is_not_an_infra_fault`, run 30716979773 attempt 1 β€” ~0.4%/test over ~479 observations, zero on Postgres/119 and zero on SQLite/1,105). **The bound was never the cause and must not be raised**: the test passes in max 0.204s on green SQL Server jobs and 0.576s at worst across 241 runs, so 8.0s is 14–39Γ— the worst passing run and both failures sit ~7Γ— beyond the *entire* passing distribution β€” a gap, not a tail. Past ~31s a raise would convert a real 30-second store hang into a silent PASS. -The actual mechanism, **proven by forcing it on a live SQL Server** rather than argued: `claim_fifo_heads` runs under `SET LOCK_TIMEOUT 0`, so a momentarily contended head raises native error **1222** instantly; the store **catches 1222 and returns a normal EMPTY result** (`store/sqlserver.py`, the `_is_lock_timeout` branch β€” deliberate, the "never-block" yield, logged only at DEBUG). The dispatcher's EMPTY branch then takes **T12**: `phase=IDLE` with **no timer armed**. In production the periodic sweep re-readies exactly such a lane; the ADR 0070 tests set `sweep_interval=3600` with an empty `lane_provider` **on purpose**, so IDLE is **terminal** there and the lane can never be re-claimed β€” the poll then cannot succeed at any budget. Holding a conflicting row lock across the post-unpark re-claim reproduces it deterministically: `empty_claims` goes `(0,0,0)` β†’ `(1,0,1)`, the lane sits `IDLE` with `park_until=None` and no armed timer, the head is still `pending` and **due**, and releasing the lock does *not* recover it. The same stranding was then observed **unforced** on a local full-file run (`test_adr0070_1_retry_forever_never_stops_alerts_stuck[sqlserver]`). This is a **test-rig gap, not an engine defect** β€” production's backstop is intact; SQLite's immunity is structural (in-process, no lock-timeout translation), and Postgres's 119 observations are too few to exonerate it, so "SQL Server-only" should be read as "server-backed store". +The actual mechanism, **proven by forcing it on a live SQL Server** rather than argued: `claim_fifo_heads` runs under `SET LOCK_TIMEOUT 0`, so a momentarily contended head raises native error **1222** instantly; the store **catches 1222 and returns a normal EMPTY result** (`store/sqlserver.py`, the `_is_lock_timeout` branch β€” deliberate, the "never-block" yield, logged only at DEBUG). The dispatcher's EMPTY branch then takes **T12**: `phase=IDLE` with **no timer armed**. In production the periodic sweep re-readies exactly such a lane; the ADR 0070 tests set `sweep_interval=3600` with an empty `lane_provider` **on purpose**, so IDLE is **terminal** there and the lane can never be re-claimed β€” the poll then cannot succeed at any budget. Holding a conflicting row lock across the post-unpark re-claim reproduces it deterministically: `empty_claims` goes `(0,0,0)` β†’ `(1,0,1)`, the lane sits `IDLE` with `park_until=None` and no armed timer, the head is still `pending` and **due**, and releasing the lock does *not* recover it. The same stranding was then observed **unforced** on a local full-file run (`test_adr0070_1_retry_forever_never_stops_alerts_stuck[sqlserver]`). This is a **test-rig gap, not an engine defect** β€” production's backstop (the sweep) is intact, and arming a timer on every EMPTY instead would re-introduce the very spin ADR 0070's fix-A backoff exists to collapse. + +**"SQL Server-only" is the wrong reading, and the distribution does not say otherwise.** There is a *second*, quieter route to the same spurious EMPTY on SQL Server: the batch claim's lock probe runs `WITH (UPDLOCK, ROWLOCK, READPAST)`, so a contended head is **skipped**, and the head-pinned contiguity step then drops the whole lane ("rn=1 missing drops the whole lane => EMPTY") β€” with **no log line at all**, not even the DEBUG one. And Postgres is **not structurally immune**: its claim uses `FOR UPDATE SKIP LOCKED` ([`store/postgres.py`](../messagefoundry/store/postgres.py)), the same head-of-line skip; its 119 observations at a ~0.4% rate expect ~0.5 events, so they exonerate nothing. Only **SQLite's** 0/1,105 is structural (in-process, no lock-timeout translation and no skip-locked semantics). Read the symptom as **server-backed store**, and note that the counters cannot separate the two SQL Server routes β€” both read `(1, 0, 1)`. Fixed two ways in [`tests/test_stage_dispatcher.py`](../tests/test_stage_dispatcher.py): `_wait_until` now **raises on expiry** carrying the lane's phase, park deadline, streak, task state, the store row's status/`next_attempt_at`, the clock, and `empty_claims` β€” plus a one-line **verdict** naming which hypothesis the reading proves, so no future occurrence needs re-diagnosing from scratch; and the ADR 0070 waits now stand in for the sweep those tests disable β€” re-readying a lane found in terminal IDLE, but **counted and capped at one**, so a genuine contention regression still fails loudly instead of being absorbed. Both halves are falsification-tested: with the stand-in disabled the same injected EMPTY reproduces the original failure, now carrying the full diagnostic instead of a bare `assert False`. diff --git a/tests/test_stage_dispatcher.py b/tests/test_stage_dispatcher.py index b5c567dc..8a188e3d 100644 --- a/tests/test_stage_dispatcher.py +++ b/tests/test_stage_dispatcher.py @@ -407,29 +407,44 @@ def _lane_report(d: StageDispatcher, lane: str) -> str: ) -def _verdict(d: StageDispatcher) -> str: +def _verdict(d: StageDispatcher, lane: str | None = None) -> str: """State which #344 hypothesis this expiry is, so the next reader need not know the theory. - `empty_claims` is the discriminator (`StageDispatcher.empty_claims`, fed only by the EMPTY branch - of `_claim_and_dispatch`): under the ADR 0070 topology a clean run reads (0, 0, 0). + `empty_claims` alone is NOT a complete discriminator β€” it must be read WITH the lane phase. + `empty_claims[0] > 0` is biconditional with the T12 stranding only because the other EMPTY + consumer (T11, EMPTY-with-dirty) is unreachable under this topology, and `== 0` covers several + distinct stuck states that only the phase separates. """ - if d.empty_claims[0] > 0: + phase = d.phase(lane) if lane is not None else None + pname = getattr(phase, "name", "?") + if d.empty_claims[0] > 0 and (phase is None or phase is _LanePhase.IDLE): return ( "VERDICT: a claim came back EMPTY (empty_claims[0] > 0) and T12 dropped the lane to a" " TERMINAL IDLE β€” no timer armed, and these tests disable the sweep that would re-ready" - " it. On SQL Server the usual cause is a swallowed lock-timeout (native 1222 under" - " SET LOCK_TIMEOUT 0, reported by the store as a normal empty result). BACKLOG #344" - " instance 2." + " it. Two known routes, both SQL Server, both reported to the dispatcher as an ordinary" + " empty result: a swallowed lock-timeout (native 1222 under SET LOCK_TIMEOUT 0, logged" + " only at DEBUG) and a READPAST head skip (the batch claim drops the whole lane when its" + " rn=1 head is locked β€” no log line at all). Postgres is NOT structurally immune: its" + " claim uses FOR UPDATE SKIP LOCKED, the same head-of-line skip. BACKLOG #344 instance 2." + ) + if d.empty_claims[0] > 0: + return ( + f"VERDICT: an EMPTY claim was recorded (empty_claims[0] > 0) but the lane is {pname}," + " not IDLE β€” so this is NOT the plain #344 instance-2 stranding. Read the phase:" + " CLAIMING/PROCESSING means a later claim or serializer is still outstanding; PAUSED" + " means the pause branch consumed it." ) return ( "VERDICT: NO empty claim was recorded (empty_claims[0] == 0), so the claim never returned at" - " all β€” a stalled statement or a lost wakeup. This is NOT the #344 instance-2 stranding and" - " must not be papered over with a re-nudge; check the lane/claimer task state below." + f" all β€” a stalled statement or a lost wakeup. The lane is {pname}: CLAIMING = the claim is" + " outstanding; PROCESSING = the serializer is hung; READY = the claimer is not picking it up" + " (check slots_free and any claim-error backoff). This is NOT the #344 instance-2 stranding" + " and must NOT be papered over with a re-nudge." ) -async def _expiry_report(pred: Callable[[], bool] | None = None) -> str: - """Everything a reader needs to tell the two #344 hypotheses apart, without a second CI round-trip.""" +async def _expiry_report(pred: Callable[[], bool] | None = None, lane: str | None = None) -> str: + """Everything a reader needs to tell the #344 hypotheses apart, without a second CI round-trip.""" lines = ["_wait_until expired."] if pred is not None: try: @@ -437,22 +452,28 @@ async def _expiry_report(pred: Callable[[], bool] | None = None) -> str: except Exception as exc: # noqa: BLE001 β€” a raising predicate must not hide the report lines.append(f" predicate re-read RAISED: {exc!r}") for i, d in enumerate(_LIVE_DISPATCHERS): - lines.append(f" {_verdict(d)}") + # The verdict needs a lane: use the caller's, else the only one if this dispatcher has one. + subject = ( + lane if lane is not None else (next(iter(d._states)) if len(d._states) == 1 else None) + ) + lines.append(f" {_verdict(d, subject)}") lines.append( f" dispatcher[{i}] stage={d._stage.value}" f" empty_claims(total,wake_fanout,idle_poll)={d.empty_claims}" f" busy_violations={d.busy_violations} processing_lanes={d.processing_lanes}" f" slots_free={d._slots_free}" ) - lines.extend(_lane_report(d, lane) for lane in d._states) + # NB distinct loop names: a bare `for lane in ...` here would REBIND the `lane` parameter and + # give the next dispatcher's verdict a stale subject. + lines.extend(_lane_report(d, ln) for ln in d._states) # The store row is the other half: status + next_attempt_at say whether the head was even # claimable. Bounded and swallowed β€” a diagnostic that hangs or raises would MASK the failure # it is meant to explain. try: - for lane in list(d._states): - rows = await asyncio.wait_for(_lane_rows(d._store, lane), timeout=5.0) + for ln in list(d._states): # `ln`, not `lane` β€” see the rebinding note above + rows = await asyncio.wait_for(_lane_rows(d._store, ln), timeout=5.0) lines.append( - f" {lane} rows=" + f" {ln} rows=" + str([(r["status"], r["attempts"], r["next_attempt_at"]) for r in rows]) ) except Exception as exc: # noqa: BLE001 β€” a diagnostic must never mask the real failure @@ -1139,7 +1160,7 @@ async def _wait_lane( f"{lane} stranded in terminal IDLE {used + 1} times β€” past the" f" {_MAX_SWEEP_STANDINS} allowed sweep stand-in(s). That is a contention" f" regression, not the transient 1222 this stands in for.\n" - + await _expiry_report() + + await _expiry_report(lane=lane) ) _SWEEP_STANDINS[lane] = used + 1 # LOUD, but not fatal: surfaced in pytest's warnings summary so the real-world rate of the @@ -1154,7 +1175,7 @@ async def _wait_lane( d.mark_ready(lane, woken=False) await asyncio.sleep(0.003) want = "/".join(p.name for p in phases) - raise _WaitTimeout(f"{lane} never reached {want}\n" + await _expiry_report()) + raise _WaitTimeout(f"{lane} never reached {want}\n" + await _expiry_report(lane=lane)) def _sweep_standins(lane: str) -> int: From 66443098e9ef147e735126b6b9e648a307c300f7 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 11:10:29 -0500 Subject: [PATCH 3/5] backlog(#344): the banner is a claim about the body, so it lands with the body MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #138's session declined my merged-banner proposal, and the argument is better than mine was. A banner asserting "instance 2 resolved" while main still carries "what is NOT settled is the mechanism" is a green signal ahead of its evidence -- the exact failure this item is about, and backlog_status_check.py cannot catch it because it counts banners rather than reading them. Their banner is accurate against the document that will be on main after #138; mine is accurate against the document that is on main after THIS branch. So the banner belongs in the same landing as the RESOLVED body, and that is here. I did NOT take their offered wording. They supplied instance 3's text so I could "name all three" -- but instance 3 and proposal 5 exist only on their branch, so naming them would recreate the mirror of what they just declined: a banner describing a body that is not there if this PR lands first. So the count is gone entirely, per CLAUDE.md Β§11 / Secure_Development_Standards Β§3 -- a completeness claim is a liability, and with concurrent PRs adding and closing instances an enumeration goes stale on whichever lands first. The banner now states only what this branch delivers (instance 2 resolved, with the mechanism named) and characterises the rest without counting, so it is true in either merge order. The reason is recorded in the banner itself so the next editor does not helpfully restore a tally. Also merges origin/main (dc0da097, #148's #345/#346 work). Both directions verified by CONTENT, not by the item count: my #344 text (RESOLVED, READPAST, "FOR UPDATE SKIP LOCKED", "not structurally immune") and main's new ##345/##346 all resolve in the merged file, and the merge touched no test files. Gate green at 270. KNOWN, and deliberately left: this still conflicts with #138 on exactly this one line (git merge-tree --write-tree reports a single hunk at :8328, banner only). That is the agreed division -- when #138 lands, take this banner and keep their two corrected sentences in the RE-DIAGNOSED paragraph. --- docs/BACKLOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index f67267da..fcdd141e 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8325,7 +8325,7 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme ## 344. Fixed wall-clock bounds have drifted out of proportion to the work they bound -> 🚧 **Status OPEN (filed 2026-08-01; both named instances now closed, the generic remedy is not).** Value **6/10** Β· Difficulty **4/10** Β· _fill-in_. Hardcoded real-time budgets β€” a CI `step_timeout`, a test helper's poll deadline β€” were sized when the work was smaller or the machine faster, and nothing re-derives them. Instance 1 (the Windows `step_timeout`) was fixed on filing; **instance 2 was resolved 2026-08-02 and turned out not to be a bound problem at all** β€” a swallowed SQL Server lock-timeout stranded a lane in a terminal IDLE, and no budget would have helped. What remains open is the mechanical margin check (proposal 1) and the sweep of the remaining bounds (proposal 2). The item's real lesson is now instance 2's: **a timeout with zero failing assertions is a diagnosis to be made, not a number to be raised.** +> 🚧 **Status OPEN (filed 2026-08-01).** Value **6/10** Β· Difficulty **4/10** Β· _fill-in_. Hardcoded real-time budgets β€” a CI `step_timeout`, a CI `job_timeout`, a test helper's poll deadline β€” were sized when the work was smaller or the machine faster, and nothing re-derives them. The CI-cap instances are closed as each is re-measured; **instance 2 was resolved 2026-08-02 and turned out not to be a bound problem at all** β€” a swallowed SQL Server lock-timeout stranded a lane in a terminal IDLE, and no budget would have helped. The generic remedy β€” a mechanical margin check, and a sweep of the remaining bounds β€” is **not** built. *Deliberately no count of instances in this banner:* concurrent PRs are adding and closing them, so an enumeration is a completeness claim that goes stale on whichever lands first β€” the liability [`Secure_Development_Standards`](Secure_Development_Standards.md) Β§3 warns about. The item's real lesson is now instance 2's: **a timeout with zero failing assertions is a diagnosis to be made, not a number to be raised.** **Cluster:** Developer Experience & CI. **Priority:** P2. **Verdict:** build. **Severity:** medium. From 4d8d69cba2ff1d3d603b091dd0fadb5fac3f58d2 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 11:39:12 -0500 Subject: [PATCH 4/5] =?UTF-8?q?docs(handoff):=20stopping=20note=20for=20#3?= =?UTF-8?q?44=20instance=202=20=E2=80=94=20this=20work=20exists=20in=20exa?= =?UTF-8?q?ctly=20one=20place?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Paused on the owner's instruction via the coordinator session. Nothing is half-done; the four preceding commits are coherent and independently verified. Why this file exists: every other session's work is pushed to a remote branch. This is LOCAL ONLY -- no PR, no remote branch at all (`git rev-parse --verify origin/` fails outright). A resumer checking GitHub finds nothing and would reasonably conclude #344 instance 2 was never fixed. Records what is NOT recoverable from the diff: - The mechanism, which was expensive to prove: SET LOCK_TIMEOUT 0 -> native 1222 -> the store CATCHES it and returns a normal EMPTY (deliberate, DEBUG-logged only) -> T12 parks the lane in a TERMINAL IDLE because these tests disable the sweep on purpose. Plus the second, silent READPAST route, and why Postgres is not immune. - The deterministic reproduction recipe. The scratch harnesses were deleted and this is the part nobody should re-derive: hold a conflicting row lock across the post-unpark re-claim, watch empty_claims go (0,0,0) -> (1,0,1) with the head still pending AND due. Includes the signature to match and the [3] clause -- the lane does NOT recover when the lock is released -- which is what proves TERMINAL rather than slow. - That an ISOLATED repro loop cannot reproduce this (800/800 green): running the two tests alone is the one configuration that cannot generate contention. Force it. - Verification already done, including the falsification arm, so nobody redoes it blind. - How to rebuild the DB rigs, with the traps: the native MSSQLSERVER service owning 1434, the single shared MEFOR_STORE_* config that forbids both backends in one pytest invocation, and the silent skip that makes a green local run meaningless. - The #344 banner agreement with PR #138, which until now lived only in two sessions' heads and both are pausing -- including why the agreed order is preferable but NOT load-bearing, so a resumer neither panics about ordering nor restores an instance tally (instance 3 / proposal 5 exist only on #138's branch). - That the ledger claim on 344 is HELD ON PURPOSE and scoped to tests/ only. NOTE on what is deliberately absent: the branch name and worktree path. The leak guard blocked the first version of this file, correctly -- it matches worktree/branch slugs BY SHAPE, on the reasoning that a slug is whatever the task happened to be called and can therefore name a customer engagement, and this repo is public. Not a false positive and NOT allowlisted. Those two strings live in .git/mefor-coord/HANDOFF-344-instance-2.md, which is never published; the committed note points at it and is fully usable without it, since a reader is already on the branch. Docs-only: no code, no test, no ledger banner touched. --- HANDOFF-344-instance-2.md | 185 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 185 insertions(+) create mode 100644 HANDOFF-344-instance-2.md diff --git a/HANDOFF-344-instance-2.md b/HANDOFF-344-instance-2.md new file mode 100644 index 00000000..eec0f786 --- /dev/null +++ b/HANDOFF-344-instance-2.md @@ -0,0 +1,185 @@ +# HANDOFF β€” BACKLOG #344 instance 2 (paused 2026-08-02) + +> **This work is UNPUSHED. There is no PR and no remote branch.** A resumer checking GitHub will +> find nothing and may conclude #344 instance 2 was never fixed. It was. It lives in exactly one +> place: +> +> **HEAD `66443098`, 4 commits ahead of `origin/main`, working tree clean.** You are reading this +> from the branch itself; `git branch --show-current` names it. The branch name is deliberately +> not written here β€” the leak guard matches worktree/branch slugs by shape, because a slug is +> whatever the task was called and this repo is public. It is recorded, with the worktree path, +> in `.git/mefor-coord/HANDOFF-344-instance-2.md` (never published). +> +> `git rev-parse --verify origin/` β†’ *"Needed a single revision"*. That is not an +> error; it is the confirmation that nothing was pushed. + +Paused on the owner's instruction, relayed by the coordinator session. Nothing is half-done: the +four commits are coherent and independently verified. **Push / PR / merge were never taken β€” they +route to the owner, and pausing is not a reason to push.** + +--- + +## 1. What was wrong, and what the mechanism actually is + +`tests/test_stage_dispatcher.py`'s ADR 0070 tests failed intermittently on the **SQL Server leg +only** β€” a bare `assert await _wait_until(...)` β†’ `assert False` with *zero* logic assertions +failing. Two occurrences in 21 days, ~0.4%/test over ~479 observations. + +**It was never the 8.0s bound.** Do not raise it. The test passes in max 0.204s on green SQL Server +jobs and 0.576s at worst across 241 runs β€” the bound is 14–39Γ— the worst passing run, and both +failures sit ~7Γ— beyond the *entire* passing distribution. A gap, not a tail. Past ~31s a raise +would convert a real 30-second store hang into a silent PASS. + +The actual chain β€” **proven by forcing it on a live SQL Server, not inferred**: + +1. `claim_fifo_heads` ([`store/sqlserver.py`](messagefoundry/store/sqlserver.py)) runs under + `SET LOCK_TIMEOUT 0`, so a momentarily contended head raises **native error 1222** instantly. +2. The store **catches 1222 and returns a normal EMPTY result** (the `_is_lock_timeout` branch). + This is deliberate β€” the ADR 0114 "never-block" yield β€” and is logged **only at DEBUG**, which + is why nothing ever reported it. +3. The dispatcher's EMPTY branch takes **T12**: `phase = IDLE`, **no timer armed**. +4. In production the periodic sweep re-readies such a lane. The ADR 0070 tests set + `sweep_interval=_HUGE_SWEEP` (3600) with an **empty `lane_provider`** *on purpose*, so IDLE is + **terminal** there and the lane can never be re-claimed. The poll then cannot succeed at any + budget. + +**This is a test-rig gap, not an engine defect.** Production's backstop is intact. Do **not** "fix" +T12 by arming a timer on every EMPTY β€” that re-introduces the exact spin ADR 0070's fix-A backoff +exists to collapse. + +### The reproduction recipe (the expensive part β€” the scratch harnesses were deleted) + +Deterministic, ~4s, on a live SQL Server. Drive ADR 0070 test 1 to its first PARKED, then from a +**second pooled connection** take a conflicting lock on the head row and hold it across the +post-unpark re-claim: + +``` +cur = await blocker.cursor() +await cur.execute("UPDATE queue SET last_error = last_error WHERE stage=? AND channel_id=?", + (Stage.INGRESS.value, lane)) # NOT committed -> holds an X lock +pu = d.park_until(lane); mc.advance((pu - mc.now) + 0.5); await _settle() +``` + +Observed, and this is the signature to match: + +``` +[1] after fault 1: phase=PARKED park_until=1001.0 empty_claims=(0, 0, 0) +[2] after unpark into a LOCKED head: + phase=IDLE park_until=None armed_timers={} empty_claims=(1, 0, 1) +[3] after releasing the lock: recovered=False phase=IDLE <- TERMINAL, not merely slow +[4] after mark_ready(lane, woken=False): PARKED, streak=2 <- the fix works +``` + +Step [3] is the clause that proves *terminal* rather than *slow*; no timeout reasoning reaches it. + +**A second, quieter route exists** and produces the identical observable: the batch claim's lock +probe runs `WITH (UPDLOCK, ROWLOCK, READPAST)`, so a contended head is *skipped* and the head-pin +step drops the whole lane β€” with **no log line at all**. Both routes read `(1,0,1)`, so the counters +cannot separate them. That is a limit of the instrument, not doubt about the mechanism. + +**Postgres is NOT immune.** It uses `FOR UPDATE SKIP LOCKED` β€” the same head-of-line skip. Its 119 +observations at ~0.4% expect ~0.5 events and exonerate nothing. Only **SQLite's** 0/1,105 is +structural. Read the symptom as *server-backed store*, not "SQL Server only". + +--- + +## 2. What was changed (4 commits) + +| SHA | What | +|---|---| +| `58f8f134` | The fix + ledger: `_wait_until` raises on expiry with a full diagnostic; `_wait_lane` sweep stand-in; #344 instance 2 β†’ RESOLVED | +| `e42f0ae3` | Three corrections from adversarial review (see below) | +| `7e430e82` | Merge `origin/main` (`dc0da097`, #148's #345/#346) β€” verified by **content**, both directions | +| `66443098` | Banner rewritten to land with its body; no instance count | + +**Two halves of the fix**, both in `tests/test_stage_dispatcher.py`: + +1. **`_wait_until` now RAISES** `_WaitTimeout` on expiry (BACKLOG #344 proposal 6) carrying lane + phase, park deadline, infra streak, lane-task liveness/exception, the store row's status and + `next_attempt_at`, the clock, and `empty_claims` β€” plus a one-line **VERDICT** naming which + hypothesis the reading proves. All ~60 bare-assert call sites convert for free; two that + legitimately tolerate a timeout pass `required=False`; one that carried a message passes `note=`. +2. **`_wait_lane`** stands in for the disabled sweep: a lane found in terminal IDLE is re-readied + via `mark_ready(lane, woken=False)`, **counted, capped at `_MAX_SWEEP_STANDINS = 1`, and + `warnings.warn`-loud**. Past the cap it raises, calling it a contention regression. Disabled when + IDLE is itself the target phase. Measured: 12 consecutive full-file SQL Server runs produced + **zero** stand-ins, so the cap of 1 has margin. + +The `e42f0ae3` corrections, all verified in source before being written: `empty_claims` alone is +**not** a complete discriminator (`== 0` covers β‰₯3 stuck states that only the *phase* separates, so +the verdict reads both); the READPAST second route; and Postgres not being structurally immune. It +also fixed a shadowing bug from the first commit β€” a `for lane in ...` loop rebinding the `lane` +**parameter**, which would have named a stale lane with two live dispatchers. + +--- + +## 3. Verification already done β€” do not redo it blind + +- `ruff format --check`, `ruff check`, **`mypy --strict`** β€” all clean on the changed file. +- `scripts/docs/backlog_status_check.py` β€” **green at 270 items**. +- Full `tests/test_stage_dispatcher.py`: **76 passed / 38 skipped** on a live SQL Server 2022 + container *and* on a live Postgres 16; **38 passed** sqlite-only (the default CI leg). +- **Falsification (the load-bearing check):** with `_MAX_SWEEP_STANDINS` forced to 0, the same + injected EMPTY reproduces the original failure β€” now carrying the full diagnostic instead of a + bare `assert False`. A guard that passes against unpatched code measures nothing. + +### Rebuilding the DB rigs (mine were torn down) + +Both containers were **removed** at the end of the session; the shared `mefor-mssql` / `mefor-pg-ci` +were left alone. To re-verify: + +``` +scripts\dev\sqlserver-docker.ps1 -ContainerName mefor-mssql- -Volume mefor-mssql--data -Port +docker run -d --name mefor-pg- -e POSTGRES_PASSWORD=mefor -e POSTGRES_DB=messagefoundry -p :5432 postgres:16 +``` + +- ⚠️ **A native `MSSQLSERVER` service owns `127.0.0.1:1434` on this box.** Docker had 1433; I used + **14330** for mine. Always check the owner first, then sanity-check `SELECT @@VERSION` matches the + image you started β€” a wrong-server connect reports a misleading login failure and nothing names it. +- ⚠️ **The two backends share ONE `MEFOR_STORE_*` config.** They cannot run in the same pytest + invocation; run them as separate legs, as CI does. Clear `MEFOR_*` between legs. +- Local pytest **silently skips** both server legs without `MEFOR_TEST_SQLSERVER` / + `MEFOR_TEST_POSTGRES` β€” a green local run proves nothing about them. +- ⚠️ **An isolated repro loop will not reproduce this.** 800 iterations of the two tests alone + returned 800/800 green: running them in isolation is the one configuration that cannot generate + lock contention. It *did* appear unforced in a **full-file** run. Force it (Β§1) rather than sample. + +--- + +## 4. Open threads a resumer must not rediscover + +**(a) One known conflict with PR #138** (OPEN, auto-merge ARMED, CI-BLOCKED at pause). +`git merge-tree --write-tree HEAD ` β†’ **exactly one hunk, `docs/BACKLOG.md:~8328`, +the status banner only.** + +**Agreement reached with that session** (peer-to-peer, before the coordinator's remit; the +coordinator has also recorded it β€” it otherwise lived only in two paused sessions' heads): + +> **#138 lands first. Then merge and take *this branch's* banner, keeping #138's two corrected +> sentences in the `*Instance 2, RE-DIAGNOSED*` paragraph.** + +Rationale: a banner is a claim about the body beneath it, so it must land in the same commit as the +body it describes. #138's banner is true of main-after-#138; mine is true of main-after-this-branch. +**This branch's banner deliberately carries no instance count**, so it stays true in either order β€” +the agreed order is *preferable, not load-bearing*. Do not panic about ordering, and do **not** +restore a tally: instance 3 and proposal 5 exist only on #138's branch, so naming them here would +describe a body that is not present if this branch lands first. + +Use `git merge-tree --write-tree A B` to re-check β€” no worktree, no dirty state, no abort to recover +from. It caught this after both sessions had verified the region they were told about and both +concluded the merge was clean. + +**(b) The ledger claim is HELD and must stay held.** Number **344**, scoped to the **fix in +`tests/` only** β€” #138 holds the `ci.yml`/ledger half. Both notes say so. Do not release it: the +work is real, unlanded and unpushed, and the claim is the only thing marking that territory. + +**(c) Out of scope, already filed as a task chip:** a swallowed 1222 increments the same counter as +a genuinely idle poll, so an operator cannot distinguish contention from no-work. The yield itself +is by design (ADR 0114) and must **not** be changed β€” this is about making it countable. + +--- + +## 5. Not done + +- **Push, PR, merge** β€” the owner's call, deliberately not taken. +- The #138 banner reconcile (Β§4a), which cannot happen until #138 lands. From e5f369daaee25163947305354908c1e3403ef8b9 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 12:00:18 -0500 Subject: [PATCH 5/5] docs(handoff): a THIRD source of the 1222, and name the fix commit not the tip Two additions from the #348 / ADR 0159 session, which reached the same 1222 from the opposite end and sent it over rather than sitting on it. Still paused -- this finishes the stopping note, it does not resume work. 1. A CANCELLED store call is a third route to the same EMPTY, and it refines how the fix commit words the cause. CancelledError derives from BaseException, so the store's `except Exception: await conn.rollback()` idiom never runs its rollback on cancellation, and aioodbc's Pool.release() returns the connection to the free deque with no rollback or reset. THEIR measurement (live container): cancelling release_claimed left 7 KEY X locks on `queue`, vs 0 for a claim_fifo_heads control, after which a real claim returned EMPTY-all and a raw writer got 1222. VERIFIED HERE before recording it, rather than relayed: store/sqlserver.py has 90 rollback sites guarded by `except Exception` and ZERO using `except BaseException` or a `finally`. So the gap is real in our source, not just in principle. Why it matters: 58f8f134's message reasons from MOMENTARY contention -- a live producer holding a head lock in flight. A connection poisoned this way holds its locks as long as it sits unclaimed in the pool, so the 1222 can repeat across successive sweep ticks instead of clearing on the next. The chain into T12 and the terminal IDLE is identical; the duration and origin of the contention are not. It does NOT change this branch's conclusion -- production still recovers via the sweep, so "test-rig gap, not an engine defect" stands, and that session explicitly declined to escalate severity on it. Recorded as: if you see a 1222 you cannot attribute to a live producer, look at #348 first. 2. Name the fix commit, not the tip. HEAD was circulated between sessions as "the fix"; it is a banner edit plus this note and touches no code. THE FIX IS 58f8f134. The handoff now says so in a callout above the commit table, because the mis-relay already happened once and a tip SHA moves every time this note is amended. Cross-referenced by LEDGER NUMBER (#348 / ADR 0159), never by SHA -- that work is also unpushed and may be rebased. Docs-only. --- HANDOFF-344-instance-2.md | 32 +++++++++++++++++++++++++++++++- 1 file changed, 31 insertions(+), 1 deletion(-) diff --git a/HANDOFF-344-instance-2.md b/HANDOFF-344-instance-2.md index eec0f786..6645e709 100644 --- a/HANDOFF-344-instance-2.md +++ b/HANDOFF-344-instance-2.md @@ -81,13 +81,43 @@ cannot separate them. That is a limit of the instrument, not doubt about the mec observations at ~0.4% expect ~0.5 events and exonerate nothing. Only **SQLite's** 0/1,105 is structural. Read the symptom as *server-backed store*, not "SQL Server only". +### A THIRD source of the 1222 β€” and it refines the wording above (BACKLOG #348 / ADR 0159) + +Added 2026-08-02 from the #348 session, which reached the same 1222 from the opposite end. **Their +measurement, my verification of the mechanism in our source:** + +`CancelledError` derives from `BaseException`, so the store's `except Exception: await +conn.rollback()` idiom **never runs its rollback on a cancellation** β€” and `aioodbc`'s +`Pool.release()` returns the connection to the free deque with no rollback or reset. Verified here: +`store/sqlserver.py` has **90** rollback sites guarded by `except Exception` and **zero** using +`except BaseException` or a `finally`. They measured the consequence on a live container β€” +cancelling `release_claimed` left 7 KEY X locks on `queue` (`reschedule_claimed` 7, `mark_done` 9, +`enqueue_ingress` 11), against 0 for a `claim_fifo_heads` control β€” after which a real +`claim_fifo_heads` returned EMPTY-all and a raw writer got 1222. + +**Why this matters to the text above:** Β§1 and the commit message for the fix reason from +*momentary* contention β€” a live producer holding a head lock in flight. A connection poisoned this +way holds its locks **for as long as it sits unclaimed in the pool's free deque**, so the 1222 can +repeat across successive sweep ticks instead of clearing on the next one. The chain into T12 and the +terminal IDLE is identical; only the *duration and origin* of the contention differ. + +**It does not change this branch's conclusion** β€” production still recovers via the sweep, so +"test-rig gap, not an engine defect" stands, and that session explicitly declined to escalate its +severity on the strength of this finding. But: **if you ever see a 1222 that cannot be attributed to +a live producer, look here first.** Cross-referenced by ledger number (#348 / ADR 0159), not by SHA, +because that work is also unpushed. + --- ## 2. What was changed (4 commits) +> **If you cite one SHA, cite `58f8f134` β€” that is THE FIX.** `66443098` and the HEAD commit are a +> banner edit and this note; they touch **no code**. This was already mis-relayed once between +> sessions (HEAD was circulated as "the fix"), so name the commit, not the tip. + | SHA | What | |---|---| -| `58f8f134` | The fix + ledger: `_wait_until` raises on expiry with a full diagnostic; `_wait_lane` sweep stand-in; #344 instance 2 β†’ RESOLVED | +| `58f8f134` | **THE FIX** + ledger: `_wait_until` raises on expiry with a full diagnostic; `_wait_lane` sweep stand-in; #344 instance 2 β†’ RESOLVED | | `e42f0ae3` | Three corrections from adversarial review (see below) | | `7e430e82` | Merge `origin/main` (`dc0da097`, #148's #345/#346) β€” verified by **content**, both directions | | `66443098` | Banner rewritten to land with its body; no instance count |