diff --git a/headroom/proxy/hard_watchdog.py b/headroom/proxy/hard_watchdog.py new file mode 100644 index 000000000..a04816c26 --- /dev/null +++ b/headroom/proxy/hard_watchdog.py @@ -0,0 +1,103 @@ +"""Last-resort liveness watchdog that survives a held GIL. + +The in-process compression watchdogs bound slow work with timed thread joins, +which quietly assumes the GIL keeps changing hands: resuming from a timed +``join`` needs the GIL, so a native call that computes without releasing it +freezes every Python thread at once -- uvicorn, ``/readyz``, logging, and the +very watchdog meant to bound the offender. Field report: 61+ seconds of +full-process silence at three times the compression deadline, TCP backlog +still accepting connections nothing would ever answer (#3178). + +``faulthandler.dump_traceback_later`` is the one escape hatch the interpreter +offers: its timer runs on a C thread that never takes the GIL, and on expiry +it writes every thread's stack with signal-safe code and (optionally) hard +exits. A Python heartbeat thread re-arms the timer while the interpreter is +healthy; if the GIL is seized for longer than the deadline, the heartbeat +cannot re-arm and the C timer fires -- naming the culprit stack in stderr +(the proxy log) and ending a process that was already unable to serve +anything. Supervised deployments restart it; unsupervised ones trade an +eternal zombie that hangs every client for a visible crash with a diagnosis. + +The deadline is deliberately generous (90s against a 20s compression +deadline and 15s stats timeouts): this must only ever fire when the process +is beyond every softer recovery path. +""" + +from __future__ import annotations + +import atexit +import faulthandler +import logging +import os +import sys +import threading +import time + +logger = logging.getLogger(__name__) + +ENV_VAR = "HEADROOM_HARD_WATCHDOG_SECS" +DEFAULT_SECS = 90.0 +# Below this the heartbeat interval (a third of the deadline) gets close to +# scheduler jitter and a busy-but-healthy interpreter could be shot. +MIN_SECS = 5.0 + +_started = threading.Event() + + +def _resolve_secs() -> float: + raw = os.environ.get(ENV_VAR, "") + if not raw.strip(): + return DEFAULT_SECS + try: + secs = float(raw) + except ValueError: + logger.warning("Ignoring non-numeric %s=%r; using %ss", ENV_VAR, raw, DEFAULT_SECS) + return DEFAULT_SECS + if secs <= 0: + return 0.0 + return max(secs, MIN_SECS) + + +def _arm(secs: float) -> None: + # Re-arming replaces the previous timer, so a healthy interpreter never + # lets it expire. ``file`` is the underlying stderr fd, which supervisors + # already redirect into the proxy log. + faulthandler.dump_traceback_later(secs, exit=True, file=sys.stderr) + + +def _heartbeat(secs: float) -> None: + while True: + time.sleep(secs / 3.0) + _arm(secs) + + +def start_hard_watchdog() -> bool: + """Arm the watchdog for this process. Returns True when armed. + + Per-process by design: uvicorn workers each arm their own (the timer and + the GIL are both process-local). Safe to call more than once. + """ + if _started.is_set(): + return True + secs = _resolve_secs() + if not secs: + logger.info("Hard watchdog disabled (%s=0)", ENV_VAR) + return False + _started.set() + # Normal interpreter shutdown must not be shot by a timer armed moments + # earlier; CPython additionally cancels the C thread during finalization. + atexit.register(faulthandler.cancel_dump_traceback_later) + # First arm happens here, synchronously: the caller is covered from the + # moment this returns, even if the very next call seizes the GIL before + # the heartbeat thread gets scheduled. + _arm(secs) + threading.Thread( + target=_heartbeat, args=(secs,), name="headroom-hard-watchdog", daemon=True + ).start() + logger.info( + "Hard watchdog armed: dump all stacks and exit if the interpreter " + "makes no progress for %.0fs (%s to tune, 0 to disable)", + secs, + ENV_VAR, + ) + return True diff --git a/headroom/proxy/server.py b/headroom/proxy/server.py index f90b082ee..385d11f63 100644 --- a/headroom/proxy/server.py +++ b/headroom/proxy/server.py @@ -2644,6 +2644,14 @@ def create_app(config: ProxyConfig | None = None) -> FastAPI: @asynccontextmanager async def lifespan(app: FastAPI): # type: ignore[no-untyped-def] + # Arm the C-level liveness watchdog before anything that can touch + # native code: a GIL seized during startup freezes the process just as + # thoroughly as one seized while serving (#3178). Per worker, because + # the timer and the GIL are both process-local. + from headroom.proxy.hard_watchdog import start_hard_watchdog + + start_hard_watchdog() + # Hotfix-A0: Rust core deployment smoke test. Refuse to accept # traffic if the Rust extension is missing unless the operator # explicitly opted out with HEADROOM_REQUIRE_RUST_CORE=false. See diff --git a/tests/test_hard_watchdog.py b/tests/test_hard_watchdog.py new file mode 100644 index 000000000..33c6bc18c --- /dev/null +++ b/tests/test_hard_watchdog.py @@ -0,0 +1,106 @@ +"""The hard watchdog must fire under a held GIL -- the case nothing else survives. + +The proxy's soft watchdogs (timed thread joins, asyncio timeouts) all need the +GIL to act, so a native call that computes without releasing it freezes the +process beyond their reach (#3178: 61+ seconds of full-process silence at three +times the compression deadline). ``faulthandler.dump_traceback_later``'s timer +is a C thread that never takes the GIL; these tests pin the two properties the +design depends on: + +* a process whose GIL is seized past the deadline is dumped and exited, and +* a healthy process re-arms the timer and is never shot. + +The GIL seizure is simulated with ``ctypes.PyDLL`` -- unlike ``CDLL``, calls +through it do NOT release the GIL, so ``libc sleep()`` becomes a perfect stand +-in for a native call that holds the interpreter hostage. +""" + +from __future__ import annotations + +import subprocess +import sys +import textwrap + +import pytest + +from headroom.proxy.hard_watchdog import DEFAULT_SECS, MIN_SECS, _resolve_secs + + +def test_resolve_secs_defaults_and_clamps(monkeypatch): + monkeypatch.delenv("HEADROOM_HARD_WATCHDOG_SECS", raising=False) + assert _resolve_secs() == DEFAULT_SECS + + monkeypatch.setenv("HEADROOM_HARD_WATCHDOG_SECS", "0") + assert _resolve_secs() == 0.0 + monkeypatch.setenv("HEADROOM_HARD_WATCHDOG_SECS", "-3") + assert _resolve_secs() == 0.0 + + # A deadline near scheduler jitter would shoot healthy processes. + monkeypatch.setenv("HEADROOM_HARD_WATCHDOG_SECS", "1") + assert _resolve_secs() == MIN_SECS + + monkeypatch.setenv("HEADROOM_HARD_WATCHDOG_SECS", "not-a-number") + assert _resolve_secs() == DEFAULT_SECS + + +_SEIZE_GIL = textwrap.dedent( + """ + import ctypes, ctypes.util, sys + from headroom.proxy.hard_watchdog import start_hard_watchdog + + assert start_hard_watchdog() + libc = ctypes.PyDLL(ctypes.util.find_library("c")) + print("SEIZING", flush=True) + libc.sleep(60) # PyDLL: the GIL is held for the whole call + print("UNREACHABLE", flush=True) + """ +) + +_HEALTHY = textwrap.dedent( + """ + import time + from headroom.proxy.hard_watchdog import start_hard_watchdog + + assert start_hard_watchdog() + time.sleep(12) # well past the 5s deadline; sleep releases the GIL + print("SURVIVED", flush=True) + """ +) + + +@pytest.mark.skipif(sys.platform == "win32", reason="libc lookup is POSIX-only") +def test_seized_gil_is_dumped_and_exited(): + proc = subprocess.run( + [sys.executable, "-c", _SEIZE_GIL], + env={"HEADROOM_HARD_WATCHDOG_SECS": "5", "PATH": "/usr/bin:/bin"}, + capture_output=True, + text=True, + timeout=40, + ) + assert "UNREACHABLE" not in proc.stdout + # faulthandler's timeout path exits the process abnormally... + assert proc.returncode != 0 + # ...after writing every thread's stack to stderr, naming the culprit. + assert "Thread 0x" in proc.stderr or "Current thread" in proc.stderr + assert "sleep" in proc.stderr or "SEIZING" in proc.stdout + + +@pytest.mark.skipif(sys.platform == "win32", reason="keep the pair symmetric") +def test_healthy_process_is_never_shot(): + proc = subprocess.run( + [sys.executable, "-c", _HEALTHY], + env={"HEADROOM_HARD_WATCHDOG_SECS": "5", "PATH": "/usr/bin:/bin"}, + capture_output=True, + text=True, + timeout=40, + ) + assert proc.returncode == 0, proc.stderr + assert "SURVIVED" in proc.stdout + + +def test_disabled_by_env(monkeypatch): + monkeypatch.setenv("HEADROOM_HARD_WATCHDOG_SECS", "0") + from headroom.proxy import hard_watchdog + + monkeypatch.setattr(hard_watchdog, "_started", type(hard_watchdog._started)()) + assert hard_watchdog.start_hard_watchdog() is False