From d6722cdaf9a05a65f7edcf261b512e2db5672ae2 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Wed, 29 Jul 2026 18:05:32 -0500 Subject: [PATCH] =?UTF-8?q?fix(test):=20/ws/stats=20tests=20slept=2050=20m?= =?UTF-8?q?s=20and=20hoped=20=E2=80=94=20poll=20the=20condition=20instead?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit main is RED. `test (windows-2022, py3.14)` failed at be2fc08c, 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). --- tests/test_ws_stats_revalidation.py | 100 ++++++++++++++++++++++++++-- 1 file changed, 95 insertions(+), 5 deletions(-) diff --git a/tests/test_ws_stats_revalidation.py b/tests/test_ws_stats_revalidation.py index 18c7f44e..28989476 100644 --- a/tests/test_ws_stats_revalidation.py +++ b/tests/test_ws_stats_revalidation.py @@ -105,6 +105,56 @@ async def _login_token(service: AuthService, username: str) -> str: return (await service.login(username, PW)).token +#: Bound on waiting for the server's FIRST stats frame. Generous on purpose: this is a scheduling wait +#: on a possibly-loaded CI runner, not a behavioural timeout. The pytest-level timeout (60 s) is the +#: real backstop against a hang, and the deliberately-slow-`stats()` regression test below is what +#: proves the wait is load-bearing rather than decorative. +_FIRST_FRAME_TIMEOUT = 10.0 + +#: The harness's own budget must exceed the first-frame wait PLUS the close it then waits for, or the +#: harness would time out while we were still legitimately waiting and the failure would point at the +#: route instead of at the clock. +_HARNESS_TIMEOUT = 20.0 + + +async def _wait_for_first_frame(harness: _WSHarness, task: asyncio.Task[None]) -> None: + """Wait until the server has actually sent a frame, instead of sleeping a fixed 50 ms and hoping. + + The fixed sleep was a race, and it FAILED on `main` @ ``be2fc08c``, ``test (windows-2022, + py3.14)``:: + + assert harness.frames, "expected at least one stats frame before revocation" + AssertionError: assert [] + + 50 ms had to cover scheduling the harness task, the handshake, the handshake-time authorize *and* + the ``store.stats()`` query the first frame is built from — none of which these tests are + measuring. Polling the **actual asserted condition** makes the precondition deterministic without + weakening it: a frame is still required, and still required *before* the revocation. It also makes + what the test exercises deterministic, which the sleep did not — on a slow box the revocation + landed before the first send, silently exercising the pre-first-send path that + ``test_revoke_before_first_send_yields_no_frames`` already owns. + + If the task dies first, surface THAT: a route that raised would otherwise be indistinguishable + from a slow one, and "timed out waiting for a frame" is the least useful description of a + traceback. + """ + loop = asyncio.get_running_loop() + deadline = loop.time() + _FIRST_FRAME_TIMEOUT + while not harness.frames: + if task.done(): + task.result() # re-raise the real failure if the route blew up + raise AssertionError( + f"the /ws/stats task finished before sending any frame " + f"(close_code={harness.close_code})" + ) + if loop.time() >= deadline: + raise AssertionError( + f"no stats frame within {_FIRST_FRAME_TIMEOUT}s " + f"(close_code={harness.close_code}, frames={harness.frames})" + ) + await asyncio.sleep(0.01) + + async def test_revoked_session_is_closed_promptly( engine: Engine, monkeypatch: pytest.MonkeyPatch ) -> None: @@ -114,9 +164,9 @@ async def test_revoked_session_is_closed_promptly( token = await _login_token(service, "op") app = create_app(engine, auth=service) harness = _WSHarness(app, token) - task = asyncio.create_task(harness.run(timeout=5.0)) - # let the first frame land, then revoke the session server-side - await asyncio.sleep(0.05) + task = asyncio.create_task(harness.run(timeout=_HARNESS_TIMEOUT)) + # Wait for the first frame to actually land, then revoke the session server-side. + await _wait_for_first_frame(harness, task) assert harness.frames, "expected at least one stats frame before revocation" await service.revoke_sessions_for_user(uid, actor="admin") await task @@ -130,14 +180,54 @@ async def test_disabled_account_is_closed(engine: Engine, monkeypatch: pytest.Mo token = await _login_token(service, "op") app = create_app(engine, auth=service) harness = _WSHarness(app, token) - task = asyncio.create_task(harness.run(timeout=5.0)) - await asyncio.sleep(0.05) + task = asyncio.create_task(harness.run(timeout=_HARNESS_TIMEOUT)) + # Wait for a frame first, so "mid-stream" is a fact rather than an aspiration. With the old fixed + # sleep this test still PASSED on a slow box while exercising the wrong path — the account was + # disabled before the first send, so the close came from the pre-first-send re-check instead of the + # mid-stream revalidation. Same 1008 either way, so nothing failed and the coverage quietly moved. + await _wait_for_first_frame(harness, task) # disable the account mid-stream → identity_for_token returns None → the feed must close await engine.store.set_user_disabled(uid, disabled=True) await task assert harness.close_code == 1008 +async def test_a_slow_first_stats_build_does_not_break_the_precondition( + engine: Engine, monkeypatch: pytest.MonkeyPatch +) -> None: + """Reproduce the CI failure deterministically, so the fix is proven rather than observed. + + The first frame cannot be sent until ``store.stats()`` returns — the route awaits it, builds the + frame, then sends. The old fixed 50 ms sleep had to cover that query *plus* task scheduling, the + handshake and the handshake-time authorize. Stall the query well past 50 ms and the old form fails + **every time** instead of once per loaded runner. + + This is the property the original flake never had: revert ``_wait_for_first_frame`` to + ``await asyncio.sleep(0.05)`` and this test goes red on any machine, which is why it is worth more + than a green CI run. A load-dependent failure that only reproduces on a busy Windows runner is not + something you can iterate against. + """ + real_stats = engine.store.stats + + async def slow_stats() -> dict[str, int]: + await asyncio.sleep(0.4) # 8x the old budget — deterministic on any machine + return await real_stats() + + monkeypatch.setattr(engine.store, "stats", slow_stats) + monkeypatch.setattr(app_module, "_WS_REVALIDATE_SECONDS", 0.1) + service = await _service(engine) + uid = await _add(service, "op", Role.OPERATOR) + token = await _login_token(service, "op") + app = create_app(engine, auth=service) + harness = _WSHarness(app, token) + task = asyncio.create_task(harness.run(timeout=_HARNESS_TIMEOUT)) + await _wait_for_first_frame(harness, task) + assert harness.frames, "the slow stats build must still yield a frame, just later" + await service.revoke_sessions_for_user(uid, actor="admin") + await task + assert harness.close_code == 1008 + + async def test_revoke_before_first_send_yields_no_frames( engine: Engine, monkeypatch: pytest.MonkeyPatch ) -> None: