From 2010e17c0f70b728be5012a93431e6e25a4c891e Mon Sep 17 00:00:00 2001 From: Scott Hall Date: Mon, 19 Oct 2026 17:55:15 -0500 Subject: [PATCH 1/3] test_ui_dr_outlive holds the drain and retries a deadline that beat the release (BACKLOG #3871) The console DR release test set a 0.2 s request deadline and asserted the release finished once outliving_operations.inflight was empty. The deadline is wall time from the start of the request, so when the auth dependencies alone outlasted 0.2 s the 503 came before the handler reached outliving.run: nothing was ever registered, the wait loop exited at once, and coord.active was still True. The failed CI log shows only the request-timeout warning, never outlive.run's "caller was cancelled" one. Reproduced 1 in 200 serial runs locally, and every time with the first step-up check slowed by 0.5 s. The drain now blocks on an event until the 503 is in, so it cannot finish first. An attempt that registered nothing (and never reached the drain) is retried with twice the deadline, up to 6.4 s, then fails loudly. The test asserts the release is still running when the deadline answers, then lets the drain end and waits for the operation itself. No product change: a deadline that fires before the release begins leaves the box active with nothing half done, which is correct. Proposed PR title: test_ui_dr_outlive waits on the coordinator, not wall time (BACKLOG #3871) --- .../tests/test_ui_dr_outlive.py | 62 +++++++++++++++---- 1 file changed, 49 insertions(+), 13 deletions(-) diff --git a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py index 14f9be7840..3f0239a439 100644 --- a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py +++ b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py @@ -5,8 +5,15 @@ ``/ui/dr/release`` calls the engine's own ``dr_release`` handler in process, so the deadline that cuts the console's request off is the same middleware, around the same handler. This drives the -console route with the deadline patched down and a drain that outlasts it, and checks the release -still completes and records its row: the protection the handler carries reaches the console too. +console route with the deadline patched down and a drain held open until the deadline has answered, +and checks the release still completes and records its row: the protection the handler carries +reaches the console too. + +The deadline is wall time from the start of the request, so on a loaded runner the auth +dependencies alone can outlast it. The 503 then comes before the handler ever starts the release, +and there is nothing to outlive (vault BACKLOG #3871). Such an attempt proves nothing, so the test +retries it with a longer deadline. It never waits on wall time for the outcome: the drain does not +end until the test lets it, and the test then waits for the operation itself to finish. """ from __future__ import annotations @@ -51,26 +58,55 @@ async def test_a_console_release_cut_off_by_the_deadline_still_completes( coord._active = True dr_engine._dr_active = True - async def slow_drain() -> dict[str, object]: - await asyncio.sleep(0.6) # outlasts the 0.2 s deadline below + drain_started = asyncio.Event() + let_drain_end = asyncio.Event() + + async def held_drain() -> dict[str, object]: + drain_started.set() + # Held until the deadline has answered, so the drain cannot end first however slow the + # request was to reach the handler. + await let_drain_end.wait() dr_engine._dr_active = False return {"depth_left": 0} - coord._deactivate_profile = slow_drain + coord._deactivate_profile = held_drain service = await auth_service(dr_engine) await provision(service, "boss", ["administrator"]) app = create_app(dr_engine, auth=service, serve_ui=True) + outliving = app.state.outliving_operations + loop = asyncio.get_running_loop() async with httpx.AsyncClient(transport=httpx.ASGITransport(app=app), base_url="http://t") as c: await cookie_login(c, "boss") - # After the login: its password hash alone outlasts the deadline set here. - app.state.request_timeout_seconds = 0.2 - r = await c.post("/ui/dr/release", headers=SAME_ORIGIN) - assert r.status_code == 503 - - deadline = asyncio.get_running_loop().time() + 10 - while app.state.outliving_operations.inflight: - assert asyncio.get_running_loop().time() < deadline, "the release never finished" + # After the login: its password hash alone outlasts the deadline set here. The drain is + # held, so every attempt ends in the deadline's 503. An attempt whose deadline fired before + # the handler started the release left nothing registered and the box still active; retry + # it with twice the deadline. 0.2 s doubles to 6.4 s by the sixth attempt. + timeout = 0.2 + for _attempt in range(6): + app.state.request_timeout_seconds = timeout + r = await c.post("/ui/dr/release", headers=SAME_ORIGIN) + assert r.status_code == 503 + if outliving.inflight: + break + # Nothing registered: the deadline fired before the release began, not part way through. + assert not drain_started.is_set(), "the release reached its drain and was not outlived" + assert coord.active is True + timeout *= 2 + else: + pytest.fail( + f"no attempt registered the release as an outliving operation before its deadline " + f"answered, the last after {timeout / 2:.1f} s" + ) + # The deadline answered while the release was still running, cut off rather than finished. + assert outliving.inflight == ["DR release"] + assert coord.active is True + await asyncio.wait_for(drain_started.wait(), timeout=10) + let_drain_end.set() + + deadline = loop.time() + 10 + while outliving.inflight: + assert loop.time() < deadline, "the release never finished" await asyncio.sleep(0.02) assert coord.active is False and dr_engine.dr_active is False From 70cc63dd83530780cda8f347f1f62c49a4b92fc3 Mon Sep 17 00:00:00 2001 From: Scott Hall Date: Mon, 19 Oct 2026 18:11:04 -0500 Subject: [PATCH 2/3] test_ui_dr_outlive: bound the post, assert the deadline's own 503, no failed-release row (BACKLOG #3871) Code-review round 1 on the previous commit: - each post is bounded (deadline + 10 s), so a deadline that never fires fails in about 10 s instead of hanging the session on the held drain; - every 503 must carry the middleware's "timed out" body, so a handler 503 is not mistaken for a deadline that beat the release; - no dr_release_failed row on a retried attempt, after the cut-off, or at the end, so a cancel that reached the release cannot pass as the flake; - the drain is released in a finally, so a failure does not park the release on the session-scoped loop; - the final wait polls the outcome (coord inactive) as well as the registry. Proposed PR title: test_ui_dr_outlive holds the drain and retries a deadline that beat the release (BACKLOG #3871) Proposed ledger banner for #3871: PARTIAL -- the console test (test_ui_dr_outlive) is fixed; the mechanism is "before the work is registered": the deadline fired in the auth dependencies, before the handler reached outliving.run. tests/test_dr_outlive_deadline.py, tests/test_reload_cancellation.py and tests/test_upload_api.py carry the same wall-clock race and are not changed here; the row stays open. --- .../tests/test_ui_dr_outlive.py | 87 +++++++++++-------- 1 file changed, 52 insertions(+), 35 deletions(-) diff --git a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py index 3f0239a439..96442362a1 100644 --- a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py +++ b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py @@ -49,6 +49,14 @@ async def dr_engine(tmp_path: Path) -> AsyncIterator[Engine]: await eng.stop() +async def _audit(engine: Engine, action: str) -> list[object]: + return [ + json.loads(row["detail"]) + for row in await engine.store.list_audit(limit=100) + if row["action"] == action + ] + + async def test_a_console_release_cut_off_by_the_deadline_still_completes( dr_engine: Engine, ) -> None: @@ -76,43 +84,52 @@ async def held_drain() -> dict[str, object]: app = create_app(dr_engine, auth=service, serve_ui=True) outliving = app.state.outliving_operations loop = asyncio.get_running_loop() - async with httpx.AsyncClient(transport=httpx.ASGITransport(app=app), base_url="http://t") as c: - await cookie_login(c, "boss") - # After the login: its password hash alone outlasts the deadline set here. The drain is - # held, so every attempt ends in the deadline's 503. An attempt whose deadline fired before - # the handler started the release left nothing registered and the box still active; retry - # it with twice the deadline. 0.2 s doubles to 6.4 s by the sixth attempt. - timeout = 0.2 - for _attempt in range(6): - app.state.request_timeout_seconds = timeout - r = await c.post("/ui/dr/release", headers=SAME_ORIGIN) - assert r.status_code == 503 - if outliving.inflight: - break - # Nothing registered: the deadline fired before the release began, not part way through. - assert not drain_started.is_set(), "the release reached its drain and was not outlived" + try: + async with httpx.AsyncClient( + transport=httpx.ASGITransport(app=app), base_url="http://t" + ) as c: + await cookie_login(c, "boss") + # After the login: its password hash alone outlasts the deadline set here. The drain + # is held, so every attempt ends in the deadline's 503. An attempt whose deadline fired + # before the handler started the release left nothing registered and the box still + # active; retry it with twice the deadline, 0.2 s up to 6.4 s on the sixth attempt. + for timeout in (0.2 * 2**attempt for attempt in range(6)): + app.state.request_timeout_seconds = timeout + # Bounded, so a deadline that never fires fails here rather than hanging the run. + r = await asyncio.wait_for( + c.post("/ui/dr/release", headers=SAME_ORIGIN), timeout=timeout + 10 + ) + assert r.status_code == 503 and "timed out" in r.json()["detail"], r.text + if outliving.inflight: + break + # Nothing registered: the deadline fired before the release began, not part way. + assert not drain_started.is_set(), "the release reached its drain, not outlived" + assert coord.active is True + assert await _audit(dr_engine, "dr_release_failed") == [] + else: + pytest.fail( + "no attempt registered the release as an outliving operation before its " + f"deadline answered, the last after {timeout:.1f} s" + ) + # The deadline answered while the release was still running: cut off, not cancelled. + assert outliving.inflight == ["DR release"] assert coord.active is True - timeout *= 2 - else: - pytest.fail( - f"no attempt registered the release as an outliving operation before its deadline " - f"answered, the last after {timeout / 2:.1f} s" - ) - # The deadline answered while the release was still running, cut off rather than finished. - assert outliving.inflight == ["DR release"] - assert coord.active is True - await asyncio.wait_for(drain_started.wait(), timeout=10) + await asyncio.wait_for(drain_started.wait(), timeout=10) + assert await _audit(dr_engine, "dr_release_failed") == [] + let_drain_end.set() + + # The registry forgets an operation in its task's done-callback, so an empty registry + # means release() has returned, with its row written. + deadline = loop.time() + 10 + while coord.active or outliving.inflight: + assert loop.time() < deadline, "the release never finished" + await asyncio.sleep(0.02) + finally: + # A failed assertion above must not leave the release parked on the session's loop. let_drain_end.set() - deadline = loop.time() + 10 - while outliving.inflight: - assert loop.time() < deadline, "the release never finished" - await asyncio.sleep(0.02) - assert coord.active is False and dr_engine.dr_active is False - rows = [ - json.loads(r["detail"]) - for r in await dr_engine.store.list_audit(limit=100) - if r["action"] == "dr.release" + assert await _audit(dr_engine, "dr.release") == [ + {"depth_left": 0, "drained": True, "vip_hook_ran": False} ] - assert rows == [{"depth_left": 0, "drained": True, "vip_hook_ran": False}] + assert await _audit(dr_engine, "dr_release_failed") == [] From 19ae348facd3d0814fed944fca5cfb235bc5ae61 Mon Sep 17 00:00:00 2001 From: Scott Hall Date: Mon, 19 Oct 2026 18:27:19 -0500 Subject: [PATCH 3/3] test_ui_dr_outlive fires the middleware's deadline from inside the drain (BACKLOG #3871) Code-review round 2: the retry ladder only lowered the odds of the race. The test now swaps asyncio for a capturing stand-in inside the deadline middleware's module only, opens the release request under a 30 s deadline, and the held drain reschedules that real deadline to now. The middleware's own TimeoutError arm answers 503 while the release sits in its drain, in one attempt, whatever the auth dependencies cost. The 503 body is compared exactly; outliving.drain(timeout=10) replaces the poll and runs again in the finally; audit reads filter by action in SQL. Verified: every step-up slowed to 1.0 s passes 50/50; 200 serial and 960 at -n 96 pass; four production mutations (run not outliving, route bypassing it, release never deactivating, deadline never armed) each fail. Proposed PR title: test_ui_dr_outlive fires the request deadline inside the drain, not on wall time (BACKLOG #3871) Proposed ledger banner for #3871: PARTIAL -- the console test (test_ui_dr_outlive) is fixed; the mechanism is "before the work is registered": the deadline fired in the auth dependencies, before the handler reached outliving.run. tests/test_dr_outlive_deadline.py, tests/test_reload_cancellation.py and tests/test_upload_api.py carry the same wall-clock race and are not changed here; the row stays open. --- .../tests/test_ui_dr_outlive.py | 108 +++++++++--------- 1 file changed, 56 insertions(+), 52 deletions(-) diff --git a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py index 96442362a1..72a4ad4f53 100644 --- a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py +++ b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py @@ -5,15 +5,16 @@ ``/ui/dr/release`` calls the engine's own ``dr_release`` handler in process, so the deadline that cuts the console's request off is the same middleware, around the same handler. This drives the -console route with the deadline patched down and a drain held open until the deadline has answered, -and checks the release still completes and records its row: the protection the handler carries -reaches the console too. - -The deadline is wall time from the start of the request, so on a loaded runner the auth -dependencies alone can outlast it. The 503 then comes before the handler ever starts the release, -and there is nothing to outlive (vault BACKLOG #3871). Such an attempt proves nothing, so the test -retries it with a longer deadline. It never waits on wall time for the outcome: the drain does not -end until the test lets it, and the test then waits for the operation itself to finish. +console route with the middleware's own deadline firing while the release is in its drain, and +checks the release still completes and records its row: the protection the handler carries reaches +the console too. + +The deadline is not set to a short wall time any more (vault BACKLOG #3871). It is wall time from +the start of the request, so on a loaded runner the auth dependencies alone outlasted 0.2 s: the +503 came before the handler started the release, nothing was registered to outlive, and the box +was still active when the test asserted. The test now captures the deadline the middleware opens +and brings it forward from inside the drain, so it fires there and nowhere else. The drain is held +until the 503 is in, and the test then waits on the operation itself, not on a clock. """ from __future__ import annotations @@ -22,16 +23,20 @@ import json from collections.abc import AsyncIterator from pathlib import Path +from typing import Any import httpx import pytest from _ui_clients import SAME_ORIGIN, auth_service, cookie_login, provision -from messagefoundry.api import create_app +from messagefoundry.api import create_app, request_timeout from messagefoundry.config.settings import DrSettings, EgressSettings, StoreSettings from messagefoundry.pipeline import Engine from messagefoundry.store import MessageStore +#: Long enough that the deadline never fires on its own during the test: the drain fires it. +_GENEROUS_DEADLINE_SECONDS = 30.0 + @pytest.fixture async def dr_engine(tmp_path: Path) -> AsyncIterator[Engine]: @@ -49,16 +54,28 @@ async def dr_engine(tmp_path: Path) -> AsyncIterator[Engine]: await eng.stop() +class _DeadlineCapture: + """Stands in for ``asyncio`` inside the deadline middleware's module only, and keeps each + deadline the middleware opens, so a test can make the real deadline fire when it chooses.""" + + def __init__(self) -> None: + self.deadlines: list[asyncio.Timeout] = [] + + def timeout(self, delay: float | None) -> asyncio.Timeout: + deadline = asyncio.timeout(delay) + self.deadlines.append(deadline) + return deadline + + def __getattr__(self, name: str) -> Any: + return getattr(asyncio, name) + + async def _audit(engine: Engine, action: str) -> list[object]: - return [ - json.loads(row["detail"]) - for row in await engine.store.list_audit(limit=100) - if row["action"] == action - ] + return [json.loads(row["detail"]) for row in await engine.store.list_audit(action=action)] async def test_a_console_release_cut_off_by_the_deadline_still_completes( - dr_engine: Engine, + dr_engine: Engine, monkeypatch: pytest.MonkeyPatch ) -> None: coord = dr_engine.dr_coordinator assert coord is not None @@ -66,13 +83,18 @@ async def test_a_console_release_cut_off_by_the_deadline_still_completes( coord._active = True dr_engine._dr_active = True + capture = _DeadlineCapture() + monkeypatch.setattr(request_timeout, "asyncio", capture) + loop = asyncio.get_running_loop() drain_started = asyncio.Event() let_drain_end = asyncio.Event() async def held_drain() -> dict[str, object]: drain_started.set() - # Held until the deadline has answered, so the drain cannot end first however slow the - # request was to reach the handler. + # The release request's deadline fires now, inside the drain, whatever the request spent + # reaching the handler. It is the last one opened: only that request is in flight. + capture.deadlines[-1].reschedule(loop.time()) + # Held until the deadline has answered, so the drain cannot end first. await let_drain_end.wait() dr_engine._dr_active = False return {"depth_left": 0} @@ -83,50 +105,32 @@ async def held_drain() -> dict[str, object]: await provision(service, "boss", ["administrator"]) app = create_app(dr_engine, auth=service, serve_ui=True) outliving = app.state.outliving_operations - loop = asyncio.get_running_loop() try: async with httpx.AsyncClient( transport=httpx.ASGITransport(app=app), base_url="http://t" ) as c: - await cookie_login(c, "boss") - # After the login: its password hash alone outlasts the deadline set here. The drain - # is held, so every attempt ends in the deadline's 503. An attempt whose deadline fired - # before the handler started the release left nothing registered and the box still - # active; retry it with twice the deadline, 0.2 s up to 6.4 s on the sixth attempt. - for timeout in (0.2 * 2**attempt for attempt in range(6)): - app.state.request_timeout_seconds = timeout - # Bounded, so a deadline that never fires fails here rather than hanging the run. - r = await asyncio.wait_for( - c.post("/ui/dr/release", headers=SAME_ORIGIN), timeout=timeout + 10 - ) - assert r.status_code == 503 and "timed out" in r.json()["detail"], r.text - if outliving.inflight: - break - # Nothing registered: the deadline fired before the release began, not part way. - assert not drain_started.is_set(), "the release reached its drain, not outlived" - assert coord.active is True - assert await _audit(dr_engine, "dr_release_failed") == [] - else: - pytest.fail( - "no attempt registered the release as an outliving operation before its " - f"deadline answered, the last after {timeout:.1f} s" - ) - # The deadline answered while the release was still running: cut off, not cancelled. + await cookie_login(c, "boss") # under the default deadline + app.state.request_timeout_seconds = _GENEROUS_DEADLINE_SECONDS + # Bounded, so a deadline that never fires fails here rather than hanging the run. + r = await asyncio.wait_for( + c.post("/ui/dr/release", headers=SAME_ORIGIN), + timeout=_GENEROUS_DEADLINE_SECONDS + 10, + ) + # The middleware's own 503, not a handler's: the deadline cut the request off. + assert r.status_code == 503, r.text + assert r.json() == {"detail": "the server timed out building a response"} + assert drain_started.is_set() + # Cut off while the release was still running, and not cancelled with the request. assert outliving.inflight == ["DR release"] assert coord.active is True - await asyncio.wait_for(drain_started.wait(), timeout=10) assert await _audit(dr_engine, "dr_release_failed") == [] let_drain_end.set() - - # The registry forgets an operation in its task's done-callback, so an empty registry - # means release() has returned, with its row written. - deadline = loop.time() + 10 - while coord.active or outliving.inflight: - assert loop.time() < deadline, "the release never finished" - await asyncio.sleep(0.02) + assert await outliving.drain(timeout=10) == [], "the release never finished" finally: - # A failed assertion above must not leave the release parked on the session's loop. + # After a failed assertion above, release the drain and wait for the release, so it does + # not run on into the fixture's engine stop or the session's next test. let_drain_end.set() + await outliving.drain(timeout=10) assert coord.active is False and dr_engine.dr_active is False assert await _audit(dr_engine, "dr.release") == [