From 394c3eb9d99a0901c6eed38330adfe7825043f7e Mon Sep 17 00:00:00 2001 From: David Shoen Date: Tue, 14 Jul 2026 14:46:34 +0300 Subject: [PATCH 1/4] feat: debounce forced-reload trigger endpoints (PER-15248) Replace OpalClient's ungated /policy-updater/trigger and /data-updater/trigger handlers (and route the legacy /update_policy* aliases) through per-updater DebouncedTrigger instances, so an authenticated caller or buggy SDK can no longer amplify full-reload load onto the shared control plane. Coalesces triggers within a configurable window (PDP_TRIGGER_DEBOUNCE_SECONDS, default 10s) and collapses concurrent triggers into the in-flight pull; a failed pull does not consume the window. Response/auth parity with the routes it replaces is preserved. Co-Authored-By: Claude Fable 5 --- horizon/config.py | 14 ++ horizon/debounce.py | 99 +++++++++ horizon/pdp.py | 179 ++++++++++++---- horizon/tests/test_opal_trigger_auth.py | 10 +- horizon/tests/test_route_auth_audit.py | 5 +- horizon/tests/test_trigger_debounce.py | 272 ++++++++++++++++++++++++ 6 files changed, 529 insertions(+), 50 deletions(-) create mode 100644 horizon/debounce.py create mode 100644 horizon/tests/test_trigger_debounce.py diff --git a/horizon/config.py b/horizon/config.py index 87fb42dc..8e0a8e01 100644 --- a/horizon/config.py +++ b/horizon/config.py @@ -288,6 +288,20 @@ def parse_plugins(value: Any) -> dict[str, dict[str, int | bool | str]]: ), ) + TRIGGER_DEBOUNCE_SECONDS = confi.float( + "TRIGGER_DEBOUNCE_SECONDS", + 10.0, + description=( + "Minimum number of seconds between forced full reloads triggered via the API trigger " + "routes (/policy-updater/trigger, /data-updater/trigger and their legacy /update_policy* " + "aliases). Triggers arriving within the window - or while a forced reload is already in " + "flight - coalesce into the in-flight/most-recent pull instead of amplifying load onto the " + "control plane. Set to 0 to disable debouncing (every trigger forces a fresh reload). " + "Remote-config overridable fleet-wide, so ops can raise it (e.g. to 30-60s under a degraded " + "control plane) without shipping a release." + ), + ) + @staticmethod def parse_callbacks(value: Any) -> list[CallbackEntry]: if isinstance(value, str): diff --git a/horizon/debounce.py b/horizon/debounce.py new file mode 100644 index 00000000..ab027231 --- /dev/null +++ b/horizon/debounce.py @@ -0,0 +1,99 @@ +"""Debounce/coalesce forced-reload triggers for a single logical updater. + +The PDP exposes API routes that force a *full* policy/data reload on every call +(``/policy-updater/trigger``, ``/data-updater/trigger`` and their legacy aliases). +Nothing dampens an authenticated caller (or a buggy SDK) hammering them, and each +forced reload amplifies straight onto the shared control plane - exactly when a +degraded control plane can least afford it. ``DebouncedTrigger`` holds the small +amount of coalescing *state* for one logical updater and decides, per call, whether +to actually run the reload or collapse it into a recent/in-flight one. + +The class holds only state + policy; the actual reload work is passed in per call +(``run``). That lets the canonical and legacy-alias routes share a single instance +per updater (so an alternating canonical/legacy hammer still coalesces - both hit +the same control-plane resource) while each supplies its own ``run`` closure and +its own log context. +""" + +import time +from collections.abc import Awaitable, Callable + +from loguru import logger + + +class DebouncedTrigger: + """Coalesces forced-reload triggers for one logical updater (policy or data). + + Semantics of :meth:`trigger` (in evaluation order): + + * ``window_seconds <= 0`` -> passthrough (debounce disabled): always run. + * A reload is already **in flight** -> coalesce regardless of the window. Under a + degraded control plane a single forced pull can run for minutes (the PDP configures + many retries with exponential backoff), so a pure time-window check would still admit + a *concurrent* full pull every ``window_seconds`` - the in-flight guard is what prevents + that pile-up. + * Otherwise, if the last successful reload was **within the window** -> coalesce. + * Otherwise -> run, recording the completion time **only on success**. + + Recording ``_last_fired`` only on success is deliberate: a failed pull must not burn the + window (a legitimate retry within ``window_seconds`` must still fire), and the exception is + re-raised so the route surfaces it. + """ + + def __init__(self, name: str) -> None: + # Short label used purely for logs, e.g. "policy" / "data". + self._name = name + # Monotonic seconds of the last *successful* reload; ``None`` until the first one. + # Deliberately ``None`` and NEVER ``0.0``: ``time.monotonic()`` is ~seconds since boot + # on Linux, so a ``0.0`` sentinel would read as "fired at boot" and silently coalesce + # the very first real trigger on a freshly booted host. + self._last_fired: float | None = None + # True while a reload is running under this instance (see the in-flight guard). + self._in_flight: bool = False + + async def trigger(self, run: Callable[[], Awaitable[None]], window_seconds: float) -> bool: + """Run ``run`` (a coroutine factory doing the forced reload) unless it can be coalesced. + + Returns ``True`` if ``run`` was awaited, ``False`` if the trigger was coalesced into a + recent/in-flight reload. A coalesced trigger is an immediate no-op success from the + caller's perspective - it does NOT await the in-flight reload. + """ + # 1. Debounce disabled -> passthrough. Any exception from ``run`` propagates. + if window_seconds <= 0: + await run() + return True + + # 2. In-flight guard: collapse concurrent triggers into the one already running. + if self._in_flight: + logger.info( + "Coalescing {} reload trigger: a forced reload is already in flight; collapsing into it.", + self._name, + ) + return False + + # 3. Window guard: collapse triggers that arrive within the debounce window of the + # last successful reload. + if self._last_fired is not None: + elapsed = time.monotonic() - self._last_fired + if elapsed < window_seconds: + logger.info( + "Coalescing {} reload trigger: within the {:g}s debounce window ({:.1f}s remaining).", + self._name, + window_seconds, + window_seconds - elapsed, + ) + return False + + # 4. Fire. Single-worker assumption (the Rust supervisor spawns uvicorn with no + # --workers -> exactly one event loop): there is NO ``await`` between the guards + # above and this set, so the check-then-set is atomic and needs no lock. A second + # trigger cannot interleave until we ``await run()`` below, by which point + # ``_in_flight`` is already True and step 2 will coalesce it. + self._in_flight = True + try: + await run() + # Record completion time only on success so a failed pull does not burn the window. + self._last_fired = time.monotonic() + return True + finally: + self._in_flight = False diff --git a/horizon/pdp.py b/horizon/pdp.py index 24a2b7a5..f6518d37 100644 --- a/horizon/pdp.py +++ b/horizon/pdp.py @@ -5,7 +5,6 @@ from uuid import UUID, uuid4 from fastapi import Depends, FastAPI, HTTPException, status -from fastapi.dependencies.utils import get_parameterless_sub_dependant from fastapi.routing import APIRoute from loguru import logger from logzio.handler import LogzioHandler @@ -29,6 +28,7 @@ from horizon.authentication import enforce_pdp_token from horizon.config import MOCK_API_KEY, sidecar_config from horizon.connectivity.api import init_connectivity_router +from horizon.debounce import DebouncedTrigger from horizon.enforcer.api import init_enforcer_api_router, init_enforcer_health_router, stats_manager from horizon.enforcer.opa.config_maker import ( get_opa_authz_policy_file_path, @@ -100,44 +100,44 @@ def apply_config(overrides_dict: dict, config_object: Confi): logger.warning(f"Ignored non-existing config key: {prefixed_key}") -# The OPAL client mounts these trigger routes before PermitPDP gains control, so they -# cannot be gated by an include_router-level dependency - they are secured post-hoc by -# _gate_opal_trigger_routes instead. Kept as a frozenset so the route-audit test can -# assert both are present and authenticated. +# OpalClient mounts these two forced-reload trigger routes before PermitPDP gains control. +# Their handlers are OPAL closures that force a FULL reload on every call with no damping, so +# the PDP REPLACES them (see _remove_opal_trigger_routes + the replacements registered in +# _configure_api_routes) with its own gated, debounced handlers at the same paths. Kept as a +# frozenset so the route-audit test (test_route_auth_audit.py) can assert both remain present +# and authenticated after the swap. OPAL_TRIGGER_ROUTE_PATHS: frozenset[str] = frozenset({"/policy-updater/trigger", "/data-updater/trigger"}) -def _gate_opal_trigger_routes(app: FastAPI) -> None: - """Inject ``Depends(enforce_pdp_token)`` into the OPAL-mounted trigger routes. +def _remove_opal_trigger_routes(app: FastAPI) -> None: + """Remove the OPAL-mounted forced-reload trigger routes so the PDP can replace them. - OpalClient mounts ``POST /policy-updater/trigger`` and ``POST /data-updater/trigger`` - on the app before ``PermitPDP`` gains control (opal_client.client._configure_api_routes), - so the include_router-level dependencies used for every PDP-owned router cannot reach - them. We inject the standard PDP-token dependency into the already-mounted route objects - instead, mirroring what FastAPI itself does at ``APIRoute.__init__`` (fastapi/routing.py): - insert a parameterless sub-dependant at the head of ``route.dependant.dependencies``. + OpalClient mounts ``POST /policy-updater/trigger`` and ``POST /data-updater/trigger`` on the + app before ``PermitPDP`` gains control (opal_client.client._configure_api_routes). Those + handlers are closures we cannot cleanly intercept, and a FastAPI dependency cannot + short-circuit a request to a 200 no-op (it can only raise) - so both gating AND debouncing + them requires OWNING the handler. We strip the OPAL routes here; the caller immediately + re-registers gated, debounced replacements at the same two paths. - The Dependant is mutated IN PLACE - the route's request handler closes over that exact - object, so the check is enforced on every request; do NOT reassign ``route.dependant``. - ``enforce_pdp_token`` only reads a header, so the route's body field needs no rebuild. + Remove-then-add, never add-only: Starlette matches routes first-match-wins, so a lingering + OPAL route would shadow the replacement AND stay ungated + un-debounced. - Fails loud if a target route is missing (e.g. an OPAL upgrade renamed it): a silently - skipped injection would leave an update-trigger endpoint unauthenticated. + Fails loud (``SystemExit``) if either path is missing - e.g. an OPAL upgrade renamed a route. + A silently-skipped removal would leave the original ungated, un-debounced OPAL handler in + place, reopening exactly the amplification/auth hole this replacement closes. """ - gated: set[str] = set() - for route in app.routes: + removed: set[str] = set() + # Iterate over a copy: we mutate app.router.routes inside the loop. + for route in list(app.router.routes): if isinstance(route, APIRoute) and route.path in OPAL_TRIGGER_ROUTE_PATHS: - route.dependant.dependencies.insert( - 0, - get_parameterless_sub_dependant(depends=Depends(enforce_pdp_token), path=route.path_format), - ) - gated.add(route.path) + app.router.routes.remove(route) + removed.add(route.path) - missing = OPAL_TRIGGER_ROUTE_PATHS - gated + missing = OPAL_TRIGGER_ROUTE_PATHS - removed if missing: logger.critical( - "Could not secure OPAL trigger route(s) {} - not found on the app. Refusing to " - "start with potentially unauthenticated update-trigger endpoints.", + "Could not find OPAL trigger route(s) {} to replace - not found on the app. Refusing " + "to start with potentially unauthenticated, un-debounced update-trigger endpoints.", ", ".join(sorted(missing)), ) raise SystemExit(GUNICORN_EXIT_APP) @@ -497,7 +497,33 @@ def _configure_api_routes(self, app: FastAPI): dependencies=[Depends(enforce_pdp_token)], ) - # TODO: remove this when clients update sdk version (legacy routes) + # Forced-reload trigger routes (canonical OPAL routes replaced with debounced, + # PDP-gated handlers + their legacy aliases). Extracted to keep this method's + # cyclomatic complexity in check and to co-locate all trigger routes + debounce state. + self._configure_trigger_routes(app) + + # High-signal warning if the OPAL-authenticated routes are left open by a disabled + # verifier (must never happen in a managed PDP). + _warn_if_opal_verifier_disabled(self._opal) + + def _configure_trigger_routes(self, app: FastAPI): + """Mount the forced-reload trigger routes, debounced and PDP-gated. + + OpalClient mounts ``POST /policy-updater/trigger`` / ``POST /data-updater/trigger`` with + ungated closures that force a FULL reload on every call. We remove those and register + PDP-owned replacements at the same paths, plus the two legacy ``/update_policy*`` aliases, + all routed through per-updater :class:`DebouncedTrigger`s so an authenticated hammer (or a + buggy SDK) cannot amplify load onto the shared control plane. + """ + # Per-updater debounce state, owned by this PermitPDP instance (never module-global: + # production has exactly one instance, and per-instance scope gives each test's fresh + # MockPermitPDP its own clean state). Each debouncer is shared by a canonical route and + # its legacy alias (via the _reload helpers below) so an alternating hammer still + # coalesces into one forced reload. + self._policy_trigger_debounce = DebouncedTrigger("policy") + self._data_trigger_debounce = DebouncedTrigger("data") + + # TODO: remove the two legacy aliases when clients update sdk version. @app.post( "/update_policy", status_code=status.HTTP_200_OK, @@ -506,9 +532,7 @@ def _configure_api_routes(self, app: FastAPI): ) async def legacy_trigger_policy_update(): logger.info("triggered policy update from api (legacy route)") - # deliberately no None-guard: exact parity with the canonical (unguarded) - # /policy-updater/trigger handler; the PDP never disables the policy updater - await self._opal.policy_updater.trigger_update_policy(force_full_update=True) + await self._debounced_policy_reload() return {"status": "ok"} @app.post( @@ -519,21 +543,86 @@ async def legacy_trigger_policy_update(): ) async def legacy_trigger_data_update(): logger.info("triggered policy data update from api (legacy route)") - if self._opal.data_updater is None: - raise HTTPException( - status_code=status.HTTP_503_SERVICE_UNAVAILABLE, - detail="Data Updater is currently disabled. Dynamic data updates are not available.", - ) - await self._opal.data_updater.get_base_policy_data(data_fetch_reason="request from sdk (legacy alias)") + # Preserve the distinct legacy reason string - a test asserts it verbatim. + await self._debounced_data_reload("request from sdk (legacy alias)") return {"status": "ok"} - # The OPAL trigger routers were mounted by OpalClient before the PDP took over, so - # the include_router-level dependencies above cannot reach them. Inject the PDP - # token dependency into those two routes directly. - _gate_opal_trigger_routes(app) - # High-signal warning if the OPAL-authenticated routes are left open by a disabled - # verifier (must never happen in a managed PDP). - _warn_if_opal_verifier_disabled(self._opal) + # OpalClient mounted POST /policy-updater/trigger and POST /data-updater/trigger before + # the PDP took over; their closures force a FULL reload on every call with no damping. + # Remove them and re-register PDP-owned replacements at the same paths that (a) carry the + # normal Depends(enforce_pdp_token) gate and (b) route through the per-updater debouncers + # above. Remove-then-add order matters: Starlette is first-match-wins, so a surviving OPAL + # route would shadow the replacement and stay ungated/un-debounced. + _remove_opal_trigger_routes(app) + + @app.post( + "/policy-updater/trigger", + status_code=status.HTTP_200_OK, + tags=["Policy Updater"], + dependencies=[Depends(enforce_pdp_token)], + ) + async def trigger_policy_update(): + """Force a full policy reload, debounced (replaces OpalClient's ungated handler). + + Response parity with the route it replaces: always 200 ``{"status": "ok"}``. The policy + route already had fire-and-forget 200 semantics (the underlying call only *enqueues* an + update), so debouncing changes nothing observable here beyond collapsing redundant + triggers into one reload. + """ + logger.info("triggered policy update from api") + await self._debounced_policy_reload() + return {"status": "ok"} + + @app.post( + "/data-updater/trigger", + status_code=status.HTTP_200_OK, + tags=["Data Updater"], + dependencies=[Depends(enforce_pdp_token)], + ) + async def trigger_data_update(): + """Force a full base-data reload, debounced (replaces OpalClient's ungated handler). + + SEMANTIC SHIFT worth calling out: with the OPAL route a 200 meant the inline base-data + fetch had actually COMPLETED. With debouncing a 200 now means "a recent or in-flight + forced pull already covers you" - the underlying get_base_policy_data may have been + coalesced and not re-run. The body stays exactly ``{"status": "ok"}`` either way so + SDKs polling this route never error-spiral. A disabled data updater still returns 503, + checked BEFORE the debouncer so a 503 never consumes the window. + """ + logger.info("triggered policy data update from api") + await self._debounced_data_reload("request from sdk") + return {"status": "ok"} + + async def _debounced_policy_reload(self) -> None: + """Force a full policy reload through the shared policy debouncer. + + Backs both /policy-updater/trigger and the /update_policy legacy alias so they coalesce + against each other. No None-guard: the PDP never disables the policy updater. + """ + + async def _run() -> None: + await self._opal.policy_updater.trigger_update_policy(force_full_update=True) + + await self._policy_trigger_debounce.trigger(run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS) + + async def _debounced_data_reload(self, data_fetch_reason: str) -> None: + """Force a full base-data reload through the shared data debouncer. + + Backs both /data-updater/trigger and the /update_policy_data legacy alias (the caller + passes the route-specific ``data_fetch_reason``). Raises 503 - exact OpalClient parity - + when the data updater is disabled, checked BEFORE the debouncer so a 503 never consumes + the window. + """ + if self._opal.data_updater is None: + raise HTTPException( + status_code=status.HTTP_503_SERVICE_UNAVAILABLE, + detail="Data Updater is currently disabled. Dynamic data updates are not available.", + ) + + async def _run() -> None: + await self._opal.data_updater.get_base_policy_data(data_fetch_reason=data_fetch_reason) + + await self._data_trigger_debounce.trigger(run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS) @property def app(self): diff --git a/horizon/tests/test_opal_trigger_auth.py b/horizon/tests/test_opal_trigger_auth.py index 9d0cad7c..e0937249 100644 --- a/horizon/tests/test_opal_trigger_auth.py +++ b/horizon/tests/test_opal_trigger_auth.py @@ -1,8 +1,10 @@ -"""Integration tests proving the OPAL-mounted trigger routes are now gated. +"""Integration tests proving the OPAL-mounted trigger routes are gated. -The app is built exactly like production via ``PermitPDP._configure_api_routes`` (which -runs ``_gate_opal_trigger_routes``), so these tests directly exercise the post-hoc -dependency injection on the two routes OpalClient mounts before the PDP gets control. +The app is built exactly like production via ``PermitPDP._configure_api_routes``, which +removes the two trigger routes OpalClient mounts before the PDP gets control and +re-registers PDP-owned, debounced replacements at the same paths (see +``_configure_trigger_routes`` / ``_remove_opal_trigger_routes``). These tests exercise the +``Depends(enforce_pdp_token)`` gate those replacement routes carry. The TestClient is used WITHOUT a context manager, so the app lifespan never runs (no OPAL policy/data fetch, no OPA process, no control-plane connection). ``raise_server_exceptions diff --git a/horizon/tests/test_route_auth_audit.py b/horizon/tests/test_route_auth_audit.py index 0291f5a4..e1d2eeb0 100644 --- a/horizon/tests/test_route_auth_audit.py +++ b/horizon/tests/test_route_auth_audit.py @@ -104,7 +104,10 @@ def test_no_route_is_unprotected(): def test_opal_trigger_route_is_pdp_gated(path: str): """Regression guard for the actual fix: the OPAL-mounted trigger routes require the PDP token.""" by_path = {route.path: route for route in _sidecar._app.routes if isinstance(route, APIRoute)} - assert path in by_path, f"{path} is no longer mounted (OPAL rename?) - _gate_opal_trigger_routes must be updated" + assert path in by_path, ( + f"{path} is no longer mounted (OPAL rename?) - _remove_opal_trigger_routes / " + "_configure_trigger_routes must be updated" + ) assert "enforce_pdp_token" in _route_auth_gates(by_path[path]) diff --git a/horizon/tests/test_trigger_debounce.py b/horizon/tests/test_trigger_debounce.py new file mode 100644 index 00000000..7cc92df1 --- /dev/null +++ b/horizon/tests/test_trigger_debounce.py @@ -0,0 +1,272 @@ +"""Behaviour tests for the debounced forced-reload trigger routes (PER-15248). + +The PDP replaces OpalClient's ungated, un-damped ``POST /policy-updater/trigger`` and +``POST /data-updater/trigger`` handlers with its own gated, DEBOUNCED handlers, and routes +the legacy ``/update_policy`` / ``/update_policy_data`` aliases through the same per-updater +debouncers. These tests exercise the observable coalescing behaviour end-to-end through the +real app, mirroring the idiom of ``test_legacy_update_routes.py``: a fresh ``MockPermitPDP`` +per test (so each gets its own debounce state), a ``TestClient``, and ``AsyncMock``s +monkeypatched onto the underlying updater methods. + +The debounce window is read from ``sidecar_config.TRIGGER_DEBOUNCE_SECONDS`` at call time, so +each test sets it via ``monkeypatch.setattr`` (monkeypatch reverts it at teardown). +""" + +import asyncio +from unittest.mock import AsyncMock + +import pytest +from fastapi.testclient import TestClient +from horizon.config import sidecar_config +from httpx import ASGITransport, AsyncClient + +# Basename import (not horizon.tests.*): CI installs the package non-editably, so the wheel +# ships no tests/ package; pytest's prepend import mode puts this directory on sys.path and +# imports test modules by basename. Same rationale as test_legacy_update_routes.py. +from test_enforcer_api import MockPermitPDP + +WINDOW = 10.0 + + +@pytest.fixture +def pdp() -> MockPermitPDP: + # Fresh instance per test => fresh per-updater debounce state, so tests never coalesce + # into each other (the debouncers live on the PermitPDP instance, not a module global). + return MockPermitPDP() + + +@pytest.fixture +def auth() -> dict[str, str]: + return {"authorization": f"Bearer {sidecar_config.API_KEY}"} + + +# --- case 1: triggers within the window coalesce into a single underlying reload --------- + + +def test_policy_triggers_within_window_coalesce(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + trigger = AsyncMock() + monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", trigger) + client = TestClient(pdp._app) + + first = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) + second = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) + + assert first.status_code == 200 and first.json() == {"status": "ok"} + assert second.status_code == 200 and second.json() == {"status": "ok"} + # Second call coalesced: the updater was forced exactly once. + trigger.assert_awaited_once_with(force_full_update=True) + + +def test_data_triggers_within_window_coalesce(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + get_base = AsyncMock() + monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) + client = TestClient(pdp._app) + + first = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + second = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + + assert first.status_code == 200 and first.json() == {"status": "ok"} + assert second.status_code == 200 and second.json() == {"status": "ok"} + get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") + + +def test_canonical_and_legacy_policy_share_one_debouncer(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + # Alternating canonical + legalias within the window must still collapse into one reload: + # both routes hit the same policy debouncer instance. + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + trigger = AsyncMock() + monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", trigger) + client = TestClient(pdp._app) + + canonical = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) + legacy = client.post("/update_policy", headers=auth, follow_redirects=False) + + assert canonical.status_code == 200 and legacy.status_code == 200 + trigger.assert_awaited_once_with(force_full_update=True) + + +def test_canonical_and_legacy_data_share_one_debouncer(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + get_base = AsyncMock() + monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) + client = TestClient(pdp._app) + + canonical = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + legacy = client.post("/update_policy_data", headers=auth, follow_redirects=False) + + assert canonical.status_code == 200 and legacy.status_code == 200 + # The canonical call fired first, so its reason string is the one that ran; the legacy + # call coalesced and never invoked the updater with its own "(legacy alias)" reason. + get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") + + +# --- case 2: after the window elapses, the next trigger fires again ---------------------- + + +def test_trigger_fires_again_after_window_elapses(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + trigger = AsyncMock() + monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", trigger) + client = TestClient(pdp._app) + + assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + assert trigger.await_count == 1 + + # Rewind the debouncer's last-fired past the window (no real sleep): the next trigger + # now sees the window as elapsed and fires. + pdp._policy_trigger_debounce._last_fired -= WINDOW + 1 + + assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + assert trigger.await_count == 2 + + +# --- case 3: window == 0 disables debouncing (passthrough on every call) ------------------ + + +def test_zero_window_passes_every_trigger_through(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", 0) + trigger = AsyncMock() + monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", trigger) + client = TestClient(pdp._app) + + for _ in range(3): + assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + assert trigger.await_count == 3 + + +# --- case 4: an in-flight reload coalesces later triggers regardless of the window -------- + + +@pytest.mark.asyncio +async def test_in_flight_reload_coalesces_even_past_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + + started = asyncio.Event() # set once the reload is genuinely running + release = asyncio.Event() # keeps the reload in flight until the test releases it + + async def blocking(**_kwargs) -> None: + started.set() + await release.wait() + + get_base = AsyncMock(side_effect=blocking) + monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) + + transport = ASGITransport(app=pdp._app) + async with AsyncClient(transport=transport, base_url="http://test") as client: + # Fire the first trigger and let it block inside the underlying reload. + first = asyncio.create_task(client.post("/data-updater/trigger", headers=auth)) + await asyncio.wait_for(started.wait(), timeout=2) + + # The window guard would admit this (last_fired is still None because the first pull + # has not completed), but the in-flight guard must coalesce it: no second pull. + second = await client.post("/data-updater/trigger", headers=auth) + assert second.status_code == 200 and second.json() == {"status": "ok"} + assert get_base.await_count == 1 + + # Release the in-flight reload and confirm the first request completes cleanly. + release.set() + first_response = await first + assert first_response.status_code == 200 and first_response.json() == {"status": "ok"} + assert get_base.await_count == 1 + + +# --- case 5: a failed reload does not burn the window (immediate retry still fires) ------- + + +def test_failed_reload_does_not_burn_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + get_base = AsyncMock(side_effect=RuntimeError("boom")) + monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) + # raise_server_exceptions=False so the propagated error surfaces as a 500 response. + client = TestClient(pdp._app, raise_server_exceptions=False) + + first = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert first.status_code == 500 + # Failure must not record last_fired... + assert pdp._data_trigger_debounce._last_fired is None + + # ...so an immediate retry within the window still fires (is not coalesced). + second = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert second.status_code == 500 + assert get_base.await_count == 2 + + +# --- case 6: a disabled data updater 503s before the debouncer (window not consumed) ----- + + +def test_disabled_data_updater_503s_before_debouncer(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + get_base = AsyncMock() + original_updater = pdp._opal.data_updater + monkeypatch.setattr(original_updater, "get_base_policy_data", get_base) + + # Disable the data updater -> exact OPAL 503 parity, raised BEFORE the debouncer. + monkeypatch.setattr(pdp._opal, "data_updater", None) + client = TestClient(pdp._app) + disabled = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert disabled.status_code == 503 + assert disabled.json()["detail"] == "Data Updater is currently disabled. Dynamic data updates are not available." + # The 503 must not have consumed the window. + assert pdp._data_trigger_debounce._last_fired is None + get_base.assert_not_awaited() + + # Re-enable: because the 503 never touched the debouncer, the next trigger fires. + monkeypatch.setattr(pdp._opal, "data_updater", original_updater) + enabled = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert enabled.status_code == 200 + get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") + + +# --- case 7: policy and data debouncers are independent; state is per-instance ----------- + + +def test_policy_and_data_debouncers_are_independent(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + policy_trigger = AsyncMock() + data_get_base = AsyncMock() + monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", policy_trigger) + monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", data_get_base) + client = TestClient(pdp._app) + + # Firing policy must not consume the data window: both fire within the same window. + assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + assert client.post("/data-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + policy_trigger.assert_awaited_once_with(force_full_update=True) + data_get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") + + +def test_debounce_state_is_per_pdp_instance(auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + + pdp_a = MockPermitPDP() + trigger_a = AsyncMock() + monkeypatch.setattr(pdp_a._opal.policy_updater, "trigger_update_policy", trigger_a) + resp_a = TestClient(pdp_a._app).post("/policy-updater/trigger", headers=auth, follow_redirects=False) + assert resp_a.status_code == 200 + trigger_a.assert_awaited_once() + + # A brand-new instance carries its own debounce state, so its first trigger always fires, + # even though pdp_a just fired within the window. + pdp_b = MockPermitPDP() + trigger_b = AsyncMock() + monkeypatch.setattr(pdp_b._opal.policy_updater, "trigger_update_policy", trigger_b) + resp_b = TestClient(pdp_b._app).post("/policy-updater/trigger", headers=auth, follow_redirects=False) + assert resp_b.status_code == 200 + trigger_b.assert_awaited_once() + + +# --- case 8: auth is untouched by the replacement (sanity) ------------------------------- + + +def test_replacement_route_still_rejects_missing_token(pdp: MockPermitPDP, monkeypatch): + # The replacements carry the normal Depends(enforce_pdp_token) gate; the dedicated auth + # tests live in test_opal_trigger_auth.py / test_route_auth_audit.py. This is a light guard + # that debouncing did not accidentally open the route. + trigger = AsyncMock() + monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", trigger) + + resp = TestClient(pdp._app).post("/policy-updater/trigger", follow_redirects=False) + assert resp.status_code == 401 + trigger.assert_not_awaited() From 5ad9c54bcf092d9503fe8306bc2b49f58b5182f3 Mon Sep 17 00:00:00 2001 From: David Shoen Date: Wed, 15 Jul 2026 10:53:15 +0300 Subject: [PATCH 2/4] test: fix typo in trigger-debounce test comment (legalias -> legacy alias) Addresses Copilot review comment on PR #327. Co-Authored-By: Claude Fable 5 --- horizon/tests/test_trigger_debounce.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/horizon/tests/test_trigger_debounce.py b/horizon/tests/test_trigger_debounce.py index 7cc92df1..a30e9c56 100644 --- a/horizon/tests/test_trigger_debounce.py +++ b/horizon/tests/test_trigger_debounce.py @@ -73,7 +73,7 @@ def test_data_triggers_within_window_coalesce(pdp: MockPermitPDP, auth: dict[str def test_canonical_and_legacy_policy_share_one_debouncer(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): - # Alternating canonical + legalias within the window must still collapse into one reload: + # Alternating canonical + legacy alias within the window must still collapse into one reload: # both routes hit the same policy debouncer instance. monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) trigger = AsyncMock() From 728b8bcdb9b2ba38bc935e208e07c7726ce92585 Mon Sep 17 00:00:00 2001 From: David Shoen Date: Tue, 4 Aug 2026 12:33:11 -0400 Subject: [PATCH 3/4] fix: correct debounce semantics to match OPAL's actual call graph (PER-15248) Review of the initial implementation found that three of DebouncedTrigger's documented invariants were false against OPAL's real behaviour, because both updaters are fire-and-forget underneath: trigger_update_policy is a single put onto an unbounded asyncio.Queue whose consumer swallows exceptions, and get_base_policy_data awaits only a config GET before handing the per-entry fetches to a task pool. So `await run()` returns on DISPATCH, not completion. Corrections: - _last_fired -> _last_dispatched, and the "a failed pull does not burn the window" guarantee is removed. It was never achievable at this layer: a reload that fails in a background task still consumes the window. - The in-flight guard no longer claims to cover multi-minute pulls, and is now unconditional - window_seconds <= 0 disables only the time window, never the single-flight property. - Trailing edge: a trigger coalesced by the in-flight guard now causes exactly one follow-up dispatch, so it is not silently dropped. Capped at two dispatches per call so a sustained hammer cannot become a reload loop. Trailing failures are logged and swallowed - the caller executing the re-run already had its own dispatch succeed and must not be handed someone else's 500. A trigger coalesced into a failed dispatch stays pending instead of being discarded. - The /data-updater/trigger docstring claimed a 200 previously meant the fetch had COMPLETED. It never did; corrected. Also: - Routes return {"status": "ok", "triggered": bool} so callers and metrics can distinguish a dispatch from a coalesce. Documented that `false` is a success and must not be retried, since retrying re-creates the amplification this change exists to dampen. - Handler docstrings were being published as the operation description in the customer-facing /openapi.json and /scalar explorer, leaking internal notes including "replaces OpalClient's ungated handler". Replaced with explicit summary=/description= written for that audience. - TRIGGER_DEBOUNCE_SECONDS is clamped to [0, 300] and the effective value is logged at startup. clamp_window coerces defensively rather than raising: confi.float's cast_from_json is no_cast, so a remote-config override arrives verbatim, and null or "30" would otherwise abort startup. - Coalesce logging is INFO on the first suppression per dispatch and DEBUG thereafter, so the mitigation does not amplify log volume under the exact hammering it absorbs. - Config description corrected: the restart requirement comes from remote config being fetched once at startup, not from the window being read once. Tests: new test_debounce_unit.py covers DebouncedTrigger directly (burst collapse, cancellation, trailing edge, clamp_window edges, coalesce logging). Route-audit now asserts exactly one route per trigger path and PDP ownership, which the previous last-wins dict lookup could not catch. test_opal_trigger_auth gets an autouse fixture so per-instance debounce state cannot leak between tests in that module. 155 passed; ruff check and format clean. Co-Authored-By: Claude Opus 5 (1M context) --- horizon/config.py | 18 +- horizon/debounce.py | 201 ++++++++-- horizon/pdp.py | 109 +++-- horizon/tests/test_debounce_unit.py | 440 +++++++++++++++++++++ horizon/tests/test_legacy_update_routes.py | 7 +- horizon/tests/test_opal_trigger_auth.py | 31 ++ horizon/tests/test_route_auth_audit.py | 47 ++- horizon/tests/test_trigger_debounce.py | 179 ++++++--- 8 files changed, 901 insertions(+), 131 deletions(-) create mode 100644 horizon/tests/test_debounce_unit.py diff --git a/horizon/config.py b/horizon/config.py index 8e0a8e01..5d4edfa4 100644 --- a/horizon/config.py +++ b/horizon/config.py @@ -292,13 +292,19 @@ def parse_plugins(value: Any) -> dict[str, dict[str, int | bool | str]]: "TRIGGER_DEBOUNCE_SECONDS", 10.0, description=( - "Minimum number of seconds between forced full reloads triggered via the API trigger " - "routes (/policy-updater/trigger, /data-updater/trigger and their legacy /update_policy* " - "aliases). Triggers arriving within the window - or while a forced reload is already in " - "flight - coalesce into the in-flight/most-recent pull instead of amplifying load onto the " - "control plane. Set to 0 to disable debouncing (every trigger forces a fresh reload). " + "Debounce window, in seconds, for forced full reloads triggered via the API trigger routes " + "(/policy-updater/trigger, /data-updater/trigger and their legacy /update_policy* aliases). " + "A trigger arriving within this many seconds of the last one - or while a forced reload is " + "already in flight - is coalesced instead of amplifying load onto the control plane, so data " + "served by this PDP may lag a forced trigger by up to this many seconds. Not a hard floor " + "between reloads: a trigger coalesced into an in-flight reload causes one immediate follow-up " + "reload once that one finishes, so a single request can dispatch at most two. Set to 0 to " + "disable the time window; concurrent triggers are still collapsed into a single in-flight " + "reload. Negative, non-numeric and non-finite values also disable it. Clamped to at most 300s; " + "the effective value is logged at startup whenever it differs from what was configured. " "Remote-config overridable fleet-wide, so ops can raise it (e.g. to 30-60s under a degraded " - "control plane) without shipping a release." + "control plane) without shipping a release - but the remote config is fetched once during " + "startup, so a change needs a PDP restart to take effect." ), ) diff --git a/horizon/debounce.py b/horizon/debounce.py index ab027231..7b9fd467 100644 --- a/horizon/debounce.py +++ b/horizon/debounce.py @@ -6,94 +6,215 @@ forced reload amplifies straight onto the shared control plane - exactly when a degraded control plane can least afford it. ``DebouncedTrigger`` holds the small amount of coalescing *state* for one logical updater and decides, per call, whether -to actually run the reload or collapse it into a recent/in-flight one. +to actually dispatch the reload or collapse it into a recent/in-flight one. The class holds only state + policy; the actual reload work is passed in per call (``run``). That lets the canonical and legacy-alias routes share a single instance per updater (so an alternating canonical/legacy hammer still coalesces - both hit the same control-plane resource) while each supplies its own ``run`` closure and its own log context. + +WHAT ``run`` ACTUALLY DOES - read this before reasoning about the guards below. +Both updaters are fire-and-forget underneath, so ``await run()`` returns once the +reload has been *dispatched*, NOT once it has completed: + +* policy - ``PolicyUpdater.trigger_update_policy`` is a single ``await queue.put(...)`` + onto an unbounded ``asyncio.Queue``. It cannot block and cannot fail. The real pull + runs later in ``PolicyUpdater.handle_policy_updates``, which swallows every exception. +* data - ``DataUpdater.get_base_policy_data`` awaits ``_stop_polling_update_tasks()`` + and one data-source config GET, then hands the per-entry fetches to + ``TasksPool.add_task`` (i.e. ``asyncio.create_task``). The retries/backoff configured + via ``DATA_UPDATER_CONN_RETRY`` live inside those spawned tasks. + +Two consequences that the guards below cannot paper over: + +1. ``_last_dispatched`` is a DISPATCH timestamp. A reload that later fails in the + background still consumes the window. There is no "only on success" guarantee to + be had at this layer without an upstream OPAL change. +2. The in-flight window covers the dispatch only - a queue put (policy), or the config + GET plus task hand-off (data). It is still worth having: that config GET has no + explicit timeout and falls back to aiohttp's 5-minute default, so it genuinely can + stall, and the guard is what stops concurrent triggers from piling up behind it. """ +import math import time from collections.abc import Awaitable, Callable from loguru import logger +# Upper bound for the debounce window. The value is remote-config overridable from the +# control plane, so an unclamped fat-finger (a stray "600000") would wedge every forced +# reload fleet-wide with no way to force a sync short of a rollout. Five minutes is far +# beyond any legitimate tuning range (ops guidance tops out around 60s). +MAX_DEBOUNCE_SECONDS: float = 300.0 + + +def clamp_window(window_seconds: float) -> float: + """Normalise a configured debounce window into the range the debouncer honours. + + Coerces defensively rather than trusting the type. ``confi.float`` casts from the + ENVIRONMENT but its ``cast_from_json`` is ``no_cast``, so a remote config override from + the control plane lands on the attribute VERBATIM - ``null`` and ``"30"`` both reach here + unconverted. This function runs at startup as well as per request, so raising on a + fat-fingered override would turn a bad config value into a PDP that will not boot. + A numeric string is honoured; anything genuinely uninterpretable, and any non-finite + value, collapses to 0 (debouncing disabled). The caller logs a warning when the + effective window differs from what was configured. + """ + try: + window = float(window_seconds) + except (TypeError, ValueError): + return 0.0 + if not math.isfinite(window): + return 0.0 + return min(max(window, 0.0), MAX_DEBOUNCE_SECONDS) + class DebouncedTrigger: """Coalesces forced-reload triggers for one logical updater (policy or data). Semantics of :meth:`trigger` (in evaluation order): - * ``window_seconds <= 0`` -> passthrough (debounce disabled): always run. - * A reload is already **in flight** -> coalesce regardless of the window. Under a - degraded control plane a single forced pull can run for minutes (the PDP configures - many retries with exponential backoff), so a pure time-window check would still admit - a *concurrent* full pull every ``window_seconds`` - the in-flight guard is what prevents - that pile-up. - * Otherwise, if the last successful reload was **within the window** -> coalesce. - * Otherwise -> run, recording the completion time **only on success**. - - Recording ``_last_fired`` only on success is deliberate: a failed pull must not burn the - window (a legitimate retry within ``window_seconds`` must still fire), and the exception is - re-raised so the route surfaces it. + * A reload is already **in flight** -> coalesce, and arm the trailing edge. This + guard is unconditional: it applies even when ``window_seconds`` is 0, because + "no time-based damping" should still never mean "two concurrent full pulls". + * Otherwise, if ``window_seconds > 0`` and the last dispatch was **within the + window** -> coalesce. No trailing edge here; staleness is bounded by + ``window_seconds`` by construction, which is the entire point of the knob. + * Otherwise -> dispatch, recording the dispatch time. + + **Trailing edge.** A trigger coalesced by the in-flight guard would otherwise be + lost: the reload it collapsed into may have already read its data before the + caller's change landed, and nothing would schedule a follow-up. Since an in-flight + dispatch has no bounded duration, that staleness would be unbounded too. So the + dispatching call re-runs **once** if any trigger arrived while it was running, + capping the work at two dispatches per call. + + Be precise about what that does and does not promise. It bounds the damage from the + in-flight guard; it is NOT a guarantee that every trigger is eventually served. This + class never schedules future work - it only ever runs inside a caller's request - so + a trigger arriving during the trailing run is coalesced and simply waits for somebody + to trigger again. Closing that last gap needs a background timer task with its own + lifecycle, which is deliberately out of scope here. """ def __init__(self, name: str) -> None: # Short label used purely for logs, e.g. "policy" / "data". self._name = name - # Monotonic seconds of the last *successful* reload; ``None`` until the first one. + # Monotonic seconds of the last *dispatch*; ``None`` until the first one. # Deliberately ``None`` and NEVER ``0.0``: ``time.monotonic()`` is ~seconds since boot # on Linux, so a ``0.0`` sentinel would read as "fired at boot" and silently coalesce # the very first real trigger on a freshly booted host. - self._last_fired: float | None = None - # True while a reload is running under this instance (see the in-flight guard). + self._last_dispatched: float | None = None + # True while a dispatch is running under this instance (see the in-flight guard). self._in_flight: bool = False + # When the current dispatch started, so a coalesce log can report how long the + # thing it is collapsing into has been running. + self._in_flight_since: float | None = None + # Set when the in-flight guard coalesces a trigger; consumed by the trailing edge. + self._pending: bool = False + # Coalesced-since-last-dispatch counter. Keeps the log quiet under the exact + # hammering this class exists to absorb: the first suppression per dispatch logs + # at INFO, the rest at DEBUG, and the dispatch logs the total. + self._coalesced: int = 0 async def trigger(self, run: Callable[[], Awaitable[None]], window_seconds: float) -> bool: - """Run ``run`` (a coroutine factory doing the forced reload) unless it can be coalesced. + """Dispatch ``run`` (a coroutine factory doing the forced reload) unless it can be coalesced. - Returns ``True`` if ``run`` was awaited, ``False`` if the trigger was coalesced into a + Returns ``True`` if ``run`` was dispatched, ``False`` if the trigger was coalesced into a recent/in-flight reload. A coalesced trigger is an immediate no-op success from the caller's perspective - it does NOT await the in-flight reload. """ - # 1. Debounce disabled -> passthrough. Any exception from ``run`` propagates. - if window_seconds <= 0: - await run() - return True + window_seconds = clamp_window(window_seconds) - # 2. In-flight guard: collapse concurrent triggers into the one already running. + # 1. In-flight guard: collapse concurrent triggers into the one already running, and + # arm the trailing edge so this trigger is honoured rather than dropped. if self._in_flight: - logger.info( - "Coalescing {} reload trigger: a forced reload is already in flight; collapsing into it.", - self._name, - ) + self._pending = True + self._note_coalesced("a forced reload is already in flight ({:.1f}s so far)", self._in_flight_age()) return False - # 3. Window guard: collapse triggers that arrive within the debounce window of the - # last successful reload. - if self._last_fired is not None: - elapsed = time.monotonic() - self._last_fired + # 2. Window guard: collapse triggers that arrive within the debounce window of the + # last dispatch. Skipped entirely when the window is disabled (<= 0). + if window_seconds > 0 and self._last_dispatched is not None: + elapsed = time.monotonic() - self._last_dispatched if elapsed < window_seconds: - logger.info( - "Coalescing {} reload trigger: within the {:g}s debounce window ({:.1f}s remaining).", - self._name, - window_seconds, - window_seconds - elapsed, + self._note_coalesced( + "within the {:g}s debounce window ({:.1f}s remaining)", window_seconds, window_seconds - elapsed ) return False - # 4. Fire. Single-worker assumption (the Rust supervisor spawns uvicorn with no + # 3. Dispatch. Single-worker assumption (the Rust supervisor spawns uvicorn with no # --workers -> exactly one event loop): there is NO ``await`` between the guards # above and this set, so the check-then-set is atomic and needs no lock. A second # trigger cannot interleave until we ``await run()`` below, by which point - # ``_in_flight`` is already True and step 2 will coalesce it. + # ``_in_flight`` is already True and step 1 will coalesce it. self._in_flight = True + self._in_flight_since = time.monotonic() + # Clear before running, so anything arriving from here on counts as "arrived during + # this dispatch". NOT cleared in the finally below: if ``run`` raises, a trigger that + # was coalesced into this failed dispatch must stay pending rather than be discarded - + # the next dispatch clears it right here, at the point where it actually serves it. + self._pending = False try: await run() - # Record completion time only on success so a failed pull does not burn the window. - self._last_fired = time.monotonic() + self._last_dispatched = time.monotonic() + self._log_dispatched() + if self._pending: + await self._run_trailing(run) return True finally: self._in_flight = False + self._in_flight_since = None + + async def _run_trailing(self, run: Callable[[], Awaitable[None]]) -> None: + """Re-dispatch once, for triggers that arrived while the first dispatch was running. + + Failures are logged and swallowed, never propagated. The caller executing this re-run + already had its OWN dispatch succeed; handing it a 500 caused by somebody else's + trigger would be both confusing and wrong (its request did what it asked). Losing the + trailing reload is the lesser evil, and it is logged at ERROR. + """ + self._pending = False + logger.info( + "Re-running {} reload (trailing edge): a trigger arrived while the previous one was in flight.", + self._name, + ) + try: + await run() + except Exception: # noqa: BLE001 + logger.opt(exception=True).error( + "Trailing {} reload failed. The triggers it was serving were not applied; " + "the next trigger after the debounce window will retry.", + self._name, + ) + return + self._last_dispatched = time.monotonic() + self._log_dispatched() + + def _log_dispatched(self) -> None: + """Report how many triggers the dispatch that just completed absorbed.""" + if not self._coalesced: + return + logger.info("Dispatched {} reload, absorbing {} coalesced trigger(s).", self._name, self._coalesced) + # Reset only here, on a dispatch that actually completed. A dispatch that raised leaves + # the count standing, so the triggers it failed to serve are still attributed to the + # dispatch that eventually does serve them. + self._coalesced = 0 + + def _in_flight_age(self) -> float: + """Seconds the current dispatch has been running (0.0 when nothing is in flight).""" + if self._in_flight_since is None: + return 0.0 + return time.monotonic() - self._in_flight_since + + def _note_coalesced(self, reason: str, *args: float) -> None: + """Count a coalesced trigger and log it, loudly the first time and quietly thereafter.""" + self._coalesced += 1 + message = "Coalescing {} reload trigger: " + reason + "." + # Only the first suppression per dispatch is worth an INFO line - under a hammer, one + # INFO per suppressed request would make the mitigation amplify log volume into the + # (unbounded, enqueue=True) logzio sink. The dispatch line reports the total. + log = logger.info if self._coalesced == 1 else logger.debug + log(message, self._name, *args) diff --git a/horizon/pdp.py b/horizon/pdp.py index f6518d37..cc731b68 100644 --- a/horizon/pdp.py +++ b/horizon/pdp.py @@ -28,7 +28,7 @@ from horizon.authentication import enforce_pdp_token from horizon.config import MOCK_API_KEY, sidecar_config from horizon.connectivity.api import init_connectivity_router -from horizon.debounce import DebouncedTrigger +from horizon.debounce import MAX_DEBOUNCE_SECONDS, DebouncedTrigger, clamp_window from horizon.enforcer.api import init_enforcer_api_router, init_enforcer_health_router, stats_manager from horizon.enforcer.opa.config_maker import ( get_opa_authz_policy_file_path, @@ -523,6 +523,22 @@ def _configure_trigger_routes(self, app: FastAPI): self._policy_trigger_debounce = DebouncedTrigger("policy") self._data_trigger_debounce = DebouncedTrigger("data") + # Log the EFFECTIVE window, not the configured one: the value is remote-config + # overridable and is clamped to [0, MAX_DEBOUNCE_SECONDS], so a fat-fingered override + # should be visible at startup rather than silently reinterpreted. + effective_window = clamp_window(sidecar_config.TRIGGER_DEBOUNCE_SECONDS) + if effective_window != sidecar_config.TRIGGER_DEBOUNCE_SECONDS: + logger.warning( + "PDP_TRIGGER_DEBOUNCE_SECONDS={} is out of range; clamped to {:g}s (max {:g}s).", + sidecar_config.TRIGGER_DEBOUNCE_SECONDS, + effective_window, + MAX_DEBOUNCE_SECONDS, + ) + elif effective_window > 0: + logger.info("Forced-reload trigger routes are debounced with a {:g}s window.", effective_window) + else: + logger.warning("Forced-reload trigger debouncing is DISABLED (PDP_TRIGGER_DEBOUNCE_SECONDS=0).") + # TODO: remove the two legacy aliases when clients update sdk version. @app.post( "/update_policy", @@ -532,8 +548,8 @@ def _configure_trigger_routes(self, app: FastAPI): ) async def legacy_trigger_policy_update(): logger.info("triggered policy update from api (legacy route)") - await self._debounced_policy_reload() - return {"status": "ok"} + triggered = await self._debounced_policy_reload() + return {"status": "ok", "triggered": triggered} @app.post( "/update_policy_data", @@ -544,8 +560,8 @@ async def legacy_trigger_policy_update(): async def legacy_trigger_data_update(): logger.info("triggered policy data update from api (legacy route)") # Preserve the distinct legacy reason string - a test asserts it verbatim. - await self._debounced_data_reload("request from sdk (legacy alias)") - return {"status": "ok"} + triggered = await self._debounced_data_reload("request from sdk (legacy alias)") + return {"status": "ok", "triggered": triggered} # OpalClient mounted POST /policy-updater/trigger and POST /data-updater/trigger before # the PDP took over; their closures force a FULL reload on every call with no damping. @@ -555,74 +571,101 @@ async def legacy_trigger_data_update(): # route would shadow the replacement and stay ungated/un-debounced. _remove_opal_trigger_routes(app) + # NOTE: keep implementation notes in comments, never in these handlers' docstrings - + # FastAPI publishes a handler docstring as the operation `description` in the + # customer-facing /openapi.json and /scalar explorer. The explicit summary=/description= + # below win over the docstring and are written for that audience. @app.post( "/policy-updater/trigger", status_code=status.HTTP_200_OK, tags=["Policy Updater"], dependencies=[Depends(enforce_pdp_token)], + summary="Trigger a full policy reload", + description=( + "Requests a full policy reload from the control plane. Redundant triggers are " + "coalesced: if a reload was already requested within the debounce window, or one " + "is currently in flight, this call is absorbed into it. Returns 200 either way; " + "`triggered` reports whether this call started a reload (`true`) or was coalesced " + "into an existing one (`false`). **`false` is a success, not a failure - do not " + "retry on it.** It means a reload covering your request is already happening; " + "retrying only adds load to the control plane." + ), ) async def trigger_policy_update(): - """Force a full policy reload, debounced (replaces OpalClient's ungated handler). - - Response parity with the route it replaces: always 200 ``{"status": "ok"}``. The policy - route already had fire-and-forget 200 semantics (the underlying call only *enqueues* an - update), so debouncing changes nothing observable here beyond collapsing redundant - triggers into one reload. - """ + # The reload is dispatched, not awaited to completion: the underlying OPAL call only + # enqueues onto the policy updater's queue. That was already true of the handler this + # replaces, so a 200 means the same thing it always did. logger.info("triggered policy update from api") - await self._debounced_policy_reload() - return {"status": "ok"} + triggered = await self._debounced_policy_reload() + return {"status": "ok", "triggered": triggered} @app.post( "/data-updater/trigger", status_code=status.HTTP_200_OK, tags=["Data Updater"], dependencies=[Depends(enforce_pdp_token)], + summary="Trigger a full base-data reload", + description=( + "Requests a full reload of base policy data from the control plane. Redundant " + "triggers are coalesced: if a reload was already requested within the debounce " + "window, or one is currently in flight, this call is absorbed into it. Returns 200 " + "either way; `triggered` reports whether this call started a reload (`true`) or was " + "coalesced into an existing one (`false`). **`false` is a success, not a failure - " + "do not retry on it.** It means a reload covering your request is already happening; " + "retrying only adds load to the control plane. Returns 503 if the data updater is " + "disabled. This endpoint is a best-effort refresh, not a read-your-writes barrier - " + "use the facts API's `X-Wait-timeout` when you need to block on a specific write." + ), ) async def trigger_data_update(): - """Force a full base-data reload, debounced (replaces OpalClient's ungated handler). - - SEMANTIC SHIFT worth calling out: with the OPAL route a 200 meant the inline base-data - fetch had actually COMPLETED. With debouncing a 200 now means "a recent or in-flight - forced pull already covers you" - the underlying get_base_policy_data may have been - coalesced and not re-run. The body stays exactly ``{"status": "ok"}`` either way so - SDKs polling this route never error-spiral. A disabled data updater still returns 503, - checked BEFORE the debouncer so a 503 never consumes the window. - """ + # Like the policy route, this dispatches rather than completes: get_base_policy_data + # awaits the data-source config GET and then hands the per-entry fetches to a task + # pool. That was already true of the OPAL handler this replaces - a 200 never meant + # the data had landed. A disabled data updater still returns 503, checked BEFORE the + # debouncer so a 503 never consumes the window. logger.info("triggered policy data update from api") - await self._debounced_data_reload("request from sdk") - return {"status": "ok"} + triggered = await self._debounced_data_reload("request from sdk") + return {"status": "ok", "triggered": triggered} - async def _debounced_policy_reload(self) -> None: - """Force a full policy reload through the shared policy debouncer. + async def _debounced_policy_reload(self) -> bool: + """Dispatch a full policy reload through the shared policy debouncer. Backs both /policy-updater/trigger and the /update_policy legacy alias so they coalesce against each other. No None-guard: the PDP never disables the policy updater. + + Returns True if this call dispatched a reload, False if it was coalesced. """ async def _run() -> None: await self._opal.policy_updater.trigger_update_policy(force_full_update=True) - await self._policy_trigger_debounce.trigger(run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS) + return await self._policy_trigger_debounce.trigger( + run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS + ) - async def _debounced_data_reload(self, data_fetch_reason: str) -> None: - """Force a full base-data reload through the shared data debouncer. + async def _debounced_data_reload(self, data_fetch_reason: str) -> bool: + """Dispatch a full base-data reload through the shared data debouncer. Backs both /data-updater/trigger and the /update_policy_data legacy alias (the caller passes the route-specific ``data_fetch_reason``). Raises 503 - exact OpalClient parity - when the data updater is disabled, checked BEFORE the debouncer so a 503 never consumes the window. + + Returns True if this call dispatched a reload, False if it was coalesced. """ - if self._opal.data_updater is None: + data_updater = self._opal.data_updater + if data_updater is None: raise HTTPException( status_code=status.HTTP_503_SERVICE_UNAVAILABLE, detail="Data Updater is currently disabled. Dynamic data updates are not available.", ) async def _run() -> None: - await self._opal.data_updater.get_base_policy_data(data_fetch_reason=data_fetch_reason) + await data_updater.get_base_policy_data(data_fetch_reason=data_fetch_reason) - await self._data_trigger_debounce.trigger(run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS) + return await self._data_trigger_debounce.trigger( + run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS + ) @property def app(self): diff --git a/horizon/tests/test_debounce_unit.py b/horizon/tests/test_debounce_unit.py new file mode 100644 index 00000000..6cf826b7 --- /dev/null +++ b/horizon/tests/test_debounce_unit.py @@ -0,0 +1,440 @@ +"""Unit tests for :class:`horizon.debounce.DebouncedTrigger` (PER-15248). + +``test_trigger_debounce.py`` covers the same coalescing behaviour end-to-end through the real +app; this module drives the state machine directly - no FastAPI, no OpalClient, no TestClient - +so the concurrency-shaped cases (a burst arriving mid-dispatch, the trailing edge, cancellation) +can be sequenced deterministically with ``asyncio.Event``s instead of hoping real requests +interleave the right way. It is also where the pure helper ``clamp_window`` is pinned. + +TIME IS FAKED, NEVER SLEPT. The debouncer reads the clock as ``time.monotonic()`` via the module +global ``horizon.debounce.time``, so the ``clock`` fixture swaps that whole module reference for +a fake. Patching ``time.monotonic`` itself would be patching the *stdlib* function - which is +also the asyncio event loop's clock (``BaseEventLoop.time`` calls it) - and a frozen or rewound +loop clock would break every ``asyncio.wait_for`` timeout below. + +Every test that leaves a dispatch parked inside ``run`` cancels its task in a ``finally``: an +assertion failing mid-test must not leak a task that outlives it (which shows up later as an +unrelated "Task was destroyed but it is pending" against whichever test runs next). +""" + +import asyncio +import math +from collections.abc import Awaitable, Callable, Iterator + +import pytest +from horizon import debounce +from horizon.debounce import MAX_DEBOUNCE_SECONDS, DebouncedTrigger, clamp_window +from loguru import logger + +# Long enough that a real elapsed-time race can never make a "within the window" case flake; +# the fake clock means nothing actually waits for it. +WINDOW = 10.0 +# Timeout for every "the other task should have reached this point by now" wait. Generous +# because it only bounds a hang: on the happy path these resolve on the next loop iteration. +TIMEOUT = 2.0 + + +class FakeClock: + """Stand-in for the ``time`` module as ``horizon.debounce`` uses it (only ``monotonic``). + + Starts well above zero so a test can never accidentally pass because ``_last_dispatched`` + happened to look like the ``None`` sentinel or like "the epoch". + """ + + def __init__(self, now: float = 1_000.0) -> None: + self._now = now + + def monotonic(self) -> float: + return self._now + + def advance(self, seconds: float) -> None: + self._now += seconds + + +@pytest.fixture +def clock(monkeypatch: pytest.MonkeyPatch) -> FakeClock: + fake = FakeClock() + monkeypatch.setattr(debounce, "time", fake) + return fake + + +async def trigger_promptly(trigger: DebouncedTrigger, run: Callable[[], Awaitable[None]], window_seconds: float): + """Issue a trigger that is expected to be coalesced, bounded by ``TIMEOUT``. + + The bound is part of the contract, not just hygiene: a coalesced trigger is documented to + be an immediate no-op success that does NOT await the reload it collapsed into. It is also + what keeps a regression in the guards *failing* instead of *hanging*. A trigger that should + have been coalesced but instead runs ``run`` parks on the same event the in-flight dispatch + is already parked on and never returns - and with no pytest-timeout plugin in this repo, + a bare ``await`` there hangs the whole suite instead of reporting a failure. + """ + return await asyncio.wait_for(trigger.trigger(run=run, window_seconds=window_seconds), timeout=TIMEOUT) + + +@pytest.fixture +def captured_logs() -> Iterator[list[tuple[str, str]]]: + """``(level name, formatted message)`` for every loguru record emitted during the test.""" + records: list[tuple[str, str]] = [] + sink_id = logger.add( + lambda message: records.append((message.record["level"].name, message.record["message"])), + level="DEBUG", + ) + yield records + logger.remove(sink_id) + + +# --- clamp_window: the guard against a fat-fingered remote-config override ---------------- + + +@pytest.mark.parametrize( + ("configured", "expected"), + [ + (-1.0, 0.0), # negative == disabled, not "always coalesce" + (0.0, 0.0), + (0.5, 0.5), + (WINDOW, WINDOW), + (MAX_DEBOUNCE_SECONDS, MAX_DEBOUNCE_SECONDS), # the cap itself is honoured, not clamped off + (MAX_DEBOUNCE_SECONDS + 1, MAX_DEBOUNCE_SECONDS), + (600_000.0, MAX_DEBOUNCE_SECONDS), # the stray-zeroes override the cap exists for + (math.inf, 0.0), # non-finite collapses to "disabled"... + (-math.inf, 0.0), + (math.nan, 0.0), # ...rather than making every comparison silently false + ], +) +def test_clamp_window(configured: float, expected: float): + assert clamp_window(configured) == expected + + +@pytest.mark.asyncio +async def test_window_is_clamped_inside_trigger(clock: FakeClock): + """The clamp is applied per call, so an out-of-range config cannot wedge the debouncer.""" + trigger = DebouncedTrigger("policy") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + + huge = 600_000.0 + assert await trigger.trigger(run=run, window_seconds=huge) is True + + clock.advance(MAX_DEBOUNCE_SECONDS - 1) + assert await trigger.trigger(run=run, window_seconds=huge) is False + + # Past the CAP - not past the configured 600000s - the next trigger fires again. + clock.advance(2.0) + assert await trigger.trigger(run=run, window_seconds=huge) is True + assert calls == 2 + + +# --- the window guard, and what the return value means ------------------------------------ + + +@pytest.mark.asyncio +async def test_returns_true_when_dispatched_and_false_when_coalesced(clock: FakeClock): + trigger = DebouncedTrigger("policy") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + assert calls == 1 + + clock.advance(WINDOW - 0.001) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + assert calls == 1 + + # Boundary: the guard is `elapsed < window`, so at exactly one window the trigger fires. + clock.advance(0.001) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + assert calls == 2 + + +@pytest.mark.asyncio +async def test_window_is_consumed_by_the_dispatch_not_by_the_reload_succeeding(clock: FakeClock): + """``_last_dispatched`` is a DISPATCH timestamp - there is no "only on success" guarantee. + + Both real updaters are fire-and-forget: ``trigger_update_policy`` is a queue put, and + ``get_base_policy_data`` hands the per-entry fetches to a task pool. ``run`` returning + therefore means "handed off", and a reload that fails afterwards in a background task is + invisible from here - so it still consumes the window. The only failure this layer can + observe is one raised out of ``run`` itself (see the cancellation/raise tests below). + """ + trigger = DebouncedTrigger("data") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + # Stands in for the real hand-off: returns immediately, whatever happens next. + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + assert trigger._last_dispatched is not None + + clock.advance(1.0) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + assert calls == 1 + + +@pytest.mark.asyncio +async def test_zero_window_lets_every_sequential_trigger_through(): + # No `clock` fixture: with the window disabled the guard never reads the clock at all. + trigger = DebouncedTrigger("policy") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + + for _ in range(3): + assert await trigger.trigger(run=run, window_seconds=0) is True + assert calls == 3 + + +# --- the in-flight guard, which is unconditional ------------------------------------------- + + +@pytest.mark.asyncio +async def test_in_flight_guard_applies_even_with_the_window_disabled(): + """``window_seconds=0`` disables the TIME guard only. + + "No time-based damping" must never mean "two concurrent full pulls", so the in-flight guard + is checked before - and independently of - the window. This is the case the pre-rewrite code + got wrong: it returned early on ``window_seconds <= 0`` and bypassed the guard entirely. + """ + trigger = DebouncedTrigger("policy") + calls = 0 + started = asyncio.Event() + release = asyncio.Event() + + async def run() -> None: + nonlocal calls + calls += 1 + started.set() + await release.wait() + + dispatch = asyncio.create_task(trigger.trigger(run=run, window_seconds=0)) + try: + await asyncio.wait_for(started.wait(), timeout=TIMEOUT) + assert await trigger_promptly(trigger, run, window_seconds=0) is False + assert calls == 1 + + release.set() + assert await asyncio.wait_for(dispatch, timeout=TIMEOUT) is True + finally: + release.set() + if not dispatch.done(): + dispatch.cancel() + + # The coalesced trigger armed the trailing edge, so it was honoured rather than dropped. + assert calls == 2 + + +@pytest.mark.asyncio +async def test_concurrent_burst_collapses_into_a_single_dispatch(): + """The load-amplification case: N simultaneous triggers must not become N control-plane pulls.""" + trigger = DebouncedTrigger("data") + calls = 0 + started = asyncio.Event() + release = asyncio.Event() + + async def run() -> None: + nonlocal calls + calls += 1 + started.set() + await release.wait() + + burst = asyncio.gather(*(trigger.trigger(run=run, window_seconds=0) for _ in range(5))) + try: + await asyncio.wait_for(started.wait(), timeout=TIMEOUT) + # By the time the first dispatch has parked inside `run`, the other four have already + # run and been coalesced behind the in-flight guard. + assert calls == 1 + + release.set() + results = await asyncio.wait_for(burst, timeout=TIMEOUT) + finally: + release.set() + if not burst.done(): + burst.cancel() + + assert results.count(True) == 1, f"exactly one call should report a dispatch, got {results}" + assert results.count(False) == 4, f"the other four should report a coalesce, got {results}" + # Two dispatches, not five: the original plus the single trailing edge covering all four + # absorbed triggers. + assert calls == 2 + + +# --- the trailing edge ---------------------------------------------------------------------- + + +@pytest.mark.asyncio +async def test_trailing_edge_fires_exactly_once_and_is_not_re_armed(): + """Triggers absorbed in flight get ONE follow-up run, and that run cannot chain another. + + Without the trailing edge a trigger coalesced by the in-flight guard is simply lost: the + reload it collapsed into may already have read its data before the caller's change landed. + With an unbounded trailing edge, a sustained hammer would keep re-arming it and never let + the dispatch finish. So: two runs per call, maximum. + """ + trigger = DebouncedTrigger("policy") + # Three slots so a (buggy) third run has somewhere to go and can be asserted against, + # rather than blowing up with an IndexError that reads like an unrelated failure. + entered = [asyncio.Event() for _ in range(3)] + gates = [asyncio.Event() for _ in range(3)] + calls = 0 + + async def run() -> None: + nonlocal calls + index = calls + calls += 1 + entered[index].set() + await gates[index].wait() + + dispatch = asyncio.create_task(trigger.trigger(run=run, window_seconds=0)) + try: + await asyncio.wait_for(entered[0].wait(), timeout=TIMEOUT) + + # Two triggers absorbed by the in-flight guard must produce ONE trailing run, not two. + assert await trigger_promptly(trigger, run, window_seconds=0) is False + assert await trigger_promptly(trigger, run, window_seconds=0) is False + + gates[0].set() + await asyncio.wait_for(entered[1].wait(), timeout=TIMEOUT) + assert calls == 2 + + # A trigger arriving during the TRAILING run is still coalesced (the guard is on + # `_in_flight`, which is still set) but the trailing edge is spent, so it must not + # schedule a further run - staleness from here is bounded by the window guard. + assert await trigger_promptly(trigger, run, window_seconds=0) is False + + gates[1].set() + assert await asyncio.wait_for(dispatch, timeout=TIMEOUT) is True + finally: + for gate in gates: + gate.set() + if not dispatch.done(): + dispatch.cancel() + + assert calls == 2 + assert not entered[2].is_set(), "the trailing edge re-armed itself; dispatches are not capped at two" + + +@pytest.mark.asyncio +async def test_no_trailing_edge_when_nothing_arrived_mid_dispatch(): + trigger = DebouncedTrigger("policy") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + # A real suspension point, so a concurrent trigger *could* have interleaved here. + # Nothing does, so the trailing edge must stay disarmed. + await asyncio.sleep(0) + + assert await trigger.trigger(run=run, window_seconds=0) is True + assert calls == 1 + assert trigger._pending is False + assert trigger._in_flight is False + + +# --- failure paths: the guards must never wedge -------------------------------------------- + + +@pytest.mark.asyncio +async def test_cancelling_a_dispatch_resets_in_flight_and_records_no_dispatch(): + """A cancelled dispatch (client disconnect, shutdown) must not leave the guard stuck on. + + ``_in_flight`` is cleared by the ``finally``; ``_last_dispatched`` is assigned only after + ``await run()`` *returns*, which cancellation prevents. So the debouncer is left exactly as + it was before the call, and ``CancelledError`` still propagates to the caller. + """ + trigger = DebouncedTrigger("data") + started = asyncio.Event() + never = asyncio.Event() + + async def run() -> None: + started.set() + await never.wait() # only cancellation ends this + + dispatch = asyncio.create_task(trigger.trigger(run=run, window_seconds=0)) + try: + await asyncio.wait_for(started.wait(), timeout=TIMEOUT) + finally: + dispatch.cancel() + + with pytest.raises(asyncio.CancelledError): + await dispatch + + assert trigger._in_flight is False + assert trigger._last_dispatched is None + assert trigger._pending is False + + # Not wedged: the next trigger dispatches instead of coalescing forever. + calls = 0 + + async def run_again() -> None: + nonlocal calls + calls += 1 + + assert await trigger.trigger(run=run_again, window_seconds=WINDOW) is True + assert calls == 1 + + +@pytest.mark.asyncio +async def test_a_run_that_raises_propagates_and_records_no_dispatch(): + # No `clock` fixture: nothing here needs time to move, which is precisely the point - the + # retry below is admitted because no dispatch was ever recorded, not because time passed. + trigger = DebouncedTrigger("data") + + async def boom() -> None: + raise RuntimeError("dispatch failed") + + with pytest.raises(RuntimeError, match="dispatch failed"): + await trigger.trigger(run=boom, window_seconds=WINDOW) + + assert trigger._last_dispatched is None + assert trigger._in_flight is False + + # ...so an immediate retry inside the window is NOT coalesced. + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + assert calls == 1 + + +# --- logging: the mitigation must not amplify log volume ----------------------------------- + + +@pytest.mark.asyncio +async def test_coalesce_logging_is_loud_once_then_quiet(clock: FakeClock, captured_logs: list[tuple[str, str]]): + """Under the exact hammering this class absorbs, one INFO per suppressed request would just + move the amplification from the control plane to the (unbounded, enqueue=True) log sink.""" + trigger = DebouncedTrigger("policy") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + for _ in range(3): + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + + coalesce_levels = [level for level, message in captured_logs if message.startswith("Coalescing")] + assert coalesce_levels == ["INFO", "DEBUG", "DEBUG"] + + # The DEBUG lines are not a blind spot: the next dispatch reports the absorbed total. + clock.advance(WINDOW + 1) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + assert calls == 2 + assert ("INFO", "Dispatched policy reload, absorbing 3 coalesced trigger(s).") in captured_logs + + # ...and the counter resets, so the next burst is reported on its own terms. + assert trigger._coalesced == 0 diff --git a/horizon/tests/test_legacy_update_routes.py b/horizon/tests/test_legacy_update_routes.py index 8cbcdc68..dd3094fd 100644 --- a/horizon/tests/test_legacy_update_routes.py +++ b/horizon/tests/test_legacy_update_routes.py @@ -30,7 +30,10 @@ def test_update_policy_triggers_updater(pdp: MockPermitPDP, auth: dict[str, str] response = TestClient(pdp._app).post("/update_policy", headers=auth, follow_redirects=False) assert response.status_code == 200 - assert response.json() == {"status": "ok"} + # `triggered` reports whether THIS call dispatched a reload; a fresh PDP has no recent + # dispatch to coalesce into, so the first call always dispatches. The coalescing cases + # (triggered=false) live in test_trigger_debounce.py. + assert response.json() == {"status": "ok", "triggered": True} trigger.assert_awaited_once_with(force_full_update=True) @@ -59,7 +62,7 @@ def test_update_policy_data_triggers_updater(pdp: MockPermitPDP, auth: dict[str, response = TestClient(pdp._app).post("/update_policy_data", headers=auth, follow_redirects=False) assert response.status_code == 200 - assert response.json() == {"status": "ok"} + assert response.json() == {"status": "ok", "triggered": True} get_base.assert_awaited_once_with(data_fetch_reason="request from sdk (legacy alias)") diff --git a/horizon/tests/test_opal_trigger_auth.py b/horizon/tests/test_opal_trigger_auth.py index e0937249..fce77629 100644 --- a/horizon/tests/test_opal_trigger_auth.py +++ b/horizon/tests/test_opal_trigger_auth.py @@ -17,6 +17,7 @@ from fastapi import FastAPI from fastapi.testclient import TestClient from horizon.config import sidecar_config +from horizon.debounce import DebouncedTrigger from horizon.enforcer.api import stats_manager from horizon.pdp import PermitPDP, _warn_if_opal_verifier_disabled from loguru import logger @@ -41,6 +42,26 @@ def __init__(self): _sidecar = MockPermitPDP() +@pytest.fixture(autouse=True) +def _reset_trigger_debouncers() -> None: + """Give every test in this module a clean debounce state. + + ``_sidecar`` is module-level because building an OpalClient per test is slow, and since + PER-15248 a PermitPDP instance carries MUTABLE debounce state: a trigger that reaches the + handler records a dispatch, and for the next ``TRIGGER_DEBOUNCE_SECONDS`` (default 10) + every further trigger on that updater is coalesced into it and never touches the updater. + + That turns this shared instance into an order-dependent trap. The policy trigger below + genuinely succeeds even offline (``trigger_update_policy`` is just a queue put), so a + second policy-triggering test added to this module would be silently coalesced and fail + with a baffling "Awaited 0 times" - or pass or fail depending on which test ran first. + Swapping in fresh DebouncedTriggers is far cheaper than a fresh PDP and keeps every test + here independent of the ones before it. + """ + _sidecar._policy_trigger_debounce = DebouncedTrigger("policy") + _sidecar._data_trigger_debounce = DebouncedTrigger("data") + + @pytest.fixture def client() -> TestClient: # No context manager -> lifespan/startup never runs -> no network. @@ -66,6 +87,16 @@ def test_trigger_route_with_valid_token_is_not_blocked(client: TestClient, path: assert resp.status_code != status.HTTP_401_UNAUTHORIZED +def test_debounce_state_does_not_leak_between_tests(): + """Teeth for the autouse reset above - this test runs *after* the trigger tests. + + Without the reset, the policy trigger they just made would still be recorded here and the + next test to call that route would be coalesced instead of reaching the updater. + """ + assert _sidecar._policy_trigger_debounce._last_dispatched is None + assert _sidecar._data_trigger_debounce._last_dispatched is None + + @pytest.mark.parametrize("path", TRIGGER_ROUTES) def test_trigger_route_with_wrong_token_is_401(client: TestClient, path: str): resp = client.post(path, headers=_auth("wrong-token")) diff --git a/horizon/tests/test_route_auth_audit.py b/horizon/tests/test_route_auth_audit.py index e1d2eeb0..0c652d80 100644 --- a/horizon/tests/test_route_auth_audit.py +++ b/horizon/tests/test_route_auth_audit.py @@ -25,7 +25,8 @@ from fastapi.routing import APIRoute from horizon.authentication import PUBLIC_ROUTE_PATHS, enforce_pdp_token from horizon.config import sidecar_config -from horizon.pdp import OPAL_TRIGGER_ROUTE_PATHS, PermitPDP +from horizon.pdp import OPAL_TRIGGER_ROUTE_PATHS, PermitPDP, _remove_opal_trigger_routes +from horizon.system.consts import GUNICORN_EXIT_APP from opal_client.client import OpalClient from starlette.routing import Route @@ -103,12 +104,50 @@ def test_no_route_is_unprotected(): @pytest.mark.parametrize("path", sorted(OPAL_TRIGGER_ROUTE_PATHS)) def test_opal_trigger_route_is_pdp_gated(path: str): """Regression guard for the actual fix: the OPAL-mounted trigger routes require the PDP token.""" - by_path = {route.path: route for route in _sidecar._app.routes if isinstance(route, APIRoute)} - assert path in by_path, ( + # Collect ALL routes at this path rather than a dict keyed by path: a dict is last-wins and + # would happily hide a surviving OPAL duplicate behind the PDP replacement, which is the one + # failure mode this test exists to catch. + matches = [route for route in _sidecar._app.routes if isinstance(route, APIRoute) and route.path == path] + assert matches, ( f"{path} is no longer mounted (OPAL rename?) - _remove_opal_trigger_routes / " "_configure_trigger_routes must be updated" ) - assert "enforce_pdp_token" in _route_auth_gates(by_path[path]) + # Exactly one, because Starlette matches first-wins: a leftover OPAL route at the same path + # would SHADOW the replacement and stay ungated and un-debounced - the removal silently + # failing open is indistinguishable from success by any per-route assertion. + assert len(matches) == 1, f"{len(matches)} routes mounted at {path}; _remove_opal_trigger_routes missed one" + + route = matches[0] + # ...and the survivor is the PDP's handler, not OPAL's (opal_client.policy.api / + # opal_client.data.api), so "gated" cannot be satisfied by an OPAL route that merely + # happens to carry a dependency. + assert route.endpoint.__module__ == "horizon.pdp", ( + f"{path} is served by {route.endpoint.__module__}.{route.endpoint.__name__}, not horizon.pdp" + ) + assert "enforce_pdp_token" in _route_auth_gates(route) + + +@pytest.mark.parametrize("present", [(), ("/policy-updater/trigger",), ("/data-updater/trigger",)]) +def test_remove_opal_trigger_routes_exits_when_a_path_is_missing(present: tuple[str, ...]): + """Fail loud, never fail open: a trigger route the PDP cannot find must stop the process. + + If OPAL renames or drops one of these paths, the removal silently no-ops and the caller + re-registers only its replacement - leaving OPAL's original ungated, un-debounced handler + mounted under the new name. That reopens exactly the auth + amplification hole this + replacement closes, so ``_remove_opal_trigger_routes`` exits instead (gunicorn's + "don't restart me" code, so the container fails rather than crash-loops silently). + """ + + async def _stub() -> dict: + return {} + + app = FastAPI() + for path in present: + app.post(path)(_stub) + + with pytest.raises(SystemExit) as exit_info: + _remove_opal_trigger_routes(app) + assert exit_info.value.code == GUNICORN_EXIT_APP def test_audit_detects_a_bare_ungated_route(): diff --git a/horizon/tests/test_trigger_debounce.py b/horizon/tests/test_trigger_debounce.py index a30e9c56..27cc8350 100644 --- a/horizon/tests/test_trigger_debounce.py +++ b/horizon/tests/test_trigger_debounce.py @@ -8,11 +8,19 @@ per test (so each gets its own debounce state), a ``TestClient``, and ``AsyncMock``s monkeypatched onto the underlying updater methods. +All four routes answer 200 ``{"status": "ok", "triggered": }``: ``triggered`` is true +when the call dispatched a reload and false when it was absorbed into a recent or in-flight +one. A coalesced call is a success, not an error - SDKs polling these routes must never +error-spiral - so the status code alone cannot distinguish the two and every assertion below +checks the body. + The debounce window is read from ``sidecar_config.TRIGGER_DEBOUNCE_SECONDS`` at call time, so -each test sets it via ``monkeypatch.setattr`` (monkeypatch reverts it at teardown). +each test sets it via ``monkeypatch.setattr`` (monkeypatch reverts it at teardown). The unit +tests in ``test_debounce_unit.py`` cover the same state machine directly, with a fake clock. """ import asyncio +import time from unittest.mock import AsyncMock import pytest @@ -26,6 +34,12 @@ from test_enforcer_api import MockPermitPDP WINDOW = 10.0 +# Bounds a hang rather than a real wait: on the happy path these resolve immediately. +TIMEOUT = 2.0 + +# The two possible bodies. Naming them keeps every assertion below about WHICH one came back. +DISPATCHED = {"status": "ok", "triggered": True} +COALESCED = {"status": "ok", "triggered": False} @pytest.fixture @@ -52,8 +66,10 @@ def test_policy_triggers_within_window_coalesce(pdp: MockPermitPDP, auth: dict[s first = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) second = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) - assert first.status_code == 200 and first.json() == {"status": "ok"} - assert second.status_code == 200 and second.json() == {"status": "ok"} + assert first.status_code == 200 + assert first.json() == DISPATCHED + assert second.status_code == 200 + assert second.json() == COALESCED # Second call coalesced: the updater was forced exactly once. trigger.assert_awaited_once_with(force_full_update=True) @@ -67,8 +83,10 @@ def test_data_triggers_within_window_coalesce(pdp: MockPermitPDP, auth: dict[str first = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) second = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) - assert first.status_code == 200 and first.json() == {"status": "ok"} - assert second.status_code == 200 and second.json() == {"status": "ok"} + assert first.status_code == 200 + assert first.json() == DISPATCHED + assert second.status_code == 200 + assert second.json() == COALESCED get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") @@ -83,7 +101,10 @@ def test_canonical_and_legacy_policy_share_one_debouncer(pdp: MockPermitPDP, aut canonical = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) legacy = client.post("/update_policy", headers=auth, follow_redirects=False) - assert canonical.status_code == 200 and legacy.status_code == 200 + assert canonical.status_code == 200 + assert canonical.json() == DISPATCHED + assert legacy.status_code == 200 + assert legacy.json() == COALESCED trigger.assert_awaited_once_with(force_full_update=True) @@ -96,7 +117,10 @@ def test_canonical_and_legacy_data_share_one_debouncer(pdp: MockPermitPDP, auth: canonical = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) legacy = client.post("/update_policy_data", headers=auth, follow_redirects=False) - assert canonical.status_code == 200 and legacy.status_code == 200 + assert canonical.status_code == 200 + assert canonical.json() == DISPATCHED + assert legacy.status_code == 200 + assert legacy.json() == COALESCED # The canonical call fired first, so its reason string is the one that ran; the legacy # call coalesced and never invoked the updater with its own "(legacy alias)" reason. get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") @@ -111,71 +135,127 @@ def test_trigger_fires_again_after_window_elapses(pdp: MockPermitPDP, auth: dict monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", trigger) client = TestClient(pdp._app) - assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + first = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) + assert first.status_code == 200 + assert first.json() == DISPATCHED assert trigger.await_count == 1 - # Rewind the debouncer's last-fired past the window (no real sleep): the next trigger + # Rewind the debouncer's last dispatch past the window (no real sleep): the next trigger # now sees the window as elapsed and fires. - pdp._policy_trigger_debounce._last_fired -= WINDOW + 1 + pdp._policy_trigger_debounce._last_dispatched -= WINDOW + 1 - assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + second = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) + assert second.status_code == 200 + assert second.json() == DISPATCHED assert trigger.await_count == 2 -# --- case 3: window == 0 disables debouncing (passthrough on every call) ------------------ +# --- case 3: window == 0 disables the TIME window (sequential triggers all pass through) -- -def test_zero_window_passes_every_trigger_through(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): +def test_zero_window_passes_every_sequential_trigger_through(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + # Note the scope: 0 disables the time window only. Concurrent triggers are still collapsed + # by the in-flight guard (test_in_flight_guard_applies_even_with_the_window_disabled in + # test_debounce_unit.py); these calls are sequential, so each completes before the next. monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", 0) trigger = AsyncMock() monkeypatch.setattr(pdp._opal.policy_updater, "trigger_update_policy", trigger) client = TestClient(pdp._app) for _ in range(3): - assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + response = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) + assert response.status_code == 200 + assert response.json() == DISPATCHED assert trigger.await_count == 3 -# --- case 4: an in-flight reload coalesces later triggers regardless of the window -------- +# --- case 4: the in-flight guard is checked BEFORE the window, so it wins even when the --- +# --- window has fully elapsed ------------------------------------------------------------ @pytest.mark.asyncio -async def test_in_flight_reload_coalesces_even_past_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): +async def test_in_flight_guard_beats_an_elapsed_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + """Set both conditions at once: a reload in flight AND a window that has already elapsed. + + Getting there needs three triggers, because a dispatch records ``_last_dispatched`` only + when it *returns* - so while the first reload is still in flight the window guard has + nothing to compare against and would admit everything on its own. This test therefore lets + one trigger complete, rewinds its timestamp past the window, and only then parks a second + trigger in flight. The third trigger is the interesting one: the window guard would let it + through, so anything that coalesces it must be the in-flight guard. + """ monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) - started = asyncio.Event() # set once the reload is genuinely running - release = asyncio.Event() # keeps the reload in flight until the test releases it + started = asyncio.Event() # set once the second reload is genuinely running + release = asyncio.Event() # keeps that reload in flight until the test releases it async def blocking(**_kwargs) -> None: started.set() await release.wait() - get_base = AsyncMock(side_effect=blocking) + get_base = AsyncMock() monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) + debouncer = pdp._data_trigger_debounce transport = ASGITransport(app=pdp._app) async with AsyncClient(transport=transport, base_url="http://test") as client: - # Fire the first trigger and let it block inside the underlying reload. - first = asyncio.create_task(client.post("/data-updater/trigger", headers=auth)) - await asyncio.wait_for(started.wait(), timeout=2) - - # The window guard would admit this (last_fired is still None because the first pull - # has not completed), but the in-flight guard must coalesce it: no second pull. - second = await client.post("/data-updater/trigger", headers=auth) - assert second.status_code == 200 and second.json() == {"status": "ok"} - assert get_base.await_count == 1 - - # Release the in-flight reload and confirm the first request completes cleanly. - release.set() - first_response = await first - assert first_response.status_code == 200 and first_response.json() == {"status": "ok"} - assert get_base.await_count == 1 - - -# --- case 5: a failed reload does not burn the window (immediate retry still fires) ------- - - -def test_failed_reload_does_not_burn_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + # 1. A first, non-blocking trigger completes and records a dispatch timestamp... + first = await client.post("/data-updater/trigger", headers=auth) + assert first.json() == DISPATCHED + # ...which we rewind past the window, so from here the window guard would ADMIT. + debouncer._last_dispatched -= WINDOW + 1 + + # 2. A second trigger parks inside the reload. It cannot refresh the timestamp while + # it is in flight, so the window stays elapsed underneath it. + get_base.side_effect = blocking + second = asyncio.create_task(client.post("/data-updater/trigger", headers=auth)) + try: + await asyncio.wait_for(started.wait(), timeout=TIMEOUT) + assert debouncer._in_flight is True + assert time.monotonic() - debouncer._last_dispatched > WINDOW, ( + "the window must be elapsed, otherwise the window guard could be doing the coalescing" + ) + + # 3. The third trigger: only the in-flight guard can account for this coalesce. + # Bounded by wait_for because that bound is part of the contract - a coalesced + # trigger returns immediately and never awaits the reload it collapsed into. It + # also keeps a regression here failing rather than HANGING: a third call that + # wrongly dispatched would park on `release`, which nothing has set yet, and + # this repo has no pytest-timeout plugin to rescue the run. + third = await asyncio.wait_for(client.post("/data-updater/trigger", headers=auth), timeout=TIMEOUT) + assert third.status_code == 200 + assert third.json() == COALESCED + assert get_base.await_count == 2 + + release.set() + second_response = await asyncio.wait_for(second, timeout=TIMEOUT) + finally: + # An assertion above failing must not leave the request task parked in `run`. + release.set() + if not second.done(): + second.cancel() + + assert second_response.status_code == 200 + assert second_response.json() == DISPATCHED + # The coalesced third trigger armed the trailing edge, so the in-flight dispatch re-ran + # exactly once after completing rather than dropping that trigger on the floor. + assert get_base.await_count == 3 + + +# --- case 5: a dispatch that RAISES propagates and does not consume the window ------------ + + +def test_raising_dispatch_500s_and_does_not_consume_the_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + """The narrow, honest version of the deleted "a failed pull does not burn the window" claim. + + ``_last_dispatched`` is assigned only after ``await run()`` RETURNS, so an exception raised + out of the dispatch skips it and an immediate retry still fires. But note how little that + covers: both updaters are fire-and-forget underneath (a queue put for policy; a config GET + plus a task hand-off for data), so a reload that is dispatched and then fails in the + background returns normally here and DOES consume the window. See + ``test_window_is_consumed_by_the_dispatch_not_by_the_reload_succeeding`` in + test_debounce_unit.py for that half of the contract. + """ monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) get_base = AsyncMock(side_effect=RuntimeError("boom")) monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) @@ -184,10 +264,12 @@ def test_failed_reload_does_not_burn_window(pdp: MockPermitPDP, auth: dict[str, first = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) assert first.status_code == 500 - # Failure must not record last_fired... - assert pdp._data_trigger_debounce._last_fired is None + assert pdp._data_trigger_debounce._last_dispatched is None + # The `finally` still clears the in-flight flag, so a raise cannot wedge the debouncer into + # coalescing every future trigger. + assert pdp._data_trigger_debounce._in_flight is False - # ...so an immediate retry within the window still fires (is not coalesced). + # ...so an immediate retry within the window is not coalesced: it dispatches (and 500s again). second = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) assert second.status_code == 500 assert get_base.await_count == 2 @@ -209,13 +291,14 @@ def test_disabled_data_updater_503s_before_debouncer(pdp: MockPermitPDP, auth: d assert disabled.status_code == 503 assert disabled.json()["detail"] == "Data Updater is currently disabled. Dynamic data updates are not available." # The 503 must not have consumed the window. - assert pdp._data_trigger_debounce._last_fired is None + assert pdp._data_trigger_debounce._last_dispatched is None get_base.assert_not_awaited() # Re-enable: because the 503 never touched the debouncer, the next trigger fires. monkeypatch.setattr(pdp._opal, "data_updater", original_updater) enabled = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) assert enabled.status_code == 200 + assert enabled.json() == DISPATCHED get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") @@ -231,8 +314,10 @@ def test_policy_and_data_debouncers_are_independent(pdp: MockPermitPDP, auth: di client = TestClient(pdp._app) # Firing policy must not consume the data window: both fire within the same window. - assert client.post("/policy-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 - assert client.post("/data-updater/trigger", headers=auth, follow_redirects=False).status_code == 200 + policy = client.post("/policy-updater/trigger", headers=auth, follow_redirects=False) + data = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert policy.json() == DISPATCHED + assert data.json() == DISPATCHED policy_trigger.assert_awaited_once_with(force_full_update=True) data_get_base.assert_awaited_once_with(data_fetch_reason="request from sdk") @@ -245,6 +330,7 @@ def test_debounce_state_is_per_pdp_instance(auth: dict[str, str], monkeypatch): monkeypatch.setattr(pdp_a._opal.policy_updater, "trigger_update_policy", trigger_a) resp_a = TestClient(pdp_a._app).post("/policy-updater/trigger", headers=auth, follow_redirects=False) assert resp_a.status_code == 200 + assert resp_a.json() == DISPATCHED trigger_a.assert_awaited_once() # A brand-new instance carries its own debounce state, so its first trigger always fires, @@ -254,6 +340,7 @@ def test_debounce_state_is_per_pdp_instance(auth: dict[str, str], monkeypatch): monkeypatch.setattr(pdp_b._opal.policy_updater, "trigger_update_policy", trigger_b) resp_b = TestClient(pdp_b._app).post("/policy-updater/trigger", headers=auth, follow_redirects=False) assert resp_b.status_code == 200 + assert resp_b.json() == DISPATCHED trigger_b.assert_awaited_once() From 2b3be4bcc2f2b14ab1899ca9a7fe5cb35c06c118 Mon Sep 17 00:00:00 2001 From: David Shoen Date: Mon, 17 Aug 2026 20:51:58 -0400 Subject: [PATCH 4/4] fix: address review findings on trigger debounce (PER-15248) Zeev's review raised 7 non-blocking findings. All are real; six are fixed as suggested, one is fixed differently because the suggested remedy regresses. The three MEDIUMs are coupled and land together: * A failed dispatch now consumes the debounce window. `_last_dispatched` is stamped in a `finally` rather than after `await run()` succeeds, so a control plane returning 5xx (get_policy_data_config raises ClientError on any non-200) is damped instead of admitting a fresh GET per request. Cancellation is the one exception: the attempt was abandoned, not made. * A window-coalesced trigger is no longer dropped. Both guards now arm a trailing run that fires at window expiry, so "staleness is bounded by window_seconds" is a guarantee rather than a comment. Dropping it lost the refresh permanently - the PDP is pubsub-driven with no periodic full-refresh - which PER-15248 explicitly forbids. Shipping the window change without this would turn a hard failure into a 200 {"triggered": false} for a reload that never happens. * The trailing run moved off the request path into a task. It used to be awaited inline by whichever caller won the dispatch, billing that caller for a second full reload it never asked for, against the 60s client timeout of the Rust server that fronts horizon. The chain terminates: `_pending` is written by `trigger()` alone, so chain length is bounded by real triggers. Not taken: wrapping `run()` in `asyncio.wait_for` to bound the in-flight guard. `get_base_policy_data` tears down every periodic poller (updater.py:268) before the unbounded config GET and only recreates them at the end (:296), so a timeout landing on the stalled GET would kill periodic data updates outright, with no error and no recovery short of an OPAL reconnect - open-ended silent staleness in place of a bounded, self-healing stall. The stall is made observable instead: past MAX_DISPATCH_SECONDS every coalesce logs at ERROR. Remaining findings: * clamp_window fails safe. An uninterpretable remote override (null, "tem", a negative) now falls back to the default instead of 0, so a control-plane typo can no longer switch the mitigation off fleet-wide; only an explicit, parseable 0 disables it. resolve_window reports why a value changed, which kills the false "out of range; clamped" warning a valid JSON-string override used to trigger (confi's cast_from_json is no_cast). The default is single-sourced in debounce.py; config.py imports it (one-way edge). * TriggerResponse is declared as a response_model on all four routes, so `triggered` appears in /openapi.json instead of an empty 200 schema, and the data route documents its 502/503/504. Runtime validation keeps all four bodies in lockstep. Its docstring is customer-facing; rationale lives in comments. * A failed control-plane fetch answers 502 (504 on timeout) with Retry-After, not a bare 500 - the one code every SDK and mesh retries. 502/504 matches horizon/enforcer/api.py and keeps 503 meaning "data updater disabled", a permanent config state a client must be able to tell apart. Retry-After is the window, since the failed attempt just consumed it. Also fixed a bug found reviewing this change: cancellation during the trailing run's wait bypassed the inner handler, so aclose() - which usually finds the task waiting, with `_pending` still set - armed a replacement task mid-teardown. Test added; it fails without the fix. 183 passed; ruff check and ruff format clean. Co-Authored-By: Claude Opus 5 (1M context) --- horizon/config.py | 25 +- horizon/debounce.py | 341 +++++++++++--- horizon/pdp.py | 169 +++++-- horizon/tests/test_debounce_unit.py | 592 +++++++++++++++++++++---- horizon/tests/test_trigger_debounce.py | 186 ++++++-- 5 files changed, 1092 insertions(+), 221 deletions(-) diff --git a/horizon/config.py b/horizon/config.py index 5d4edfa4..8b31af82 100644 --- a/horizon/config.py +++ b/horizon/config.py @@ -4,6 +4,11 @@ from opal_common.schemas.data import CallbackEntry from pydantic import parse_obj_as, parse_raw_as +# One-way import edge, config -> debounce: the default lives beside the clamp that falls back +# to it, so a value this module declares and a value the debouncer substitutes can never drift. +# horizon.debounce must never import this module back (it takes its window as a parameter). +from horizon.debounce import DEFAULT_DEBOUNCE_SECONDS + MOCK_API_KEY = "MUST BE DEFINED" @@ -290,21 +295,23 @@ def parse_plugins(value: Any) -> dict[str, dict[str, int | bool | str]]: TRIGGER_DEBOUNCE_SECONDS = confi.float( "TRIGGER_DEBOUNCE_SECONDS", - 10.0, + DEFAULT_DEBOUNCE_SECONDS, description=( "Debounce window, in seconds, for forced full reloads triggered via the API trigger routes " "(/policy-updater/trigger, /data-updater/trigger and their legacy /update_policy* aliases). " "A trigger arriving within this many seconds of the last one - or while a forced reload is " "already in flight - is coalesced instead of amplifying load onto the control plane, so data " - "served by this PDP may lag a forced trigger by up to this many seconds. Not a hard floor " - "between reloads: a trigger coalesced into an in-flight reload causes one immediate follow-up " - "reload once that one finishes, so a single request can dispatch at most two. Set to 0 to " + "served by this PDP may lag a forced trigger by up to this many seconds. A coalesced trigger " + "is never dropped: the PDP arms a background trailing reload that runs once the window " + "expires, so staleness is bounded by this value rather than by whenever a client happens to " + "trigger again. Under a sustained hammer that converges to one reload per window. Set to 0 to " "disable the time window; concurrent triggers are still collapsed into a single in-flight " - "reload. Negative, non-numeric and non-finite values also disable it. Clamped to at most 300s; " - "the effective value is logged at startup whenever it differs from what was configured. " - "Remote-config overridable fleet-wide, so ops can raise it (e.g. to 30-60s under a degraded " - "control plane) without shipping a release - but the remote config is fetched once during " - "startup, so a change needs a PDP restart to take effect." + "reload. Clamped to at most 300s. Values that cannot be interpreted as a non-negative number " + "(null, a typo, a non-finite) FAIL SAFE to the default rather than disabling the mitigation - " + "only an explicit, parseable 0 disables it. The effective value is logged at startup whenever " + "it differs from what was configured. Remote-config overridable fleet-wide, so ops can raise " + "it (e.g. to 30-60s under a degraded control plane) without shipping a release - but the " + "remote config is fetched once during startup, so a change needs a PDP restart to take effect." ), ) diff --git a/horizon/debounce.py b/horizon/debounce.py index 7b9fd467..e3fe95b4 100644 --- a/horizon/debounce.py +++ b/horizon/debounce.py @@ -14,6 +14,11 @@ the same control-plane resource) while each supplies its own ``run`` closure and its own log context. +IMPORT DIRECTION. This module must never import ``horizon.config``. ``config.py`` +imports ``DEFAULT_DEBOUNCE_SECONDS`` from here to declare the setting's default, so +the edge is one-way (config -> debounce). Nothing here needs the config: ``trigger`` +receives the window as a parameter. + WHAT ``run`` ACTUALLY DOES - read this before reasoning about the guards below. Both updaters are fire-and-forget underneath, so ``await run()`` returns once the reload has been *dispatched*, NOT once it has completed: @@ -26,49 +31,100 @@ ``TasksPool.add_task`` (i.e. ``asyncio.create_task``). The retries/backoff configured via ``DATA_UPDATER_CONN_RETRY`` live inside those spawned tasks. -Two consequences that the guards below cannot paper over: +Three consequences the guards below are built around: -1. ``_last_dispatched`` is a DISPATCH timestamp. A reload that later fails in the - background still consumes the window. There is no "only on success" guarantee to - be had at this layer without an upstream OPAL change. +1. ``_last_dispatched`` records the ATTEMPT, not the outcome - it is stamped in a + ``finally``, so a dispatch that raises still consumes the window. This matters most + under a degraded control plane: ``get_policy_data_config`` raises ``ClientError`` on + any non-200, and a window consumed only by *successes* would leave the mitigation + switched off in precisely the conditions it exists for. The one exception is + cancellation, which means the attempt was abandoned rather than made. 2. The in-flight window covers the dispatch only - a queue put (policy), or the config GET plus task hand-off (data). It is still worth having: that config GET has no explicit timeout and falls back to aiohttp's 5-minute default, so it genuinely can stall, and the guard is what stops concurrent triggers from piling up behind it. +3. ``run`` is NEVER wrapped in ``asyncio.wait_for``. Cancelling ``get_base_policy_data`` + mid-flight is destructive: it awaits ``_stop_polling_update_tasks()`` (which cancels + and clears every ``periodic_update_interval`` poller) BEFORE the config GET, and the + pollers are only ever recreated at the very end of that same function. A timeout + landing on the stalled GET would therefore leave every periodic data source + permanently dead, with no error and no recovery short of an OPAL reconnect - strictly + worse than the bounded, self-healing stall it would be "fixing". A stalled dispatch + is made *observable* instead (see ``MAX_DISPATCH_SECONDS``), not cancellable. """ +import asyncio import math import time from collections.abc import Awaitable, Callable +from typing import Any, Literal from loguru import logger +# Default debounce window. Single-sourced HERE rather than in config.py so that the +# fallback `clamp_window`/`resolve_window` apply to an uninterpretable value is the same +# number the setting declares as its default (see the import-direction note above). +DEFAULT_DEBOUNCE_SECONDS: float = 10.0 + # Upper bound for the debounce window. The value is remote-config overridable from the # control plane, so an unclamped fat-finger (a stray "600000") would wedge every forced # reload fleet-wide with no way to force a sync short of a rollout. Five minutes is far # beyond any legitimate tuning range (ops guidance tops out around 60s). MAX_DEBOUNCE_SECONDS: float = 300.0 +# How long a dispatch may run before we treat it as STALLED rather than merely slow. +# Purely an observability threshold - it never cancels anything (see consequence 3 in the +# module docstring). The awaited work is a task-cancel gather plus one small JSON GET, so +# a healthy dispatch is low single-digit seconds; past this the control plane is hung and +# every coalesce logs at ERROR so it is alertable instead of silent. +MAX_DISPATCH_SECONDS: float = 30.0 + +# Why a window ended up different from what was configured, for the caller's startup log. +WindowProblem = Literal["unparseable", "clamped"] -def clamp_window(window_seconds: float) -> float: - """Normalise a configured debounce window into the range the debouncer honours. + +async def _sleep(seconds: float) -> None: + """Indirection so the unit tests can drive the trailing timer without real time passing. + + Deliberately a module-level function looked up at call time, mirroring how this module's + ``time`` reference is faked in ``test_debounce_unit.py``. Never ``from asyncio import + sleep`` and never capture it in a default argument - both would defeat the monkeypatch. + """ + await asyncio.sleep(seconds) + + +def resolve_window(value: Any, default: float = DEFAULT_DEBOUNCE_SECONDS) -> tuple[float, WindowProblem | None]: + """Normalise a configured debounce window, reporting *why* it was changed. Coerces defensively rather than trusting the type. ``confi.float`` casts from the ENVIRONMENT but its ``cast_from_json`` is ``no_cast``, so a remote config override from the control plane lands on the attribute VERBATIM - ``null`` and ``"30"`` both reach here - unconverted. This function runs at startup as well as per request, so raising on a - fat-fingered override would turn a bad config value into a PDP that will not boot. - A numeric string is honoured; anything genuinely uninterpretable, and any non-finite - value, collapses to 0 (debouncing disabled). The caller logs a warning when the - effective window differs from what was configured. + unconverted. A numeric string is therefore honoured, and honouring it must not be + mistaken for a clamp (the old code compared ``float`` to the raw attribute and logged a + false "out of range" warning for a perfectly valid ``"30"``). + + Fails SAFE, not open. Anything uninterpretable - ``None``, ``"tem"``, a non-finite, a + negative - falls back to ``default``, leaving the mitigation ON. Only an explicit, + parseable ``0`` disables the window. The previous behaviour collapsed all of these to + ``0``, so a single control-plane typo silently switched off the very protection this + module exists to provide, fleet-wide. + + Never raises: this runs at startup as well as per request, and a fat-fingered remote + override must not turn into a PDP that will not boot. """ try: - window = float(window_seconds) + window = float(value) except (TypeError, ValueError): - return 0.0 - if not math.isfinite(window): - return 0.0 - return min(max(window, 0.0), MAX_DEBOUNCE_SECONDS) + return default, "unparseable" + if not math.isfinite(window) or window < 0: + return default, "unparseable" + clamped = min(window, MAX_DEBOUNCE_SECONDS) + return clamped, "clamped" if clamped != window else None + + +def clamp_window(value: Any, default: float = DEFAULT_DEBOUNCE_SECONDS) -> float: + """The window :meth:`DebouncedTrigger.trigger` will actually honour. See :func:`resolve_window`.""" + return resolve_window(value, default)[0] class DebouncedTrigger: @@ -76,33 +132,45 @@ class DebouncedTrigger: Semantics of :meth:`trigger` (in evaluation order): - * A reload is already **in flight** -> coalesce, and arm the trailing edge. This - guard is unconditional: it applies even when ``window_seconds`` is 0, because - "no time-based damping" should still never mean "two concurrent full pulls". - * Otherwise, if ``window_seconds > 0`` and the last dispatch was **within the - window** -> coalesce. No trailing edge here; staleness is bounded by - ``window_seconds`` by construction, which is the entire point of the knob. - * Otherwise -> dispatch, recording the dispatch time. - - **Trailing edge.** A trigger coalesced by the in-flight guard would otherwise be - lost: the reload it collapsed into may have already read its data before the - caller's change landed, and nothing would schedule a follow-up. Since an in-flight - dispatch has no bounded duration, that staleness would be unbounded too. So the - dispatching call re-runs **once** if any trigger arrived while it was running, - capping the work at two dispatches per call. - - Be precise about what that does and does not promise. It bounds the damage from the - in-flight guard; it is NOT a guarantee that every trigger is eventually served. This - class never schedules future work - it only ever runs inside a caller's request - so - a trigger arriving during the trailing run is coalesced and simply waits for somebody - to trigger again. Closing that last gap needs a background timer task with its own - lifecycle, which is deliberately out of scope here. + * A reload is already **in flight**, or a **trailing run is already armed** -> coalesce, + and mark the trigger pending. This guard is unconditional: it applies even when + ``window_seconds`` is 0, because "no time-based damping" should still never mean "two + concurrent full pulls". + * Otherwise, if ``window_seconds > 0`` and the last dispatch was **within the window** + -> coalesce, and arm the trailing edge. + * Otherwise -> dispatch. + + **Trailing edge.** A coalesced trigger is never dropped. The reload it collapsed into + already read the control plane *before* the caller's change landed, and this PDP is + pubsub-driven with no periodic full-refresh cadence - so dropping it would lose the + refresh permanently, which is exactly what PER-15248 forbids ("must not debounce so + aggressively that a legitimately-needed reload is dropped"). Instead the debouncer arms + a background task that re-runs once the window expires, which is what makes "staleness + is bounded by ``window_seconds``" an actual guarantee rather than a hopeful comment. + + **The trailing run is a task, not part of a request.** It used to be awaited inline by + whichever caller won the dispatch, which billed that caller for a second full reload it + never asked for - against a 60s client timeout in the Rust server that fronts this app. + The dispatching caller now returns as soon as its own dispatch is handed off, which is + what its 200 already meant. + + **The chain terminates.** A trailing run re-arms only if ``_pending`` is set when it + finishes, and ``_pending`` is written ``True`` in exactly one place: :meth:`trigger`, by + an external caller. Nothing in the trailing path sets it. So the chain length is bounded + by the number of real triggers and stops one run after they stop - it can never + self-perpetuate into a standing 1-per-window load on the control plane. Under a sustained + hammer it converges to one dispatch per ``window_seconds``, which is the intended damping. + + **What the trailing run serves.** It re-runs the ``run`` closure captured when it was + armed - the first *coalesced* caller's on the window path, the *dispatcher's* on the + in-flight path. The closures differ only in their ``data_fetch_reason`` log string, so + this is a log-attribution detail, not a behavioural one. """ def __init__(self, name: str) -> None: # Short label used purely for logs, e.g. "policy" / "data". self._name = name - # Monotonic seconds of the last *dispatch*; ``None`` until the first one. + # Monotonic seconds of the last dispatch ATTEMPT; ``None`` until the first one. # Deliberately ``None`` and NEVER ``0.0``: ``time.monotonic()`` is ~seconds since boot # on Linux, so a ``0.0`` sentinel would read as "fired at boot" and silently coalesce # the very first real trigger on a freshly booted host. @@ -112,8 +180,11 @@ def __init__(self, name: str) -> None: # When the current dispatch started, so a coalesce log can report how long the # thing it is collapsing into has been running. self._in_flight_since: float | None = None - # Set when the in-flight guard coalesces a trigger; consumed by the trailing edge. + # Set when a trigger is coalesced; consumed by the trailing edge. self._pending: bool = False + # The armed trailing run, if any. Doubles as a guard (see guard 1) and as the strong + # reference that keeps the task from being garbage collected mid-flight. + self._trailing_task: asyncio.Task[None] | None = None # Coalesced-since-last-dispatch counter. Keeps the log quiet under the exact # hammering this class exists to absorb: the first suppression per dispatch logs # at INFO, the rest at DEBUG, and the dispatch logs the total. @@ -124,25 +195,29 @@ async def trigger(self, run: Callable[[], Awaitable[None]], window_seconds: floa Returns ``True`` if ``run`` was dispatched, ``False`` if the trigger was coalesced into a recent/in-flight reload. A coalesced trigger is an immediate no-op success from the - caller's perspective - it does NOT await the in-flight reload. + caller's perspective - it does NOT await the reload it collapsed into, and it is not + dropped: a trailing run is armed to serve it once the window expires. """ window_seconds = clamp_window(window_seconds) - # 1. In-flight guard: collapse concurrent triggers into the one already running, and - # arm the trailing edge so this trigger is honoured rather than dropped. - if self._in_flight: + # 1. In-flight / already-armed guard: collapse concurrent triggers into the reload + # already running, or into the trailing run already scheduled to serve them. + if self._in_flight or self._trailing_task is not None: self._pending = True - self._note_coalesced("a forced reload is already in flight ({:.1f}s so far)", self._in_flight_age()) + self._note_in_flight_coalesce() return False # 2. Window guard: collapse triggers that arrive within the debounce window of the - # last dispatch. Skipped entirely when the window is disabled (<= 0). + # last dispatch, and arm the trailing edge so the trigger is served rather than + # dropped. Skipped entirely when the window is disabled (<= 0). if window_seconds > 0 and self._last_dispatched is not None: elapsed = time.monotonic() - self._last_dispatched if elapsed < window_seconds: + self._pending = True self._note_coalesced( "within the {:g}s debounce window ({:.1f}s remaining)", window_seconds, window_seconds - elapsed ) + self._arm_trailing(run, window_seconds) return False # 3. Dispatch. Single-worker assumption (the Rust supervisor spawns uvicorn with no @@ -153,45 +228,136 @@ async def trigger(self, run: Callable[[], Awaitable[None]], window_seconds: floa self._in_flight = True self._in_flight_since = time.monotonic() # Clear before running, so anything arriving from here on counts as "arrived during - # this dispatch". NOT cleared in the finally below: if ``run`` raises, a trigger that - # was coalesced into this failed dispatch must stay pending rather than be discarded - - # the next dispatch clears it right here, at the point where it actually serves it. + # this dispatch" and is served by the trailing edge. Biases towards one redundant + # run, never a lost one. self._pending = False + cancelled = False try: await run() - self._last_dispatched = time.monotonic() self._log_dispatched() - if self._pending: - await self._run_trailing(run) return True + except asyncio.CancelledError: + # The attempt was ABANDONED, not made: client disconnect, or shutdown. Record no + # dispatch (so the window is not consumed by work that never reached the control + # plane) and arm nothing (on shutdown there would be nobody left to run it). + cancelled = True + raise finally: + # INVARIANT: this block must never ``await``. The no-overlap argument for the two + # guards rests on the handoff from ``_in_flight`` to ``_trailing_task`` being + # atomic, which holds only while nothing here yields to the event loop. + if not cancelled: + # The ATTEMPT consumes the window - see consequence 1 in the module docstring. + self._last_dispatched = time.monotonic() + if self._pending: + self._arm_trailing(run, window_seconds) self._in_flight = False self._in_flight_since = None - async def _run_trailing(self, run: Callable[[], Awaitable[None]]) -> None: - """Re-dispatch once, for triggers that arrived while the first dispatch was running. + async def aclose(self) -> None: + """Cancel any armed trailing run. Idempotent; safe to call with nothing armed. - Failures are logged and swallowed, never propagated. The caller executing this re-run - already had its OWN dispatch succeed; handing it a 500 caused by somebody else's - trigger would be both confusing and wrong (its request did what it asked). Losing the - trailing reload is the lesser evil, and it is logged at ERROR. + Wired to the app's ``shutdown`` event so a pending trailing reload does not outlive + the event loop as a "Task was destroyed but it is pending" warning. """ - self._pending = False - logger.info( - "Re-running {} reload (trailing edge): a trigger arrived while the previous one was in flight.", - self._name, - ) + task = self._trailing_task + if task is None: + return + task.cancel() + # gather(return_exceptions=True) rather than a bare await: this runs on the shutdown + # path, where re-raising the task's CancelledError could be mistaken for the shutdown + # coroutine's own cancellation. + await asyncio.gather(task, return_exceptions=True) + + def _arm_trailing(self, run: Callable[[], Awaitable[None]], window_seconds: float) -> None: + """Schedule the trailing run. Called from ``finally`` blocks, so it must never raise. + + An exception escaping here would replace whatever was propagating AND discard the + ``return True`` of a dispatch that actually succeeded, turning it into a 500. + """ + if self._trailing_task is not None: + return try: - await run() - except Exception: # noqa: BLE001 - logger.opt(exception=True).error( - "Trailing {} reload failed. The triggers it was serving were not applied; " - "the next trigger after the debounce window will retry.", - self._name, - ) + task = asyncio.create_task(self._run_trailing(run, window_seconds)) + except RuntimeError: # no running loop - we are being torn down; nothing to schedule onto + logger.opt(exception=True).error("Could not arm the trailing {} reload.", self._name) return - self._last_dispatched = time.monotonic() - self._log_dispatched() + self._trailing_task = task + # Safety net for the one case ``_run_trailing``'s own ``finally`` cannot cover: a task + # cancelled BEFORE its first step never runs its body at all, which would leave + # ``_trailing_task`` set forever and coalesce every future trigger - a permanent wedge, + # the exact failure this class exists to prevent. + task.add_done_callback(self._on_trailing_done) + + def _on_trailing_done(self, task: "asyncio.Task[None]") -> None: + """Clear the handle and surface anything that escaped the trailing task.""" + if self._trailing_task is task: + self._trailing_task = None + if not task.cancelled() and task.exception() is not None: + # Retrieved here so it cannot resurface as "Task exception was never retrieved" + # at garbage-collection time, detached from any useful context. + logger.opt(exception=task.exception()).error("Trailing {} reload task failed.", self._name) + + async def _run_trailing(self, run: Callable[[], Awaitable[None]], window_seconds: float) -> None: + """Serve the triggers coalesced since the last dispatch, once the window has expired. + + Failures are logged and swallowed, never propagated: nobody is awaiting this task, and + the caller whose request armed it has long since been answered. + """ + cancelled = False + try: + delay = self._time_until_window_expires(window_seconds) + if delay > 0: + logger.info( + "Scheduling a trailing {} reload in {:.1f}s to serve coalesced trigger(s).", self._name, delay + ) + await _sleep(delay) + # Cleared immediately before the run: anything arriving from here on counts as + # "arrived during this run" and chains into one more trailing run. + self._pending = False + self._in_flight = True + self._in_flight_since = time.monotonic() + try: + await run() + self._log_dispatched() + except asyncio.CancelledError: + cancelled = True + raise + except Exception: # noqa: BLE001 + logger.opt(exception=True).error( + "Trailing {} reload failed. The triggers it was serving were not applied; " + "the next trigger after the debounce window will retry.", + self._name, + ) + finally: + if not cancelled: + self._last_dispatched = time.monotonic() + self._in_flight = False + self._in_flight_since = None + except asyncio.CancelledError: + # Also catches cancellation during ``_sleep`` above, which the inner handler cannot + # see. That is the COMMON case on shutdown - ``aclose`` usually finds this task + # waiting out the window - and ``_pending`` is still set there, so without this the + # ``finally`` below would happily arm a replacement task mid-teardown. + cancelled = True + raise + finally: + # Also await-free, for the same reason as the ``finally`` in ``trigger``. Clear the + # handle BEFORE re-arming or the re-arm is immediately clobbered by the guard in + # ``_arm_trailing``. + if self._trailing_task is asyncio.current_task(): + self._trailing_task = None + # Never chain while cancellation is propagating: the new task would be created + # during loop teardown, after the cancel-all sweep has already run, and would be + # left pending with nobody to await it. + if self._pending and not cancelled: + self._arm_trailing(run, window_seconds) + + def _time_until_window_expires(self, window_seconds: float) -> float: + """Seconds until the debounce window is clear again (0.0 when it already is).""" + if window_seconds <= 0 or self._last_dispatched is None: + return 0.0 + return max(0.0, window_seconds - (time.monotonic() - self._last_dispatched)) def _log_dispatched(self) -> None: """Report how many triggers the dispatch that just completed absorbed.""" @@ -209,12 +375,41 @@ def _in_flight_age(self) -> float: return 0.0 return time.monotonic() - self._in_flight_since - def _note_coalesced(self, reason: str, *args: float) -> None: + def _note_in_flight_coalesce(self) -> None: + """Log a trigger absorbed by guard 1, escalating when the thing it waits on is stalled. + + The dispatch it is collapsing into cannot be cancelled (see consequence 3 in the module + docstring), so a hung control-plane GET can hold the guard for aiohttp's 5-minute + default. That must not be silent: past ``MAX_DISPATCH_SECONDS`` every coalesce logs at + ERROR, which is the signal that forced reloads are currently absorbed rather than served. + """ + if not self._in_flight: + # Guard 1 also fires when only a trailing run is armed - no dispatch is running, the + # trigger is simply already accounted for by scheduled work. + self._note_coalesced("a trailing reload is already armed to serve it") + return + age = self._in_flight_age() + if age > MAX_DISPATCH_SECONDS: + self._note_coalesced( + "a forced reload has been in flight for {:.1f}s (over the {:g}s a healthy dispatch takes) - " + "the control plane looks stalled and forced reloads are being absorbed, not served", + age, + MAX_DISPATCH_SECONDS, + stalled=True, + ) + return + self._note_coalesced("a forced reload is already in flight ({:.1f}s so far)", age) + + def _note_coalesced(self, reason: str, *args: float, stalled: bool = False) -> None: """Count a coalesced trigger and log it, loudly the first time and quietly thereafter.""" self._coalesced += 1 message = "Coalescing {} reload trigger: " + reason + "." # Only the first suppression per dispatch is worth an INFO line - under a hammer, one # INFO per suppressed request would make the mitigation amplify log volume into the - # (unbounded, enqueue=True) logzio sink. The dispatch line reports the total. + # (unbounded, enqueue=True) logzio sink. The dispatch line reports the total. A stalled + # dispatch is the exception: that one is alertable and must not be buried at DEBUG. + if stalled: + logger.error(message, self._name, *args) + return log = logger.info if self._coalesced == 1 else logger.debug log(message, self._name, *args) diff --git a/horizon/pdp.py b/horizon/pdp.py index cc731b68..ac35a6d7 100644 --- a/horizon/pdp.py +++ b/horizon/pdp.py @@ -1,9 +1,13 @@ +import asyncio import logging +import math import os import sys from pathlib import Path +from typing import ClassVar, Literal from uuid import UUID, uuid4 +import aiohttp from fastapi import Depends, FastAPI, HTTPException, status from fastapi.routing import APIRoute from loguru import logger @@ -23,12 +27,13 @@ HttpMethods, ) from opal_common.logging_utils.formatter import Formatter +from pydantic import BaseModel, Field from scalar_fastapi import get_scalar_api_reference from horizon.authentication import enforce_pdp_token from horizon.config import MOCK_API_KEY, sidecar_config from horizon.connectivity.api import init_connectivity_router -from horizon.debounce import MAX_DEBOUNCE_SECONDS, DebouncedTrigger, clamp_window +from horizon.debounce import MAX_DEBOUNCE_SECONDS, DebouncedTrigger, clamp_window, resolve_window from horizon.enforcer.api import init_enforcer_api_router, init_enforcer_health_router, stats_manager from horizon.enforcer.opa.config_maker import ( get_opa_authz_policy_file_path, @@ -100,6 +105,36 @@ def apply_config(overrides_dict: dict, config_object: Confi): logger.warning(f"Ignored non-existing config key: {prefixed_key}") +# Declared as a ``response_model`` (rather than left as a bare dict) because the trigger routes' +# customer-facing OpenAPI description tells integrators to branch on ``triggered``: without one, +# FastAPI publishes an empty 200 schema, so the prose would reference a field the machine-readable +# contract never describes and typed SDKs would have nothing to bind to. The two +# ``include_in_schema=False`` legacy aliases use it too - not for docs, but because response_model +# also validates at runtime, which is what keeps all four bodies in lockstep as they share one +# debouncer. +# +# NOTE: the class docstring below is PUBLISHED as the schema description in /openapi.json and the +# /scalar explorer - same rule as the route handlers further down. Implementation notes go in +# comments like this one; the docstring is written for integrators. +class TriggerResponse(BaseModel): + """The result of a forced-reload trigger.""" + + status: Literal["ok"] = Field( + "ok", + description="Always `ok`. Retained verbatim from the pre-debounce body so SDKs never error-spiral.", + ) + triggered: bool = Field( + ..., + description=( + "`true` if this call dispatched a reload, `false` if it was coalesced into a recent or " + "in-flight one. `false` is a success - see the endpoint description." + ), + ) + + class Config: + schema_extra: ClassVar[dict] = {"example": {"status": "ok", "triggered": True}} + + # OpalClient mounts these two forced-reload trigger routes before PermitPDP gains control. # Their handlers are OPAL closures that force a FULL reload on every call with no damping, so # the PDP REPLACES them (see _remove_opal_trigger_routes + the replacements registered in @@ -523,13 +558,29 @@ def _configure_trigger_routes(self, app: FastAPI): self._policy_trigger_debounce = DebouncedTrigger("policy") self._data_trigger_debounce = DebouncedTrigger("data") + # A trailing reload is a background task, so it has to be cancelled on the way down or + # it outlives the event loop as a "Task was destroyed but it is pending" warning. + app.on_event("shutdown")(self._policy_trigger_debounce.aclose) + app.on_event("shutdown")(self._data_trigger_debounce.aclose) + # Log the EFFECTIVE window, not the configured one: the value is remote-config - # overridable and is clamped to [0, MAX_DEBOUNCE_SECONDS], so a fat-fingered override - # should be visible at startup rather than silently reinterpreted. - effective_window = clamp_window(sidecar_config.TRIGGER_DEBOUNCE_SECONDS) - if effective_window != sidecar_config.TRIGGER_DEBOUNCE_SECONDS: + # overridable, so a fat-fingered override should be visible at startup rather than + # silently reinterpreted. resolve_window reports WHY the value changed, which matters + # because the two cases warrant different messages and different severities - and + # because comparing the coerced float against the raw attribute (as this did before) + # reported a false "out of range" for a valid override delivered as the JSON string + # "30": confi's cast_from_json is no_cast, so remote overrides arrive uncast. + effective_window, problem = resolve_window(sidecar_config.TRIGGER_DEBOUNCE_SECONDS) + if problem == "unparseable": + logger.error( + "PDP_TRIGGER_DEBOUNCE_SECONDS={!r} is not a usable window; falling back to the default " + "{:g}s. Forced-reload trigger debouncing REMAINS ENABLED.", + sidecar_config.TRIGGER_DEBOUNCE_SECONDS, + effective_window, + ) + elif problem == "clamped": logger.warning( - "PDP_TRIGGER_DEBOUNCE_SECONDS={} is out of range; clamped to {:g}s (max {:g}s).", + "PDP_TRIGGER_DEBOUNCE_SECONDS={!r} is out of range; clamped to {:g}s (allowed 0-{:g}s).", sidecar_config.TRIGGER_DEBOUNCE_SECONDS, effective_window, MAX_DEBOUNCE_SECONDS, @@ -543,25 +594,25 @@ def _configure_trigger_routes(self, app: FastAPI): @app.post( "/update_policy", status_code=status.HTTP_200_OK, + response_model=TriggerResponse, include_in_schema=False, dependencies=[Depends(enforce_pdp_token)], ) - async def legacy_trigger_policy_update(): + async def legacy_trigger_policy_update() -> TriggerResponse: logger.info("triggered policy update from api (legacy route)") - triggered = await self._debounced_policy_reload() - return {"status": "ok", "triggered": triggered} + return TriggerResponse(triggered=await self._debounced_policy_reload()) @app.post( "/update_policy_data", status_code=status.HTTP_200_OK, + response_model=TriggerResponse, include_in_schema=False, dependencies=[Depends(enforce_pdp_token)], ) - async def legacy_trigger_data_update(): + async def legacy_trigger_data_update() -> TriggerResponse: logger.info("triggered policy data update from api (legacy route)") # Preserve the distinct legacy reason string - a test asserts it verbatim. - triggered = await self._debounced_data_reload("request from sdk (legacy alias)") - return {"status": "ok", "triggered": triggered} + return TriggerResponse(triggered=await self._debounced_data_reload("request from sdk (legacy alias)")) # OpalClient mounted POST /policy-updater/trigger and POST /data-updater/trigger before # the PDP took over; their closures force a FULL reload on every call with no damping. @@ -578,54 +629,70 @@ async def legacy_trigger_data_update(): @app.post( "/policy-updater/trigger", status_code=status.HTTP_200_OK, + response_model=TriggerResponse, tags=["Policy Updater"], dependencies=[Depends(enforce_pdp_token)], summary="Trigger a full policy reload", description=( "Requests a full policy reload from the control plane. Redundant triggers are " - "coalesced: if a reload was already requested within the debounce window, or one " - "is currently in flight, this call is absorbed into it. Returns 200 either way; " - "`triggered` reports whether this call started a reload (`true`) or was coalesced " - "into an existing one (`false`). **`false` is a success, not a failure - do not " - "retry on it.** It means a reload covering your request is already happening; " - "retrying only adds load to the control plane." + "coalesced: if a reload is already in flight, or one was dispatched within the " + "debounce window, this call is absorbed into it. Returns 200 either way; " + "`triggered` reports whether this call dispatched a reload (`true`) or was " + "coalesced into another one (`false`).\n\n" + "**`false` is a success, not a failure - do not retry on it.** A coalesced trigger " + "is not dropped: the PDP schedules a follow-up reload that begins *after* your " + "call, within `PDP_TRIGGER_DEBOUNCE_SECONDS` (default 10s). Retrying sooner is " + "coalesced again and only adds load to the control plane.\n\n" + "This is a best-effort refresh, not a read-your-writes barrier: 200 means the " + "reload was dispatched, not that the new policy has been loaded." ), ) - async def trigger_policy_update(): + async def trigger_policy_update() -> TriggerResponse: # The reload is dispatched, not awaited to completion: the underlying OPAL call only # enqueues onto the policy updater's queue. That was already true of the handler this # replaces, so a 200 means the same thing it always did. logger.info("triggered policy update from api") - triggered = await self._debounced_policy_reload() - return {"status": "ok", "triggered": triggered} + return TriggerResponse(triggered=await self._debounced_policy_reload()) @app.post( "/data-updater/trigger", status_code=status.HTTP_200_OK, + response_model=TriggerResponse, + responses={ + 502: {"description": "The control plane rejected or failed the data-source config request"}, + 503: {"description": "The data updater is disabled on this PDP"}, + 504: {"description": "The control plane did not answer the data-source config request in time"}, + }, tags=["Data Updater"], dependencies=[Depends(enforce_pdp_token)], summary="Trigger a full base-data reload", description=( "Requests a full reload of base policy data from the control plane. Redundant " - "triggers are coalesced: if a reload was already requested within the debounce " - "window, or one is currently in flight, this call is absorbed into it. Returns 200 " - "either way; `triggered` reports whether this call started a reload (`true`) or was " - "coalesced into an existing one (`false`). **`false` is a success, not a failure - " - "do not retry on it.** It means a reload covering your request is already happening; " - "retrying only adds load to the control plane. Returns 503 if the data updater is " - "disabled. This endpoint is a best-effort refresh, not a read-your-writes barrier - " - "use the facts API's `X-Wait-timeout` when you need to block on a specific write." + "triggers are coalesced: if a reload is already in flight, or one was dispatched " + "within the debounce window, this call is absorbed into it. Returns 200 either " + "way; `triggered` reports whether this call dispatched a reload (`true`) or was " + "coalesced into another one (`false`).\n\n" + "**`false` is a success, not a failure - do not retry on it.** A coalesced trigger " + "is not dropped: the PDP schedules a follow-up reload that begins *after* your " + "call, within `PDP_TRIGGER_DEBOUNCE_SECONDS` (default 10s). Retrying sooner is " + "coalesced again and only adds load to the control plane.\n\n" + "This is a best-effort refresh, not a read-your-writes barrier: 200 means the " + "reload was dispatched, not that the new data has been loaded. Use the facts API's " + "`X-Wait-timeout` when you need to block on a specific write.\n\n" + "Returns 503 if the data updater is disabled on this PDP - a configuration state, " + "so retrying will not help. Returns 502 or 504 with a `Retry-After` header if the " + "control plane could not be reached; honour that header rather than retrying " + "immediately." ), ) - async def trigger_data_update(): + async def trigger_data_update() -> TriggerResponse: # Like the policy route, this dispatches rather than completes: get_base_policy_data # awaits the data-source config GET and then hands the per-entry fetches to a task # pool. That was already true of the OPAL handler this replaces - a 200 never meant # the data had landed. A disabled data updater still returns 503, checked BEFORE the # debouncer so a 503 never consumes the window. logger.info("triggered policy data update from api") - triggered = await self._debounced_data_reload("request from sdk") - return {"status": "ok", "triggered": triggered} + return TriggerResponse(triggered=await self._debounced_data_reload("request from sdk")) async def _debounced_policy_reload(self) -> bool: """Dispatch a full policy reload through the shared policy debouncer. @@ -663,8 +730,42 @@ async def _debounced_data_reload(self, data_fetch_reason: str) -> bool: async def _run() -> None: await data_updater.get_base_policy_data(data_fetch_reason=data_fetch_reason) - return await self._data_trigger_debounce.trigger( - run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS + try: + return await self._data_trigger_debounce.trigger( + run=_run, window_seconds=sidecar_config.TRIGGER_DEBOUNCE_SECONDS + ) + except asyncio.TimeoutError as exc: + raise self._control_plane_unreachable(status.HTTP_504_GATEWAY_TIMEOUT, "timed out", exc) from exc + except aiohttp.ClientError as exc: + raise self._control_plane_unreachable(status.HTTP_502_BAD_GATEWAY, "failed", exc) from exc + + @staticmethod + def _control_plane_unreachable(status_code: int, verb: str, exc: BaseException) -> HTTPException: + """Translate a failed data-source config fetch into a gateway error with backoff advice. + + ``get_policy_data_config`` raises ``ClientError`` on any non-200 from the control plane, + which used to escape the handler as a bare 500 with no body - the one status code SDK and + service-mesh retry logic always retries, so the failure mode actively recruited clients + into a retry storm against an already-degraded control plane. + + 502/504 rather than 503, for two reasons. It matches the mapping this codebase already + uses for an upstream failure (horizon/enforcer/api.py: "502 indicates server got an error + from another server"), and it keeps 503 meaning what it already means on this route - + "the data updater is disabled", a configuration state where retrying is pointless + indefinitely. Collapsing both into 503 would leave a client unable to tell "back off ten + seconds" from "stop forever". + + ``Retry-After`` is the debounce window, because the failed attempt just consumed it: any + earlier retry is guaranteed to be coalesced, so a smaller value would be the server + instructing the client to make a provably useless call. + """ + retry_after = max(1, math.ceil(clamp_window(sidecar_config.TRIGGER_DEBOUNCE_SECONDS))) + detail = f"Fetching base policy data from the control plane {verb}: {exc!s}" + logger.warning(detail) + return HTTPException( + status_code=status_code, + detail=detail, + headers={"Retry-After": str(retry_after)}, ) @property diff --git a/horizon/tests/test_debounce_unit.py b/horizon/tests/test_debounce_unit.py index 6cf826b7..5fa8cc0a 100644 --- a/horizon/tests/test_debounce_unit.py +++ b/horizon/tests/test_debounce_unit.py @@ -4,26 +4,47 @@ app; this module drives the state machine directly - no FastAPI, no OpalClient, no TestClient - so the concurrency-shaped cases (a burst arriving mid-dispatch, the trailing edge, cancellation) can be sequenced deterministically with ``asyncio.Event``s instead of hoping real requests -interleave the right way. It is also where the pure helper ``clamp_window`` is pinned. - -TIME IS FAKED, NEVER SLEPT. The debouncer reads the clock as ``time.monotonic()`` via the module -global ``horizon.debounce.time``, so the ``clock`` fixture swaps that whole module reference for -a fake. Patching ``time.monotonic`` itself would be patching the *stdlib* function - which is -also the asyncio event loop's clock (``BaseEventLoop.time`` calls it) - and a frozen or rewound -loop clock would break every ``asyncio.wait_for`` timeout below. - -Every test that leaves a dispatch parked inside ``run`` cancels its task in a ``finally``: an -assertion failing mid-test must not leak a task that outlives it (which shows up later as an -unrelated "Task was destroyed but it is pending" against whichever test runs next). +interleave the right way. It is also where the pure helpers ``resolve_window`` / ``clamp_window`` +are pinned. + +TIME IS FAKED, NEVER SLEPT - in two places that must stay coherent with each other: + +* the debouncer reads the clock as ``time.monotonic()`` via the module global + ``horizon.debounce.time``, so the ``clock`` fixture swaps that whole module reference for a + fake. Patching ``time.monotonic`` itself would be patching the *stdlib* function - which is + also the asyncio event loop's clock (``BaseEventLoop.time`` calls it) - and a frozen or + rewound loop clock would break every ``asyncio.wait_for`` timeout below. +* the trailing edge waits out the debounce window via the module global + ``horizon.debounce._sleep``, so the ``sleeper`` fixture swaps that for a fake that ADVANCES + the clock by the requested delay instead of waiting. Advancing is not a nicety: the debouncer + re-stamps ``_last_dispatched`` from the (fake) clock after the trailing run, so a sleep that + returned without moving time would leave every later window assertion off by the delay. + +TRAILING RUNS ARE TASKS, so a test that arms one must also drain it - ``drain_trailing`` - or +assert deliberately that it is still armed. Every trigger is built through the ``make_trigger`` +factory, whose teardown calls the production ``aclose()``; that keeps an assertion failing +mid-test from leaking a task into whichever test runs next (as an unrelated "Task was destroyed +but it is pending"), and doubles as coverage of the shutdown path. + +Every test that leaves a dispatch parked inside ``run`` also cancels its own task in a +``finally``, for the same reason. """ import asyncio import math -from collections.abc import Awaitable, Callable, Iterator +from collections.abc import AsyncIterator, Awaitable, Callable, Iterator import pytest +import pytest_asyncio from horizon import debounce -from horizon.debounce import MAX_DEBOUNCE_SECONDS, DebouncedTrigger, clamp_window +from horizon.debounce import ( + DEFAULT_DEBOUNCE_SECONDS, + MAX_DEBOUNCE_SECONDS, + MAX_DISPATCH_SECONDS, + DebouncedTrigger, + clamp_window, + resolve_window, +) from loguru import logger # Long enough that a real elapsed-time race can never make a "within the window" case flake; @@ -51,6 +72,23 @@ def advance(self, seconds: float) -> None: self._now += seconds +class FakeSleep: + """Stand-in for ``horizon.debounce._sleep``: records the delay and advances the clock by it. + + Returns without waiting, but still yields to the event loop once, so a trailing run cannot + quietly become synchronous and hide an ordering bug that real time would expose. + """ + + def __init__(self, clock: FakeClock) -> None: + self._clock = clock + self.requested: list[float] = [] + + async def __call__(self, seconds: float) -> None: + self.requested.append(seconds) + self._clock.advance(seconds) + await asyncio.sleep(0) + + @pytest.fixture def clock(monkeypatch: pytest.MonkeyPatch) -> FakeClock: fake = FakeClock() @@ -58,6 +96,32 @@ def clock(monkeypatch: pytest.MonkeyPatch) -> FakeClock: return fake +@pytest.fixture +def sleeper(clock: FakeClock, monkeypatch: pytest.MonkeyPatch) -> FakeSleep: + fake = FakeSleep(clock) + monkeypatch.setattr(debounce, "_sleep", fake) + return fake + + +@pytest_asyncio.fixture +async def make_trigger() -> AsyncIterator[Callable[[str], DebouncedTrigger]]: + """Build ``DebouncedTrigger``s that are guaranteed to be closed down at teardown. + + Uses the production ``aclose()``, so every test in this module is also a small exercise of + the shutdown path wired up in ``PermitPDP._configure_trigger_routes``. + """ + created: list[DebouncedTrigger] = [] + + def factory(name: str) -> DebouncedTrigger: + trigger = DebouncedTrigger(name) + created.append(trigger) + return trigger + + yield factory + for trigger in created: + await trigger.aclose() + + async def trigger_promptly(trigger: DebouncedTrigger, run: Callable[[], Awaitable[None]], window_seconds: float): """Issue a trigger that is expected to be coalesced, bounded by ``TIMEOUT``. @@ -71,6 +135,16 @@ async def trigger_promptly(trigger: DebouncedTrigger, run: Callable[[], Awaitabl return await asyncio.wait_for(trigger.trigger(run=run, window_seconds=window_seconds), timeout=TIMEOUT) +async def drain_trailing(trigger: DebouncedTrigger) -> None: + """Run every armed (and chained) trailing task to completion, bounded by ``TIMEOUT``. + + Loops because a trailing run re-arms when triggers arrived while it was running. It + terminates for the same reason the production chain does: nothing here sets ``_pending``. + """ + while (task := trigger._trailing_task) is not None: + await asyncio.wait_for(asyncio.gather(task, return_exceptions=True), timeout=TIMEOUT) + + @pytest.fixture def captured_logs() -> Iterator[list[tuple[str, str]]]: """``(level name, formatted message)`` for every loguru record emitted during the test.""" @@ -83,32 +157,72 @@ def captured_logs() -> Iterator[list[tuple[str, str]]]: logger.remove(sink_id) -# --- clamp_window: the guard against a fat-fingered remote-config override ---------------- +# --- resolve_window / clamp_window: the guard against a fat-fingered remote-config override --- @pytest.mark.parametrize( ("configured", "expected"), [ - (-1.0, 0.0), # negative == disabled, not "always coalesce" + # An explicit, parseable 0 is the ONLY way to disable the window. (0.0, 0.0), + (0, 0.0), (0.5, 0.5), (WINDOW, WINDOW), + # confi's cast_from_json is no_cast, so a remote override arrives VERBATIM - a numeric + # string is a perfectly valid override and must be honoured, not treated as garbage. + ("30", 30.0), (MAX_DEBOUNCE_SECONDS, MAX_DEBOUNCE_SECONDS), # the cap itself is honoured, not clamped off (MAX_DEBOUNCE_SECONDS + 1, MAX_DEBOUNCE_SECONDS), (600_000.0, MAX_DEBOUNCE_SECONDS), # the stray-zeroes override the cap exists for - (math.inf, 0.0), # non-finite collapses to "disabled"... - (-math.inf, 0.0), - (math.nan, 0.0), # ...rather than making every comparison silently false + # Everything uninterpretable falls back to the DEFAULT, not to 0. Failing open here + # would mean one control-plane typo silently switches the mitigation off fleet-wide - + # the opposite of what a protection knob should do when it cannot be read. + (-1.0, DEFAULT_DEBOUNCE_SECONDS), # a negative is a typo, not a request to disable + (math.inf, DEFAULT_DEBOUNCE_SECONDS), + (-math.inf, DEFAULT_DEBOUNCE_SECONDS), + (math.nan, DEFAULT_DEBOUNCE_SECONDS), # ...and never a value that makes every comparison false + (None, DEFAULT_DEBOUNCE_SECONDS), # a remote-config `null` + ("", DEFAULT_DEBOUNCE_SECONDS), + ("tem", DEFAULT_DEBOUNCE_SECONDS), # a fat-fingered "ten" ], ) -def test_clamp_window(configured: float, expected: float): +def test_clamp_window(configured: object, expected: float): assert clamp_window(configured) == expected +@pytest.mark.parametrize( + ("configured", "expected_window", "expected_problem"), + [ + (WINDOW, WINDOW, None), + (0.0, 0.0, None), + (30, 30.0, None), + # The regression this reporting exists for: comparing the coerced float against the raw + # attribute made a VALID override delivered as the JSON string "30" look like a clamp, + # and logged "out of range; clamped to 30s" - false on both counts. + ("30", 30.0, None), + (600_000.0, MAX_DEBOUNCE_SECONDS, "clamped"), + (MAX_DEBOUNCE_SECONDS + 1, MAX_DEBOUNCE_SECONDS, "clamped"), + (-1.0, DEFAULT_DEBOUNCE_SECONDS, "unparseable"), + (None, DEFAULT_DEBOUNCE_SECONDS, "unparseable"), + ("tem", DEFAULT_DEBOUNCE_SECONDS, "unparseable"), + (math.nan, DEFAULT_DEBOUNCE_SECONDS, "unparseable"), + ], +) +def test_resolve_window_reports_why_the_value_changed( + configured: object, expected_window: float, expected_problem: str | None +): + """The caller logs a different message and severity per case, so the reason has to survive.""" + assert resolve_window(configured) == (expected_window, expected_problem) + + +def test_resolve_window_honours_an_explicit_default(): + assert resolve_window("nonsense", default=42.0) == (42.0, "unparseable") + + @pytest.mark.asyncio -async def test_window_is_clamped_inside_trigger(clock: FakeClock): +async def test_window_is_clamped_inside_trigger(clock: FakeClock, sleeper: FakeSleep, make_trigger): """The clamp is applied per call, so an out-of-range config cannot wedge the debouncer.""" - trigger = DebouncedTrigger("policy") + trigger = make_trigger("policy") calls = 0 async def run() -> None: @@ -121,9 +235,10 @@ async def run() -> None: clock.advance(MAX_DEBOUNCE_SECONDS - 1) assert await trigger.trigger(run=run, window_seconds=huge) is False - # Past the CAP - not past the configured 600000s - the next trigger fires again. - clock.advance(2.0) - assert await trigger.trigger(run=run, window_seconds=huge) is True + # The trailing run waits out the remainder of the CAP - one second - not the remainder of + # the configured 600000s, which is what an unclamped window would have parked on. + await drain_trailing(trigger) + assert sleeper.requested == [1.0] assert calls == 2 @@ -131,8 +246,10 @@ async def run() -> None: @pytest.mark.asyncio -async def test_returns_true_when_dispatched_and_false_when_coalesced(clock: FakeClock): - trigger = DebouncedTrigger("policy") +async def test_returns_true_when_dispatched_and_false_when_coalesced( + clock: FakeClock, sleeper: FakeSleep, make_trigger +): + trigger = make_trigger("policy") calls = 0 async def run() -> None: @@ -146,23 +263,98 @@ async def run() -> None: assert await trigger.trigger(run=run, window_seconds=WINDOW) is False assert calls == 1 + # The coalesced trigger is served by the trailing run, not dropped. + await drain_trailing(trigger) + assert sleeper.requested == [pytest.approx(0.001)] + assert calls == 2 + # Boundary: the guard is `elapsed < window`, so at exactly one window the trigger fires. - clock.advance(0.001) + clock.advance(WINDOW) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + assert calls == 3 + + +@pytest.mark.asyncio +async def test_window_coalesced_trigger_is_served_by_a_trailing_run(clock: FakeClock, sleeper: FakeSleep, make_trigger): + """The headline semantic: a window-coalesced trigger is DEFERRED, never discarded. + + The dispatch it collapsed into already read the control plane before this caller's change + landed, and the PDP is pubsub-driven with no periodic full-refresh cadence - so dropping it + would lose the refresh permanently, which is what PER-15248 forbids. The endpoint tells + clients "do not retry on `triggered: false`", and this is the mechanism that makes that + instruction safe to follow. + """ + trigger = make_trigger("data") + reasons: list[str] = [] + + async def run_first() -> None: + reasons.append("first") + + async def run_coalesced() -> None: + reasons.append("coalesced") + + assert await trigger.trigger(run=run_first, window_seconds=WINDOW) is True + + clock.advance(2.0) + assert await trigger.trigger(run=run_coalesced, window_seconds=WINDOW) is False + assert trigger._trailing_task is not None, "a window-coalesced trigger must arm a trailing run" + assert reasons == ["first"], "the trailing run must not start before the window expires" + + await drain_trailing(trigger) + # It waited out the REMAINDER of the window (8s of 10), and it ran the coalesced caller's + # own closure rather than re-running the original. + assert sleeper.requested == [pytest.approx(8.0)] + assert reasons == ["first", "coalesced"] + # ...and the chain stops, because nothing arrived while it was running. + assert trigger._trailing_task is None + assert trigger._pending is False + + +@pytest.mark.asyncio +@pytest.mark.usefixtures("sleeper") +async def test_guard_one_coalesces_while_a_trailing_run_is_armed_even_past_the_window(clock: FakeClock, make_trigger): + """An armed trailing run accounts for later triggers, so they must not start a second pull. + + Without ``_trailing_task`` in guard 1 a trigger arriving after the window elapsed - but + before the armed trailing run fires - would dispatch concurrently with it. + """ + trigger = make_trigger("policy") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + clock.advance(1.0) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False # arms the trailing run + assert trigger._trailing_task is not None + + # Jump the clock clean past the window: the window guard alone would now ADMIT. + clock.advance(WINDOW * 5) + # Awaited DIRECTLY rather than through `trigger_promptly`: the coalesce path contains no + # `await`, so this never yields, and the armed trailing task has still not had a single + # step. Routing it through `wait_for` would hand the loop over and let the trailing run + # finish first, quietly turning this into a test of the window guard instead. + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + assert calls == 1, "only guard 1 can account for this coalesce" + + await drain_trailing(trigger) assert calls == 2 @pytest.mark.asyncio -async def test_window_is_consumed_by_the_dispatch_not_by_the_reload_succeeding(clock: FakeClock): - """``_last_dispatched`` is a DISPATCH timestamp - there is no "only on success" guarantee. +@pytest.mark.usefixtures("sleeper") +async def test_window_is_consumed_by_the_dispatch_not_by_the_reload_succeeding(clock: FakeClock, make_trigger): + """``_last_dispatched`` is a DISPATCH timestamp - it never waits on the reload succeeding. Both real updaters are fire-and-forget: ``trigger_update_policy`` is a queue put, and ``get_base_policy_data`` hands the per-entry fetches to a task pool. ``run`` returning therefore means "handed off", and a reload that fails afterwards in a background task is - invisible from here - so it still consumes the window. The only failure this layer can - observe is one raised out of ``run`` itself (see the cancellation/raise tests below). + invisible from here - so it still consumes the window. See + ``test_a_run_that_raises_consumes_the_window`` for the failure this layer CAN observe. """ - trigger = DebouncedTrigger("data") + trigger = make_trigger("data") calls = 0 async def run() -> None: @@ -177,11 +369,14 @@ async def run() -> None: assert await trigger.trigger(run=run, window_seconds=WINDOW) is False assert calls == 1 + await drain_trailing(trigger) + assert calls == 2 + @pytest.mark.asyncio -async def test_zero_window_lets_every_sequential_trigger_through(): +async def test_zero_window_lets_every_sequential_trigger_through(make_trigger): # No `clock` fixture: with the window disabled the guard never reads the clock at all. - trigger = DebouncedTrigger("policy") + trigger = make_trigger("policy") calls = 0 async def run() -> None: @@ -191,20 +386,23 @@ async def run() -> None: for _ in range(3): assert await trigger.trigger(run=run, window_seconds=0) is True assert calls == 3 + # Nothing was ever coalesced, so no trailing run was armed. + assert trigger._trailing_task is None + assert trigger._pending is False # --- the in-flight guard, which is unconditional ------------------------------------------- @pytest.mark.asyncio -async def test_in_flight_guard_applies_even_with_the_window_disabled(): +async def test_in_flight_guard_applies_even_with_the_window_disabled(make_trigger): """``window_seconds=0`` disables the TIME guard only. "No time-based damping" must never mean "two concurrent full pulls", so the in-flight guard is checked before - and independently of - the window. This is the case the pre-rewrite code got wrong: it returned early on ``window_seconds <= 0`` and bypassed the guard entirely. """ - trigger = DebouncedTrigger("policy") + trigger = make_trigger("policy") calls = 0 started = asyncio.Event() release = asyncio.Event() @@ -228,14 +426,16 @@ async def run() -> None: if not dispatch.done(): dispatch.cancel() - # The coalesced trigger armed the trailing edge, so it was honoured rather than dropped. + # The coalesced trigger armed the trailing edge, so it is honoured rather than dropped - + # but off the request path, so the dispatching caller was not billed for it. + await drain_trailing(trigger) assert calls == 2 @pytest.mark.asyncio -async def test_concurrent_burst_collapses_into_a_single_dispatch(): +async def test_concurrent_burst_collapses_into_a_single_dispatch(make_trigger): """The load-amplification case: N simultaneous triggers must not become N control-plane pulls.""" - trigger = DebouncedTrigger("data") + trigger = make_trigger("data") calls = 0 started = asyncio.Event() release = asyncio.Event() @@ -264,6 +464,7 @@ async def run() -> None: assert results.count(False) == 4, f"the other four should report a coalesce, got {results}" # Two dispatches, not five: the original plus the single trailing edge covering all four # absorbed triggers. + await drain_trailing(trigger) assert calls == 2 @@ -271,19 +472,65 @@ async def run() -> None: @pytest.mark.asyncio -async def test_trailing_edge_fires_exactly_once_and_is_not_re_armed(): - """Triggers absorbed in flight get ONE follow-up run, and that run cannot chain another. +async def test_trailing_run_is_not_awaited_by_the_dispatching_caller(make_trigger): + """The dispatching caller must not be billed for a reload somebody else's trigger asked for. - Without the trailing edge a trigger coalesced by the in-flight guard is simply lost: the - reload it collapsed into may already have read its data before the caller's change landed. - With an unbounded trailing edge, a sustained hammer would keep re-arming it and never let - the dispatch finish. So: two runs per call, maximum. + It used to await the trailing run inline, doubling that request's worst-case latency against + the 60s client timeout of the Rust server that fronts this app - so a caller could be timed + out at the proxy for work it never requested, then retry, feeding the very amplification + loop this class exists to break. """ - trigger = DebouncedTrigger("policy") - # Three slots so a (buggy) third run has somewhere to go and can be asserted against, + trigger = make_trigger("policy") + entered = [asyncio.Event() for _ in range(2)] + gates = [asyncio.Event() for _ in range(2)] + calls = 0 + + async def run() -> None: + nonlocal calls + index = calls + calls += 1 + entered[index].set() + await gates[index].wait() + + dispatch = asyncio.create_task(trigger.trigger(run=run, window_seconds=0)) + try: + await asyncio.wait_for(entered[0].wait(), timeout=TIMEOUT) + assert await trigger_promptly(trigger, run, window_seconds=0) is False + + # Release only the FIRST run. If the trailing run were still inline, the dispatching + # call would now park on gates[1] and this wait_for would time out. + gates[0].set() + assert await asyncio.wait_for(dispatch, timeout=TIMEOUT) is True + + # It returned while the trailing run is still parked inside `run` - i.e. genuinely off + # the request path. + await asyncio.wait_for(entered[1].wait(), timeout=TIMEOUT) + assert trigger._trailing_task is not None + gates[1].set() + finally: + for gate in gates: + gate.set() + if not dispatch.done(): + dispatch.cancel() + + await drain_trailing(trigger) + assert calls == 2 + + +@pytest.mark.asyncio +async def test_trailing_edge_chains_while_triggers_keep_arriving_then_stops(make_trigger): + """A trigger arriving during a trailing run gets its own follow-up - and the chain terminates. + + ``_pending`` is written ``True`` in exactly one place (``trigger``, by an external caller) + and nothing in the trailing path sets it, so chain length is bounded by the number of real + triggers. That is what stops this from degenerating into a standing one-reload-per-window + load on the control plane with no client asking for anything. + """ + trigger = make_trigger("policy") + # Four slots so a (buggy) fourth run has somewhere to go and can be asserted against, # rather than blowing up with an IndexError that reads like an unrelated failure. - entered = [asyncio.Event() for _ in range(3)] - gates = [asyncio.Event() for _ in range(3)] + entered = [asyncio.Event() for _ in range(4)] + gates = [asyncio.Event() for _ in range(4)] calls = 0 async def run() -> None: @@ -302,29 +549,35 @@ async def run() -> None: assert await trigger_promptly(trigger, run, window_seconds=0) is False gates[0].set() + assert await asyncio.wait_for(dispatch, timeout=TIMEOUT) is True await asyncio.wait_for(entered[1].wait(), timeout=TIMEOUT) assert calls == 2 - # A trigger arriving during the TRAILING run is still coalesced (the guard is on - # `_in_flight`, which is still set) but the trailing edge is spent, so it must not - # schedule a further run - staleness from here is bounded by the window guard. + # A trigger arriving DURING the trailing run is coalesced (guard 1 - `_in_flight` is set + # again for the trailing run) and chains exactly one more run, so it is not dropped. assert await trigger_promptly(trigger, run, window_seconds=0) is False - gates[1].set() - assert await asyncio.wait_for(dispatch, timeout=TIMEOUT) is True + await asyncio.wait_for(entered[2].wait(), timeout=TIMEOUT) + assert calls == 3 + + gates[2].set() finally: for gate in gates: gate.set() if not dispatch.done(): dispatch.cancel() - assert calls == 2 - assert not entered[2].is_set(), "the trailing edge re-armed itself; dispatches are not capped at two" + await drain_trailing(trigger) + # ...and now it stops: nothing arrived during the third run, so nothing re-armed. + assert calls == 3 + assert not entered[3].is_set(), "the chain re-armed with no trigger to justify it" + assert trigger._trailing_task is None + assert trigger._pending is False @pytest.mark.asyncio -async def test_no_trailing_edge_when_nothing_arrived_mid_dispatch(): - trigger = DebouncedTrigger("policy") +async def test_no_trailing_edge_when_nothing_arrived_mid_dispatch(make_trigger): + trigger = make_trigger("policy") calls = 0 async def run() -> None: @@ -338,20 +591,109 @@ async def run() -> None: assert calls == 1 assert trigger._pending is False assert trigger._in_flight is False + assert trigger._trailing_task is None + + +@pytest.mark.asyncio +@pytest.mark.usefixtures("sleeper") +async def test_a_trailing_run_that_raises_clears_the_handle(clock: FakeClock, make_trigger): + """A failing trailing run must not wedge the debouncer into coalescing forever. + + ``_trailing_task`` is half of guard 1, so leaving it set after a failure would make every + future trigger a no-op - the exact failure this class exists to prevent. + """ + trigger = make_trigger("data") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + if calls == 2: # the trailing run + raise RuntimeError("trailing boom") + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + clock.advance(1.0) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + + await drain_trailing(trigger) + assert calls == 2 + # Not wedged, and the failed attempt still consumed the window. + assert trigger._trailing_task is None + assert trigger._in_flight is False + assert trigger._last_dispatched is not None + + clock.advance(WINDOW + 1) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + assert calls == 3 + + +@pytest.mark.asyncio +@pytest.mark.usefixtures("sleeper") +async def test_a_trailing_task_cancelled_before_its_first_step_clears_the_handle(clock: FakeClock, make_trigger): + """The case ``_run_trailing``'s own ``finally`` cannot cover, hence the done-callback. + + A task cancelled before it is ever scheduled never runs its body at all, so nothing inside + the coroutine can clear ``_trailing_task`` - and a permanently-set handle coalesces every + future trigger. + """ + trigger = make_trigger("policy") + + async def run() -> None: + pass + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + clock.advance(1.0) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + + task = trigger._trailing_task + assert task is not None + # Cancel before the loop has ever given it a step: the coalesce path above returns without + # suspending, so the task has not started. + task.cancel() + await asyncio.gather(task, return_exceptions=True) + + assert trigger._trailing_task is None + # ...and the debouncer still works. + clock.advance(WINDOW + 1) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + + +@pytest.mark.asyncio +@pytest.mark.usefixtures("sleeper") +async def test_aclose_cancels_an_armed_trailing_run_and_is_idempotent(clock: FakeClock, make_trigger): + """Shutdown must not leave a trailing reload outliving the event loop.""" + trigger = make_trigger("data") + calls = 0 + + async def run() -> None: + nonlocal calls + calls += 1 + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + clock.advance(1.0) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + assert trigger._trailing_task is not None + + await trigger.aclose() + assert trigger._trailing_task is None + assert calls == 1, "the trailing run was cancelled before it could dispatch" + + # Idempotent: closing again with nothing armed is a no-op, not an error. + await trigger.aclose() # --- failure paths: the guards must never wedge -------------------------------------------- @pytest.mark.asyncio -async def test_cancelling_a_dispatch_resets_in_flight_and_records_no_dispatch(): +async def test_cancelling_a_dispatch_resets_in_flight_and_records_no_dispatch(make_trigger): """A cancelled dispatch (client disconnect, shutdown) must not leave the guard stuck on. - ``_in_flight`` is cleared by the ``finally``; ``_last_dispatched`` is assigned only after - ``await run()`` *returns*, which cancellation prevents. So the debouncer is left exactly as - it was before the call, and ``CancelledError`` still propagates to the caller. + Cancellation is the one case that does NOT consume the window: the attempt was abandoned + rather than made, so the control plane was not necessarily asked. The debouncer is left + exactly as it was before the call, and ``CancelledError`` still propagates to the caller. """ - trigger = DebouncedTrigger("data") + trigger = make_trigger("data") started = asyncio.Event() never = asyncio.Event() @@ -371,6 +713,8 @@ async def run() -> None: assert trigger._in_flight is False assert trigger._last_dispatched is None assert trigger._pending is False + # Nothing was coalesced into it, and on shutdown there would be nobody left to run one. + assert trigger._trailing_task is None # Not wedged: the next trigger dispatches instead of coalescing forever. calls = 0 @@ -384,10 +728,17 @@ async def run_again() -> None: @pytest.mark.asyncio -async def test_a_run_that_raises_propagates_and_records_no_dispatch(): - # No `clock` fixture: nothing here needs time to move, which is precisely the point - the - # retry below is admitted because no dispatch was ever recorded, not because time passed. - trigger = DebouncedTrigger("data") +@pytest.mark.usefixtures("sleeper") +async def test_a_run_that_raises_consumes_the_window(clock: FakeClock, make_trigger): + """A FAILED dispatch damps the next one just as a successful dispatch does. + + This is the whole point of stamping ``_last_dispatched`` in a ``finally``. ``run`` for the + data route reaches ``get_policy_data_config``, which raises ``ClientError`` on any non-200 + from the control plane - so a window consumed only by SUCCESSES would leave the mitigation + switched off in exactly the degraded-control-plane conditions it exists for, letting one + retrying client sustain a fresh control-plane GET per request. + """ + trigger = make_trigger("data") async def boom() -> None: raise RuntimeError("dispatch failed") @@ -395,28 +746,83 @@ async def boom() -> None: with pytest.raises(RuntimeError, match="dispatch failed"): await trigger.trigger(run=boom, window_seconds=WINDOW) - assert trigger._last_dispatched is None + assert trigger._last_dispatched is not None, "the ATTEMPT consumes the window, not the outcome" assert trigger._in_flight is False + assert trigger._trailing_task is None, "nothing was coalesced into it, so nothing to re-run" - # ...so an immediate retry inside the window is NOT coalesced. + # An immediate retry inside the window is therefore coalesced - no second pull... calls = 0 async def run() -> None: nonlocal calls calls += 1 - assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + clock.advance(1.0) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + assert calls == 0 + + # ...and it is still not dropped: the trailing run retries once the window expires. + await drain_trailing(trigger) assert calls == 1 +# --- observability: a stalled dispatch must not be silent ---------------------------------- + + +@pytest.mark.asyncio +@pytest.mark.usefixtures("sleeper") +async def test_a_stalled_dispatch_escalates_the_coalesce_log_to_error( + clock: FakeClock, make_trigger, captured_logs: list[tuple[str, str]] +): + """``run`` is never cancelled, so a hung control-plane GET can hold guard 1 for minutes. + + Cancelling it is not an option - ``get_base_policy_data`` tears down every periodic poller + BEFORE the config GET and only recreates them at the very end, so a timeout landing on the + stalled GET would kill periodic data updates outright. The stall is made loud instead. + """ + trigger = make_trigger("data") + started = asyncio.Event() + release = asyncio.Event() + + async def run() -> None: + started.set() + await release.wait() + + dispatch = asyncio.create_task(trigger.trigger(run=run, window_seconds=WINDOW)) + try: + await asyncio.wait_for(started.wait(), timeout=TIMEOUT) + + # A dispatch that is merely slow stays at INFO... + assert await trigger_promptly(trigger, run, window_seconds=WINDOW) is False + + # ...but once it is stalled, every coalesce is alertable rather than buried at DEBUG. + clock.advance(MAX_DISPATCH_SECONDS + 1) + for _ in range(2): + assert await trigger_promptly(trigger, run, window_seconds=WINDOW) is False + + release.set() + await asyncio.wait_for(dispatch, timeout=TIMEOUT) + finally: + release.set() + if not dispatch.done(): + dispatch.cancel() + + await drain_trailing(trigger) + + coalesce_levels = [level for level, message in captured_logs if message.startswith("Coalescing")] + assert coalesce_levels == ["INFO", "ERROR", "ERROR"] + assert any("control plane looks stalled" in message for _, message in captured_logs) + + # --- logging: the mitigation must not amplify log volume ----------------------------------- @pytest.mark.asyncio -async def test_coalesce_logging_is_loud_once_then_quiet(clock: FakeClock, captured_logs: list[tuple[str, str]]): +@pytest.mark.usefixtures("sleeper") +async def test_coalesce_logging_is_loud_once_then_quiet(make_trigger, captured_logs: list[tuple[str, str]]): """Under the exact hammering this class absorbs, one INFO per suppressed request would just move the amplification from the control plane to the (unbounded, enqueue=True) log sink.""" - trigger = DebouncedTrigger("policy") + trigger = make_trigger("policy") calls = 0 async def run() -> None: @@ -430,11 +836,47 @@ async def run() -> None: coalesce_levels = [level for level, message in captured_logs if message.startswith("Coalescing")] assert coalesce_levels == ["INFO", "DEBUG", "DEBUG"] - # The DEBUG lines are not a blind spot: the next dispatch reports the absorbed total. - clock.advance(WINDOW + 1) - assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + # The DEBUG lines are not a blind spot: the trailing run reports the absorbed total when it + # serves them. + await drain_trailing(trigger) assert calls == 2 assert ("INFO", "Dispatched policy reload, absorbing 3 coalesced trigger(s).") in captured_logs # ...and the counter resets, so the next burst is reported on its own terms. assert trigger._coalesced == 0 + + +@pytest.mark.asyncio +async def test_aclose_during_the_trailing_wait_does_not_arm_a_replacement(clock: FakeClock, make_trigger): + """Cancelling a trailing run that is still waiting out the window must end the chain. + + This is the common shutdown shape: ``aclose`` almost always finds the trailing task parked + in ``_sleep`` rather than mid-dispatch, and ``_pending`` is still set there (it is cleared + only once the wait is over). A re-arm at that point would create a task during loop + teardown - after the cancel-all sweep has already run - which is precisely the + "Task was destroyed but it is pending" that arming a background task has to avoid. + """ + trigger = make_trigger("data") + waiting = asyncio.Event() + + async def never_finishes_waiting(_seconds: float) -> None: + waiting.set() + await asyncio.Event().wait() # only cancellation ends this + + async def run() -> None: + pass + + assert await trigger.trigger(run=run, window_seconds=WINDOW) is True + clock.advance(1.0) + + # Patch the sleep only now, so the dispatch above is unaffected. + with pytest.MonkeyPatch.context() as patch: + patch.setattr(debounce, "_sleep", never_finishes_waiting) + assert await trigger.trigger(run=run, window_seconds=WINDOW) is False + await asyncio.wait_for(waiting.wait(), timeout=TIMEOUT) + assert trigger._pending is True, "the trigger is still unserved while the run waits" + + await trigger.aclose() + + assert trigger._trailing_task is None, "cancellation must not chain a replacement task" + assert trigger._in_flight is False diff --git a/horizon/tests/test_trigger_debounce.py b/horizon/tests/test_trigger_debounce.py index 27cc8350..88de9756 100644 --- a/horizon/tests/test_trigger_debounce.py +++ b/horizon/tests/test_trigger_debounce.py @@ -23,9 +23,12 @@ import time from unittest.mock import AsyncMock +import aiohttp import pytest from fastapi.testclient import TestClient +from horizon import debounce from horizon.config import sidecar_config +from horizon.debounce import DebouncedTrigger from httpx import ASGITransport, AsyncClient # Basename import (not horizon.tests.*): CI installs the package non-editably, so the wheel @@ -42,6 +45,21 @@ COALESCED = {"status": "ok", "triggered": False} +async def _no_wait(_seconds: float) -> None: + """Patched over ``debounce._sleep``: fire the trailing run now instead of at window expiry. + + Still yields, so the trailing run stays a genuinely separate scheduling step rather than + collapsing into its caller and hiding an ordering bug. + """ + await asyncio.sleep(0) + + +async def drain_trailing(trigger: DebouncedTrigger) -> None: + """Run every armed (and chained) trailing task to completion, bounded by ``TIMEOUT``.""" + while (task := trigger._trailing_task) is not None: + await asyncio.wait_for(asyncio.gather(task, return_exceptions=True), timeout=TIMEOUT) + + @pytest.fixture def pdp() -> MockPermitPDP: # Fresh instance per test => fresh per-updater debounce state, so tests never coalesce @@ -70,8 +88,15 @@ def test_policy_triggers_within_window_coalesce(pdp: MockPermitPDP, auth: dict[s assert first.json() == DISPATCHED assert second.status_code == 200 assert second.json() == COALESCED - # Second call coalesced: the updater was forced exactly once. + # Second call coalesced: the updater was forced exactly once *during these requests*. trigger.assert_awaited_once_with(force_full_update=True) + # The coalesced trigger was deferred rather than dropped - it armed a trailing reload - but + # that is deliberately NOT asserted here. A TestClient used without `with` runs each request + # on its own event loop and tears it down afterwards, so the background task is cancelled + # with the loop and the handle is cleared on a schedule this test cannot pin down. That is a + # property of the harness, not of the debouncer. The trailing edge is driven for real where + # a single loop spans the whole test: test_in_flight_guard_beats_an_elapsed_window below, + # and the trailing-edge tests in test_debounce_unit.py. def test_data_triggers_within_window_coalesce(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): @@ -185,13 +210,23 @@ async def test_in_flight_guard_beats_an_elapsed_window(pdp: MockPermitPDP, auth: through, so anything that coalesces it must be the in-flight guard. """ monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + # The trailing run waits out the remainder of the window before firing. Skip the wait + # (without skipping the scheduling) so the test does not park on ten real seconds. + monkeypatch.setattr(debounce, "_sleep", _no_wait) - started = asyncio.Event() # set once the second reload is genuinely running - release = asyncio.Event() # keeps that reload in flight until the test releases it + # One gate per blocking reload: index 0 is the dispatch parked in flight, index 1 is the + # trailing run it arms. Keeping them separate is what lets the test prove the dispatching + # REQUEST was answered while the trailing run was still going. + started = [asyncio.Event(), asyncio.Event()] + release = [asyncio.Event(), asyncio.Event()] + blocking_calls = 0 async def blocking(**_kwargs) -> None: - started.set() - await release.wait() + nonlocal blocking_calls + index = blocking_calls + blocking_calls += 1 + started[index].set() + await release[index].wait() get_base = AsyncMock() monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) @@ -210,7 +245,7 @@ async def blocking(**_kwargs) -> None: get_base.side_effect = blocking second = asyncio.create_task(client.post("/data-updater/trigger", headers=auth)) try: - await asyncio.wait_for(started.wait(), timeout=TIMEOUT) + await asyncio.wait_for(started[0].wait(), timeout=TIMEOUT) assert debouncer._in_flight is True assert time.monotonic() - debouncer._last_dispatched > WINDOW, ( "the window must be elapsed, otherwise the window guard could be doing the coalescing" @@ -227,52 +262,100 @@ async def blocking(**_kwargs) -> None: assert third.json() == COALESCED assert get_base.await_count == 2 - release.set() + release[0].set() second_response = await asyncio.wait_for(second, timeout=TIMEOUT) + assert second_response.status_code == 200 + assert second_response.json() == DISPATCHED + + # 4. The trailing run that serves the third trigger is parked on release[1], which + # nothing has set - and the dispatching REQUEST has already been answered above. + # That is the proof it runs off the request path: inline, this caller would still + # be blocked here, paying for a second full reload it never asked for (against + # the 60s client timeout of the Rust server that fronts this app). + await asyncio.wait_for(started[1].wait(), timeout=TIMEOUT) + assert debouncer._trailing_task is not None + assert get_base.await_count == 3 + + release[1].set() + await drain_trailing(debouncer) finally: - # An assertion above failing must not leave the request task parked in `run`. - release.set() + # An assertion above failing must not leave a request task or a trailing run parked. + for gate in release: + gate.set() if not second.done(): second.cancel() - assert second_response.status_code == 200 - assert second_response.json() == DISPATCHED - # The coalesced third trigger armed the trailing edge, so the in-flight dispatch re-ran - # exactly once after completing rather than dropping that trigger on the floor. + # The coalesced third trigger was served, not dropped - exactly once. assert get_base.await_count == 3 + assert debouncer._trailing_task is None -# --- case 5: a dispatch that RAISES propagates and does not consume the window ------------ +# --- case 5: a dispatch that RAISES consumes the window and answers with a gateway error --- -def test_raising_dispatch_500s_and_does_not_consume_the_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): - """The narrow, honest version of the deleted "a failed pull does not burn the window" claim. +def test_control_plane_failure_502s_and_consumes_the_window(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + """A FAILING control plane must be damped harder than a healthy one, not left unthrottled. - ``_last_dispatched`` is assigned only after ``await run()`` RETURNS, so an exception raised - out of the dispatch skips it and an immediate retry still fires. But note how little that - covers: both updaters are fire-and-forget underneath (a queue put for policy; a config GET - plus a task hand-off for data), so a reload that is dispatched and then fails in the - background returns normally here and DOES consume the window. See - ``test_window_is_consumed_by_the_dispatch_not_by_the_reload_succeeding`` in - test_debounce_unit.py for that half of the contract. + ``get_policy_data_config`` raises ``ClientError`` on any non-200 from the control plane, so + a window consumed only by SUCCESSES would switch the mitigation off in exactly the degraded + conditions it exists for. ``_last_dispatched`` therefore records the ATTEMPT. + + The status matters too: this used to escape as a bare 500 - the one code every SDK and + service mesh retries - so the failure mode recruited clients into a retry storm against an + already-struggling control plane. 502 attributes the failure upstream (matching + horizon/enforcer/api.py) and carries a `Retry-After` telling the client when a retry could + actually accomplish something. """ monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) - get_base = AsyncMock(side_effect=RuntimeError("boom")) + get_base = AsyncMock(side_effect=aiohttp.ClientError("control plane said 503")) monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) - # raise_server_exceptions=False so the propagated error surfaces as a 500 response. client = TestClient(pdp._app, raise_server_exceptions=False) first = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) - assert first.status_code == 500 - assert pdp._data_trigger_debounce._last_dispatched is None + assert first.status_code == 502 + # Never sooner than the window: the failed attempt just consumed it, so an earlier retry is + # guaranteed to be coalesced and would be a provably useless call. + assert first.headers["Retry-After"] == str(int(WINDOW)) + assert pdp._data_trigger_debounce._last_dispatched is not None # The `finally` still clears the in-flight flag, so a raise cannot wedge the debouncer into # coalescing every future trigger. assert pdp._data_trigger_debounce._in_flight is False - # ...so an immediate retry within the window is not coalesced: it dispatches (and 500s again). + # An immediate retry within the window is coalesced instead of opening a second connection + # to the failing control plane - and it is not lost either: a trailing reload is armed. second = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) - assert second.status_code == 500 - assert get_base.await_count == 2 + assert second.status_code == 200 + assert second.json() == COALESCED + assert get_base.await_count == 1 + + +def test_control_plane_timeout_504s(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + get_base = AsyncMock(side_effect=asyncio.TimeoutError()) + monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) + client = TestClient(pdp._app, raise_server_exceptions=False) + + response = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert response.status_code == 504 + assert response.headers["Retry-After"] == str(int(WINDOW)) + + +def test_an_unexpected_error_is_still_a_500(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + """Only *control-plane* failures are translated; a genuine bug must not be dressed up as one. + + A 502/504 tells the caller "upstream is unwell, retry later". Mapping an internal + ``RuntimeError`` to that would send clients into a retry loop over a defect no amount of + retrying can clear, and would hide the bug from PDP-side alerting. + """ + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + get_base = AsyncMock(side_effect=RuntimeError("boom")) + monkeypatch.setattr(pdp._opal.data_updater, "get_base_policy_data", get_base) + client = TestClient(pdp._app, raise_server_exceptions=False) + + response = client.post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert response.status_code == 500 + # Still consumed the window: the attempt was made regardless of how it failed. + assert pdp._data_trigger_debounce._last_dispatched is not None # --- case 6: a disabled data updater 503s before the debouncer (window not consumed) ----- @@ -357,3 +440,46 @@ def test_replacement_route_still_rejects_missing_token(pdp: MockPermitPDP, monke resp = TestClient(pdp._app).post("/policy-updater/trigger", follow_redirects=False) assert resp.status_code == 401 trigger.assert_not_awaited() + + +# --- case 9: the published contract actually describes the body clients are told to read --- + + +def test_openapi_declares_the_trigger_response_shape(pdp: MockPermitPDP): + """`triggered` must exist in the SCHEMA, not just in the prose that tells clients to use it. + + The routes' customer-facing `description=` instructs integrators to branch on `triggered`. + Without a `response_model` FastAPI publishes an empty 200 schema, so that instruction would + reference a field no code generator or typed SDK can see. + """ + spec = pdp._app.openapi() + + for path in ("/policy-updater/trigger", "/data-updater/trigger"): + operation = spec["paths"][path]["post"] + schema = operation["responses"]["200"]["content"]["application/json"]["schema"] + assert schema == {"$ref": "#/components/schemas/TriggerResponse"}, path + + trigger_response = spec["components"]["schemas"]["TriggerResponse"] + assert set(trigger_response["properties"]) == {"status", "triggered"} + assert trigger_response["properties"]["triggered"]["type"] == "boolean" + + # The data route's documented failure modes are declared too, so a client can tell the + # permanent "updater disabled" 503 from the transient, Retry-After-carrying 502/504. + assert {"502", "503", "504"} <= set(spec["paths"]["/data-updater/trigger"]["post"]["responses"]) + + # The legacy aliases stay out of the published contract - they are compatibility shims. + assert not [path for path in spec["paths"] if "update_policy" in path] + + +def test_disabled_data_updater_503_carries_no_retry_after(pdp: MockPermitPDP, auth: dict[str, str], monkeypatch): + """A disabled updater is a configuration state: retrying cannot help, so promise nothing. + + This is why the control-plane failures map to 502/504 rather than joining this 503 - a + client must be able to tell "back off and retry" from "stop, this will never work". + """ + monkeypatch.setattr(sidecar_config, "TRIGGER_DEBOUNCE_SECONDS", WINDOW) + monkeypatch.setattr(pdp._opal, "data_updater", None) + + response = TestClient(pdp._app).post("/data-updater/trigger", headers=auth, follow_redirects=False) + assert response.status_code == 503 + assert "Retry-After" not in response.headers