fix(supervisor): odpornosc petli na zawieszenie + timeout blokujacych wywolan — petla stanela cicho po ha_websocket_dead (mozg martwy 24h, healthy ale nie tika)
This commit is contained in:
parent
052b3c1584
commit
409b583ab9
|
|
@ -47,7 +47,13 @@ services:
|
||||||
- REPO_ROOT=/repo
|
- REPO_ROOT=/repo
|
||||||
- RUNTIME_PATH=/opt/homelab
|
- RUNTIME_PATH=/opt/homelab
|
||||||
healthcheck:
|
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
|
interval: 60s
|
||||||
timeout: 5s
|
timeout: 5s
|
||||||
retries: 3
|
retries: 3
|
||||||
|
|
|
||||||
|
|
@ -3,6 +3,7 @@ import json
|
||||||
import time
|
import time
|
||||||
import logging
|
import logging
|
||||||
import yaml
|
import yaml
|
||||||
|
from concurrent.futures import ThreadPoolExecutor
|
||||||
from pathlib import Path
|
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=false on the control-plane node when ready for live actions.
|
||||||
HA_DIAG_SHADOW_MODE = os.getenv("HA_DIAG_SHADOW_MODE", "true").lower() == "true"
|
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 setup
|
||||||
logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s')
|
logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s')
|
||||||
logger = logging.getLogger("supervisor")
|
logger = logging.getLogger("supervisor")
|
||||||
|
|
@ -815,11 +836,56 @@ class Supervisor:
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
logger.error(f"Failed to save action {action_id}: {e}")
|
logger.error(f"Failed to save action {action_id}: {e}")
|
||||||
|
|
||||||
def loop(self, interval=30):
|
def _run_cycle_safely(self):
|
||||||
logger.info("Starting supervisor loop")
|
"""Run one reconcile() cycle, never letting an exception escape.
|
||||||
while True:
|
|
||||||
|
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()
|
self.reconcile()
|
||||||
|
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)
|
time.sleep(interval)
|
||||||
|
finally:
|
||||||
|
executor.shutdown(wait=False, cancel_futures=True)
|
||||||
|
|
||||||
|
|
||||||
if __name__ == "__main__":
|
if __name__ == "__main__":
|
||||||
|
|
|
||||||
155
services/control-plane/tests/test_supervisor_loop_resilience.py
Normal file
155
services/control-plane/tests/test_supervisor_loop_resilience.py
Normal file
|
|
@ -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()
|
||||||
Loading…
Reference in a new issue