From a8229b5698713389ad6d92c96987634d779e074f Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 21:09:48 -0500 Subject: [PATCH 01/12] ci: the margin table in #131 was wrong in every row, and the job cap had already fired #131 replaced a "~2x headroom" claim with a measured table. The table was itself wrong -- every row, each in the safe-looking direction -- and the job cap it left in place was already negative. MEASURED over all 101 CI runs created 2026-08-01 (`gh api --paginate`), timing each leg's `Tests (pytest)` STEP and filtering on the STEP's own conclusion: leg claimed true (n) old cap true margin ubuntu-latest 12:27 12:31 (n=57) 19:00 1.518x windows-2022 18:39 21:34 (n=52) 26:00 1.206x windows-2025 24:35 25:51 (n=49) 26:00 1.006x Nine seconds, not 85. Two mechanical causes, both cheap to repeat: * THE POOL WAS A PAGE, NOT A QUESTION. It came from `gh run list --limit 20` -- a default-sized listing reported as though the sample had been chosen. 20 of 101. * FILTERING ON *JOB* CONCLUSION DROPS THE TIGHTEST STEPS BY CONSTRUCTION. A step near step_timeout is the one most likely to push its job into job_timeout, so the job is cancelled while the step concluded success. Five such rows exist that day and they include the maximum. Only the windows-2025 row was ever a maximum; ubuntu's and windows-2022's figures were that same run's other two legs. AND THE TWO-GATED-STEPS HAZARD IS NOT LATENT -- IT FIRED. Both `Tests (pytest)` and `Web console tests (pytest)` carry `step_timeout`, so a job can hold 2x step_timeout of gated work that step_timeout cannot bound. Run 30724385719 (main @ 8f01cef8): Tests (pytest) 25:51 SUCCESS (9s under the 26:00 cap) Web console tests (pytest) CANCELLED JOB 30:13 CANCELLED <- job_timeout 30 fired A green first step, then an unattributed job-level kill during the second -- precisely what ci.yml:218's nesting note exists to prevent, by the path it does not consider. It cannot happen when a step is KILLED (that ends the job and skips what follows), only when the first step PASSES near its budget. Sizing job_timeout to hold both gated steps plus setup, rather than step_timeout plus a constant: leg step + web(max) + overhead old job new job ubuntu 19:00 + 1:58 + 0:41 = 21:39 22:00 +21s 26:00 +4:21 (1.20x) W22/W25 36:00 + 3:27 + 0:41 = 40:08 40:00 -8s 46:00 +5:52 (1.15x) All three legs sat inside a minute of their job cap and Windows was already negative: the +4 convention was carried through two cap changes without anyone summing what it had to cover. The 36:00 step decision is unchanged and remains correct -- 1.393x over the true 25:51 maximum, still comfortably above the 5:26 observed spread. Only its justification moves. Found by the ADR 0158 verification pass (eight agents re-deriving every claimed number against the API; 50 claims checked, 6 refuted), reported by the intersession-communication-hooks session, and re-derived here before acting. BACKLOG #344 still restates the superseded figures; that edit is blocked on three live sessions holding docs/BACKLOG.md and follows separately. --- .github/workflows/ci.yml | 85 +++++++++++++++++++++++++++++++--------- 1 file changed, 67 insertions(+), 18 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index d794d57e..b4bd3561 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -230,19 +230,37 @@ 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 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). # - # 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 + # POOL: every CI run created on 2026-08-01 (101 runs, enumerated with `gh api --paginate`), each + # leg's `Tests (pytest)` step, keeping rows whose STEP concluded success. n is per leg. # - # 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. + # leg max passing step n old cap old margin + # ubuntu-latest 12:31 57 19:00 1.518x + # windows-2022 21:34 52 26:00 1.206x + # windows-2025 25:51 49 26:00 1.006x <- NINE SECONDS + # + # An earlier revision of this table said 12:27 / 18:39 / 24:35 over "11 passing runs". Every figure + # was wrong and each in the safe-looking direction. Two errors produced it, both worth naming + # because they are cheap to repeat: + # + # * THE POOL WAS A PAGE, NOT A QUESTION. It came from `gh run list --limit 20` -- a default-sized + # listing, not the set of runs that day. 20 of 101. The sample size was set by a tool default + # and then 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. Five such rows exist on 2026-08-01, and + # they include the maximum. Measure the step; filter on the step. + # + # Only the windows-2025 row was ever a maximum; ubuntu's 12:27 and windows-2022's 18:39 were that + # same run's other two legs, quoted as if each were its leg's worst case. + # + # 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 +269,41 @@ 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 maximum -- comfortably above the 5:26 spread the same pool shows + # (20:41 .. 26:07 on windows-2025, identical code), which is the criterion that matters: HEADROOM + # MUST EXCEED OBSERVED SPREAD, not some multiple of a single point. A ratio against one run says + # nothing about a distribution, and #119 died from the distribution, not from 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, which job_timeout must cover and step_timeout cannot bound. + # 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. + # + # job_timeout is therefore sized to hold BOTH gated steps plus setup -- not step_timeout plus a + # constant, which is what the previous +4 relationship was. Web-console is stable (max 3:27 on + # windows-2025, 1:58 on ubuntu) while `Tests` swings 19:50-25:51, so the sum is dominated by a + # budget the step cap already bounds and an addend the job cap must absorb on its own: + # + # leg step + web-console(max) + overhead old job new job + # ubuntu 19:00 + 1:58 + 0:41 = 21:39 22:00 -> +21s 26:00 -> +4:21 (1.20x) + # W22/W25 36:00 + 3:27 + 0:41 = 40:08 40:00 -> -8s 46:00 -> +5:52 (1.15x) + # + # ALL THREE legs were inside a minute of their job cap and windows was already NEGATIVE -- the + # +4 convention had been carried through two cap changes without anyone summing what it had to + # cover. The structural fix is to stop the two steps sharing a budget (a 3:27 suite has no + # business holding 36:00) and is filed as BACKLOG #344; this sizing makes the invariant hold + # until someone does it. Re-derive it if either suite's duration moves. # # 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 @@ -421,9 +470,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 From a7a83bd4b73c36ec78980e6527f480359e95920a Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 22:54:04 -0500 Subject: [PATCH 02/12] docs: handoff for ci-margin-correction Written at the owner's stop-work instruction (usage cap). Chat does not survive; a claim that lives only in a transcript reaches nobody. Carries: #138's state and its SQL Server blocker (NOT called a flake -- unproven), the corrected margin table, four retractions of my own findings with their corrected forms, and seven traps stated as fact-plus-measurement. The load-bearing line: the cap raise in #131 is correct and unchanged; its justification was wrong in every row, and #138 fixes it. --- HANDOFF-ci-margin-correction.md | 173 ++++++++++++++++++++++++++++++++ 1 file changed, 173 insertions(+) create mode 100644 HANDOFF-ci-margin-correction.md diff --git a/HANDOFF-ci-margin-correction.md b/HANDOFF-ci-margin-correction.md new file mode 100644 index 00000000..aa8319fd --- /dev/null +++ b/HANDOFF-ci-margin-correction.md @@ -0,0 +1,173 @@ +# HANDOFF — ci-margin-correction + +Written 2026-08-02 ~04:00Z, winding down at the owner's stop-work instruction (relayed via another +session; usage cap). Claim key: `ci-margin-correction`. + +**If you read one line:** the cap raise in #131 was correct and is unchanged. Its *justification* was +wrong in every row, and #138 fixes it. Don't re-litigate the decision; don't trust the old numbers. + +--- + +## 1. STATE + +| | | +|---|---| +| Branch | `claude/ci-margin-correction` @ `8e71fcdf`, pushed, **0 behind main** | +| PR | **#138**, OPEN, auto-merge **ARMED** (squash) | +| CI | **2 failures** — see BLOCKED ON | +| Uncommitted | none (this file is the only addition) | + +The worktree carrying this branch has a *different* recorded HOME branch, so a session-start hook will +warn about a possible worktree-hijack. That is expected: the branch was created here deliberately +because the previous one had been squash-merged and could not fast-forward. + +--- + +## 2. DONE (landed on main) + +| SHA | What | +|---|---| +| `f7e12695` | #74 — prune-merged worktree destruction fix (was stalled since 2026-07-30) | +| `28d186b5` | #131 — Windows step cap 26→36, job 30→40; stall detector; BACKLOG #340 + #344 | +| `002be182` | #119 — ADR 0154 increment B (I updated its branch when its owner went idle mid-task) | + +**Shipped in #131 and still current:** +- `scripts/ci/check_stalled_prs.py` + `.github/workflows/stalled-prs.yml` — daily, **advisory by + placement, must never become required** (it reports on *other* PRs; a stall on one would block + another). +- Signature: `state=OPEN AND mergeStateStatus=BEHIND AND failing=0 AND pending=0`. Matches `BEHIND` + **only** — `BLOCKED` is excluded deliberately, because `BLOCKED` self-resolves and `BEHIND` cannot + clear without external action. Verified against all four states. + +--- + +## 3. IN FLIGHT — PR #138 + +Corrects #131's own justification. **The 36:00 step decision is unchanged and remains correct.** + +Measured over **all 101 CI runs created 2026-08-01** (`gh api --paginate`), timing each leg's +`Tests (pytest)` **step**, filtering on the **step's own** conclusion: + +``` +leg #131 claimed TRUE n old cap true margin +ubuntu-latest 12:27 12:31 57 19:00 1.518x +windows-2022 18:39 21:34 52 26:00 1.206x +windows-2025 24:35 25:51 49 26:00 1.006x <- NINE SECONDS +``` + +Also raises `job_timeout` on all three legs, because the job cap was the binding constraint and +**nobody was watching it**: + +``` +leg step + web-console(max) + overhead old job new job +ubuntu 19:00 + 1:58 + 0:41 = 21:39 22:00 +21s 26:00 +4:21 (1.20x) +W22/W25 36:00 + 3:27 + 0:41 = 40:08 40:00 -8s 46:00 +5:52 (1.15x) +``` + +--- + +## 4. BLOCKED ON + +**#138 CI: `sql server (store + connector) 2022` FAILED, which fails `CI gate`.** + +``` +tests/test_sqlserver_store.py::test_cipher_invocations_upsert_is_atomic_and_additive +pyodbc.OperationalError: ('HYT00', ... 'Query timeout expired (0) (SQLExecDirectW)') +1 failed, 148 passed in 60.19s +``` + +**Do not call this a flake without proving it.** This repo's two famous "flakes" were a livelock and a +test that was right. What is known: #138's diff is `.github/workflows/ci.yml` only — the matrix values +for the ubuntu/W22/W25 `test` legs and the comment above `Tests (pytest)`. The sqlserver leg is a +separate job whose timeouts I did not touch. So a causal path from this diff to that failure is not +obvious, but **it has not been ruled out**. Next step: re-run the single job and check whether it +reproduces, and compare against the same test on `main`. + +Note the failure is itself a fixed wall-clock bound expiring (a *query* timeout) — i.e. plausibly +another BACKLOG #344 instance, in a third place. + +**Who clears it:** whoever picks this up. #138 is armed, so it lands by itself once the leg is green. + +--- + +## 5. RETRACTIONS — things I asserted that were wrong + +Four of mine. All were caught by a peer measuring, **none by me re-reading**. + +1. **"The collision gate never self-clears after a squash merge."** FALSE. `overlap.ps1` intersects + three-dot with two-dot; `git diff A..B` compares trees, so once content is in main the two-dot set + empties and the intersection clears. `collision_gate.ps1:70` *delegates* to `overlap.ps1`, so it + inherits this by construction. I read a three-dot diff and stopped. +2. **"#131's own run proves the raised cap applied."** It did apply — but the run does not show it. + Its step ran 24:22, under both 26:00 and 36:00. Durations cannot discriminate. **The matrix the run + echoes into its own log can** (`"job_timeout":40,"step_timeout":36`), and it was there the whole + time. Read the configuration; don't infer it from behaviour consistent with several configurations. +3. **"#119 died in a race between the step cap and the job cap"** (`26:07 + 3:18 + 0:41 = 30:06`). + FALSE — arithmetic over an impossible state. A step kill ends the job and skips what follows; + the killed run shows `Web console tests: completed/SKIPPED` and a 27:15 job against a 30:00 cap. + #119 was killed by the step cap alone and its attribution was correct. +4. **"The primary checkout is serving a stale collision gate."** FALSE — I hashed a **CRLF working + file against an LF blob**. Normalised, they are identical. I was one command from `git pull`-ing a + shared checkout used by every session, on the strength of this. + +--- + +## 6. TRAPS — each is a fact plus its measurement + +**T1. `step_timeout` gates TWO steps, and the job must cover their sum.** +`ci.yml` applies `timeout-minutes: ${{ matrix.step_timeout }}` to both `Tests (pytest)` and +`Web console tests (pytest)`. So a job can hold 2 × `step_timeout` of gated work that `step_timeout` +cannot bound. **This is not theoretical** — run `30724385719` (main @ `8f01cef8`): +``` +Tests (pytest) 25:51 SUCCESS <- 9s under the 26:00 cap +Web console tests (pytest) CANCELLED +JOB 30:13 CANCELLED <- job_timeout 30 fired +``` +A **green** first step, then an unattributed job kill during the second. It cannot happen when a step +is *killed*; only when the first step **passes** near its budget. The real fix is to stop the two +steps sharing a budget — a 3:27 suite has no business holding 36:00 (BACKLOG #344). + +**T2. Filtering a pool by JOB conclusion while measuring STEP durations removes the tightest cases by +construction.** A step near `step_timeout` is exactly the one that pushes its job into `job_timeout`, +so the job is cancelled while the step concluded success. **Five such rows existed on 2026-08-01 and +they include the maximum.** This is what produced #131's wrong table. Measure the step; filter on the +step. + +**T3. A default `gh run list` page is 20 rows.** #131's "11 passing runs" was a tool-truncated sample +reported as though it had been chosen — 20 of 101. Enumerate with `gh api --paginate`. + +**T4. Job durations are NOT step durations.** The job runs several minutes longer (setup **plus the +second pytest step**) and is capped separately. `c53f752b`'s JOB ran 28:41 and PASSED against job cap +30 / step cap 26. **Four sessions made this error tonight**, one of them immediately after writing the +correction about it. Rule: quote step figures from the step's own `started_at`/`completed_at` — never +by subtracting setup from a job total, never from elapsed wall-clock mid-run. + +**T5. To compare a working file against a git object, hash it WITH git.** +`git hash-object ` and `git rev-parse :` agree; `sha256sum` does not, because +`core.autocrlf` means the working file is CRLF and the blob is LF. Retraction 4 above. + +**T6. Sizing a cap by ratio-against-one-run is the wrong criterion.** windows-2025's step spread on +identical code is **5:26** (20:41 … 26:07 across seven observations). The rule that matters is +**headroom > observed spread**, not a multiple of a point estimate. Against 26:00 the headroom over +the true max was *negative*; #119's death was arithmetic, not luck. + +**T7. `check_stalled_prs.py` uses `gh pr list --limit 100`.** Past 100 open PRs the remainder is +invisible and the receipt prints `scanned 100` — true, and reading as complete. Not biting at ~15 open +PRs; unguarded regardless. My own instance of *a rule quantified over what is present cannot notice +what is missing*. + +--- + +## 7. Adjacent, not mine + +- **BACKLOG #340** (merge queue) — the ADR-0154 session is adding measured evidence after #137 lands: + #132 took **four full CI cycles to land, none from a failure** (~80 min runner time for a change + correct on the first pass). Their caveat belongs with it: tonight's queue *did* resolve without a + queue, via hand coordination, so a queue is a **convenience, not a correctness fix**. +- **BACKLOG #344** still restates #138's superseded figures (`24:35`, `1.06x`, `11 runs`, `1.45x`). + **That edit is not done** — it was blocked on live sessions holding `docs/BACKLOG.md`. Do it. +- **ADR 0158** ("Silent controls") is the announce session's, drafted not committed. ADR **0157** is + the HA session's *demotion safety* — I mis-routed taxonomy material to 0157 for hours; it is 0158. +- **The collision-gate fix (#133) needs the PRIMARY checkout advanced before it is in force.** + Check with `grep -c MatchedDirty /scripts/hooks/collision_gate.ps1` — non-zero means live. + Merged ≠ deployed, and nothing reports the gap. From a6aabff218c213e47d1af30b6df8c8703e221877 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 23:27:11 -0500 Subject: [PATCH 03/12] ci: re-measure the margin table a third time, and size the job cap from maxima The correction in this PR fixed #131's maxima but repeated #131's own failure mode in a new place: it reported a pool and an n that its stated pool cannot produce. Two independent re-derivations agree the day holds 70 ci.yml runs, not 101, and per-leg n = 42 / 39 / 36, not 57 / 52 / 49. The three MAXIMA (12:31 / 21:34 / 25:51) re-derive to the second and are unchanged, so the 36:00 step / 46:00 job decision stands on the same numbers it always did. What actually changed: * POOL AND n. 70 runs created 2026-08-01 UTC, cross-checked four ways; n = 42 / 39 / 36. A table whose own point is "state your pool and your n" has to carry an n the next reader can recompute. * THE POOL IS RIGHT-CENSORED, and nothing said so. Every run in it predates #131 (28d186b5, 2026-08-02T00:35:28Z), so each observation survived a 26:00 cap. 25:51 is the largest step that FIT, not the largest the suite wants, and a multiple of a censored maximum under-provisions by construction. This is why 1.06x read as survivable right up to the moment #119 died. * THE JOB-CAP ADDENDS WERE TYPICAL VALUES, NOT MAXIMA. 0:41 is the median setup; the web-console figures 1:58 / 3:27 are each only third-highest on their leg. Measured maxima are 2:00 / 2:33 / 3:33 (web) and 1:20 / 1:09 / 1:04 (setup). Re-summed, ubuntu was -0:20 and Windows -0:37 against the old caps: BOTH were already negative, not just Windows. * THE NESTING INVARIANT IS NOT RESTORED, and now says so. It holds for `Tests (pytest)` on every leg and for `Web console tests (pytest)` on none: reaching that step already spends setup plus `Tests`, so its own cap can never fire first. A hang there still surfaces as an unattributed job kill. Stating otherwise would rest a compensating control on a false premise. * The "5:26 spread ... identical code" claim is withdrawn; neither endpoint re-derives. The true in-pool spread is 9:55, which is wider and supports the decision more strongly than the figure it replaces. Also corrects three pre-existing claims in this file that match no configuration -- the same defect class this note is about: - the pytest step's cap described as `timeout-minutes: 13` (it is matrix.step_timeout, 19 or 36) - "the 15-min job cap" (it is matrix.job_timeout, 26 or 46) - the mechanical margin guard cited as BACKLOG #341, which does not exist on main; it is #344 item 1 Drops HANDOFF-ci-margin-correction.md: session ephemera, and no HANDOFF file has ever been tracked at the repo root on main. --- .github/workflows/ci.yml | 97 +++++++++++------- HANDOFF-ci-margin-correction.md | 173 -------------------------------- 2 files changed, 62 insertions(+), 208 deletions(-) delete mode 100644 HANDOFF-ci-margin-correction.md diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b4bd3561..4065af35 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -56,8 +56,8 @@ jobs: # 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. + # 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,7 +200,7 @@ 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: @@ -231,32 +231,47 @@ jobs: # went 19:35 -> 26:07 on the same branch. The claim was already false when it was written. # # 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 three sessions misread job + # 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 CI run created on 2026-08-01 (101 runs, enumerated with `gh api --paginate`), each - # leg's `Tests (pytest)` step, keeping rows whose STEP concluded success. n is per leg. + # 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 57 19:00 1.518x - # windows-2022 21:34 52 26:00 1.206x - # windows-2025 25:51 49 26:00 1.006x <- NINE SECONDS + # 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 # - # An earlier revision of this table said 12:27 / 18:39 / 24:35 over "11 passing runs". Every figure - # was wrong and each in the safe-looking direction. Two errors produced it, both worth naming - # because they are cheap to repeat: + # 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 died at 26:07. # - # * THE POOL WAS A PAGE, NOT A QUESTION. It came from `gh run list --limit 20` -- a default-sized - # listing, not the set of runs that day. 20 of 101. The sample size was set by a tool default - # and then reported as though it had been chosen. + # 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: + # + # * 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. Five such rows exist on 2026-08-01, and - # they include the maximum. Measure the step; filter on the step. + # 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; ubuntu's 12:27 and windows-2022's 18:39 were that - # same run's other two legs, quoted as if each were its leg's worst case. + # 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 @@ -269,10 +284,12 @@ 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.393x over the 25:51 maximum -- comfortably above the 5:26 spread the same pool shows - # (20:41 .. 26:07 on windows-2025, identical code), which is the criterion that matters: HEADROOM - # MUST EXCEED OBSERVED SPREAD, not some multiple of a single point. A ratio against one run says - # nothing about a distribution, and #119 died from the distribution, not from its own duration. + # 36:00 is 1.393x over the 25:51 maximum and -- the criterion that actually matters -- it clears + # the 9:55 spread the pool shows on that leg (15:56 .. 25:51): HEADROOM MUST EXCEED OBSERVED + # SPREAD, not some multiple of a single point. A ratio against one run says nothing about a + # distribution, and #119 died from the distribution, not from its own duration. An earlier revision + # quoted a narrower "5:26 spread ... identical code" (20:41 .. 26:07); neither endpoint could be + # re-derived from this pool, and the honest wider number is the one that supports the decision. # 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. # @@ -291,19 +308,29 @@ jobs: # durations never sum); it happens when the first step PASSES near its budget. # # job_timeout is therefore sized to hold BOTH gated steps plus setup -- not step_timeout plus a - # constant, which is what the previous +4 relationship was. Web-console is stable (max 3:27 on - # windows-2025, 1:58 on ubuntu) while `Tests` swings 19:50-25:51, so the sum is dominated by a - # budget the step cap already bounds and an addend the job cap must absorb on its own: + # constant, which is what the previous +4 relationship was. Each addend below is that addend's + # MEASURED MAXIMUM over the same pool. An earlier revision used 0:41 for setup, which is the + # MEDIAN and not the maximum, and web-console figures (1:58 / 3:27) that are each only the + # third-highest on their leg -- an addend sized at a typical value cannot bound a worst case: + # + # 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/W25 36:00 + 3:33 + 1:04 = 40:37 40:00 -> -0:37 46:00 -> +5:23 (1.13x) # - # leg step + web-console(max) + overhead old job new job - # ubuntu 19:00 + 1:58 + 0:41 = 21:39 22:00 -> +21s 26:00 -> +4:21 (1.20x) - # W22/W25 36:00 + 3:27 + 0:41 = 40:08 40:00 -> -8s 46:00 -> +5:52 (1.15x) + # BOTH rows were already NEGATIVE -- ubuntu as well as Windows, which the previous revision had + # the wrong way round -- because the +4 convention was carried through two cap changes without + # anyone summing what it had to cover. Windows is sized on windows-2025, the worse of the pair; + # windows-2022 alone comes to 39:42, which was the one row genuinely in the black at +0:18. # - # ALL THREE legs were inside a minute of their job cap and windows was already NEGATIVE -- the - # +4 convention had been carried through two cap changes without anyone summing what it had to - # cover. The structural fix is to stop the two steps sharing a budget (a 3:27 suite has no - # business holding 36:00) and is filed as BACKLOG #344; this sizing makes the invariant hold - # until someone does it. Re-derive it if either suite's duration moves. + # 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 -- satisfying it would need + # job_timeout past 39:24 on ubuntu and 73:21 on Windows, using the pool's most FAVOURABLE observed + # values. 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. # # 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 @@ -312,7 +339,7 @@ jobs: # # 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. + # 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 }} diff --git a/HANDOFF-ci-margin-correction.md b/HANDOFF-ci-margin-correction.md deleted file mode 100644 index aa8319fd..00000000 --- a/HANDOFF-ci-margin-correction.md +++ /dev/null @@ -1,173 +0,0 @@ -# HANDOFF — ci-margin-correction - -Written 2026-08-02 ~04:00Z, winding down at the owner's stop-work instruction (relayed via another -session; usage cap). Claim key: `ci-margin-correction`. - -**If you read one line:** the cap raise in #131 was correct and is unchanged. Its *justification* was -wrong in every row, and #138 fixes it. Don't re-litigate the decision; don't trust the old numbers. - ---- - -## 1. STATE - -| | | -|---|---| -| Branch | `claude/ci-margin-correction` @ `8e71fcdf`, pushed, **0 behind main** | -| PR | **#138**, OPEN, auto-merge **ARMED** (squash) | -| CI | **2 failures** — see BLOCKED ON | -| Uncommitted | none (this file is the only addition) | - -The worktree carrying this branch has a *different* recorded HOME branch, so a session-start hook will -warn about a possible worktree-hijack. That is expected: the branch was created here deliberately -because the previous one had been squash-merged and could not fast-forward. - ---- - -## 2. DONE (landed on main) - -| SHA | What | -|---|---| -| `f7e12695` | #74 — prune-merged worktree destruction fix (was stalled since 2026-07-30) | -| `28d186b5` | #131 — Windows step cap 26→36, job 30→40; stall detector; BACKLOG #340 + #344 | -| `002be182` | #119 — ADR 0154 increment B (I updated its branch when its owner went idle mid-task) | - -**Shipped in #131 and still current:** -- `scripts/ci/check_stalled_prs.py` + `.github/workflows/stalled-prs.yml` — daily, **advisory by - placement, must never become required** (it reports on *other* PRs; a stall on one would block - another). -- Signature: `state=OPEN AND mergeStateStatus=BEHIND AND failing=0 AND pending=0`. Matches `BEHIND` - **only** — `BLOCKED` is excluded deliberately, because `BLOCKED` self-resolves and `BEHIND` cannot - clear without external action. Verified against all four states. - ---- - -## 3. IN FLIGHT — PR #138 - -Corrects #131's own justification. **The 36:00 step decision is unchanged and remains correct.** - -Measured over **all 101 CI runs created 2026-08-01** (`gh api --paginate`), timing each leg's -`Tests (pytest)` **step**, filtering on the **step's own** conclusion: - -``` -leg #131 claimed TRUE n old cap true margin -ubuntu-latest 12:27 12:31 57 19:00 1.518x -windows-2022 18:39 21:34 52 26:00 1.206x -windows-2025 24:35 25:51 49 26:00 1.006x <- NINE SECONDS -``` - -Also raises `job_timeout` on all three legs, because the job cap was the binding constraint and -**nobody was watching it**: - -``` -leg step + web-console(max) + overhead old job new job -ubuntu 19:00 + 1:58 + 0:41 = 21:39 22:00 +21s 26:00 +4:21 (1.20x) -W22/W25 36:00 + 3:27 + 0:41 = 40:08 40:00 -8s 46:00 +5:52 (1.15x) -``` - ---- - -## 4. BLOCKED ON - -**#138 CI: `sql server (store + connector) 2022` FAILED, which fails `CI gate`.** - -``` -tests/test_sqlserver_store.py::test_cipher_invocations_upsert_is_atomic_and_additive -pyodbc.OperationalError: ('HYT00', ... 'Query timeout expired (0) (SQLExecDirectW)') -1 failed, 148 passed in 60.19s -``` - -**Do not call this a flake without proving it.** This repo's two famous "flakes" were a livelock and a -test that was right. What is known: #138's diff is `.github/workflows/ci.yml` only — the matrix values -for the ubuntu/W22/W25 `test` legs and the comment above `Tests (pytest)`. The sqlserver leg is a -separate job whose timeouts I did not touch. So a causal path from this diff to that failure is not -obvious, but **it has not been ruled out**. Next step: re-run the single job and check whether it -reproduces, and compare against the same test on `main`. - -Note the failure is itself a fixed wall-clock bound expiring (a *query* timeout) — i.e. plausibly -another BACKLOG #344 instance, in a third place. - -**Who clears it:** whoever picks this up. #138 is armed, so it lands by itself once the leg is green. - ---- - -## 5. RETRACTIONS — things I asserted that were wrong - -Four of mine. All were caught by a peer measuring, **none by me re-reading**. - -1. **"The collision gate never self-clears after a squash merge."** FALSE. `overlap.ps1` intersects - three-dot with two-dot; `git diff A..B` compares trees, so once content is in main the two-dot set - empties and the intersection clears. `collision_gate.ps1:70` *delegates* to `overlap.ps1`, so it - inherits this by construction. I read a three-dot diff and stopped. -2. **"#131's own run proves the raised cap applied."** It did apply — but the run does not show it. - Its step ran 24:22, under both 26:00 and 36:00. Durations cannot discriminate. **The matrix the run - echoes into its own log can** (`"job_timeout":40,"step_timeout":36`), and it was there the whole - time. Read the configuration; don't infer it from behaviour consistent with several configurations. -3. **"#119 died in a race between the step cap and the job cap"** (`26:07 + 3:18 + 0:41 = 30:06`). - FALSE — arithmetic over an impossible state. A step kill ends the job and skips what follows; - the killed run shows `Web console tests: completed/SKIPPED` and a 27:15 job against a 30:00 cap. - #119 was killed by the step cap alone and its attribution was correct. -4. **"The primary checkout is serving a stale collision gate."** FALSE — I hashed a **CRLF working - file against an LF blob**. Normalised, they are identical. I was one command from `git pull`-ing a - shared checkout used by every session, on the strength of this. - ---- - -## 6. TRAPS — each is a fact plus its measurement - -**T1. `step_timeout` gates TWO steps, and the job must cover their sum.** -`ci.yml` applies `timeout-minutes: ${{ matrix.step_timeout }}` to both `Tests (pytest)` and -`Web console tests (pytest)`. So a job can hold 2 × `step_timeout` of gated work that `step_timeout` -cannot bound. **This is not theoretical** — run `30724385719` (main @ `8f01cef8`): -``` -Tests (pytest) 25:51 SUCCESS <- 9s under the 26:00 cap -Web console tests (pytest) CANCELLED -JOB 30:13 CANCELLED <- job_timeout 30 fired -``` -A **green** first step, then an unattributed job kill during the second. It cannot happen when a step -is *killed*; only when the first step **passes** near its budget. The real fix is to stop the two -steps sharing a budget — a 3:27 suite has no business holding 36:00 (BACKLOG #344). - -**T2. Filtering a pool by JOB conclusion while measuring STEP durations removes the tightest cases by -construction.** A step near `step_timeout` is exactly the one that pushes its job into `job_timeout`, -so the job is cancelled while the step concluded success. **Five such rows existed on 2026-08-01 and -they include the maximum.** This is what produced #131's wrong table. Measure the step; filter on the -step. - -**T3. A default `gh run list` page is 20 rows.** #131's "11 passing runs" was a tool-truncated sample -reported as though it had been chosen — 20 of 101. Enumerate with `gh api --paginate`. - -**T4. Job durations are NOT step durations.** The job runs several minutes longer (setup **plus the -second pytest step**) and is capped separately. `c53f752b`'s JOB ran 28:41 and PASSED against job cap -30 / step cap 26. **Four sessions made this error tonight**, one of them immediately after writing the -correction about it. Rule: quote step figures from the step's own `started_at`/`completed_at` — never -by subtracting setup from a job total, never from elapsed wall-clock mid-run. - -**T5. To compare a working file against a git object, hash it WITH git.** -`git hash-object ` and `git rev-parse :` agree; `sha256sum` does not, because -`core.autocrlf` means the working file is CRLF and the blob is LF. Retraction 4 above. - -**T6. Sizing a cap by ratio-against-one-run is the wrong criterion.** windows-2025's step spread on -identical code is **5:26** (20:41 … 26:07 across seven observations). The rule that matters is -**headroom > observed spread**, not a multiple of a point estimate. Against 26:00 the headroom over -the true max was *negative*; #119's death was arithmetic, not luck. - -**T7. `check_stalled_prs.py` uses `gh pr list --limit 100`.** Past 100 open PRs the remainder is -invisible and the receipt prints `scanned 100` — true, and reading as complete. Not biting at ~15 open -PRs; unguarded regardless. My own instance of *a rule quantified over what is present cannot notice -what is missing*. - ---- - -## 7. Adjacent, not mine - -- **BACKLOG #340** (merge queue) — the ADR-0154 session is adding measured evidence after #137 lands: - #132 took **four full CI cycles to land, none from a failure** (~80 min runner time for a change - correct on the first pass). Their caveat belongs with it: tonight's queue *did* resolve without a - queue, via hand coordination, so a queue is a **convenience, not a correctness fix**. -- **BACKLOG #344** still restates #138's superseded figures (`24:35`, `1.06x`, `11 runs`, `1.45x`). - **That edit is not done** — it was blocked on live sessions holding `docs/BACKLOG.md`. Do it. -- **ADR 0158** ("Silent controls") is the announce session's, drafted not committed. ADR **0157** is - the HA session's *demotion safety* — I mis-routed taxonomy material to 0157 for hours; it is 0158. -- **The collision-gate fix (#133) needs the PRIMARY checkout advanced before it is in force.** - Check with `grep -c MatchedDirty /scripts/hooks/collision_gate.ps1` — non-zero means live. - Merged ≠ deployed, and nothing reports the gap. From 2e796dc29350718db05ce714cce45a8adeb47e6b Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 23:28:20 -0500 Subject: [PATCH 04/12] ci: mark the job-cap exhibit as mechanism, not verdict Run 30724385719 ran under the retired 26/30 pair and would have passed under #131's 40:00. It demonstrates that two steps sharing one step_timeout lets the job cap fire behind a green step; it is not itself evidence that 40:00 is too tight. That case rests on the arithmetic, which is arithmetic -- no job has been observed hitting 40:00. --- .github/workflows/ci.yml | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 4065af35..ea5c0fc5 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -307,6 +307,10 @@ jobs: # 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 to hold BOTH gated steps plus setup -- not step_timeout plus a # constant, which is what the previous +4 relationship was. Each addend below is that addend's # MEASURED MAXIMUM over the same pool. An earlier revision used 0:41 for setup, which is the From ee8c887b2d90c10b183513ca4cea1912b60834af Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 23:38:47 -0500 Subject: [PATCH 05/12] backlog: correct #344's own figures, and file the job cap as instance 3 #344 is the item about bounds stated independently of the work they bound. Its instance 1 still carried the retracted measurement -- 24:35 over "11 runs", 1.06x, raised to "1.46x" -- every figure of which was superseded, and the edit had been outstanding since it was filed. Instance 1 now reads 25:51 / 1.006x / 1.393x, and carries its pool (70 ci.yml runs created 2026-08-01 UTC; per-leg n = 42 / 39 / 36) so the next reader can recompute it rather than trust it. Adds two things the re-measurement turned up: * INSTANCE 3 -- the CI job cap. Two steps in that job carry step_timeout, so job_timeout must cover their sum, and the +4 convention that sized it was never summed against what it had to hold. Recomputed from measured maxima, ubuntu was -0:20 and windows-2025 -0:37: both already underwater. It presents as a GREEN first step followed by an unattributed job-level kill, which is a signature instance 1's own proposed margin check would not catch, because the step it measures passed. * THE CENSORING TRAP. A max-passing figure is a LOWER BOUND: the pool is censored by whatever cap was in force when it was collected, so the runs that would have exceeded it were killed and are missing from exactly the tail being measured. This is why 1.006x looked survivable until #119 died. Proposal 5 records the structural fix instance 3 does not make: give the web-console step its own cap, because until then ci.yml's nesting invariant is unenforceable for the second gated step on every leg. Banner moves from "not started" to PARTIAL -- instances 1 and 3 are fixed, instance 2 is not. One banner, still OPEN. Also records, once, that instance 1's figures have now been published wrong twice; the maxima survived both passes and the pools did not. --- docs/BACKLOG.md | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 5b39004f..24ee218c 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8307,26 +8307,31 @@ 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. *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 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:37** 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. 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. +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. **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. --- From 5be4d1feead30f568db45a960a0251ca86af2a91 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 23:46:03 -0500 Subject: [PATCH 06/12] ci: fix what the verification pass found in my own correction Nine agents re-derived this block; two re-derived the table from scratch under instructions to refute it. They confirmed every figure in the step table and refuted six things written around it. Fixing my own text, since the whole point of this change is not to ship a third unchecked table. * 26:07 EXISTS, and I said it did not. It is in this very pool -- run 30717229521 attempt 1, sha 8c407fb5, step conclusion FAILURE, killed at the 26:00 cap -- hidden because the jobs endpoint defaults to `filter=latest`, which returns only the passing attempt-2 re-run. Same filter hid seven same-commit pairs, so the "no identical-code spread is computable" claim was also wrong. `?filter=all` shows both. * THE SPREAD RULE IS NOT MET, and I claimed it was. The first day after the raise produced 26:23 TWICE, both concluding SUCCESS -- uncensored evidence that the population exceeds the old 26:00 cap. Against 26:23 the headroom is 9:37 and the spread 10:27, so "headroom must exceed observed spread" FAILS at 36:00; it would need ~37:00. 36:00 is kept and the reason is now stated plainly -- this cap catches a deadlock, not slowness, and 1.365x over the worst observed run is ample for that -- rather than the rule being asserted as satisfied. Re-derive if a windows-2025 step is ever seen above 28:00. * WINDOWS setup(max) IS 1:20, NOT 1:04. 1:04 came from restricting to rows where BOTH gated steps succeeded, which drops the exhibit run printed 20 lines above (its web-console step was cancelled) -- the same censoring mistake as filtering the step table by job conclusion, made again. W25 is 40:53, so the old cap was -0:53, not -0:37. windows-2022 now gets its own row with its own addends instead of an unrecheckable 39:42. * "the +4 convention" was Windows-only. ubuntu went 15/13 -> 22/19, so +2 then +3, never +4. * "2 x step_timeout ... which job_timeout must cover" asserted a requirement the shipped caps do not meet (38 > 26, 72 > 46). Now says what they are actually sized against. * The nesting invariant at the top of the block asserted a guarantee it does not provide for the SECOND gated step on any leg. Amended there, where a reader meets it, not only in a caveat 100 lines below. Also: pytest_timeout / fault_timeout were quoted as flat 60s / 90s in three places; they are matrix values (60/120 and 90/150) passed explicitly on the command line, so each figure was false on two of three legs. And records that `test` is the only one of this file's ten jobs with any cap at all -- the other nine run on GitHub's 6h default. --- .github/workflows/ci.yml | 96 ++++++++++++++++++++++++++++------------ 1 file changed, 68 insertions(+), 28 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index ea5c0fc5..a51ec82f 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -54,8 +54,9 @@ 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 + # 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 }} @@ -205,11 +206,13 @@ jobs: # 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 @@ -253,6 +263,14 @@ jobs: # censored maximum under-provisions by construction, and that is exactly how "1.06x" read as # survivable right up until #119 died at 26:07. # + # 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. + # # 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, @@ -284,18 +302,28 @@ 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.393x over the 25:51 maximum and -- the criterion that actually matters -- it clears - # the 9:55 spread the pool shows on that leg (15:56 .. 25:51): HEADROOM MUST EXCEED OBSERVED - # SPREAD, not some multiple of a single point. A ratio against one run says nothing about a - # distribution, and #119 died from the distribution, not from its own duration. An earlier revision - # quoted a narrower "5:26 spread ... identical code" (20:41 .. 26:07); neither endpoint could be - # re-derived from this pool, and the honest wider number is the one that supports the decision. - # 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. + # 36:00 is 1.393x over the 25:51 that fit under the old cap, and 1.365x 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.365x 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 died from the distribution, + # not from 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, which job_timeout must cover and step_timeout cannot bound. + # 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) @@ -311,31 +339,43 @@ jobs: # 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 to hold BOTH gated steps plus setup -- not step_timeout plus a - # constant, which is what the previous +4 relationship was. Each addend below is that addend's - # MEASURED MAXIMUM over the same pool. An earlier revision used 0:41 for setup, which is the - # MEDIAN and not the maximum, and web-console figures (1:58 / 3:27) that are each only the - # third-highest on their leg -- an addend sized at a typical value cannot bound a worst case: + # 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/W25 36:00 + 3:33 + 1:04 = 40:37 40:00 -> -0:37 46:00 -> +5:23 (1.13x) + # 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) # - # BOTH rows were already NEGATIVE -- ubuntu as well as Windows, which the previous revision had - # the wrong way round -- because the +4 convention was carried through two cap changes without - # anyone summing what it had to cover. Windows is sized on windows-2025, the worse of the pair; - # windows-2022 alone comes to 39:42, which was the one row genuinely in the black at +0:18. + # 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 -- satisfying it would need - # job_timeout past 39:24 on ubuntu and 73:21 on Windows, using the pool's most FAVOURABLE observed - # values. 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 + # 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 # above a healthy run. Sizing it tight buys no detection and costs false failures on green suites, From be46924d8b3c3ab8430912f11a17f8b6040e3ef9 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 23:48:30 -0500 Subject: [PATCH 07/12] backlog: #344 instance 3 carried the superseded -0:37, and the censoring now has evidence The windows-2025 job-cap shortfall is -0:53, not -0:37: the 1:04 setup addend it was computed from excluded the exhibit run itself, because that run's web-console step was cancelled. Same censoring mistake, one layer down. Instance 1 now cites the uncensored observation rather than only arguing the maximum must be a lower bound: the day after the raise, windows-2025 produced 26:23 twice, both passing -- runs the old 26:00 cap would have killed. Records that the jobs endpoint hides a killed attempt behind its passing re-run unless asked for ?filter=all, which is why nobody had seen them. --- docs/BACKLOG.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 24ee218c..271b8c67 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8313,11 +8313,11 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme **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 **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. +*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 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:37** 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. +*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. From 07b6e55a32d4c535e7a1b70aa1fee1cabb228332 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 23:51:00 -0500 Subject: [PATCH 08/12] =?UTF-8?q?ci:=20#119=20merged=20=E2=80=94=20stop=20?= =?UTF-8?q?saying=20it=20"died"?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Reported by the announce-hook session, verified here: gh pr view 119 gives MERGED, mergedAt 2026-08-02T01:45:00Z. What the 26:00 cap killed was a RUN, not the PR. "#119 died" reads as never-landed, and that reading had already propagated -- docs/WORKTREES.md asserted #119 "never merged (it died on an unrelated CI timeout)", which that session corrected against the API. This block was one of the places the phrasing came from, so it is fixed at the source rather than only downstream. --- .github/workflows/ci.yml | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index a51ec82f..2d6c00c2 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -261,7 +261,9 @@ jobs: # 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 died at 26:07. + # 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 @@ -315,8 +317,8 @@ jobs: # 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 died from the distribution, - # not from its own duration. Both Windows legs take the same number: windows-2022 is the faster, so + # 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 @@ -382,7 +384,7 @@ 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. + # 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' From f5667455265020088cad9beb21a355cf7536a603 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sat, 1 Aug 2026 23:52:43 -0500 Subject: [PATCH 09/12] ci: 36:00/26:23 is 1.364x, not 1.365x Caught by running an exact-arithmetic assertion over every figure in the block rather than re-reading it: 2160/1583 = 1.3644978, which rounds to 1.364. I had rounded it up by hand in both places. Trivial in size and not in kind -- this is a change whose entire subject is numbers published without being recomputed, so it does not get to ship one. Every ratio, sum and delta in the block is now covered by that assertion and all fifteen are exact. --- .github/workflows/ci.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 2d6c00c2..0f75c447 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -304,7 +304,7 @@ 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.393x over the 25:51 that fit under the old cap, and 1.365x over 26:23, the largest + # 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. # @@ -312,7 +312,7 @@ jobs: # 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.365x over the worst observed + # 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. From 94229bf644bf128542fab93adf597ae358580171 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 08:33:14 -0500 Subject: [PATCH 10/12] backlog: #344's own proposal 3 was harmful, and instance 2 was mis-diagnosed Found by investigating a sqlserver failure on this very PR, which turned out to be instance 2 recurring on a different test. PROPOSAL 3 IS WITHDRAWN. It said a poll deadline over a virtual-clock system should follow that clock rather than loop.time(). Implementing that would have HUNG the suite: _wait_until waits on real store I/O, never on virtual time, and ManualClock.now advances only inside advance(), which nothing calls from the poll loop (tests/test_stage_dispatcher.py:182-204). A mc.now-based deadline is never reached, so a bounded `assert False` becomes an unbounded hang stopped only by pytest_timeout or the job cap -- manufacturing the exact signature instances 1 and 3 are about. A virtual clock can only bound work it drives. INSTANCE 2 IS RE-DIAGNOSED, and the original reading -- "the 8.0s bound is too small" -- is refuted by the recurrence's own timings. The failing test took 8.185s, so _wait_until burned its full 8.000s and setup+teardown cost 0.185s: the store was FAST when it failed. In the same process against the same container the sibling retry_forever[sqlserver] drove seven identical fault cycles in 0.364s, and the [sqlite] variant of the failing test passed in 0.144s. A cycle costs ~30-45ms against an 8000ms bound. The lane is not slow to transition; it never transitions. Raising the number would not fix it and would bury it -- which is precisely the mislabelling this item's own Why warns about. The leading mechanism is recorded as evidenced-but-unconfirmed rather than asserted: a sanctioned EMPTY claim drops the lane to IDLE, and these tests deliberately disable the sweep that recovers it in production. What is settled is the negative: not latency, and not a bigger number. PROPOSAL 1 now carries the evidence for preferring a computed gate to a written instruction. Seven claims were retracted across this triage cluster and none was caught by re-reading; every one fell to a mechanism that could return "no". The one an author caught themselves was caught by running exact arithmetic over all fifteen ratios in the block. As a method, re-reading is 0-for-7 here. --- docs/BACKLOG.md | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 271b8c67..71be5507 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8317,6 +8317,8 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme *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 — roughly 200x headroom. **So raising the bound would not fix this and would bury it**: the lane is not slow to transition, it never transitions. Leading explanation, evidenced but not yet adversarially confirmed: a sanctioned EMPTY claim drops the lane to IDLE, and these ADR 0070 tests deliberately disable the production backstop (`lane_provider=set()`, `sweep_interval=3600`), so IDLE is terminal — where production re-readies the lane from its 0.25s sweep. SQLite cannot produce it (its global lock orders producers and claimers), which matches the sqlserver-only asymmetry. **What is settled is the negative**: this is not latency, and the remedy is not a bigger number. + *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. @@ -8324,9 +8326,9 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme **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.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. 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. +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. +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. From 2f548191349de45dff4b78a51750ec4995656799 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 08:39:33 -0500 Subject: [PATCH 11/12] backlog: #344 instance 2 inverts the item's own remedy, and needs observability first A second, larger pass measured what instance 2 actually costs, and the numbers change what should be done about it. RATE AND MARGIN. The two affected tests fail 2 times in ~479 observations (~0.4%), zero on postgres (119) and zero across 1,105 sqlite executions. Over a sample of green sqlserver jobs the failing test passes in min 0.185s / median 0.196s / max 0.204s -- the 8.0s bound is ~39x its worst passing run, ~14x over a wider 21-day pool. Both failures sit ~7x beyond the whole passing distribution: a gap, not a tail. SO THIS INSTANCE INVERTS THE ITEM'S OWN GENERIC REMEDY. "Size the bound against the work" would derive ~1-2s here -- TIGHTER than the 8.0s already in place. There is no larger number to justify, and raising it would only convert a 0.4% visible failure into a 0.4% invisible 30-60s pause. An item about bounds that have drifted too LOOSE has to be able to say when the answer is not a bigger number, and this is that case. MECHANISM IS EXPLICITLY UNRESOLVED. Two independent passes disagreed -- one proposes a sanctioned EMPTY claim dropping the lane to a terminal IDLE (these tests disable the sweep that recovers it in production), the other returned NOT PROVEN and is right that the evidence cannot separate that from a genuine stall. Recorded as unresolved rather than picking the more satisfying story. NEW PROPOSAL 6: make the expiry diagnostic before tuning it. `assert await _wait_until(...)` prints `assert False` and nothing else -- no phase, no park deadline, no streak, no task state -- which is why this was read as latency for a day. That is the prerequisite for judging any other proposal here, and unlike them it cannot itself be wrong about the cause. NOT changed: the note that a killed attempt hides behind its passing re-run unless you pass ?filter=all. A reviewing pass claimed filter=all does not return prior attempts; checked directly against both cited runs and it does (attempts [1,2] on each), so the existing text stands. --- docs/BACKLOG.md | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 71be5507..9ab9e70c 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8317,7 +8317,11 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme *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 — roughly 200x headroom. **So raising the bound would not fix this and would bury it**: the lane is not slow to transition, it never transitions. Leading explanation, evidenced but not yet adversarially confirmed: a sanctioned EMPTY claim drops the lane to IDLE, and these ADR 0070 tests deliberately disable the production backstop (`lane_provider=set()`, `sweep_interval=3600`), so IDLE is terminal — where production re-readies the lane from its 0.25s sweep. SQLite cannot produce it (its global lock orders producers and claimers), which matches the sqlserver-only asymmetry. **What is settled is the negative**: this is not latency, and the remedy is not a bigger number. +*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%), **zero** on postgres (119 observations) and zero across 1,105 sqlite executions. 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. @@ -8331,6 +8335,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()`.~~ **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.** A bare `assert await _wait_until(...)` reports `assert False` and nothing else, so every occurrence gets 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 state a reader needs: the lane's phase, park deadline and streak, whether its task is alive or has an exception, the store row's status, and the clock. This is cheap, it is the prerequisite for judging any of the other proposals, and unlike them it cannot itself be wrong about the cause. **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). From f59c56557700331fac9d27e632fa2d200148816c Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Sun, 2 Aug 2026 08:57:36 -0500 Subject: [PATCH 12/12] =?UTF-8?q?backlog:=20#344=20proposal=206=20?= =?UTF-8?q?=E2=80=94=20the=20instrument=20that=20settles=20instance=202=20?= =?UTF-8?q?already=20ships?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both adversarial passes converged on the same verdict (raising the bound would mask, not fix) but neither proposed the cheap discriminator, and it turns out not to need building. StageDispatcher.empty_claims (stage_dispatcher.py:1230) already returns (total, wake_fanout, idle_poll) and is fed by _record_empty, whose ONLY call site is the EMPTY branch of _claim_and_dispatch (:686). Under these tests' topology -- lane_provider=set(), sweep_interval=3600, one seeded row -- a clean run must read (0,0,0). So at the moment of failure `empty_claims[0] > 0` proves a spurious EMPTY dropped the lane to a terminal IDLE (T12 sets phase=IDLE and arms no timer), and `== 0` proves the claim never returned at all. One assertion separates the two hypotheses this item currently records as unresolved. A second signature costs nothing and is already in the captured log: a healthy run emits FOUR `re-pending head with backoff` records (1001.000 / 1003.500 / 1008.000 / 1016.500, the ManualClock base plus the infra backoff ladder); the failing run emitted ONE. The lane never took a second fault. Verified against the source before citing it -- accessor, call site and the T12 branch all read directly, not taken from the analysis. --- docs/BACKLOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index face4453..3e494bd6 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8351,7 +8351,7 @@ What is NOT settled is the mechanism. Two independent passes reached different a 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.** A bare `assert await _wait_until(...)` reports `assert False` and nothing else, so every occurrence gets 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 state a reader needs: the lane's phase, park deadline and streak, whether its task is alive or has an exception, the store row's status, and the clock. This is cheap, it is the prerequisite for judging any of the other proposals, and unlike them it cannot itself be wrong about the cause. +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 already in the captured log: a healthy run emits **four** `re-pending head with backoff` records (at `1001.000 / 1003.500 / 1008.000 / 1016.500`); the failing run emitted **one**. 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).