feat(observer): persist SHADOW_LIVENESS_MISMATCH to mounted file — survives container recreate (cutover evidence)

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

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/<service>/ 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

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/<service>/ 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",

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