diff --git a/backend/apps/health/health.py b/backend/apps/health/health.py index ed555db0..64b613f2 100644 --- a/backend/apps/health/health.py +++ b/backend/apps/health/health.py @@ -7,7 +7,17 @@ from fastapi import status, HTTPException @asynccontextmanager async def health_lifespan(): - yield + # Out-of-loop liveness backstop (hermes #66892 lift): every other watchdog here is an asyncio + # task that a wedged loop can never run; this one is a plain OS thread that hard-exits a + # provably frozen backend so Electron's respawn produces a working process. Fails open. + import asyncio + from backend.apps.system.loop_liveness_watchdog import start_loop_liveness_watchdog + p_stop = start_loop_liveness_watchdog(asyncio.get_running_loop()) + try: + yield + finally: + if p_stop is not None: + p_stop.set() health = SubApp("health", health_lifespan) diff --git a/backend/apps/system/loop_liveness_watchdog.py b/backend/apps/system/loop_liveness_watchdog.py new file mode 100644 index 00000000..fc287e21 --- /dev/null +++ b/backend/apps/system/loop_liveness_watchdog.py @@ -0,0 +1,106 @@ +"""Out-of-loop event-loop liveness watchdog (lifted from hermes-agent +gateway/shutdown_watchdog.py::start_loop_liveness_watchdog, MIT; their incident #66892: the +asyncio loop froze and every recovery path needed that same frozen loop, so a wedged-but-alive +gateway sat as a zombie forever, because supervisors only restart DEAD processes). + +Our three watchdog layers (sidecar heartbeat, delegation backstop, wedge unwedger) are all +asyncio tasks INSIDE the backend loop; if that loop wedges, none of them can fire, and Electron's +respawn only triggers on process exit. This plain OS thread probes the loop with +call_soon_threadsafe; three consecutive unanswered probes means the loop is provably frozen, so +it dumps every thread's stack to a forensics file and hard-exits with the restart code Electron's +supervisor already backs off on. + +Hermes's own rules kept: the watchdog never shares a fate with the loop it watches (daemon OS +thread), every failure inside the watchdog fails OPEN (returns, never kills), and generous +strikes so a slow-but-alive loop (sync httpx on the loop is a known 2s block here) never dies.""" + +import asyncio +import faulthandler +import logging +import os +import threading +import time +from typing import Optional + +from typeguard import typechecked + +from backend.config.paths import DATA_ROOT + +logger = logging.getLogger(__name__) + +PROBE_INTERVAL_S = 30.0 +PROBE_TIMEOUT_S = 10.0 +MAX_STRIKES = 3 +# 75 = EX_TEMPFAIL, hermes's "restart me" exit language; Electron respawns any non-zero exit. +RESTART_EXIT_CODE = 75 +DUMP_PATH = os.path.join(DATA_ROOT, "loop-watchdog-dump.log") + + +@typechecked +def p_dump_and_exit(strikes: int) -> None: + try: + logger.critical(f"backend event loop missed {strikes} consecutive liveness probes; dumping stacks and exiting {RESTART_EXIT_CODE} so Electron respawns a working process") + except Exception: + pass + try: + with open(DUMP_PATH, "a", encoding="utf-8") as fh: + fh.write(f"\n=== loop watchdog fired pid={os.getpid()} t={time.time():.0f} strikes={strikes} ===\n") + fh.flush() + faulthandler.dump_traceback(file=fh, all_threads=True) + fh.write("=== end dump ===\n") + except Exception: + pass + try: + faulthandler.dump_traceback(all_threads=True) + except Exception: + pass + os._exit(RESTART_EXIT_CODE) + + +@typechecked +def start_loop_liveness_watchdog(loop: "asyncio.AbstractEventLoop") -> Optional[threading.Event]: + """Arm the watchdog against `loop`. Returns the stop event, or None when arming failed + (fail open: a backend without a watchdog beats a backend killed by a broken one).""" + stop_event = threading.Event() + + def p_wait_for_probe(probe: threading.Event) -> Optional[bool]: + deadline = time.monotonic() + PROBE_TIMEOUT_S + while True: + if stop_event.is_set(): + return None + remaining = deadline - time.monotonic() + if remaining <= 0: + return probe.is_set() + if probe.wait(timeout=min(remaining, 0.05)): + return True + + def p_watchdog() -> None: + strikes = 0 + while not stop_event.wait(timeout=PROBE_INTERVAL_S): + probe = threading.Event() + try: + loop.call_soon_threadsafe(probe.set) + except RuntimeError: + # A closed loop is a normally exiting process; no backstop needed. + return + except Exception: + logger.debug("loop liveness probe scheduling failed", exc_info=True) + return + responded = p_wait_for_probe(probe) + if responded is None: + return + if responded: + strikes = 0 + continue + strikes += 1 + logger.warning(f"backend event loop missed liveness probe ({strikes}/{MAX_STRIKES})") + if strikes >= MAX_STRIKES and not stop_event.is_set(): + p_dump_and_exit(strikes) + return + + try: + threading.Thread(target=p_watchdog, daemon=True, name="loop-liveness-watchdog").start() + except Exception: + logger.debug("failed to start loop liveness watchdog", exc_info=True) + return None + return stop_event diff --git a/backend/tests/test_loop_liveness_watchdog.py b/backend/tests/test_loop_liveness_watchdog.py new file mode 100644 index 00000000..50e9fdbf --- /dev/null +++ b/backend/tests/test_loop_liveness_watchdog.py @@ -0,0 +1,87 @@ +"""Pins the out-of-loop watchdog (hermes #66892 lift): a frozen loop is detected and killed with +forensics; a healthy or merely-slow loop is never touched; arming failures fail open.""" + +import subprocess +import sys +import textwrap + +from backend.apps.system import loop_liveness_watchdog as w + + +def p_run_child(code: str, timeout: int = 60) -> subprocess.CompletedProcess: + return subprocess.run([sys.executable, "-c", textwrap.dedent(code)], capture_output=True, text=True, timeout=timeout) + + +P_PRELUDE = """ +import asyncio, sys, time +sys.path.insert(0, ".") +from backend.apps.system import loop_liveness_watchdog as w +w.PROBE_INTERVAL_S = 0.3 +w.PROBE_TIMEOUT_S = 0.3 +w.DUMP_PATH = "/tmp/loop_watchdog_test_dump.log" +""" + + +def test_wedged_loop_is_killed_with_forensics(tmp_path): + code = P_PRELUDE + """ +async def main(): + loop = asyncio.get_running_loop() + assert w.start_loop_liveness_watchdog(loop) is not None + time.sleep(30) # wedge the loop with a sync sleep: probes can never run + +asyncio.run(main()) +print("SURVIVED") +""" + r = p_run_child(code) + assert r.returncode == w.RESTART_EXIT_CODE, f"expected exit {w.RESTART_EXIT_CODE}, got {r.returncode}: {r.stderr[:300]}" + assert "SURVIVED" not in r.stdout + dump = open("/tmp/loop_watchdog_test_dump.log").read() + assert "loop watchdog fired" in dump + assert "Thread" in dump, "faulthandler stack dump missing" + + +def test_healthy_loop_never_killed(): + code = P_PRELUDE + """ +async def main(): + loop = asyncio.get_running_loop() + stop = w.start_loop_liveness_watchdog(loop) + await asyncio.sleep(2.5) # many probe intervals, loop responsive throughout + stop.set() + +asyncio.run(main()) +print("SURVIVED") +""" + r = p_run_child(code) + assert r.returncode == 0 and "SURVIVED" in r.stdout + + +def test_slow_but_alive_loop_survives_single_strikes(): + """Blocks shorter than MAX_STRIKES consecutive misses must never kill (sync httpx on the loop is a known 2s block).""" + code = P_PRELUDE + """ +async def main(): + loop = asyncio.get_running_loop() + stop = w.start_loop_liveness_watchdog(loop) + for _ in range(3): + time.sleep(0.5) # one missed probe worth of block + await asyncio.sleep(0.7) # then responsive again: strikes reset + stop.set() + +asyncio.run(main()) +print("SURVIVED") +""" + r = p_run_child(code) + assert r.returncode == 0 and "SURVIVED" in r.stdout + + +def test_closed_loop_ends_watchdog_quietly(): + code = P_PRELUDE + """ +async def main(): + loop = asyncio.get_running_loop() + w.start_loop_liveness_watchdog(loop) + +asyncio.run(main()) +time.sleep(1.2) # loop closed; watchdog must not fire on a normally exiting process +print("SURVIVED") +""" + r = p_run_child(code) + assert r.returncode == 0 and "SURVIVED" in r.stdout