diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index d794d57e..0f75c447 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -54,10 +54,11 @@ jobs: # runner label set; the per-repo matrix is built in `changes`. runs-on: ${{ matrix.hosted }} # Wall-clock backstop: bound each leg so a hung test fails in minutes, not the 6h default. Three - # nested watchdogs catch a hang at increasing scope (#55): the pytest-timeout per-test cap (60s, - # pyproject addopts) + the faulthandler belt fire FIRST and name the stuck frame; the pytest STEP - # has its own `timeout-minutes: 13` so a process-level deadlock below pytest fails the step fast; - # this job cap is the outermost belt if even that is somehow out-raced. + # nested watchdogs catch a hang at increasing scope (#55): the pytest-timeout per-test cap (matrix + # `pytest_timeout`, 60s ubuntu / 120s Windows -- the step passes `--timeout=`, which overrides the + # pyproject addopts value) + the faulthandler belt fire FIRST and name the stuck frame; the pytest STEP + # has its own `timeout-minutes` (matrix `step_timeout`) so a process-level deadlock below pytest + # fails the step fast; this job cap is the outermost belt if even that is somehow out-raced. timeout-minutes: ${{ matrix.job_timeout }} strategy: fail-fast: false @@ -200,16 +201,18 @@ jobs: if: (needs.changes.outputs.code == 'true' || github.event_name == 'push' || github.event_name == 'workflow_dispatch') && runner.os == 'Linux' run: mypy --platform win32 messagefoundry - # Step-level watchdog UNDER the 15-min job cap (#55): the windows-2022 leg intermittently + # Step-level watchdog UNDER the job cap (#55): the windows-2022 leg intermittently # wedges ~25% in (a Windows ProactorEventLoop listener-teardown / socket wait that the shared # session event loop can't get past), emits no output for ~12 min, then the JOB cap CANCELS it # โ€” a red โœ— with no stack and no named test. Two belts make that fail FAST and NAMED instead: # * `--timeout-method=thread` (the ONLY method on Windows โ€” SIGALRM is POSIX-only) dumps ALL - # thread stacks at the per-test cap (60s, set in pyproject addopts), naming the stuck frame. - # * PYTHONFAULTHANDLER=1 + `-o faulthandler_timeout=90` is the belt that fires even when the + # thread stacks at the per-test cap (matrix `pytest_timeout`, 120s on these Windows legs), + # naming the stuck frame. + # * PYTHONFAULTHANDLER=1 + `-o faulthandler_timeout=` (matrix `fault_timeout`) is the belt that fires even when the # thread-timer CANNOT interrupt a main-thread C-level wait (a Proactor overlapped op / # blocking accept / subprocess.wait): pytest's faulthandler plugin arms a separate watchdog - # thread that dumps the NATIVE stack of every thread at 90s (> the 60s pytest-timeout, so the + # thread that dumps the NATIVE stack of every thread at `fault_timeout` (150s here, 90s on + # ubuntu -- always set ABOVE that leg's `pytest_timeout`, so the # per-test dump is attributed first; this is the last-resort stack when the thread method is # itself out-raced). NB the plugin exposes this as the `faulthandler_timeout` ini key, not a # `--faulthandler-*` CLI flag, so it is passed with `-o`; it only DUMPS (never kills), safe. @@ -218,6 +221,13 @@ jobs: # the silent cap). Keep the gap: the step must expire BEFORE the job, or the failure surfaces as # an uninformative job-level kill with no step attribution. # + # THAT GUARANTEE COVERS THE FIRST GATED STEP ONLY, and saying otherwise would be a control resting + # on a false premise. `Web console tests (pytest)` carries the SAME `step_timeout` but runs after + # `Tests (pytest)`, so reaching it has already spent setup + `Tests`; its own cap cannot fire first + # at any job_timeout worth setting (it would take ~39 min on ubuntu, ~73 min on Windows). A hang + # THERE is still an unattributed job-level kill. Measured under `Tests (pytest)` below; the + # structural fix is BACKLOG #344 proposal 5. + # # It only works while the cap stays clear of a HEALTHY run. On 2026-07-31 the ubuntu leg finished # green in 775s against a 780s cap -- 5s of margin -- and the step was killed anyway, reported as # a failure on a run whose last line was "9598 passed, 855 skipped". A watchdog that cannot @@ -230,19 +240,62 @@ jobs: # code under test: #74 landed tests/test_worktree_prune_merged.py (1,506 lines) and windows-2025 # went 19:35 -> 26:07 on the same branch. The claim was already false when it was written. # - # Measured over the 11 PASSING windows-2025 runs on 2026-08-01, timing the `Tests (pytest)` STEP, - # which is what step_timeout gates. NOT the job: the job is ~3 min longer and capped separately, - # and two sessions misread job durations as step durations while triaging this (c53f752b's JOB ran - # 28:41 and PASSED, because job cap 30 vs step cap 26). + # Measured by timing the `Tests (pytest)` STEP, which is what step_timeout gates. NOT the job: the + # job runs several minutes longer and is capped separately, and at least three sessions misread job + # durations as step durations while triaging this (c53f752b's JOB ran 28:41 and PASSED, because + # job cap 30 vs step cap 26). + # + # POOL: every run of THIS workflow created on 2026-08-01 UTC -- 70 runs. Enumerated with + # `gh api --paginate` over a deliberately WIDER window and filtered locally on `created_at`, then + # cross-checked against the narrow `?created=` query (same 70 ids, symmetric difference 0). Rows + # are each leg's `Tests (pytest)` step, kept when THAT STEP concluded success. n is per leg. + # + # leg max passing step n old cap old margin + # ubuntu-latest 12:31 42 19:00 1.518x + # windows-2022 21:34 39 26:00 1.206x + # windows-2025 25:51 36 26:00 1.006x <- NINE SECONDS + # + # THESE MAXIMA ARE LOWER BOUNDS, BECAUSE THE POOL IS RIGHT-CENSORED. Every run in it predates #131 + # (28d186b5, landed 2026-08-02T00:35:28Z), so Windows ran under step 26:00 / job 30:00 and ubuntu + # under 19:00 / 22:00. A run that wanted longer than its cap was KILLED at the cap and then -- + # correctly, by the filter above -- dropped for not concluding success. So 25:51 is the largest + # step that FIT in 26:00, not the largest the suite wants. Sizing a cap as a multiple of a + # censored maximum under-provisions by construction, and that is exactly how "1.06x" read as + # survivable right up until #119's leg was killed at 26:07. (#119 itself merged, 2026-08-02T01:45Z + # -- what the cap killed was a run, not the PR. Saying a PR "died" here reads as never-landed and + # had already propagated into docs/WORKTREES.md as exactly that claim.) + # + # THE CENSORED VALUES ARE VISIBLE IF YOU ASK FOR THEM, AND THEY MATTER. The jobs endpoint defaults + # to `filter=latest`, which hides a killed attempt behind its passing re-run; `?filter=all` shows + # both. #119's 26:07 is in this very pool that way (run 30717229521 attempt 1, `8c407fb5`, step + # conclusion FAILURE) beside its 22:25 attempt-2 success -- a 3:42 spread on identical code, and + # the first day AFTER the raise produced 26:23 TWICE, both concluding SUCCESS (runs 30728793103 + # and 30731407003). So the population really does exceed the old 26:00 cap: the largest windows-2025 + # `Tests (pytest)` execution observed to date is 26:23, not 25:51. # - # leg max passing step old cap old margin - # ubuntu-latest 12:27 19:00 1.53x - # windows-2022 18:39 26:00 1.39x - # windows-2025 24:35 26:00 1.06x + # THIS TABLE HAS BEEN WRONG TWICE. #131 published 12:27 / 18:39 / 24:35 over "11 passing runs"; + # the first correction published the maxima above but over "101 runs" with n = 57 / 52 / 49. The + # maxima re-derive exactly; BOTH pool sizes were unreproducible. Three mechanisms produced that, + # all cheap to repeat: # - # windows-2025 had already PASSED at 24:35 -- 85 seconds of margin -- before #119 died. The "2x" - # figure matched no leg. State the MEASURED value and its DATE, never a round multiple: a bare - # multiple gives the next reader no way to tell when it has rotted, which is how this one survived. + # * THE POOL WAS A PAGE, NOT A QUESTION. #131's came from `gh run list --limit 20` -- a default + # page size, reported as though it had been chosen. + # * FILTERING ON *JOB* CONCLUSION DROPS THE TIGHTEST STEPS BY CONSTRUCTION. A step that nearly + # exhausts step_timeout is the most likely to push its job into job_timeout, so the job is + # cancelled while the step itself concluded success. Re-running this pool with a job-conclusion + # filter reproduces #131's 24:35 exactly; the step-conclusion filter gives 25:51. Measure the + # step; filter on the step. Two such rows exist on 2026-08-01 and one of them is the maximum. + # * A COUNT NOBODY RE-DERIVED. Neither "101 runs" nor n = 57 / 52 / 49 is reproducible under any + # pool definition tried. A table whose own point is "state your pool and your n" has to carry + # an n the next reader can recompute -- that column is how they would tell it had rotted. + # + # Only the windows-2025 row was ever a maximum; #131's ubuntu 12:27 was that same run's ubuntu leg, + # quoted as if it were that leg's worst case. Its 18:39 was not even that: that run's windows-2022 + # step is 18:29, and 18:39 belongs to a different run entirely. + # + # State the MEASURED value, its POOL, its n and its DATE -- never a bare multiple. A multiple gives + # the next reader no way to tell when it has rotted; a multiple without its pool cannot even be + # rechecked. # # PROOF IT WAS THE CAP, NOT THE BRANCH. #119's windows-2025 leg was RE-RUN on the SAME commit # against the SAME 26:00 cap: attempt 1 was killed at the cap, attempt 2 concluded SUCCESS. Same @@ -251,10 +304,79 @@ jobs: # see" is not a diagnosis here. A green re-run at 26:00 does not mean the suite fits; it means # that runner was fast enough that time. # - # 36:00 is 1.46x over that 24:35 maximum -- the margin ubuntu already runs with. Both Windows legs - # take the same number: windows-2022 is the faster of the two, so sizing on windows-2025 only - # leaves it more room, and one value is one thing to re-derive. job_timeout moves 30 -> 40 to keep - # the nesting invariant above: the step must still expire strictly BEFORE the job. + # 36:00 is 1.393x over the 25:51 that fit under the old cap, and 1.364x over 26:23, the largest + # windows-2025 execution actually observed. Use the second number: a ratio against a censored + # maximum flatters itself. + # + # BE HONEST ABOUT THE SPREAD RULE -- 36:00 DOES NOT MEET IT. An earlier revision argued "headroom + # must exceed observed spread". Against real values that rule FAILS here: headroom is 36:00 - 26:23 + # = 9:37, and the windows-2025 spread is 26:23 - 15:56 = 10:27. It would need roughly 37:00 to hold. + # 36:00 is kept anyway, and the reason is stated rather than dressed up: this cap exists to catch a + # whole-process DEADLOCK, not slowness (see the paragraph below), so 1.364x over the worst observed + # run is ample for its actual job, and #131 already set this value. What the spread rule is good + # for is telling you the margin is thinner than the ratio suggests. RE-DERIVE IF a windows-2025 + # `Tests (pytest)` step is ever seen above 28:00 -- that is the trigger, not a calendar reminder. + # + # A ratio against one run says nothing about a distribution, and #119's leg was killed by the + # distribution, not by its own duration. Both Windows legs take the same number: windows-2022 is the faster, so + # sizing on windows-2025 only leaves it more room, and one value is one thing to re-derive. + # + # THE JOB CAP IS NOT A ROUNDING-UP OF THE STEP CAP, AND IT HAS FIRED. Two steps in this job carry + # `step_timeout` -- `Tests (pytest)` and `Web console tests (pytest)` -- so the job can contain + # 2 x step_timeout of gated work that step_timeout cannot bound. Note the caps here do NOT cover + # that worst case and are not sized to (2 x 19 = 38 > 26 on ubuntu, 2 x 36 = 72 > 46 on Windows); + # they are sized against the OBSERVED sum, which is a weaker guarantee. See the closing paragraph. + # Observed for real on run 30724385719 (main @ 8f01cef8, 2026-08-01): + # + # Tests (pytest) 00:01:21 -> 00:27:12 25:51 SUCCESS (9s under the 26:00 cap) + # Web console tests (pytest) 00:27:12 -> 00:30:14 CANCELLED + # JOB 00:00:06 -> 00:30:19 30:13 CANCELLED <- job_timeout 30 fired + # + # A GREEN first step, then an unattributed job-level kill during the second -- exactly the failure + # the nesting note above exists to prevent, arriving by the path that note does not consider. It + # does NOT happen when a step is killed (that ends the job and skips what follows, so those + # durations never sum); it happens when the first step PASSES near its budget. + # + # READ THAT EXHIBIT FOR ITS MECHANISM, NOT AS A VERDICT ON THE CAP IT REPLACED: it ran under the + # retired 26/30 pair and would have passed under #131's 40:00. What condemns 40:00 is the + # arithmetic below -- which is arithmetic, not an observed kill; no job has yet hit 40:00. + # + # job_timeout is therefore sized against BOTH gated steps plus setup, rather than as step_timeout + # plus a constant. Each addend below is that addend's MEASURED MAXIMUM over the same pool, taken + # over rows where `Tests` concluded success -- NOT over rows where both steps did, which silently + # drops the very run that motivates this whole paragraph (its web-console step was cancelled) and + # is the same censoring mistake as filtering the step table by job conclusion. Two earlier + # revisions used a 0:41 setup (the MEDIAN), web-console values that were each only third-highest + # on their leg, and a 1:04 Windows setup that the exhibit above contradicts on its face: + # + # leg step_timeout + web-console(max) + setup(max) old job new job + # ubuntu 19:00 + 2:00 + 1:20 = 22:20 22:00 -> -0:20 26:00 -> +3:40 (1.16x) + # W22 36:00 + 2:33 + 1:09 = 39:42 40:00 -> +0:18 46:00 -> +6:18 (1.16x) + # W25 36:00 + 3:33 + 1:20 = 40:53 40:00 -> -0:53 46:00 -> +5:07 (1.13x) + # + # ubuntu and windows-2025 were ALREADY NEGATIVE -- ubuntu too, which an earlier revision had the + # wrong way round; windows-2022 was the one row genuinely in the black. Windows takes one value, + # sized on windows-2025 as the worse of the pair. The `+4` habit that produced 40 was Windows-only + # and was carried through two cap changes unchecked (30/26 then 40/36); ubuntu has never been +4 -- + # it went 15/13 to 22/19, so +2 then +3. Either way the number was derived from the OTHER BOUND + # rather than from the work, which is the defect, not the particular constant. + # + # WHAT THIS DOES NOT FIX. The nesting invariant at the top of this note holds for `Tests (pytest)` + # on every leg and for `Web console tests (pytest)` on NONE of them: reaching that step already + # spends setup plus `Tests`, so its own cap can never fire first. Guaranteeing it would need + # job_timeout above setup + 2 x step_timeout -- about 39:20 on ubuntu and 73:20 on Windows at the + # measured setup maxima above, i.e. far beyond anything worth setting. A hang in the web-console + # step therefore still surfaces as an unattributed job-level kill, which is the very failure the + # invariant is there to prevent. The structural fix is to stop + # the two steps sharing one budget (a 3:33 suite has no business holding 36:00) and is filed as + # BACKLOG #344; this sizing only makes the job cap cover the sum. Re-derive it if either suite's + # duration moves. + # + # AND KNOW WHAT IS NOT CAPPED AT ALL. `test` is the ONLY one of this file's ten jobs carrying any + # `timeout-minutes`; the other nine -- `changes`, `ide`, `sqlserver-store`, `postgres-store`, + # `load-test`, `load-test-sqlserver`, `windows-service-smoke`, `docker-smoke`, `ci-gate` -- run on + # GitHub's 6-HOUR default. That is recorded here so the omission is known rather than assumed + # deliberate; sizing them is out of scope for this change and belongs with BACKLOG #344. # # This cap is NOT what catches a hung test; pytest_timeout (120s) is, per test. The step cap only # catches a whole-process deadlock both in-process watchdogs miss, which is why it can sit well @@ -262,8 +384,8 @@ jobs: # twice now. # # The remaining margin is a SHARED budget across every PR that lands and nothing accounts for it: - # three PRs each adding a minute of Windows time reproduce #119's death, individually blameless. - # A mechanical guard for that is BACKLOG #341; the underlying slowness is #320. + # three PRs each adding a minute of Windows time reproduce #119's kill, individually blameless. + # A mechanical guard for that is BACKLOG #344 item 1; the underlying slowness is #320. - name: Tests (pytest) if: needs.changes.outputs.code == 'true' || github.event_name == 'push' || github.event_name == 'workflow_dispatch' timeout-minutes: ${{ matrix.step_timeout }} @@ -421,9 +543,9 @@ jobs: # $GITHUB_REPOSITORY is a built-in runner env var, read here as plain shell (NOT a workflow- # expression interpolation into the run body), so it is zizmor-safe and cannot be misparsed as # an Actions expression the way a literal double-brace token in a run: block would be. - U='{"os":"ubuntu-latest","python-version":"3.14","hosted":["ubuntu-latest"],"job_timeout":22,"step_timeout":19,"pytest_timeout":60,"fault_timeout":90}' - W22='{"os":"windows-2022","python-version":"3.14","hosted":["windows-2022"],"job_timeout":40,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}' - W25='{"os":"windows-2025","python-version":"3.14","hosted":["windows-2025"],"job_timeout":40,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}' + U='{"os":"ubuntu-latest","python-version":"3.14","hosted":["ubuntu-latest"],"job_timeout":26,"step_timeout":19,"pytest_timeout":60,"fault_timeout":90}' + W22='{"os":"windows-2022","python-version":"3.14","hosted":["windows-2022"],"job_timeout":46,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}' + W25='{"os":"windows-2025","python-version":"3.14","hosted":["windows-2025"],"job_timeout":46,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}' if [ "${GITHUB_REPOSITORY:-}" = "MEFORORG/MessageFoundry" ]; then echo "matrix={\"include\":[$U,$W22,$W25]}" >> "$GITHUB_OUTPUT" else diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 98ed3799..75279608 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8331,27 +8331,39 @@ 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 2026-08-02 โ€” PARTIAL: instances 1 and 3 fixed, instance 2 open.** 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. Three confirmed instances; each presents as an unrelated flake. **Cluster:** Developer Experience & CI. **Priority:** P2. **Verdict:** build. **Severity:** medium. **What:** a fixed wall-clock bound with no relationship to the work it bounds fails the day the work grows, and it fails as a **timeout with zero assertion failures** โ€” which reads as a broken branch when nothing is broken. -*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 1 (fixed 2026-08-01, this filing).* `ci.yml`'s Windows `step_timeout: 26`. windows-2025's max PASSING `Tests (pytest)` step was **25:51** โ€” a **1.006x** margin, nine seconds โ€” 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.393x) with the measurement, its pool and its date recorded in place of the multiple. Pool: every `ci.yml` run created 2026-08-01 UTC โ€” 70 runs, per-leg n = 42 ubuntu / 39 windows-2022 / 36 windows-2025 โ€” timing the STEP and filtering on the STEP's own conclusion. That pool is **right-censored**: it predates the raise, so every observation survived a 26:00 cap and 25:51 is a *lower bound* on what the suite wants. Confirmed the next day, once the cap no longer censored it: windows-2025 produced **26:23 twice, both passing** โ€” runs that the old cap would have killed. The API hides this by default: the jobs endpoint returns only the latest attempt, so a step killed at the cap is invisible behind its passing re-run unless you ask for `?filter=all`. *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, RE-DIAGNOSED 2026-08-02 โ€” and the original diagnosis was wrong.* It recurred on PR #138, on a different test (`test_adr0070_1_stop_policy_bounds_deterministic_infra_head[sqlserver]`, run 30733129076), and the timings refute "the bound is too small": the failing test took **8.185s**, i.e. `_wait_until` burned its full 8.000s and setup+teardown cost 0.185s โ€” the store was *fast* at the moment of failure. In the same process, against the same container, the sibling `test_adr0070_1_retry_forever_never_stops_alerts_stuck[sqlserver]` drove **seven** identical fault cycles in **0.364s**, and the `[sqlite]` variant of the failing test passed in 0.144s. One fault cycle costs ~30-45 ms against an 8000 ms bound. Over a sample of green sqlserver jobs this test passes in min 0.185s / median 0.196s / max 0.204s, so the bound is ~39x its worst passing run; a wider 21-day pass put the worst passing observation at 0.576s, still ~14x. Rate: 2 failures in ~479 observations of the two affected tests (~0.4%). Postgres saw zero in 119 observations, which **exonerates nothing** โ€” at ~0.4% that sample expects ~0.5 events, and Postgres claims via `FOR UPDATE SKIP LOCKED`, the same head-of-line skip; only SQLite's 0 in 1,105 is structural, because its global lock totally orders producers and claimers. Both failures sit ~7x beyond the entire passing distribution โ€” a gap, not a tail, which is the signature of a categorically different event rather than latency creep. + +**This instance therefore inverts the item's own generic remedy, and that is the useful part.** "Size the bound against the work" (proposal 2) would derive ~1-2s here โ€” *tighter* than the 8.0s already in place. There is no larger number to justify. Raising it would convert a 0.4% visible failure into a 0.4% invisible 30-60s pause. **What is settled is the negative: not latency, and the remedy is not a bigger number.** + +What is NOT settled is the mechanism. Two independent passes reached different answers โ€” one proposes a sanctioned EMPTY claim dropping the lane to IDLE, terminal because these tests deliberately disable the production sweep (`lane_provider=set()`, `sweep_interval=3600`) that recovers it; the other returned NOT PROVEN, and is right that the evidence cannot distinguish that from a genuine stall, because the assertion is a bare `assert await _wait_until(...)` that prints only `assert False` โ€” recording no phase, no park deadline, no streak, no task state. **The first fix is observability, not a bound** (proposal 6): a failure that cannot say why it failed will be re-diagnosed wrongly every time, which is exactly what happened here. + +*Instance 3 (fixed 2026-08-02).* The same `ci.yml`'s `job_timeout`, sized by a `+4`-over-`step_timeout` convention nobody ever summed against what it had to hold. **Two** steps in that job carry `step_timeout` โ€” `Tests (pytest)` and `Web console tests (pytest)` โ€” so the job must cover their sum plus setup, a quantity `step_timeout` cannot bound. Recomputed from measured maxima, ubuntu stood at **โˆ’0:20** and windows-2025 at **โˆ’0:53** against their own caps: both already underwater, unnoticed because the bound was derived from the other bound instead of from the work. It presents as a **green first step followed by an unattributed job-level kill** (run `30724385719`: `Tests` 25:51 SUCCESS, then the job cancelled at 30:13) โ€” a signature instance 1's proposed step-level margin check would *not* catch, because the step it measures passed. Raised to 26:00 / 46:00. **Still open underneath:** the nesting invariant `ci.yml` asserts holds for the first gated step and for the second on *no* leg, since reaching it already spends setup plus `Tests`; satisfying it would need `job_timeout` past 39:24 (ubuntu) / 73:21 (Windows). The fix is proposal 5. + +*A note on this item's own measurements.* Instance 1's figures have now been published wrong twice โ€” first as 24:35 over "11 passing runs" (a `gh run list` default page, filtered on the **job's** conclusion while timing the **step**, which deletes the tightest rows by construction), then as the right maxima over "101 runs" with an `n` that no pool definition reproduces. The maxima survived both passes; the *pools* did not. An item about bounds stated independently of the work is an uncomfortable place to state a sample size independently of the sample, so: the pool is named in instance 1 and is recomputable from the API in one query. + **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. **Proposed:** -1. **A mechanical margin check** (suggested by the ASVS-scorecard session, whose framing this is): compare each leg's actual `Tests (pytest)` step duration against its configured `step_timeout` and fail below ~1.3x. Computable from data CI already emits. It would have flagged windows-2025 *before* #119 died โ€” it was already at 1.06x and nothing said a word โ€” and unlike the "re-check the margin when the suite grows" instruction in `ci.yml`, it does not depend on anyone remembering. Two traps for whoever builds it: time the **STEP**, not the job (the job is ~3 min longer with its own cap โ€” `c53f752b`'s job ran 28:41 and passed against job cap 30 / step cap 26, and two sessions misread job for step while triaging this); and size against the **max passing** run, not the mean (windows-2025's mean ~21 min looks comfortable, its max passing 24:35 is what bites). +1. **A mechanical margin check** (suggested by the ASVS-scorecard session, whose framing this is): compare each leg's actual `Tests (pytest)` step duration against its configured `step_timeout` and fail below ~1.3x. Computable from data CI already emits. It would have flagged windows-2025 *before* #119 died โ€” it was already at 1.006x and nothing said a word โ€” and unlike the "re-check the margin when the suite grows" instruction in `ci.yml`, it does not depend on anyone remembering. **The case for a computed gate over an instruction is now evidential, not a matter of diligence.** Across the 2026-08-01/02 CI-triage cluster, *seven* published claims were retracted โ€” margin figures, pool sizes, "#119 died", "26:07 does not exist", a runner count read off an endpoint that cannot see org runners. Not one was caught by re-reading. Every one was caught by a mechanism that could return "no": an adversarial re-derivation, an independent query, or an assertion. The single error its own author caught was found by running exact arithmetic over all fifteen ratios in a block, not by looking at them again. **Re-reading confirms what you meant; only a check can test what you wrote** โ€” and as a method it is 0-for-7 here. Three traps for whoever builds it: time the **STEP**, not the job (the job is ~3 min longer with its own cap โ€” `c53f752b`'s job ran 28:41 and passed against job cap 30 / step cap 26, and two sessions misread job for step while triaging this); and size against the **max passing** run, not the mean (windows-2025's mean ~21 min looks comfortable, its max passing 25:51 is what bites); and treat that max as a **lower bound**, because the pool is censored by whatever cap was in force when it was collected โ€” the runs that would have exceeded it were killed, so they are missing from exactly the tail you are trying to measure. 2. Size the remaining bounds: `grep` hardcoded `timeout=` / deadline floats under `tests/` and judge each against the work it bounds. -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. +3. ~~Where a virtual clock drives the system under test, the poll deadline should follow that clock, not `loop.time()`.~~ **WITHDRAWN 2026-08-02 โ€” this proposal was wrong and would have made things worse.** `_wait_until` waits on real asynchronous I/O (store round-trips), never on virtual time, and `ManualClock.now` advances *only* inside `advance()`, which nothing calls from within the poll loop. A `mc.now + timeout` deadline is therefore never reached: the poll spins forever, converting a bounded `assert False` into an **unbounded hang** stopped only by `pytest_timeout` or the job cap โ€” i.e. it manufactures the exact signature instances 1 and 3 are about. Verified by reading `ManualClock` (`tests/test_stage_dispatcher.py`:182-204). The lesson generalises: *a virtual clock can only bound work the virtual clock drives.* +4. Prefer bounds expressed as a measured ratio with a date **and its pool** over round multiples, per instance 1's post-mortem. A ratio whose pool is not stated cannot be rechecked, and a pool stated but never recomputed is how instance 1 was published wrong twice. +5. **Stop two steps sharing one `timeout-minutes` budget.** Give `Web console tests (pytest)` its own cap sized to its own work (max observed 3:33) so `job_timeout` no longer has to absorb a budget that belongs to a step. Until then the nesting invariant `ci.yml` asserts is unenforceable for the second gated step on every leg โ€” instance 3 is the worked example. +6. **Make a bound's expiry diagnostic before tuning it โ€” and for instance 2 the instrument already ships.** A bare `assert await _wait_until(...)` reports `assert False` and nothing else, so every occurrence is re-diagnosed from scratch; instance 2 was read as latency for a day on exactly that basis. Have the helper raise on timeout carrying the lane's phase, park deadline and streak, whether its task is alive or holds an exception, the store row's status, and the clock. **One assertion settles instance 2's open mechanism:** `StageDispatcher.empty_claims` ([`stage_dispatcher.py`](../messagefoundry/pipeline/stage_dispatcher.py):1230) returns `(total, wake_fanout, idle_poll)` and is fed by `_record_empty`, called from exactly one site โ€” the EMPTY branch of `_claim_and_dispatch` (:686). Under these tests' topology a clean run must read `(0, 0, 0)`, so `empty_claims[0] > 0` at the moment of failure is proof of a spurious EMPTY, and `== 0` is proof the claim never returned at all. A second, free signature is in the captured log, **for the infra-fault test only**: a healthy `test_adr0070_1_*` emits **four** `re-pending head with backoff` records (at `1001.000 / 1003.500 / 1008.000 / 1016.500`) and the failing run emitted **one**. It does NOT generalise โ€” `test_adr0070_9_*` takes the content path, which uses `mark_failed` and never emits that line, so **zero** there is expected and is not a second mechanism. Read the counter, not the log, when in doubt. This proposal cannot itself be wrong about the cause, which is why it comes before the others. **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). -**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. +**Source:** stuck-CI triage, 2026-08-01. Instance 1 re-measured 2026-08-02 across 36 step-success windows-2025 rows (pool: 70 `ci.yml` runs created 2026-08-01 UTC), by two agents deriving it independently after the first two measurements both reported pools that did not reproduce; instance 2 reported and diagnosed by the HA-construct-recheck session from PR #129's sqlserver leg; instance 3 from the same 2026-08-02 re-measurement. --- ## 339. Sandbox IPC codec: parent executed child-chosen code (ADR 0087 MFW2)