ci: the margin table was wrong twice — re-measure the pool, and size the job cap from maxima

.github/workflows/ci.yml

@@ -54,10 +54,11 @@ jobs:
     # runner label set; the per-repo matrix is built in `changes`.
     runs-on: ${{ matrix.hosted }}
     # Wall-clock backstop: bound each leg so a hung test fails in minutes, not the 6h default. Three
-    # nested watchdogs catch a hang at increasing scope (#55): the pytest-timeout per-test cap (60s,
-    # pyproject addopts) + the faulthandler belt fire FIRST and name the stuck frame; the pytest STEP
-    # has its own `timeout-minutes: 13` so a process-level deadlock below pytest fails the step fast;
-    # this job cap is the outermost belt if even that is somehow out-raced.
+    # nested watchdogs catch a hang at increasing scope (#55): the pytest-timeout per-test cap (matrix
+    # `pytest_timeout`, 60s ubuntu / 120s Windows -- the step passes `--timeout=`, which overrides the
+    # pyproject addopts value) + the faulthandler belt fire FIRST and name the stuck frame; the pytest STEP
+    # has its own `timeout-minutes` (matrix `step_timeout`) so a process-level deadlock below pytest
+    # fails the step fast; this job cap is the outermost belt if even that is somehow out-raced.
     timeout-minutes: ${{ matrix.job_timeout }}
     strategy:
       fail-fast: false
@@ -200,16 +201,18 @@ jobs:
         if: (needs.changes.outputs.code == 'true' || github.event_name == 'push' || github.event_name == 'workflow_dispatch') && runner.os == 'Linux'
         run: mypy --platform win32 messagefoundry
 
-      # Step-level watchdog UNDER the 15-min job cap (#55): the windows-2022 leg intermittently
+      # Step-level watchdog UNDER the job cap (#55): the windows-2022 leg intermittently
       # wedges ~25% in (a Windows ProactorEventLoop listener-teardown / socket wait that the shared
       # session event loop can't get past), emits no output for ~12 min, then the JOB cap CANCELS it
       # — a red ✗ with no stack and no named test. Two belts make that fail FAST and NAMED instead:
       #   * `--timeout-method=thread` (the ONLY method on Windows — SIGALRM is POSIX-only) dumps ALL
-      #     thread stacks at the per-test cap (60s, set in pyproject addopts), naming the stuck frame.
-      #   * PYTHONFAULTHANDLER=1 + `-o faulthandler_timeout=90` is the belt that fires even when the
+      #     thread stacks at the per-test cap (matrix `pytest_timeout`, 120s on these Windows legs),
+      #     naming the stuck frame.
+      #   * PYTHONFAULTHANDLER=1 + `-o faulthandler_timeout=` (matrix `fault_timeout`) is the belt that fires even when the
       #     thread-timer CANNOT interrupt a main-thread C-level wait (a Proactor overlapped op /
       #     blocking accept / subprocess.wait): pytest's faulthandler plugin arms a separate watchdog
-      #     thread that dumps the NATIVE stack of every thread at 90s (> the 60s pytest-timeout, so the
+      #     thread that dumps the NATIVE stack of every thread at `fault_timeout` (150s here, 90s on
+      #     ubuntu -- always set ABOVE that leg's `pytest_timeout`, so the
       #     per-test dump is attributed first; this is the last-resort stack when the thread method is
       #     itself out-raced). NB the plugin exposes this as the `faulthandler_timeout` ini key, not a
       #     `--faulthandler-*` CLI flag, so it is passed with `-o`; it only DUMPS (never kills), safe.
@@ -218,6 +221,13 @@ jobs:
       # the silent cap). Keep the gap: the step must expire BEFORE the job, or the failure surfaces as
       # an uninformative job-level kill with no step attribution.
       #
+      # THAT GUARANTEE COVERS THE FIRST GATED STEP ONLY, and saying otherwise would be a control resting
+      # on a false premise. `Web console tests (pytest)` carries the SAME `step_timeout` but runs after
+      # `Tests (pytest)`, so reaching it has already spent setup + `Tests`; its own cap cannot fire first
+      # at any job_timeout worth setting (it would take ~39 min on ubuntu, ~73 min on Windows). A hang
+      # THERE is still an unattributed job-level kill. Measured under `Tests (pytest)` below; the
+      # structural fix is BACKLOG #344 proposal 5.
+      #
       # It only works while the cap stays clear of a HEALTHY run. On 2026-07-31 the ubuntu leg finished
       # green in 775s against a 780s cap -- 5s of margin -- and the step was killed anyway, reported as
       # a failure on a run whose last line was "9598 passed, 855 skipped". A watchdog that cannot
@@ -230,19 +240,62 @@ jobs:
       # code under test: #74 landed tests/test_worktree_prune_merged.py (1,506 lines) and windows-2025
       # went 19:35 -> 26:07 on the same branch. The claim was already false when it was written.
       #
-      # Measured over the 11 PASSING windows-2025 runs on 2026-08-01, timing the `Tests (pytest)` STEP,
-      # which is what step_timeout gates. NOT the job: the job is ~3 min longer and capped separately,
-      # and two sessions misread job durations as step durations while triaging this (c53f752b's JOB ran
-      # 28:41 and PASSED, because job cap 30 vs step cap 26).
+      # Measured by timing the `Tests (pytest)` STEP, which is what step_timeout gates. NOT the job: the
+      # job runs several minutes longer and is capped separately, and at least three sessions misread job
+      # durations as step durations while triaging this (c53f752b's JOB ran 28:41 and PASSED, because
+      # job cap 30 vs step cap 26).
+      #
+      # POOL: every run of THIS workflow created on 2026-08-01 UTC -- 70 runs. Enumerated with
+      # `gh api --paginate` over a deliberately WIDER window and filtered locally on `created_at`, then
+      # cross-checked against the narrow `?created=` query (same 70 ids, symmetric difference 0). Rows
+      # are each leg's `Tests (pytest)` step, kept when THAT STEP concluded success. n is per leg.
+      #
+      #   leg              max passing step   n    old cap   old margin
+      #   ubuntu-latest    12:31              42   19:00     1.518x
+      #   windows-2022     21:34              39   26:00     1.206x
+      #   windows-2025     25:51              36   26:00     1.006x   <- NINE SECONDS
+      #
+      # THESE MAXIMA ARE LOWER BOUNDS, BECAUSE THE POOL IS RIGHT-CENSORED. Every run in it predates #131
+      # (28d186b5, landed 2026-08-02T00:35:28Z), so Windows ran under step 26:00 / job 30:00 and ubuntu
+      # under 19:00 / 22:00. A run that wanted longer than its cap was KILLED at the cap and then --
+      # correctly, by the filter above -- dropped for not concluding success. So 25:51 is the largest
+      # step that FIT in 26:00, not the largest the suite wants. Sizing a cap as a multiple of a
+      # censored maximum under-provisions by construction, and that is exactly how "1.06x" read as
+      # survivable right up until #119's leg was killed at 26:07. (#119 itself merged, 2026-08-02T01:45Z
+      # -- what the cap killed was a run, not the PR. Saying a PR "died" here reads as never-landed and
+      # had already propagated into docs/WORKTREES.md as exactly that claim.)
+      #
+      # THE CENSORED VALUES ARE VISIBLE IF YOU ASK FOR THEM, AND THEY MATTER. The jobs endpoint defaults
+      # to `filter=latest`, which hides a killed attempt behind its passing re-run; `?filter=all` shows
+      # both. #119's 26:07 is in this very pool that way (run 30717229521 attempt 1, `8c407fb5`, step
+      # conclusion FAILURE) beside its 22:25 attempt-2 success -- a 3:42 spread on identical code, and
+      # the first day AFTER the raise produced 26:23 TWICE, both concluding SUCCESS (runs 30728793103
+      # and 30731407003). So the population really does exceed the old 26:00 cap: the largest windows-2025
+      # `Tests (pytest)` execution observed to date is 26:23, not 25:51.
       #
-      #   leg              max passing step   old cap   old margin
-      #   ubuntu-latest    12:27              19:00     1.53x
-      #   windows-2022     18:39              26:00     1.39x
-      #   windows-2025     24:35              26:00     1.06x
+      # THIS TABLE HAS BEEN WRONG TWICE. #131 published 12:27 / 18:39 / 24:35 over "11 passing runs";
+      # the first correction published the maxima above but over "101 runs" with n = 57 / 52 / 49. The
+      # maxima re-derive exactly; BOTH pool sizes were unreproducible. Three mechanisms produced that,
+      # all cheap to repeat:
       #
-      # windows-2025 had already PASSED at 24:35 -- 85 seconds of margin -- before #119 died. The "2x"
-      # figure matched no leg. State the MEASURED value and its DATE, never a round multiple: a bare
-      # multiple gives the next reader no way to tell when it has rotted, which is how this one survived.
+      #   * THE POOL WAS A PAGE, NOT A QUESTION. #131's came from `gh run list --limit 20` -- a default
+      #     page size, reported as though it had been chosen.
+      #   * FILTERING ON *JOB* CONCLUSION DROPS THE TIGHTEST STEPS BY CONSTRUCTION. A step that nearly
+      #     exhausts step_timeout is the most likely to push its job into job_timeout, so the job is
+      #     cancelled while the step itself concluded success. Re-running this pool with a job-conclusion
+      #     filter reproduces #131's 24:35 exactly; the step-conclusion filter gives 25:51. Measure the
+      #     step; filter on the step. Two such rows exist on 2026-08-01 and one of them is the maximum.
+      #   * A COUNT NOBODY RE-DERIVED. Neither "101 runs" nor n = 57 / 52 / 49 is reproducible under any
+      #     pool definition tried. A table whose own point is "state your pool and your n" has to carry
+      #     an n the next reader can recompute -- that column is how they would tell it had rotted.
+      #
+      # Only the windows-2025 row was ever a maximum; #131's ubuntu 12:27 was that same run's ubuntu leg,
+      # quoted as if it were that leg's worst case. Its 18:39 was not even that: that run's windows-2022
+      # step is 18:29, and 18:39 belongs to a different run entirely.
+      #
+      # State the MEASURED value, its POOL, its n and its DATE -- never a bare multiple. A multiple gives
+      # the next reader no way to tell when it has rotted; a multiple without its pool cannot even be
+      # rechecked.
       #
       # PROOF IT WAS THE CAP, NOT THE BRANCH. #119's windows-2025 leg was RE-RUN on the SAME commit
       # against the SAME 26:00 cap: attempt 1 was killed at the cap, attempt 2 concluded SUCCESS. Same
@@ -251,19 +304,88 @@ jobs:
       # see" is not a diagnosis here. A green re-run at 26:00 does not mean the suite fits; it means
       # that runner was fast enough that time.
       #
-      # 36:00 is 1.46x over that 24:35 maximum -- the margin ubuntu already runs with. Both Windows legs
-      # take the same number: windows-2022 is the faster of the two, so sizing on windows-2025 only
-      # leaves it more room, and one value is one thing to re-derive. job_timeout moves 30 -> 40 to keep
-      # the nesting invariant above: the step must still expire strictly BEFORE the job.
+      # 36:00 is 1.393x over the 25:51 that fit under the old cap, and 1.364x over 26:23, the largest
+      # windows-2025 execution actually observed. Use the second number: a ratio against a censored
+      # maximum flatters itself.
+      #
+      # BE HONEST ABOUT THE SPREAD RULE -- 36:00 DOES NOT MEET IT. An earlier revision argued "headroom
+      # must exceed observed spread". Against real values that rule FAILS here: headroom is 36:00 - 26:23
+      # = 9:37, and the windows-2025 spread is 26:23 - 15:56 = 10:27. It would need roughly 37:00 to hold.
+      # 36:00 is kept anyway, and the reason is stated rather than dressed up: this cap exists to catch a
+      # whole-process DEADLOCK, not slowness (see the paragraph below), so 1.364x over the worst observed
+      # run is ample for its actual job, and #131 already set this value. What the spread rule is good
+      # for is telling you the margin is thinner than the ratio suggests. RE-DERIVE IF a windows-2025
+      # `Tests (pytest)` step is ever seen above 28:00 -- that is the trigger, not a calendar reminder.
+      #
+      # A ratio against one run says nothing about a distribution, and #119's leg was killed by the
+      # distribution, not by its own duration. Both Windows legs take the same number: windows-2022 is the faster, so
+      # sizing on windows-2025 only leaves it more room, and one value is one thing to re-derive.
+      #
+      # THE JOB CAP IS NOT A ROUNDING-UP OF THE STEP CAP, AND IT HAS FIRED. Two steps in this job carry
+      # `step_timeout` -- `Tests (pytest)` and `Web console tests (pytest)` -- so the job can contain
+      # 2 x step_timeout of gated work that step_timeout cannot bound. Note the caps here do NOT cover
+      # that worst case and are not sized to (2 x 19 = 38 > 26 on ubuntu, 2 x 36 = 72 > 46 on Windows);
+      # they are sized against the OBSERVED sum, which is a weaker guarantee. See the closing paragraph.
+      # Observed for real on run 30724385719 (main @ 8f01cef8, 2026-08-01):
+      #
+      #   Tests (pytest)              00:01:21 -> 00:27:12   25:51   SUCCESS   (9s under the 26:00 cap)
+      #   Web console tests (pytest)  00:27:12 -> 00:30:14           CANCELLED
+      #   JOB                         00:00:06 -> 00:30:19   30:13   CANCELLED  <- job_timeout 30 fired
+      #
+      # A GREEN first step, then an unattributed job-level kill during the second -- exactly the failure
+      # the nesting note above exists to prevent, arriving by the path that note does not consider. It
+      # does NOT happen when a step is killed (that ends the job and skips what follows, so those
+      # durations never sum); it happens when the first step PASSES near its budget.
+      #
+      # READ THAT EXHIBIT FOR ITS MECHANISM, NOT AS A VERDICT ON THE CAP IT REPLACED: it ran under the
+      # retired 26/30 pair and would have passed under #131's 40:00. What condemns 40:00 is the
+      # arithmetic below -- which is arithmetic, not an observed kill; no job has yet hit 40:00.
+      #
+      # job_timeout is therefore sized against BOTH gated steps plus setup, rather than as step_timeout
+      # plus a constant. Each addend below is that addend's MEASURED MAXIMUM over the same pool, taken
+      # over rows where `Tests` concluded success -- NOT over rows where both steps did, which silently
+      # drops the very run that motivates this whole paragraph (its web-console step was cancelled) and
+      # is the same censoring mistake as filtering the step table by job conclusion. Two earlier
+      # revisions used a 0:41 setup (the MEDIAN), web-console values that were each only third-highest
+      # on their leg, and a 1:04 Windows setup that the exhibit above contradicts on its face:
+      #
+      #   leg       step_timeout + web-console(max) + setup(max)   old job         new job
+      #   ubuntu    19:00 + 2:00 + 1:20 = 22:20                    22:00 -> -0:20  26:00 -> +3:40 (1.16x)
+      #   W22       36:00 + 2:33 + 1:09 = 39:42                    40:00 -> +0:18  46:00 -> +6:18 (1.16x)
+      #   W25       36:00 + 3:33 + 1:20 = 40:53                    40:00 -> -0:53  46:00 -> +5:07 (1.13x)
+      #
+      # ubuntu and windows-2025 were ALREADY NEGATIVE -- ubuntu too, which an earlier revision had the
+      # wrong way round; windows-2022 was the one row genuinely in the black. Windows takes one value,
+      # sized on windows-2025 as the worse of the pair. The `+4` habit that produced 40 was Windows-only
+      # and was carried through two cap changes unchecked (30/26 then 40/36); ubuntu has never been +4 --
+      # it went 15/13 to 22/19, so +2 then +3. Either way the number was derived from the OTHER BOUND
+      # rather than from the work, which is the defect, not the particular constant.
+      #
+      # WHAT THIS DOES NOT FIX. The nesting invariant at the top of this note holds for `Tests (pytest)`
+      # on every leg and for `Web console tests (pytest)` on NONE of them: reaching that step already
+      # spends setup plus `Tests`, so its own cap can never fire first. Guaranteeing it would need
+      # job_timeout above setup + 2 x step_timeout -- about 39:20 on ubuntu and 73:20 on Windows at the
+      # measured setup maxima above, i.e. far beyond anything worth setting. A hang in the web-console
+      # step therefore still surfaces as an unattributed job-level kill, which is the very failure the
+      # invariant is there to prevent. The structural fix is to stop
+      # the two steps sharing one budget (a 3:33 suite has no business holding 36:00) and is filed as
+      # BACKLOG #344; this sizing only makes the job cap cover the sum. Re-derive it if either suite's
+      # duration moves.
+      #
+      # AND KNOW WHAT IS NOT CAPPED AT ALL. `test` is the ONLY one of this file's ten jobs carrying any
+      # `timeout-minutes`; the other nine -- `changes`, `ide`, `sqlserver-store`, `postgres-store`,
+      # `load-test`, `load-test-sqlserver`, `windows-service-smoke`, `docker-smoke`, `ci-gate` -- run on
+      # GitHub's 6-HOUR default. That is recorded here so the omission is known rather than assumed
+      # deliberate; sizing them is out of scope for this change and belongs with BACKLOG #344.
       #
       # This cap is NOT what catches a hung test; pytest_timeout (120s) is, per test. The step cap only
       # catches a whole-process deadlock both in-process watchdogs miss, which is why it can sit well
       # above a healthy run. Sizing it tight buys no detection and costs false failures on green suites,
       # twice now.
       #
       # The remaining margin is a SHARED budget across every PR that lands and nothing accounts for it:
-      # three PRs each adding a minute of Windows time reproduce #119's death, individually blameless.
-      # A mechanical guard for that is BACKLOG #341; the underlying slowness is #320.
+      # three PRs each adding a minute of Windows time reproduce #119's kill, individually blameless.
+      # A mechanical guard for that is BACKLOG #344 item 1; the underlying slowness is #320.
       - name: Tests (pytest)
         if: needs.changes.outputs.code == 'true' || github.event_name == 'push' || github.event_name == 'workflow_dispatch'
         timeout-minutes: ${{ matrix.step_timeout }}
@@ -421,9 +543,9 @@ jobs:
           # $GITHUB_REPOSITORY is a built-in runner env var, read here as plain shell (NOT a workflow-
           # expression interpolation into the run body), so it is zizmor-safe and cannot be misparsed as
           # an Actions expression the way a literal double-brace token in a run: block would be.
-          U='{"os":"ubuntu-latest","python-version":"3.14","hosted":["ubuntu-latest"],"job_timeout":22,"step_timeout":19,"pytest_timeout":60,"fault_timeout":90}'
-          W22='{"os":"windows-2022","python-version":"3.14","hosted":["windows-2022"],"job_timeout":40,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}'
-          W25='{"os":"windows-2025","python-version":"3.14","hosted":["windows-2025"],"job_timeout":40,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}'
+          U='{"os":"ubuntu-latest","python-version":"3.14","hosted":["ubuntu-latest"],"job_timeout":26,"step_timeout":19,"pytest_timeout":60,"fault_timeout":90}'
+          W22='{"os":"windows-2022","python-version":"3.14","hosted":["windows-2022"],"job_timeout":46,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}'
+          W25='{"os":"windows-2025","python-version":"3.14","hosted":["windows-2025"],"job_timeout":46,"step_timeout":36,"pytest_timeout":120,"fault_timeout":150}'
           if [ "${GITHUB_REPOSITORY:-}" = "MEFORORG/MessageFoundry" ]; then
             echo "matrix={\"include\":[$U,$W22,$W25]}" >> "$GITHUB_OUTPUT"
           else