diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 3ff13caf..015fe60d 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -315,7 +315,7 @@ jobs: # 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 + # at any job_timeout worth setting (it would take ~55 min on ubuntu, ~114 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. # @@ -336,15 +336,41 @@ jobs: # 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. + # POOL: every run of THIS workflow created 2026-08-01T00:00Z .. 2026-08-09T00:00Z UTC -- 688 runs. + # Enumerated with `gh api` over a deliberately WIDER page range (1,000 runs, back to 2026-07-26) and + # filtered locally on `created_at`. Jobs fetched with `?filter=all`, so an attempt killed at the cap + # is not hidden behind its passing re-run. Rows are each leg's `Tests (pytest)` STEP, kept when THAT + # STEP concluded, executions under 60s dropped (a docs-only PR skips the leg). 1,618 leg-executions; + # n below is per leg, passing rows only. Measured 2026-08-08 (BACKLOG #1096). # - # 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 + # leg max passing step n old cap old margin new cap new margin + # ubuntu-latest 16:08 441 19:00 1.178x 25:00 1.550x + # windows-2022 29:23 399 36:00 1.225x 55:00 1.872x + # windows-2025 35:47 CENSORED 360 36:00 1.006x 55:00 1.537x + # + # ONLY THE WINDOWS-2025 ROW IS CENSORED, AND THAT IS MEASURED, NOT ASSUMED. Largest ubuntu step + # FAILURE in 535 leg-executions is 14:21; largest windows-2022 failure in 542 is 25:48. Neither leg + # has ever touched its cap, so 16:08 and 29:23 are true maxima. windows-2025 was killed at the cap + # SEVEN times in this window -- 36:08 (31189317409, main b78214f5), 36:08 (31199321840, main + # 7ecff8ae), 36:08 (31202372465, PR #253), 36:07 (30955150892, 2026-08-04, the earliest), 36:07 + # (31094875320, main fdec72ca), 36:07 (31192717684, PR #249), 36:01 (31149117314, PR #261) -- THREE + # of them push runs on main. So 35:47 is the largest step that FIT in 36:00, and 36:08 is a lower + # bound on the largest the suite wants. Smaller pools give smaller counts and each is right for its + # own pool: BACKLOG #1096's day pool has five, a 3-day pool has six. State the pool with the count. + # + # THE KILLS WERE SLOWNESS, NOT A WEDGE -- CHECKED, NOT ASSUMED. Run 31149117314's pytest finished + # GREEN and the step was killed 4.85 seconds later: + # 05:37:53.777Z 10666 passed, 831 skipped, 22 warnings in 2148.75s (0:35:48) + # 05:37:58.624Z ##[error]The action 'Tests (pytest)' has timed out after 36 minutes. + # No faulthandler native-stack dump appears in any kill log. That settles the hang-versus-slow + # question the #55 note above would otherwise leave open, and it has a second consequence that is + # easy to miss: the killed rows are genuine population members, so "max passing" is CENSORED, not + # conservative. Every ratio taken against it flatters itself. + # + # SUPERSEDED READING, kept because a number without its pool cannot be rechecked: the 2026-08-01 + # pool (70 runs, pre-#131) read ubuntu 12:31 / W22 21:34 / W25 25:51 against the then-current + # 26:00 Windows cap. Those figures are correct for that pool and that code state. They are not + # comparable to the rows above, which are post-#131 and span eight days. # # 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 @@ -395,22 +421,54 @@ 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.364x over 26:23, the largest - # windows-2025 execution actually observed. Use the second number: a ratio against a censored - # maximum flatters itself. + # THE CAP IS SIZED ON THE POST-#1027 POPULATION, NOT ON WHAT RUNS TODAY. PR #253 (BACKLOG #1027) is + # open and MERGEABLE and sets testpaths = ["tests", "packaging/messagefoundry-webconsole/tests"], + # while keeping the `Web console tests (pytest)` step -- so once it lands the web console suite runs + # inside `Tests (pytest)` AS WELL. Sizing on the current population would let #253 land and re-break + # the cap on contact, which is the "three PRs each adding a minute" death recorded at the foot of + # this note. The one windows-2025 execution of that branch is one of the seven kills above, so the + # post-#1027 windows-2025 duration HAS NEVER BEEN OBSERVED UNCENSORED -- and windows-2022's sizing + # maximum (29:23) IS a post-#1027 row. One shared value, two code states, until this is fixed. + # + # leg largest observed Tests + largest observed web-console = post-#1027 anchor + # ubuntu 16:08 (uncensored) 2:22 (n=441) 18:30 + # W22 29:23 (uncensored; already a post-#1027 row) 29:23 + # W25 36:08 (RIGHT-CENSORED) 3:59 (n=360) 40:07 lower bound # - # 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. + # SIZING RULE: step_timeout = ceil_minute(1.35 x that leg's post-#1027 anchor). 1.35 is the multiple + # #131 used when it set 36:00 (1.364x over 26:23, the largest execution then observed). + # ubuntu 18:30 x 1.35 = 24:59 -> 25:00 (1.351x over the anchor, 1.550x over max passing) + # W22 29:23 x 1.35 = 39:40 -> 40:00 (takes the shared Windows value below) + # W25 40:07 x 1.35 = 54:09 -> 55:00 (1.371x over the anchor, 1.537x over max passing) + # + # UBUNTU IS CHANGED IN THE SAME ACT BECAUSE IT IS THE NEXT INSTANCE, NOT AS TIDYING. At 19:00 against + # its post-#1027 anchor of 18:30 it stands at 1.027x -- within seconds of where windows-2025 is now -- + # and its job cap is ALREADY NEGATIVE on measured maxima (see the job paragraph below). Publishing + # "ubuntu unchanged, still positive" beside a corrected Windows row would be a compensating control + # resting on a false premise, which is the defect this repo names specifically. + # + # THE SPREAD RULE NOW HOLDS, WHERE AT 36:00 IT DID NOT. The rule is "headroom must exceed observed + # spread". At 36:00 it FAILED on windows-2025 (headroom 9:37 against a 10:27 spread) and the old + # revision kept the value anyway and said so. At 55:00, on the eight-day pool: + # windows-2025 headroom 55:00 - 35:47 = 19:13 spread 35:47 - 24:48 = 10:59 HOLDS (+8:14) + # windows-2022 headroom 55:00 - 29:23 = 25:37 spread 29:23 - 18:42 = 10:41 HOLDS (+14:56) + # The 24:48 low is same-suite runner variance, not a smaller suite: three consecutive push-to-main + # runs inside 2h42m gave windows-2025 34:15 / 24:48 / 34:29 while windows-2022 held a 1:00 band. + # + # RE-DERIVE IF a windows-2025 `Tests (pytest)` STEP is ever seen above 40:00, or if any Windows + # `test` JOB is ever seen above 50:00 -- those are the triggers, not a calendar reminder. Both are + # the 1.2x decay point of their cap (55:00 / 1.2 = 45:50, floored to 40:00 for margin against the + # measured drift; 66:00 / 1.2 = 55:00, floored to 50:00). The OLD trigger of 28:00 is retired + # because it was already universally exceeded: 58 of 59 passing steps on the day pool cleared it and + # the median itself sat above it, so it had become a permanently-tripped alarm, which is + # indistinguishable from no alarm at all. # # 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. + # distribution, not by its own duration. Both Windows legs take the same values, but they are sized + # from DIFFERENT legs and that asymmetry is deliberate: the STEP cap is sized on windows-2025 (the + # slower step, 35:47 censored against 29:23), while the JOB cap is sized on windows-2022 (the worse + # non-step addends, setup 4:05 against 2:32). An earlier revision said "sized on windows-2025 as the + # worse of the pair" without qualification -- that is FALSE for the job cap. # # 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 @@ -440,14 +498,56 @@ jobs: # 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) + # THE BAND MOVED OFF step_timeout AND ONTO THE OVERHEAD, 2026-08-08 (BACKLOG #1096). The earlier + # formula multiplied the WHOLE sum (step_timeout + addends) by ~1.13-1.16. That applies a safety + # band to `step_timeout`, which is a HARD BOUND the runner enforces -- the largest step overrun in + # 1,618 measured executions is EIGHT SECONDS (36:08 against a 36:00 cap). Banding it is slack for an + # event that cannot happen, it grows with the cap (4:41 at 36:00, 7:09 at 55:00), and it makes the + # published ratio pool-dependent because the step term dominates it. Corrected rule: + # + # job_timeout = step_timeout + ceil_minute(1.5 x that leg's worst measured job OVERHEAD) + # + # where overhead = job wall clock minus the `Tests (pytest)` step, taken as the larger of (a) the + # worst SAME-ROW overhead on non-cancelled rows and (b) that leg's setup(max) + web-console(max). + # The 1.5 band is on the overhead only, and is 1.5 rather than 1.35 because setup is hosted-runner + # provisioning outside this repo's control: `Set up job` alone has been observed at 4:30 (ubuntu run + # 31109989006, inside a 5:22 setup). + # + # leg worst same-row setup(max)+wc(max) overhead used x1.5 room job + # ubuntu 7:12 (n=451) 5:22 + 2:22 = 7:44 7:44 11:36 12:00 25+12 = 37 + # W22 6:16 (n=413) 4:05 + 2:51 = 6:56 6:56 10:24 11:00 55+11 = 66 + # W25 6:29 (n=372) 2:32 + 3:59 = 6:31 6:31 9:47 10:00 (takes W22's 66) + # + # INSTRUMENT PRESERVATION, the whole point of the pairing -- worst-case job wall built from + # independent maxima with `Tests` passing one second under its cap, new values against old: + # + # ubuntu 5:22 + 24:59 + 2:22 = 32:43 vs 37:00 +4:17 | old: 26:43 vs 26:00 -0:43 NEGATIVE + # W22 4:05 + 54:59 + 2:51 = 61:55 vs 66:00 +4:05 | old: 42:55 vs 46:00 +3:04 + # W25 2:32 + 54:59 + 3:59 = 61:30 vs 66:00 +4:30 | old: 42:30 vs 46:00 +3:30 + # + # UBUNTU WAS THE LEG ACTUALLY BROKEN, at -0:43, and nobody had measured it: BACKLOG #1096 was filed + # as a Windows problem. A negative row here means the JOB cap can fire before the STEP cap, and a + # job-level kill reports NO step conclusion -- so the instrument this item was measured with is + # destroyed exactly when it is needed. Max measured post-step teardown is 0:24, so all three new + # rows stay positive with room. + # + # NESTING INVARIANT, first gated step -- setup(max) + step_timeout must stay under job_timeout, so a + # `Tests` kill is a NAMED STEP failure rather than an unattributed job cancellation: + # ubuntu 5:22 + 25:00 = 30:22 < 37:00 (gap 6:38) + # W22 4:05 + 55:00 = 59:05 < 66:00 (gap 6:55) + # W25 2:32 + 55:00 = 57:32 < 66:00 (gap 8:28) + # + # 66 IS DERIVED, NOT ROUNDED UP FROM 55. The bare minimum whole minute that clears the worst sum is + # 61:00; it is rejected as thinner than any row this file has ever carried, and thinner than the + # three-addend model's own known error -- the worst observed single row sums to 40:16 against a real + # job wall clock of 40:22, so inter-step gaps make the model an UNDER-estimate by ~6s, not a + # conservative one. + # + # SUPERSEDED, kept because a number without its pool cannot be rechecked. The previous table read: + # ubuntu 19:00 + 2:00 + 1:20 = 22:20 (26:00, +3:40) | W22 36:00 + 2:33 + 1:09 = 39:42 (46:00, + # +6:18) | W25 36:00 + 3:33 + 1:20 = 40:53 (46:00, +5:07). Correct for its pool; superseded above. # - # 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 + # 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. @@ -634,9 +734,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":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}' + U='{"os":"ubuntu-latest","python-version":"3.14","hosted":["ubuntu-latest"],"job_timeout":37,"step_timeout":25,"pytest_timeout":60,"fault_timeout":90}' + W22='{"os":"windows-2022","python-version":"3.14","hosted":["windows-2022"],"job_timeout":66,"step_timeout":55,"pytest_timeout":120,"fault_timeout":150}' + W25='{"os":"windows-2025","python-version":"3.14","hosted":["windows-2025"],"job_timeout":66,"step_timeout":55,"pytest_timeout":120,"fault_timeout":150}' if [ "${GITHUB_REPOSITORY:-}" = "MEFORORG/MessageFoundry" ]; then echo "matrix={\"include\":[$U,$W22,$W25]}" >> "$GITHUB_OUTPUT" else diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index f0a496af..a2c397ab 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -195,7 +195,7 @@ Ordered by value descending, then difficulty ascending (cheapest first at equal | 16 | **#114** | Directory validation toggle (perform vs suppress startup validation) | 6 | 3 | _quick win_ | DEMAND-GATE | The remainder is worse than a missing toggle — `File(validate_directory=True)` on an outbound is accepted and silently ignored, so an operator asks for fail-fast and gets neither validation nor an error, with only the on-demand `POST /connections/{name}/test` probe as a workaround; the fix adds a `validate_startup` hook to the `DestinationConnector` contract (`transports/base.py:459`, which today exposes only `send` at `:480`) plus a runner outbound start-path call, mirroring the source seam already at `transports/base.py:436`. | | 17 | **#158** | Per-message dynamic FTP host/path/credentials | 6 | 3 | _quick win_ | DEMAND-GATE | Real dynamic-destination gap the shipped code closes off at both ends — host/credentials/`remote_dir` freeze at construction (`messagefoundry/transports/remotefile.py:626-627`) and `render_filename` is hard-capped to one path component (`messagefoundry/transports/file.py:105-127`), so a data-driven target subdirectory cannot be expressed by a static per-folder connection fan-out nor smuggled through the filename; awkward workaround, not a clean one. Build rides the already-shipped #68 per-message metadata carry (`messagefoundry/pipeline/wiring_runner.py:4526-4531`) plus a multi-component path sanitizer — a setting into one connector. | | 18 | **#328** | `audit-verify` cannot detect a truncated audit tail | 6 | 3 | _quick win_ | P2 | Both shipped verification surfaces call `verify_audit_chain()` bare (`messagefoundry/__main__.py:3596`, `pipeline/engine.py:860`) and the `audit-verify` subparser declares only `--service-config` and `--db` (`__main__.py:571-578`), so a truncated keyed chain — the residue the anchor exists to catch — reports CLEAN with no way for an operator to supply one; the remainder is a new `audit-anchor` subcommand, an `--expected-anchor` flag into the already-present `expected_anchor=` keyword, and an `[integrity]` key for the startup path, with no change to the comparison logic and no store migration. | -| 19 | **#344** | Fixed wall-clock bounds have drifted out of proportion to the work they bound | 6 | 3 | _quick win_ | P2 | A mechanical margin check would have flagged windows-2025 at 1.006x before #119 died where the manual alternative was published wrong twice, and the shared Windows budget still admits the three-PRs-each-adding-a-minute death nobody is individually at fault for; `_wait_until` already raises with a full dispatcher/store dump citing proposal 6 (`tests/test_stage_dispatcher.py:485-497`) and no margin script exists under `scripts/ci/`, so the remainder is that script — timing the STEP, keyed on the step's own conclusion, against a right-censored max — plus giving `Web console tests (pytest)` its own cap instead of the shared `matrix.step_timeout` at `ci.yml:442`. | +| 19 | **#344** | Fixed wall-clock bounds have drifted out of proportion to the work they bound | 6 | 3 | _quick win_ | P2 | A mechanical margin check would have flagged windows-2025 at 1.006x before #119 died where the manual alternative was published wrong twice, and the shared Windows budget still admits the three-PRs-each-adding-a-minute death nobody is individually at fault for; `_wait_until` already raises with a full dispatcher/store dump citing proposal 6 (`tests/test_stage_dispatcher.py:485-497`) and no margin script exists under `scripts/ci/`, so the remainder is that script — timing the STEP, keyed on the step's own conclusion, against a right-censored max — plus giving `Web console tests (pytest)` its own cap instead of the shared `matrix.step_timeout` in `ci.yml`. | | 20 | **#1006** | A mutation that matches is not a mutation that bites: the absence-claim gate proves syntax, never behaviour | 6 | 3 | _quick win_ | P2 | `check_absences` admits an ASVS absence claim on `re.search(a.pattern, a.mutation)` (`scripts/asvs/scorecard.py:395`) — one string field of a TOML row matched against another, with the corpus never consulted and the mutation never applied — so a well-formed, honestly-authored reintroduction that would change nothing if written into the code passes all three of the gate's failure modes and certifies a non-control into the record, a mode the `Absence` docstring did not anticipate even while it closed the adjacent one; the remainder is a required per-claim observable plus a mode that applies the mutation and requires that observable to go red, in one stdlib script and its fixture tests. | | 21 | **#1007** | Sweep all 345 ASVS cells for present-tense impact language — the record asserts live exposures that do not exist | 6 | 3 | _quick win_ | P2 | The scorecard's 146 residual-prose cells (~64,000 words) and the risk register's 55 signed cell rows were written before the owner ruled the product a not-deployed beta, so cells assert live exposures that do not exist — the "compensating control must not rest on a false premise" defect `docs/Secure_Development_Standards.md:98` forbids — with the only workaround a reader silently discounting every impact sentence by hand; the fix is a wording-only pass under a hard invariant (the `(id, verdict, level)` tuple set byte-identical before and after), a crude screen already sizes it at 77 of 146 candidates spanning every verdict class, one worked example has already landed vault-side, and it moves no verdict, touches no product surface and adds no dependency. | | 22 | **#1026** | The ASVS 12.1.1 TLS-floor probe silently does not run with the console off, and its own comment names three of its four conditions | 6 | 3 | _quick win_ | P2 | The probe's gate in `__main__.py` requires FOUR conditions — `tls_terminated_upstream and PHI and enforcing and public_origin` — while the comment directly above names three ("a declared terminator, PHI, and `enforce`") and asserts "every other posture never reaches here", so a reader concludes it runs whenever a PHI instance sits behind a declared terminator under enforce. The undocumented fourth is not self-satisfying: the refusal for an unset `public_origin` is itself gated on `serve_ui`, so with the console OFF nothing requires it, it keeps its `None` default (`config/settings.py:693`), and the probe silently never runs while the API is still off-loopback behind a terminator carrying PHI. ⭐ The same block `return 2`s when the probe's MECHANISM is unavailable, explicitly because "a check that degrades to a no-op when its mechanism disappears reports success forever afterwards" — it refuses a silent no-op one level down and performs one one level up (ADR 0158's class). Value 6: an ASVS 12.1.1 control inert in a legitimate posture with nothing reporting the skip. Difficulty 3 because the design choice is the work, not the code: require `public_origin` in that posture (adds a refusal to a posture that starts today), make the skip loud, or correct only the comment and leave the control inert. ⚠️ The originating report's mechanism was WRONG — it said the console "auto-degrades" so `public_origin` stays unset; the real link is that the requirement for `public_origin` is gated on `serve_ui`. | @@ -3245,7 +3245,7 @@ Two worked instances the same day. **#74** went green on 2026-07-30 and sat unme ## 344. Fixed wall-clock bounds have drifted out of proportion to the work they bound -> 🚧 **Status OPEN (filed 2026-08-01).** Value **6/10** · Difficulty **3/10** · _quick win_. A mechanical margin check would have flagged windows-2025 at 1.006x before #119 died where the manual alternative was published wrong twice, and the shared Windows budget still admits the three-PRs-each-adding-a-minute death nobody is individually at fault for; `_wait_until` already raises with a full dispatcher/store dump citing proposal 6 (`tests/test_stage_dispatcher.py:485-497`) and no margin script exists under `scripts/ci/`, so the remainder is that script — timing the STEP, keyed on the step's own conclusion, against a right-censored max — plus giving `Web console tests (pytest)` its own cap instead of the shared `matrix.step_timeout` at `ci.yml:442`. _(was 6/10 · 4/10.)_ +> 🚧 **Status OPEN (filed 2026-08-01).** Value **6/10** · Difficulty **3/10** · _quick win_. A mechanical margin check would have flagged windows-2025 at 1.006x before #119 died where the manual alternative was published wrong twice, and the shared Windows budget still admits the three-PRs-each-adding-a-minute death nobody is individually at fault for; `_wait_until` already raises with a full dispatcher/store dump citing proposal 6 (`tests/test_stage_dispatcher.py:485-497`) and no margin script exists under `scripts/ci/`, so the remainder is that script — timing the STEP, keyed on the step's own conclusion, against a right-censored max — plus giving `Web console tests (pytest)` its own cap instead of the shared `matrix.step_timeout` in `ci.yml`. _(was 6/10 · 4/10.)_ **Cluster:** Developer Experience & CI. **Priority:** P2. **Verdict:** build. **Severity:** medium. @@ -3267,7 +3267,7 @@ Fixed two ways in [`tests/test_stage_dispatcher.py`](../tests/test_stage_dispatc 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. +*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 55:22 (ubuntu) / 114:05 (Windows) (re-measured 2026-08-08 under the #1096 caps of 25/37 and 55/66; the earlier 39:24 / 73:21 was correct for the retired 19/26 and 36/46 pair). 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. @@ -3278,7 +3278,7 @@ What is NOT settled is the mechanism. Two independent passes reached different a 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()`.~~ **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. +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:59, n=360, 8-day pool, re-measured 2026-08-08; was 3:33 on the earlier pool) so `job_timeout` no longer has to absorb a budget that belongs to a step. Until then the nesting invariant `ci.yml` asserts is unenforceable for the second gated step on every leg — instance 3 is the worked example. 6. **Make a bound's expiry diagnostic before tuning it — and for instance 2 the instrument already ships.** A bare `assert await _wait_until(...)` reports `assert False` and nothing else, so every occurrence is re-diagnosed from scratch; instance 2 was read as latency for a day on exactly that basis. Have the helper raise on timeout carrying the lane's phase, park deadline and streak, whether its task is alive or holds an exception, the store row's status, and the clock. **One assertion settles instance 2's open mechanism:** `StageDispatcher.empty_claims` ([`stage_dispatcher.py`](../messagefoundry/pipeline/stage_dispatcher.py):1230) returns `(total, wake_fanout, idle_poll)` and is fed by `_record_empty`, called from exactly one site — the EMPTY branch of `_claim_and_dispatch` (:686). Under these tests' topology a clean run must read `(0, 0, 0)`, so `empty_claims[0] > 0` at the moment of failure is proof of a spurious EMPTY, and `== 0` is proof the claim never returned at all. A second, free signature is in the captured log, **for the infra-fault test only**: a healthy `test_adr0070_1_*` emits **four** `re-pending head with backoff` records (at `1001.000 / 1003.500 / 1008.000 / 1016.500`) and the failing run emitted **one**. It does NOT generalise — `test_adr0070_9_*` takes the content path, which uses `mark_failed` and never emits that line, so **zero** there is expected and is not a second mechanism. Read the counter, not the log, when in doubt. This proposal cannot itself be wrong about the cause, which is why it comes before the others. **Related:** [`.github/workflows/ci.yml`](../.github/workflows/ci.yml) §*Tests (pytest)* (instance 1 and its measurement table); [`tests/test_stage_dispatcher.py`](../tests/test_stage_dispatcher.py) (instance 2 — `_wait_until`'s raising expiry report and the counted `_wait_lane` sweep stand-in); [`store/sqlserver.py`](../messagefoundry/store/sqlserver.py) (`_is_lock_timeout` — the 1222-as-EMPTY yield that instance 2 turned on); ADR 0070 (the infra-fault machinery the affected tests cover); #320 (windows-2025 slowness — the capacity fact that shrinks every Windows margin); #340 (the other half of this triage); [`Secure_Development_Standards`](Secure_Development_Standards.md) §3 (prose asserting a margin the numbers do not support — five instances found on 2026-08-01 alone). @@ -6515,7 +6515,7 @@ The two "No" rows are the majority and the harder half. Root cause for the ancho ## 1096. The windows-2025 `Tests (pytest)` cap is exceeded: max passing step 35:13 against 36:00, and `main` is being killed by it -> 🔢 **Filed 2026-08-07 — not started.** Value **7/10** · Difficulty **3/10** · _quick win_. [`ci.yml`](../.github/workflows/ci.yml) sets `step_timeout: 36` for both Windows legs and, in the same comment block, names its own re-derivation trigger: *"RE-DERIVE IF a windows-2025 `Tests (pytest)` step is ever seen above 28:00 — that is the trigger, not a calendar reminder."* Measured 2026-08-07, **43 of 43** passing windows-2025 steps are above 28:00, the largest passing step is **35:13** (47 seconds of margin, 1.022x), and **five** executions were killed at 36:0x — **two of them `push` runs on `main`**. The trigger has not merely fired; it is universally exceeded, and the cap is now failing green suites. +> 🚧 **PARTLY SHIPPED 2026-08-08 — the caps are re-derived; the DRIFT underneath them is not fixed, and this item stays open for it.** Value **7/10** · Difficulty **3/10** · _quick win_. **What shipped:** all six values, in one act — `windows-2022`/`windows-2025` `step_timeout` **36 → 55** and `job_timeout` **46 → 66**; `ubuntu-latest` **19 → 25** and **26 → 37**. Ubuntu was changed because it was measurably the *next* instance and its job cap was **already negative** (−0:43 on measured maxima, meaning the job cap could fire before the step cap and destroy the very instrument this item was measured with) — this item was filed as a Windows problem and ubuntu had not been measured. The step cap is sized on windows-2025 (slower step); the **job** cap is sized on windows-2022 (worse setup, 4:05 vs 2:32), correcting a `ci.yml` sentence that claimed both were sized on windows-2025. The 28:00 re-derive trigger is retired for 40:00 (step) and 50:00 (job) — the old one had become permanently tripped, which is indistinguishable from no alarm. **What did NOT ship, and why this stays open:** all three legs' medians are rising monotonically, Windows at **+1:37 to +2:06 per day**, five to six times ubuntu's rate. At that rate the new trigger fires within days. This bought a working merge gate, not a stable one; the actual fix is **#320**, not a larger integer, and re-deriving weekly is the failure mode to avoid. **Do NOT rewrite the "43 of 43" figure below** — it is correct for its own 80-run pool and this item says so explicitly; the wider readings are recorded as separate measurements with their own pools. Original filing follows. [`ci.yml`](../.github/workflows/ci.yml) sets `step_timeout: 36` for both Windows legs and, in the same comment block, names its own re-derivation trigger: *"RE-DERIVE IF a windows-2025 `Tests (pytest)` step is ever seen above 28:00 — that is the trigger, not a calendar reminder."* Measured 2026-08-07, **43 of 43** passing windows-2025 steps are above 28:00, the largest passing step is **35:13** (47 seconds of margin, 1.022x), and **five** executions were killed at 36:0x — **two of them `push` runs on `main`**. The trigger has not merely fired; it is universally exceeded, and the cap is now failing green suites. **Cluster:** CI capacity / instrument accuracy. **Priority:** P1. **Verdict:** build. **Severity:** no product effect. The engine is unaffected; what is affected is the merge gate, which fails PRs that have nothing wrong with them and reds `main` at random. @@ -6549,7 +6549,7 @@ Killed at the cap (`Tests (pytest)` step conclusion `failure`, all at 36:0x): **Measure the STEP, and filter on the STEP.** Both mistakes are recorded in [`ci.yml`](../.github/workflows/ci.yml) as having already happened here — *"at least three sessions misread job durations as step durations while triaging this"*, and filtering on **job** conclusion drops the tightest steps by construction, because a step that nearly exhausts `step_timeout` is the most likely to push its job into `job_timeout`. A job-duration reading of this same pool gives 33 to 40 minutes and invites the wrong conclusion that the cap is comfortable. -**`job_timeout` must be re-derived in the same act.** The job carries **two** `step_timeout`-gated pytest steps — `Tests (pytest)` and `Web console tests (pytest)` — and [`ci.yml`](../.github/workflows/ci.yml) is explicit that the current `job_timeout: 46` is sized against the **observed sum**, not against `2 x step_timeout` (which would be 72 on Windows). Raising `step_timeout` without re-deriving `job_timeout` moves the kill from the step cap to the job cap, where it is **worse**: a job-level kill reports no step conclusion, so the next triage loses the instrument this item was measured with. +**`job_timeout` must be re-derived in the same act.** The job carries **two** `step_timeout`-gated pytest steps — `Tests (pytest)` and `Web console tests (pytest)` — and [`ci.yml`](../.github/workflows/ci.yml) is explicit that the current `job_timeout: 46` is sized against the **observed sum**, not against `2 x step_timeout` (which would be 110 on Windows under the caps this item set). Raising `step_timeout` without re-deriving `job_timeout` moves the kill from the step cap to the job cap, where it is **worse**: a job-level kill reports no step conclusion, so the next triage loses the instrument this item was measured with. **Scope note — the two failures on this leg today are DIFFERENT and must not be merged into one cause.** PR #253 is a genuine timeout (no test failed) and PR #256 (`fix-1013`) is an assertion failure in `tests/test_connscale_cpu_probe.py` and `tests/test_connscale_smoke.py`, whose own comment already records this leg failing twice in one job on 2026-07-30. Only the first belongs to this item. diff --git a/docs/adr/0158-silent-controls-green-signals-that-mean-nothing-and-shape-over-detection.md b/docs/adr/0158-silent-controls-green-signals-that-mean-nothing-and-shape-over-detection.md index 7ce27238..96b2c2f9 100644 --- a/docs/adr/0158-silent-controls-green-signals-that-mean-nothing-and-shape-over-detection.md +++ b/docs/adr/0158-silent-controls-green-signals-that-mean-nothing-and-shape-over-detection.md @@ -456,9 +456,16 @@ credits "the session that hit four instances of the same class in one day": four - [ ] Restate [`ci.yml`](../../.github/workflows/ci.yml)'s margin block with a defined pool. Three independent re-measurements returned 35, 36 and 38 under different predicates; none is the stated 11. Decide the pool definition and record the filter beside the number. -- [ ] Decide whether the 36:00 Windows step cap clears the population spread, and against which - anchor: over the maximum passing step (25:51) the headroom is 10:09 and clears the 9:55 spread; - over the cap-kill (26:07, a failed step in no success pool) it is 9:53 and does not. +- [x] **Decided 2026-08-08 (BACKLOG #1096): the 36:00 cap did NOT clear the spread, and it has been + re-derived to 55:00.** The question asked which anchor to size against, and the answer is the + censored one: at 36:00 the headroom over the maximum passing step (35:47) was 19:13 against an + 11:59 spread on paper, but the cap-kill anchor is the honest one because windows-2025 was killed + at the cap **seven times** in an eight-day pool, so 35:47 is the largest step that FIT and 36:08 + is a lower bound on what the suite wants. Against that anchor 36:00 had *negative* headroom. At + 55:00 the rule holds on both Windows legs (windows-2025 +8:14, windows-2022 +14:56). The kills + were also confirmed to be **slowness, not a wedge** -- one kill log shows pytest finishing green + at 35:48 and the step killed 4.85s later -- which is what makes the killed rows genuine + population members rather than outliers to discard. - [ ] Correct or drop the table rows now known to be single-run values or job-filtered maxima (`24:35` and its `1.46x`, ubuntu `12:27`, windows-2022 `18:39`). - [ ] Apply the retraction already filed in `docs/BACKLOG.md` under BACKLOG #323 to the false