diff --git a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py index 14f9be784..72a4ad4f5 100644 --- a/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py +++ b/packaging/messagefoundry-webconsole/tests/test_ui_dr_outlive.py @@ -5,8 +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 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 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 @@ -15,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]: @@ -42,8 +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(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 @@ -51,32 +83,57 @@ 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 + 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() + # 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} - 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) - 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" - await asyncio.sleep(0.02) + outliving = app.state.outliving_operations + try: + async with httpx.AsyncClient( + transport=httpx.ASGITransport(app=app), base_url="http://t" + ) as c: + 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 + assert await _audit(dr_engine, "dr_release_failed") == [] + let_drain_end.set() + assert await outliving.drain(timeout=10) == [], "the release never finished" + finally: + # 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 - 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") == []