Skip to content

fix(test): /ws/stats tests slept 50 ms and hoped — poll the condition instead - #58

Merged
wshallwshall merged 1 commit into
mainfrom
claude/fix-ws-stats-first-frame-race
Jul 29, 2026
Merged

fix(test): /ws/stats tests slept 50 ms and hoped — poll the condition instead#58
wshallwshall merged 1 commit into
mainfrom
claude/fix-ws-stats-first-frame-race

Conversation

@wshallwshall

Copy link
Copy Markdown
Collaborator

main is red. test (windows-2022, py3.14) failed at be2fc08c — the squash-merge of #56, whose own head was 33/33 green:

assert harness.frames, "expected at least one stats frame before revocation"
AssertionError: assert []

Not the merged change: #56 touched TLS key-exchange policy, an OIDC settings validator and docs, none of which this route reaches. The test is defective — and deliberately not treated as a flake to re-run, because this repo has already mistaken a livelock for one and no rerun or timeout ever fixed that.

The defect

The first frame cannot be sent until store.stats() returns — the route awaits it, builds the frame, then sends. The fixed 50 ms sleep had to cover that query plus scheduling the harness task, the handshake, and the handshake-time authorize. None of which these tests measure. It passes locally 3/3, in 10.06s / 12.33s / 3.89s — and that spread is the tell.

Replaced with _wait_for_first_frame, a bounded poll on the condition actually being asserted. This does not weaken the precondition: a frame is still required, and still required before the revocation. It also separates a dead task from a slow one (task.result() re-raises the real failure), because a route that blew up would otherwise look identical to a loaded runner.

A second, quieter defect

test_disabled_account_is_closed also slept 50 ms, and asserts only close_code == 1008 — which both the mid-stream revalidation and the pre-first-send re-check produce. So on a slow box the account was disabled before the first send, the close came from the wrong path, the assertion still held, and the test silently stopped covering what its comment claims while duplicating test_revoke_before_first_send_yields_no_frames. A coverage move with no symptom. It now waits for a frame, so "mid-stream" is a fact.

Making the CI failure reproducible

test_a_slow_first_stats_build_does_not_break_the_precondition stalls store.stats() to 0.4s — 8× the old budget — so the old form fails on any machine. That is the property the original failure never had: it only reproduced on a loaded Windows runner, which is not something you can iterate against.

mutation result
M1 restore await asyncio.sleep(0.05) slow-stats regression test RED (1 failed)
M1, second half test_disabled_account_is_closed stays GREEN — the silent coverage move, demonstrated rather than argued
M2 _FIRST_FRAME_TIMEOUT = 0.0 3 failed — so the wait is load-bearing, not decorative

Timeouts

First-frame wait 10s; harness budget raised 5s → 20s, because the harness must outlive the wait plus the close it then waits for, or it times out mid-wait and the failure points at the route instead of the clock. Both sit inside the 60s pytest timeout, which stays the real backstop against a hang.

Verification

ruff check · ruff format --check · mypy --strict · full suite 9636 passed, 719 skipped. The one failure is the pre-existing environmental test_installed_metadata_matches_dunder_version (editable metadata 0.3.0 vs __version__ 0.3.2; its own comment names the case and the remedy).

… instead

main is RED. `test (windows-2022, py3.14)` failed at be2fc08, the squash-merge
of PR #56, whose own head was 33/33 green:

    assert harness.frames, "expected at least one stats frame before revocation"
    AssertionError: assert []

Not the merged change -- PR #56 touched TLS key-exchange policy, an OIDC settings
validator and docs, none of which this route reaches. The test is defective, and
this is deliberately NOT being treated as a flake to re-run: this repo has
already mistaken a livelock for one, and no rerun or timeout ever fixed that.

The defect: the first frame cannot be sent until `store.stats()` returns -- the
route awaits it, builds the frame, then sends -- and the fixed 50 ms sleep had to
cover that query PLUS scheduling the harness task, the handshake, and the
handshake-time authorize. None of which these tests measure. It passes locally
3/3 in 10.06s, 12.33s and 3.89s, and that spread is the tell.

Replaced the sleep with `_wait_for_first_frame`, a bounded poll on the ACTUAL
asserted condition. This does not weaken the precondition: a frame is still
required, and still required BEFORE the revocation. It also distinguishes a dead
task from a slow one -- `task.result()` re-raises the real failure, because a
route that blew up would otherwise be indistinguishable from a loaded runner, and
"timed out waiting for a frame" is the least useful description of a traceback.

A SECOND, quieter defect fixed at the same time. test_disabled_account_is_closed
also slept 50 ms and asserts only `close_code == 1008` -- which BOTH the
mid-stream revalidation and the pre-first-send re-check produce. So on a slow box
the account was disabled before the first send, the close came from the wrong
path, the assertion still held, and the test silently stopped covering what its
comment claims while duplicating what
test_revoke_before_first_send_yields_no_frames already owns. A coverage move with
no symptom. It now waits for a frame, so "mid-stream" is a fact.

New test_a_slow_first_stats_build_does_not_break_the_precondition makes the CI
failure DETERMINISTIC: it stalls `store.stats()` to 0.4s, 8x the old budget, so
the old form fails on any machine. That is the property the original failure
never had -- it only reproduced on a loaded Windows runner, which is not
something you can iterate against.

Two mutations, and the second half of the first is the interesting one:

  M1  restore `await asyncio.sleep(0.05)`
        -> the slow-stats regression test RED (1 failed)
        -> and test_disabled_account_is_closed stays GREEN (1 passed), which is
           the silent-coverage-move demonstrated rather than argued
  M2  `_FIRST_FRAME_TIMEOUT = 0.0`
        -> 3 failed, so the wait is load-bearing and not decorative

Timeouts: the first-frame wait is 10s and the harness budget is raised 5s -> 20s,
because the harness must outlive the wait PLUS the close it then waits for, or it
would time out mid-wait and the failure would point at the route instead of the
clock. Both sit inside the 60s pytest timeout, which stays the real backstop
against a hang.

Full suite 9636 passed / 719 skipped; the one failure is the pre-existing
environmental test_installed_metadata_matches_dunder_version (editable metadata
0.3.0 vs __version__ 0.3.2 -- its own comment names the case and the remedy).
@wshallwshall
wshallwshall merged commit df60771 into main Jul 29, 2026
32 checks passed
@wshallwshall
wshallwshall deleted the claude/fix-ws-stats-first-frame-race branch July 29, 2026 23:27
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant