diff --git a/services/control-plane/docker-compose.yml b/services/control-plane/docker-compose.yml index 4bea06f..446507d 100644 --- a/services/control-plane/docker-compose.yml +++ b/services/control-plane/docker-compose.yml @@ -47,7 +47,13 @@ services: - REPO_ROOT=/repo - RUNTIME_PATH=/opt/homelab healthcheck: - test: ["CMD", "test", "-f", "/opt/homelab/state/supervisor.heartbeat"] + # Freshness, not just existence: `test -f` stays true forever once the + # heartbeat file is created once, even if the reconcile loop has been + # silently frozen for hours (see 2026-07-15 incident — container reported + # "healthy" for 24h with a dead loop). Fail if the heartbeat hasn't been + # touched in the last 180s (loop interval 30s + RECONCILE_TIMEOUT 90s + + # buffer for a legitimately slow cycle). + test: ["CMD", "python", "-c", "import os,sys,time; p='/opt/homelab/state/supervisor.heartbeat'; sys.exit(0 if os.path.exists(p) and time.time()-os.path.getmtime(p)<180 else 1)"] interval: 60s timeout: 5s retries: 3 diff --git a/services/control-plane/src/supervisor.py b/services/control-plane/src/supervisor.py index a9a4d05..3515b92 100644 --- a/services/control-plane/src/supervisor.py +++ b/services/control-plane/src/supervisor.py @@ -3,6 +3,7 @@ import json import time import logging import yaml +from concurrent.futures import ThreadPoolExecutor from pathlib import Path @@ -99,6 +100,26 @@ NODE_ALERT_COOLDOWN = 3600 # 1-hour cooldown to avoid repeated Telegram noise # HA_DIAG_SHADOW_MODE=false on the control-plane node when ready for live actions. HA_DIAG_SHADOW_MODE = os.getenv("HA_DIAG_SHADOW_MODE", "true").lower() == "true" +# --------------------------------------------------------------------------- +# Loop resilience +# --------------------------------------------------------------------------- +# A single reconcile() cycle must never be able to freeze the process forever. +# reconcile() does only synchronous local filesystem I/O (open/fsync/os.replace, +# directory globs) — none of it has a language-level timeout — so the cycle is +# run in a single-worker executor and bounded by RECONCILE_TIMEOUT. If a cycle +# blocks past the timeout (e.g. a stalled fsync on the /opt/homelab bind mount, +# or an ever-growing EVENTS_DIR walk), the main loop logs it and keeps ticking +# instead of hanging silently; the stuck worker thread is abandoned in place +# (Python cannot forcibly cancel a blocked syscall) and the executor's single +# worker naturally serializes the next cycle behind it, so two cycles can never +# write the same action file concurrently. +RECONCILE_TIMEOUT = float(os.getenv("SUPERVISOR_RECONCILE_TIMEOUT", "90")) + +# Every Nth cycle logs an INFO "tick" line even when nothing actionable +# happened, so silence in `docker logs` is itself a meaningful signal rather +# than being indistinguishable from a healthy, quiet loop. +TICK_LOG_EVERY = int(os.getenv("SUPERVISOR_TICK_LOG_EVERY", "10")) + # Logging setup logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s') logger = logging.getLogger("supervisor") @@ -815,11 +836,56 @@ class Supervisor: except Exception as e: logger.error(f"Failed to save action {action_id}: {e}") - def loop(self, interval=30): - logger.info("Starting supervisor loop") - while True: + def _run_cycle_safely(self): + """Run one reconcile() cycle, never letting an exception escape. + + An uncaught exception here would previously propagate out of loop() + and kill the process outright — a crash is at least visible (the + container exits and restart:unless-stopped brings it back). This + makes that failure mode explicit and non-fatal: log the full + traceback and let the loop continue on the next cycle. + """ + try: self.reconcile() - time.sleep(interval) + except Exception: + logger.exception( + "reconcile cycle raised an unhandled exception — logging and " + "continuing to the next cycle" + ) + + def loop(self, interval=30, max_cycles=None, reconcile_timeout=None): + """Run reconcile() every `interval` seconds, forever. + + max_cycles: stop after N cycles instead of looping forever (tests only). + reconcile_timeout: override RECONCILE_TIMEOUT (tests only). + """ + logger.info("Starting supervisor loop") + timeout = RECONCILE_TIMEOUT if reconcile_timeout is None else reconcile_timeout + cycle = 0 + # max_workers=1 serializes cycles: if one is abandoned after a timeout, + # the next submit() queues behind it rather than running concurrently + # and racing on the same action files. + executor = ThreadPoolExecutor(max_workers=1, thread_name_prefix="supervisor-reconcile") + try: + while max_cycles is None or cycle < max_cycles: + cycle += 1 + future = executor.submit(self._run_cycle_safely) + try: + future.result(timeout=timeout) + except TimeoutError: + logger.error( + "reconcile cycle #%d did not complete within %ss — " + "likely blocked on I/O (fsync/glob/file open) with no " + "language-level timeout. Abandoning this cycle; the loop " + "continues. The stuck worker thread keeps running in the " + "background and the next cycle will queue behind it.", + cycle, timeout, + ) + if cycle % TICK_LOG_EVERY == 0: + logger.info("tick: supervisor loop alive, cycle #%d", cycle) + time.sleep(interval) + finally: + executor.shutdown(wait=False, cancel_futures=True) if __name__ == "__main__": diff --git a/services/control-plane/tests/test_supervisor_loop_resilience.py b/services/control-plane/tests/test_supervisor_loop_resilience.py new file mode 100644 index 0000000..7565aa1 --- /dev/null +++ b/services/control-plane/tests/test_supervisor_loop_resilience.py @@ -0,0 +1,155 @@ +"""Tests for supervisor loop resilience: a single cycle must never be able to +freeze the process forever, and the loop must survive exceptions. + +Regression coverage for the 2026-07-15 incident: control-plane-supervisor +reported "Up 24h (healthy)" while the reconcile loop had silently stopped +ticking after processing one ha_websocket_dead event, with zero exceptions +and zero further log lines — because reconcile() had no per-cycle timeout +and loop() had no try/except around the cycle body. +""" +from __future__ import annotations + +import sys +import time +from pathlib import Path + +import pytest + +sys.path.insert(0, str(Path(__file__).parent.parent / "src")) +import supervisor as supervisor_module +from supervisor import Supervisor + + +def _make_supervisor(tmp_path: Path, monkeypatch) -> Supervisor: + actions = tmp_path / "actions" + events = tmp_path / "events" + world = tmp_path / "world" + state = tmp_path / "state" + repo = tmp_path / "repo" + + for d in (actions, events, world, state, repo / "hosts"): + d.mkdir(parents=True, exist_ok=True) + + monkeypatch.setattr(supervisor_module, "ACTIONS_DIR", actions) + monkeypatch.setattr(supervisor_module, "EVENTS_DIR", events) + monkeypatch.setattr(supervisor_module, "WORLD_DIR", world) + monkeypatch.setattr(supervisor_module, "REPO_ROOT", repo) + + sup = Supervisor() + sup.desired_state = {"services": {}} + sup.actual_state = {"services": {}, "nodes": {}, "incidents": {}} + return sup + + +# --------------------------------------------------------------------------- +# 1. Loop processes many cycles without hanging +# --------------------------------------------------------------------------- + +def test_loop_processes_multiple_cycles(tmp_path, monkeypatch): + sup = _make_supervisor(tmp_path, monkeypatch) + monkeypatch.setattr(time, "sleep", lambda s: None) + + calls = [] + monkeypatch.setattr(sup, "reconcile", lambda: calls.append(1)) + + sup.loop(interval=0, max_cycles=5) + + assert len(calls) == 5 + + +# --------------------------------------------------------------------------- +# 2. An exception in one cycle does not kill the loop +# --------------------------------------------------------------------------- + +def test_exception_in_one_cycle_does_not_kill_loop(tmp_path, monkeypatch, caplog): + sup = _make_supervisor(tmp_path, monkeypatch) + monkeypatch.setattr(time, "sleep", lambda s: None) + + calls = [] + + def flaky_reconcile(): + calls.append(1) + if len(calls) == 2: + raise RuntimeError("simulated blowup mid-cycle") + + monkeypatch.setattr(sup, "reconcile", flaky_reconcile) + + with caplog.at_level("ERROR"): + sup.loop(interval=0, max_cycles=4) + + # All 4 cycles ran despite cycle #2 raising. + assert len(calls) == 4 + assert any("unhandled exception" in r.message for r in caplog.records) + + +def test_run_cycle_safely_never_raises(tmp_path, monkeypatch): + sup = _make_supervisor(tmp_path, monkeypatch) + monkeypatch.setattr(sup, "reconcile", lambda: (_ for _ in ()).throw(ValueError("boom"))) + + # Must not raise. + sup._run_cycle_safely() + + +# --------------------------------------------------------------------------- +# 3. A blocking cycle is bounded by a timeout; the loop continues afterward +# --------------------------------------------------------------------------- + +def test_blocking_cycle_times_out_and_loop_continues(tmp_path, monkeypatch, caplog): + """A reconcile() that hangs on a blocking call must not freeze loop(). + + Uses a single, genuinely-blocking cycle (real time.sleep in a background + thread — this is what an unkillable blocked syscall like fsync() looks + like from Python) bounded by a short reconcile_timeout. If the fix + regresses to the old bare `while True: self.reconcile()`, this test + times out the whole test run instead of failing fast. + """ + sup = _make_supervisor(tmp_path, monkeypatch) + + calls = [] + + def hanging_reconcile(): + calls.append(1) + time.sleep(0.5) # much longer than reconcile_timeout below + + monkeypatch.setattr(sup, "reconcile", hanging_reconcile) + + start = time.monotonic() + with caplog.at_level("ERROR"): + sup.loop(interval=0, max_cycles=1, reconcile_timeout=0.1) + elapsed = time.monotonic() - start + + # loop() returned control well before the 0.5s hang finished. + assert len(calls) == 1 + assert elapsed < 0.5, f"loop should not block for the full hang duration, took {elapsed}s" + assert any("did not complete within" in r.message for r in caplog.records) + + +def test_loop_keeps_advancing_across_repeated_timeouts(tmp_path, monkeypatch, caplog): + """The outer loop must reach a second iteration even while a prior cycle + is still stuck in the background — proving the control loop itself (tick + counting, logging, sleeping) is never blocked by a wedged cycle.""" + sup = _make_supervisor(tmp_path, monkeypatch) + monkeypatch.setattr(sup, "reconcile", lambda: time.sleep(0.5)) + + start = time.monotonic() + with caplog.at_level("ERROR"): + sup.loop(interval=0, max_cycles=3, reconcile_timeout=0.05) + elapsed = time.monotonic() - start + + assert elapsed < 0.5, f"outer loop should complete 3 iterations fast, took {elapsed}s" + timeout_logs = [r for r in caplog.records if "did not complete within" in r.message] + assert len(timeout_logs) == 3 + + +# --------------------------------------------------------------------------- +# 4. Existing behavior is preserved: reconcile() itself still works normally +# when called directly (not just through the loop). +# --------------------------------------------------------------------------- + +def test_reconcile_still_works_standalone(tmp_path, monkeypatch): + sup = _make_supervisor(tmp_path, monkeypatch) + heartbeat = tmp_path / "state" / "supervisor.heartbeat" + + sup.reconcile() + + assert heartbeat.exists()