Skip to content

fix(ci): read the ci-red label back, and unflake the arm that ejected PR 669 (BACKLOG #1385) - #789

Merged
wshallwshall merged 2 commits into
mainfrom
claude/1385-ci-red-reader-and-timeout-flake
Sep 4, 2026
Merged

fix(ci): read the ci-red label back, and unflake the arm that ejected PR 669 (BACKLOG #1385)#789
wshallwshall merged 2 commits into
mainfrom
claude/1385-ci-red-reader-and-timeout-flake

Conversation

@wshallwshall

@wshallwshall wshallwshall commented Sep 3, 2026

Copy link
Copy Markdown
Collaborator

Closes two limbs of BACKLOG #1385, finds a third already closed by someone else, and corrects the item's own run census.

What I re-measured at HEAD before touching anything

Claim in the brief Verdict
failure-signal.yml:71 recovers the PR number from a merge_group ref, :92 applies ci-red Confirmed, both lines exact
Nothing in this tree READS ci-red Confirmed. Grep returned the writer plus prose at CLAUDE.md:302, docs/METHOD.md:365, zizmor.yml:72 and backlog text. No reader
ci.yml:852 passes --max-worker-restart=0, landed 042ef7ff5, comment :826-:850 records four hangs of 25-46 min Confirmed, all exact
tests/test_multipart.py:142 is a ratio assertion Confirmed. Left alone per the brief -- but see the open question below
tests/test_sqlserver_store.py:4039 is test_cipher_invocations_upsert_is_atomic_and_additive Confirmed, and it runs at ci.yml:1772 under the native-crash-only wrapper at :1769

The census in #1385 is wrong by one, and my first query reproduced the error

There were four failing merge_group CI runs on PR 669, not three. An unpaginated per_page=100 query returns 100 of total_count 190 and silently drops half the population -- I hit that trap myself and nearly published "the timeout test appears nowhere in the failures", which is false. --paginate gives the real set. Each row below is read from that job's own log, not inferred:

run id failing job failing test
11:15:01Z 33249679477 test (windows-2025) hung 55 min, no FAILED line
11:37:13Z 33250553925 test (windows-2025) test_a_fast_handler_is_untouched -- assert 503 == 200
12:42:51Z 33253197221 windows + sql server 2022 hostile-disposition ratio; cipher-invocations upsert
13:01:54Z 33253973185 windows + sql server 2025 dr/connscale; cipher-invocations upsert

"Three DIFFERENT reasons with no overlap" is not what the logs say. The SQL Server test failed in both of the last two runs, identically. The no-overlap claim held only across the three runs the original pass happened to sample.

Limb 1 -- the request-timeout wall clock

test_a_fast_handler_is_untouched is not a hypothetical flake: it is the arm that ejected PR 669 at 11:37, with assert 503 == 200. A trivial handler's real cost is ~1ms, so 0.1s was never a margin -- it is inside the range of a GC pause on a shared runner.

The new bound is 5.0s, and it still discriminates. Tightness was never what that arm measured. Its job is to catch a middleware that refuses everything; a 5s deadline catches that identically. The claim that the configured value is in force is carried by the trips arms, and carried better -- a 3.0s handler under a 0.1s deadline reds if the middleware ever falls back to the shipped 120s default, which no fast-path assertion at any deadline can see. The arms asserting the bound fires keep 0.1s, because there a stall can only delay a refusal, never turn it into a pass.

I also found an arm that could not fail for its stated reason. test_a_disabled_deadline_lets_a_slow_handler_finish asked the fast route, so it passed identically with the control it exists to test switched on. It asks the slow route now.

Mutation numbers

# Mutation Result
A RequestTimeoutMiddleware refuses unconditionally 3 failed, 6 passed -- reds test_a_fast_handler_is_untouched at the new 5.0s bound
B Clamp a <= 0 deadline to 0.1 instead of disabling 1 failed, 8 passed with the new slow-route body
B-control Same mutation, old fast-route body, one variable changed 9 passed -- the mutation was completely invisible
C Drop the event != "merge_group" gate in _pr_for_run 1 failed, 14 passed -- reds the spoof test
D Count cancelled as a red 1 failed, 14 passed -- reds the cancellation test

B and its control are the load-bearing pair: same mutation, same everything else, only the requested route differs.

Limb 2 -- already fixed by #738, nothing rebuilt

Established from the log, not guessed. Both SQL Server failures are:

messagefoundry.store.base.StoreAcquireTimeout: sqlserver: store pool acquire timed out after 30s

raised from the asyncio.gather of 20 concurrent add_cipher_invocations at tests/test_sqlserver_store.py:4049. The cause is the aioodbc pool sharing the event loop's default executor -- 8 threads on a 4-vCPU runner -- against a pool_size of 40, so 20 concurrent upserts park inside a blocked execute and the lock holder's own commit queues behind them with no worker left.

cc5e09e1e (2026-09-02, PR #738) gave the store its own executor sized maxsize + 4. Its commit message names this exact test and this exact error. It is an ancestor of HEAD (checked). No SQL Server leg failure appears in the completed CI runs I sampled since it landed -- the two failures in that window were repo harness tests and web console tests, neither on this leg.

Limb 3 -- the reader, proven firing

scripts/ci/report_ci_red.py reads the label back and names the run, marking merge_group runs as NOT VISIBLE ON THE PR PAGE. That mark is the finding: it is the state PR 669 was in for three CI cycles.

It copies three rules from the writer deliberately, because a reader that classifies differently reports causes the label was never applied for: the watched workflow list, failure-only (a cancelled run is not a red -- an ejection cancels its siblings), and the attribution order -- pull_requests[0] first, then the pr-<N> ref parse gated on event == "merge_group". That gate is a security control, not tidiness: a branch name is chosen by whoever opens the branch, and a fork cannot raise a merge_group event. Two tests read failure-signal.yml itself rather than restating its list, so they cannot pass by agreeing with a stale copy.

Live proof, not just unit tests. Run against this repository it found PR 764, attributed it to backlog-hygiene run 33802457076, exit 1 -- and I verified that attribution against the API rather than trusting my own output (event=pull_request, pull_requests=[764], PR 764 does carry the label). Run against PR 669's real captured runs, with the label state constructed:

ci-red: 1 open pull request(s) carry ci-red; scanned 15 run(s) for attribution
::warning::#669 ... -- CI failed [merge_group -- NOT VISIBLE ON THE PR PAGE] .../runs/33253973185
::error::1 pull request(s) were reddened by a merge_group run. Their own checks can read GREEN ...

Open questions for the Console

  1. The hostile-disposition test is the one limb still unaddressed, and the brief waved it through. I left it alone as instructed, but the reason given does not survive the log. It was dismissed as "already a ratio assertion". It is one, and it ejected PR 669 anyway: ratio 8.02 against a bound of 8.0, a 0.25 percent margin. The best-of-3 sampling it relies on landed 2026-07-28 in db53fd45d, so the code that failed is the code in the tree today. Being a ratio rather than a wall-clock budget did not save it. This needs its own read.
  2. Nothing schedules the new reader. It is a script the Console runs, deliberately -- #1413's notes record that a workflow applying the label was already rejected as fail-open, and #1403 defers the watcher to wshallwshall/claude-multisession#108. If you want it on a cron, that is a separate decision.
  3. fix(store): the SQL Server pool shared the loop's executor and could deadlock on it #738's own note flags a residual. MERGE ... WITH (HOLDLOCK) on this path has no UPDLOCK and no 1205 retry, and five other MERGE HOLDLOCK sites would need the same read. Raising real concurrency could turn the fixed deadlock into a deadlock-victim flake. Out of scope here, unfiled.

Checks

Ran, all green: ruff check ., ruff format --check ., mypy messagefoundry messagefoundry_webconsole --exclude 'messagefoundry/tray/' (283 files, exactly as ci.yml:417 runs it), the full pre-commit hook set on the changed files, and pytest on test_api_request_timeout.py, test_ci_red_reader.py, test_failure_signal.py, test_ci_tooling_gate.py (57 passed) plus the citation and required-context gates (94 passed). Also green: the gates that ENUMERATE scripts/, since this PR adds a file there -- test_cp1252_console_safety.py (its scope is scripts/**/*.py), test_negative_controls.py, test_merge_gate_controls.py, test_backlog_status_check.py, test_conftest_name_collision_guard.py (110 passed).

Did not run: the full suite. I also started the 2879-test -m tooling sweep and it did not produce a usable result -- it ended in a subprocess.communicate timeout with no pytest summary line at all. Its harness annotation reads exited with code 0, and that is not a pass: the code answers a different question than the one asked, which is the SDS-3.8 trap, so I am not reporting it as green. The captured output was truncated to the tail, so I cannot name the test that hung and will not guess at one.

It is not this change. No test in the suite executes the scripts it enumerates -- test_serverdb_ci_coverage.py:91-99 reads scripts/ci/** as text, and the other enumerating gates do the same -- so the new script cannot be the subprocess that timed out. Checked directly by running every gate that globs scripts/: test_cp1252_console_safety.py, test_serverdb_ci_coverage.py, test_dast_claims.py, test_sds_rule_ids_are_stable.py -- all green (47 passed in the last three, plus the 110 above). No workflow or branch-protection change here, so .github/required-contexts.txt and the pinned count in tests/test_required_contexts.py are untouched and that test passes.

Legs a reader must check after my process exits, since none of them are reachable from a Builder's turn: sql server (store + connector) on both 2022 and 2025, test (windows-2025, py3.14), windows-service-smoke, and the merge_group runs themselves -- which is, with some irony, exactly the blind spot this PR is about.

🤖 Generated with Claude Code

… PR 669 (BACKLOG #1385)

THE CENSUS IN #1385 IS WRONG BY ONE. There were FOUR failing merge_group CI runs on PR 669, not
three. An unpaginated per_page=100 query returns 100 of total_count 190 and silently drops half the
population; --paginate finds 33249679477, 33250553925, 33253197221 and 33253973185. Each is
attributed below from its own job log, not inferred.

  11:15:01Z  test (windows-2025)          hung 55 min, no FAILED line
  11:37:13Z  test (windows-2025)          test_a_fast_handler_is_untouched -- assert 503 == 200
  12:42:51Z  windows + sql server 2022    hostile-disposition ratio; cipher-invocations upsert
  13:01:54Z  windows + sql server 2025    dr/connscale; cipher-invocations upsert

So "three DIFFERENT reasons with no overlap" is not what the logs say: the SQL Server test failed in
BOTH of the last two runs, identically.

TWO THINGS BUILT.

1. tests/test_api_request_timeout.py. The 0.1s deadline is gone from the arms asserting a prompt
   handler is UNTOUCHED -- the arm that actually ejected #669 at 11:37 with assert 503 == 200. A
   trivial handler's real cost is ~1ms, so 0.1s was not a margin, it was inside the range of a GC
   pause on a shared runner. The arms asserting the bound FIRES keep 0.1s, because there the margin
   runs the forgiving way: a stall can only delay a refusal, never turn it into a pass.

   Raising it costs no discrimination, and that is checked rather than asserted. Mutation A (refuse
   unconditionally) reds test_a_fast_handler_is_untouched at the new 5.0s deadline: 3 failed, 6
   passed.

   While in the file: test_a_disabled_deadline_lets_a_slow_handler_finish asked the FAST route, so it
   could not fail for its stated reason. It asks the slow route now. Proven with a controlled arm --
   Mutation B (clamp a disabled deadline instead of disabling it) with the NEW body reds 1 of 9; with
   the OLD body, same mutation, 9 passed. One variable, mutation held constant.

2. scripts/ci/report_ci_red.py plus 15 tests. failure-signal.yml has written the ci-red label since
   PR #716 and nothing read it. This reads it back and names the run, marking merge_group runs as
   NOT VISIBLE ON THE PR PAGE -- which is the finding, because that is the state PR 669 was in.

   It copies three rules from the writer on purpose: the watched workflow list, failure-only (a
   cancelled run is not a red), and the attribution order -- pull_requests[0] first, then the pr-<N>
   ref parse GATED ON event == merge_group. That gate is a security control: a branch name is chosen
   by whoever opens the branch, and a fork cannot raise a merge_group event. Mutation C (drop the
   gate) reds the spoof test; mutation D (count cancelled) reds the cancellation test.

   Proven firing, not just unit-tested. Live against this repo it found PR 764, attributed it to
   backlog-hygiene run 33802457076, exit 1 -- verified against the API (event=pull_request,
   pull_requests=[764]). Against PR 669's real captured runs it reports the merge_group ejection and
   the hidden-run error.

ALREADY FIXED BY #738, NOT REBUILT HERE. test_cipher_invocations_upsert_is_atomic_and_additive failed
StoreAcquireTimeout after 30s because the aioodbc pool shared the loop's default executor (8 threads
on a 4-vCPU runner) against pool_size 40, so 20 concurrent upserts deadlocked on the executor queue.
cc5e09e (2026-09-02) gave the store its own executor and names this exact test and error.

STILL OPEN. test_hostile_disposition_header_parses_in_linear_time was waved through as "already a
ratio assertion". It is one, and it ejected #669 anyway, at ratio 8.02 against a bound of 8.0. Left
alone per the brief; recorded in the item because the dismissal does not survive the log.

ruff, ruff format and mypy strict clean; 57 tests green across the touched and neighbouring suites.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@wshallwshall wshallwshall added the reviewed A reviewer has read this. Removed automatically when new commits arrive. label Sep 3, 2026
@github-actions github-actions Bot added the ci-red A required check went red. Attribute it before retrying. label Sep 4, 2026
tests/test_tooling_partition.py::test_every_non_engine_test_is_classified reds
all three required test legs when a test that does not import the engine is
absent from tests/tooling_manifest.txt. This PR adds such a test, so CI could
not go green as it stood.

The manifest is read as a set, so this is a single inserted line at its
alphabetical slot; no existing line moves.
@wshallwshall

Copy link
Copy Markdown
Collaborator Author

Lander: added the missing tests/tooling_manifest.txt line for the test this PR introduces.

tests/test_tooling_partition.py::test_every_non_engine_test_is_classified reds all three required
test legs when a test that does not import the engine is absent from the manifest, and it is not
marked tooling, so -m 'not tooling' does not deselect it. This PR could not go green as it stood.

Verified before pushing: the test fails on the previous head naming this exact file, and passes with
the line added. The manifest is read as a set(), so the change is one inserted line at its
alphabetical slot -- no existing line moves.

Re-applied the reviewed label, which the push stripped.

@github-actions github-actions Bot removed the reviewed A reviewer has read this. Removed automatically when new commits arrive. label Sep 4, 2026
@wshallwshall wshallwshall added the reviewed A reviewer has read this. Removed automatically when new commits arrive. label Sep 4, 2026
@wshallwshall
wshallwshall added this pull request to the merge queue Sep 4, 2026
Merged via the queue into main with commit 8d16c0b Sep 4, 2026
69 of 71 checks passed
@wshallwshall
wshallwshall deleted the claude/1385-ci-red-reader-and-timeout-flake branch September 4, 2026 17:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ci-red A required check went red. Attribute it before retrying. reviewed A reviewer has read this. Removed automatically when new commits arrive.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant