From 9e7ed3e0778fa3671c4d6378056cbd2d98e3139e Mon Sep 17 00:00:00 2001 From: oskar Date: Wed, 15 Jul 2026 15:30:44 +0200 Subject: [PATCH] =?UTF-8?q?feat(observer):=20persist=20SHADOW=5FLIVENESS?= =?UTF-8?q?=5FMISMATCH=20to=20mounted=20file=20=E2=80=94=20survives=20cont?= =?UTF-8?q?ainer=20recreate=20(cutover=20evidence)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-Authored-By: Claude Opus 4.8 (1M context) --- .../control-plane/docker-compose.override.yml | 10 +++ scripts/observer/observer.py | 77 ++++++++++++++++ .../tests/test_observer_shadow_liveness.py | 89 +++++++++++++++++++ 3 files changed, 176 insertions(+) diff --git a/hosts/vps/runtime/control-plane/docker-compose.override.yml b/hosts/vps/runtime/control-plane/docker-compose.override.yml index c48e94c..c8b958b 100644 --- a/hosts/vps/runtime/control-plane/docker-compose.override.yml +++ b/hosts/vps/runtime/control-plane/docker-compose.override.yml @@ -34,6 +34,16 @@ services: # Uncomment to enable the ≥7-day parallel-run: environment: - PROM_SHADOW_URL=http://100.95.58.48:9090 + # PERSISTENT shadow-mismatch log (cutover etap 2). The observer writes each + # SHADOW_LIVENESS_MISMATCH to /opt/homelab/logs/observer/shadow-liveness.log + # (the repo-conventional logs// path). No extra mount is needed: the + # base compose already bind-mounts the whole of /opt/homelab into this + # container, so the file lives on the HOST and survives a `docker rm`/recreate + # of the container — stdout json-file logs do NOT (a recreate on 2026-07-14 + # destroyed the 07-13/14 evidence mid-analysis, which is why this exists). + # The observer runs as uid 1000 and creates logs/observer itself, so there is + # no root-owned-bind-source ownership footgun. Override the path with the + # SHADOW_LOG_DIR env var if ever needed. supervisor: mem_limit: 400m diff --git a/scripts/observer/observer.py b/scripts/observer/observer.py index 9847bac..3f07323 100644 --- a/scripts/observer/observer.py +++ b/scripts/observer/observer.py @@ -5,6 +5,7 @@ import json import time import glob import logging +from logging.handlers import RotatingFileHandler import urllib.request import urllib.parse import yaml @@ -145,6 +146,73 @@ PROM_SHADOW_TIMEOUT = int(os.getenv("PROM_SHADOW_TIMEOUT", "5")) logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s') logger = logging.getLogger("observer") +# --- PERSISTENT shadow-mismatch log (cutover etap 2) ----------------------- +# SHADOW_LIVENESS_MISMATCH lines are cutover EVIDENCE and must survive a +# `docker rm`/recreate of the observer container. stdout (json-file) logs do +# NOT: an observer recreate on 2026-07-14 destroyed the 07-13/14 mismatch +# material mid-analysis. We therefore ALSO write each mismatch to a +# RotatingFileHandler on a HOST-mounted path so the file outlives the container. +# +# Path is the repo-conventional logs// location under RUNTIME_PATH, +# i.e. /opt/homelab/logs/observer/shadow-liveness.log. No dedicated bind-mount +# is required: the base compose already mounts the whole of /opt/homelab into +# the observer, so this file is on the host by construction, and the observer +# (uid 1000) creates the dir itself — avoiding the root-owned bind-source +# ownership footgun a separate /var/log mount would introduce. Overridable via +# SHADOW_LOG_DIR for tests / non-container runs. +SHADOW_LOG_DIR = Path(os.getenv("SHADOW_LOG_DIR", str(LOGS_DIR / "observer"))) +SHADOW_LOG_FILENAME = "shadow-liveness.log" + + +def _make_shadow_logger(): + """Build the dedicated PERSISTENT logger for SHADOW_LIVENESS_MISMATCH lines. + + Returns a `logging.getLogger("observer.shadow")` wired to a + RotatingFileHandler (5 MiB x 5 backups — mismatches are short lines, that is + weeks of headroom) writing to SHADOW_LOG_DIR/shadow-liveness.log with the + same timestamped format as the main observer log. + + propagate=False keeps these records OUT of root/stdout: the call site still + logs the mismatch to stdout via the ordinary `logger` (unchanged), so + without this each mismatch would appear twice in `docker logs`. + + FAIL-SAFE: if the directory/file cannot be created or opened (permission, + read-only mount, …) we log ONE warning on the main observer logger and + return a handler-less logger. `.info()` on a handler-less, non-propagating + logger is a silent no-op, so a broken persistent log NEVER raises and NEVER + takes the observer down — the mismatch still reaches stdout at the call site. + Idempotent: any handler from a previous call is dropped first, so + re-instantiation (tests, re-import) never double-writes or pins a stale path. + """ + sl = logging.getLogger("observer.shadow") + sl.setLevel(logging.INFO) + sl.propagate = False + for h in list(sl.handlers): + sl.removeHandler(h) + try: + h.close() + except Exception: + pass + try: + os.makedirs(SHADOW_LOG_DIR, exist_ok=True) + handler = RotatingFileHandler( + SHADOW_LOG_DIR / SHADOW_LOG_FILENAME, + maxBytes=5 * 1024 * 1024, + backupCount=5, + ) + handler.setFormatter( + logging.Formatter('%(asctime)s - %(levelname)s - %(message)s') + ) + sl.addHandler(handler) + except Exception as exc: + logger.warning( + "shadow-read: could not open persistent mismatch log at %s (%s) — " + "falling back to stdout only, observer continues", + SHADOW_LOG_DIR / SHADOW_LOG_FILENAME, exc, + ) + return sl + + class Observer: def __init__(self): # Per-node-directory checkpoint keyed on the last-processed event @@ -169,6 +237,8 @@ class Observer: self.inventory = self._load_inventory() self._ensure_dirs() self._load_checkpoint() + # Persistent SHADOW_LIVENESS_MISMATCH sink (survives container recreate). + self.shadow_logger = _make_shadow_logger() def _ensure_dirs(self): WORLD_DIR.mkdir(parents=True, exist_ok=True) @@ -416,6 +486,13 @@ class Observer: "SHADOW_LIVENESS_MISMATCH node=%s event=%s prom=%s last_seen_age=%.0fs", node_name, event_liveness, "up" if prom_up else "down", age, ) + # ALSO write to the persistent, host-mounted log so this evidence + # survives a container recreate (stdout json-file logs do not). + # Handler-less (fail-safe) → silent no-op; never affects the above. + self.shadow_logger.info( + "SHADOW_LIVENESS_MISMATCH node=%s event=%s prom=%s last_seen_age=%.0fs", + node_name, event_liveness, "up" if prom_up else "down", age, + ) else: logger.debug( "shadow-read agree node=%s event=%s prom=%s last_seen_age=%.0fs", diff --git a/services/control-plane/tests/test_observer_shadow_liveness.py b/services/control-plane/tests/test_observer_shadow_liveness.py index e1e7dfe..039cebe 100644 --- a/services/control-plane/tests/test_observer_shadow_liveness.py +++ b/services/control-plane/tests/test_observer_shadow_liveness.py @@ -58,6 +58,8 @@ def _redirect_observer_paths(tmp_path, monkeypatch): monkeypatch.setattr(obs_mod, "FAILED_EVENTS_DIR", state / "observer_failed_events") monkeypatch.setattr(obs_mod, "OBSERVER_STATE_FILE", state / "observer_checkpoint.json") monkeypatch.setattr(obs_mod, "PROM_SHADOW_URL", "") + # Persistent SHADOW_LIVENESS_MISMATCH log → per-test tmp dir (never /opt or /var). + monkeypatch.setattr(obs_mod, "SHADOW_LOG_DIR", logs / "observer") class _FakeResp: @@ -252,3 +254,90 @@ def test_node_unknown_to_prometheus_is_not_mismatch(monkeypatch, caplog): assert "SHADOW_LIVENESS_MISMATCH" not in caplog.text # And liveness still computed from events. assert obs.world_state["nodes"]["vps"]["liveness"] == FRESH + + +# --------------------------------------------------------------------------- +# 4. PERSISTENT mismatch log (cutover etap 2) — survives container recreate +# --------------------------------------------------------------------------- + +def _mismatch_prom(monkeypatch): + """Prometheus says vps is DOWN → mismatch against a FRESH event liveness.""" + monkeypatch.setattr(obs_mod, "PROM_SHADOW_URL", "http://prom:9090") + _mock_prom( + monkeypatch, + '{"data":{"result":[' + '{"metric":{"node":"vps"},"value":[1720000000,"0"]}]}}', + ) + + +def test_mismatch_is_persisted_to_file(monkeypatch, tmp_path, caplog): + """The mismatch is written to the persistent log FILE, not only stdout. + + This is the whole point: the file lives on a host-mounted path, so it + survives a `docker rm`/recreate that would drop stdout json-file logs. + """ + _mismatch_prom(monkeypatch) + obs = Observer() + _fresh_node_world(obs) + + # stdout path still emits (unchanged behaviour) AND the file is written. + with caplog.at_level(logging.INFO, logger="observer"): + obs._prune_stale_world() + + log_file = tmp_path / "logs" / "observer" / "shadow-liveness.log" + assert log_file.exists(), "persistent shadow log file was not created" + content = log_file.read_text() + assert "SHADOW_LIVENESS_MISMATCH" in content + assert "node=vps" in content + assert "event=fresh" in content + assert "prom=down" in content + # Line carries a timestamp (asctime format) — grep-able forensic record. + assert " - INFO - SHADOW_LIVENESS_MISMATCH" in content + # And stdout still got it too (no regression to docker logs visibility). + assert "SHADOW_LIVENESS_MISMATCH" in caplog.text + + +def test_agreement_is_not_persisted_to_file(monkeypatch, tmp_path): + """Agreement (event=fresh, prom=up) writes nothing to the persistent log.""" + monkeypatch.setattr(obs_mod, "PROM_SHADOW_URL", "http://prom:9090") + _mock_prom( + monkeypatch, + '{"data":{"result":[' + '{"metric":{"node":"vps"},"value":[1720000000,"1"]}]}}', + ) + obs = Observer() + _fresh_node_world(obs) + obs._prune_stale_world() + + log_file = tmp_path / "logs" / "observer" / "shadow-liveness.log" + # File may or may not exist (handler creates it lazily); if it does, empty. + if log_file.exists(): + assert "SHADOW_LIVENESS_MISMATCH" not in log_file.read_text() + + +def test_shadow_logger_failsafe_when_dir_unwritable(monkeypatch, tmp_path, caplog): + """If the persistent log dir cannot be created, the observer must NOT crash. + + It logs one warning, the shadow logger is left handler-less (a silent no-op), + and a subsequent mismatch cycle runs fine and STILL reaches stdout. + """ + # Point SHADOW_LOG_DIR under a *file*, so os.makedirs() raises. + blocker = tmp_path / "blocker" + blocker.write_text("i am a file, not a directory") + monkeypatch.setattr(obs_mod, "SHADOW_LOG_DIR", blocker / "observer") + + # Construction must not raise, and must warn about the failure. + with caplog.at_level(logging.WARNING, logger="observer"): + obs = Observer() + assert "could not open persistent mismatch log" in caplog.text + # No file handler was attached (fail-safe → handler-less logger). + assert obs.shadow_logger.handlers == [] + + # A real mismatch cycle still works: no raise, stdout still logs it. + caplog.clear() + _mismatch_prom(monkeypatch) + obs2 = Observer() # re-reads the (still broken) SHADOW_LOG_DIR + _fresh_node_world(obs2) + with caplog.at_level(logging.INFO, logger="observer"): + obs2._prune_stale_world() # must not raise + assert "SHADOW_LIVENESS_MISMATCH" in caplog.text # stdout intact