diff --git a/services/control-plane/src/executor.py b/services/control-plane/src/executor.py index c9feee1..9a89945 100644 --- a/services/control-plane/src/executor.py +++ b/services/control-plane/src/executor.py @@ -16,6 +16,7 @@ def _atomic_write_json(path: Path, data) -> None: os.fsync(f.fileno()) os.replace(tmp, path) + # Constants and Paths RUNTIME_PATH = os.getenv("RUNTIME_PATH", "/opt/homelab") ACTIONS_DIR = Path(RUNTIME_PATH) / "actions" @@ -27,6 +28,17 @@ DISPATCH_DIR = ACTIONS_DIR / "dispatch" # failure-reports every file it finds in its inbox, so a redeploy landing there # would be killed before the runner ever saw it. DEPLOY_DISPATCH_DIR = ACTIONS_DIR / "deploy" + +# Mode for the per-node inboxes under DISPATCH_DIR / DEPLOY_DISPATCH_DIR. +# These dirs are written by the executor (as the control-plane user on VPS) but +# drained by the target node, whose rsync-pull authenticates as a *different* +# user that is only a member of the owning group. --remove-source-files must +# unlink the fetched file, and unlink needs write permission on the containing +# directory — at 0o755 the group has none, so the source survives, rsync exits +# 23, and the node re-pulls the same action every cycle forever, bouncing off +# the idempotency gate. Observed on dispatch/lustro 2026-08-06 (session log, +# follow-up #1); the older dispatch/piha happened to be 775 and worked. +INBOX_DIR_MODE = 0o775 # The executor no longer reads the repo at all (the old redeploy path ran a # script out of it). Kept only so an operator can still see which checkout the # container is wired to; nothing in this module resolves paths against it. @@ -68,6 +80,27 @@ logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %( logger = logging.getLogger("executor") +def _ensure_inbox_dir(path: Path) -> None: + """Create (or repair) a per-node inbox so the target node can drain it. + + chmod runs unconditionally rather than only on creation, for two reasons: + mkdir(mode=...) is masked by the process umask and so cannot be relied on to + produce INBOX_DIR_MODE, and inboxes created by an earlier executor build + already exist at 0o755 across the fleet. Repairing here — on the same code + path that writes the dispatch file — keeps the fix to one idempotent call + and needs no startup scan that could drift out of sync with the writers. + """ + path.mkdir(parents=True, exist_ok=True) + try: + os.chmod(path, INBOX_DIR_MODE) + except OSError as e: + # Deliberately not fatal: the dispatch file still gets written and the + # node still executes the action. Only the post-fetch source delete + # stays broken — and that now surfaces as a WARNING on the node side + # (node_agent.pull_dispatched_actions) instead of being swallowed. + logger.warning(f"Could not set mode {oct(INBOX_DIR_MODE)} on {path}: {e}") + + class Executor: def __init__(self): self._ensure_dirs() @@ -217,7 +250,7 @@ class Executor: logger.error(f"Action {action_id}: container_restart with no node set") return inbox = DISPATCH_DIR / node - inbox.mkdir(parents=True, exist_ok=True) + _ensure_inbox_dir(inbox) payload = { "action_id": action_id, "type": "container_restart", @@ -249,7 +282,7 @@ class Executor: Does not resolve the action itself; _reconcile_running_actions() does. """ inbox = DEPLOY_DISPATCH_DIR / node - inbox.mkdir(parents=True, exist_ok=True) + _ensure_inbox_dir(inbox) payload = { "action_id": action_id, "type": "redeploy", diff --git a/services/control-plane/tests/test_executor_dispatch.py b/services/control-plane/tests/test_executor_dispatch.py index f073ae3..8f040f5 100644 --- a/services/control-plane/tests/test_executor_dispatch.py +++ b/services/control-plane/tests/test_executor_dispatch.py @@ -9,9 +9,11 @@ forever. from __future__ import annotations import json +import os import sys import time from pathlib import Path +from unittest.mock import MagicMock import pytest @@ -239,3 +241,78 @@ def test_alert_only_action_resolves_synchronously_not_via_dispatch(tmp_path, mon assert _exists(tmp_path, "completed", "alert-1") assert not (tmp_path / "actions" / "dispatch").exists() or \ not list((tmp_path / "actions" / "dispatch").glob("**/*.json")) + + +# --------------------------------------------------------------------------- +# Inbox permissions (dispatch leak, 2026-08-06) +# +# The per-node inbox is written here but drained by the target node over rsync +# --remove-source-files, authenticating as a different user that is only a +# group member. Unlinking the fetched file needs write permission on the +# containing dir; at 0o755 it silently fails and the node re-pulls the same +# action forever. +# --------------------------------------------------------------------------- + +@pytest.fixture +def restrictive_umask(): + """0o022 masks the group-write bit out of mkdir(mode=0o775) — the reason + the fix cannot rely on the mode argument alone.""" + old = os.umask(0o022) + yield + os.umask(old) + + +def _mode(path: Path) -> int: + return path.stat().st_mode & 0o777 + + +def test_dispatch_inbox_is_group_writable(tmp_path, monkeypatch, restrictive_umask): + ex = _setup_executor(tmp_path, monkeypatch) + + ex._execute_action(_write_approved(tmp_path, "cr-perm", node="piha")) + + inbox = tmp_path / "actions" / "dispatch" / "piha" + assert (inbox / "cr-perm.json").exists() + assert _mode(inbox) == 0o775 + + +def test_deploy_inbox_is_group_writable(tmp_path, monkeypatch, restrictive_umask): + """Same defect, same rsync-pull drain — the deploy runner's inbox needs it too.""" + ex = _setup_executor(tmp_path, monkeypatch) + + ex._execute_action( + _write_approved(tmp_path, "rd-perm", node="piha", action_type="redeploy") + ) + + inbox = tmp_path / "actions" / "deploy" / "piha" + assert (inbox / "rd-perm.json").exists() + assert _mode(inbox) == 0o775 + + +def test_existing_inbox_is_repaired_in_place(tmp_path, monkeypatch, restrictive_umask): + """Inboxes already on disk fleet-wide were created at 0o755 by an earlier + build; dispatching to one must fix it rather than inherit it.""" + ex = _setup_executor(tmp_path, monkeypatch) + inbox = tmp_path / "actions" / "dispatch" / "piha" + inbox.mkdir(parents=True) + os.chmod(inbox, 0o755) + + ex._execute_action(_write_approved(tmp_path, "cr-repair", node="piha")) + + assert _mode(inbox) == 0o775 + + +def test_dispatch_survives_unsettable_mode(tmp_path, monkeypatch, restrictive_umask): + """A chmod failure (inbox owned by another user) must not cost us the + dispatch — the action still executes on the node; only the source delete + stays broken, and the node warns about that.""" + ex = _setup_executor(tmp_path, monkeypatch) + monkeypatch.setattr( + executor_module.os, "chmod", + MagicMock(side_effect=PermissionError("Operation not permitted")), + ) + + ex._execute_action(_write_approved(tmp_path, "cr-chmod-fail", node="piha")) + + assert (tmp_path / "actions" / "dispatch" / "piha" / "cr-chmod-fail.json").exists() + assert _exists(tmp_path, "running", "cr-chmod-fail") diff --git a/services/node-agent/src/node_agent.py b/services/node-agent/src/node_agent.py index 3b14b94..9d2e448 100644 --- a/services/node-agent/src/node_agent.py +++ b/services/node-agent/src/node_agent.py @@ -169,6 +169,23 @@ def _utc_iso() -> str: _EVENT_TS_RE = re.compile(r"-(\d{9,11})-") _EVENT_TYPE_RE = re.compile(r"^evt-.+?-\d{9,11}-(.+)$") +# rsync exits 23 for two very different situations and the dispatch pull hits +# both routinely, so the stderr has to be read to tell them apart: +# +# * The remote inbox does not exist yet. The executor creates +# actions/dispatch// only on its first dispatch to that node, so until +# then every pull reports `change_dir "..." failed: No such file or +# directory`. Expected, and warning about it would mean one line a minute on +# every node that has never been sent an action. +# * The files WERE fetched but rsync could not unlink the source +# (`sender failed to remove : Permission denied`) — the dispatch leak +# of 2026-08-06. That one has to be loud: it means the same actions come +# back on every single cycle until someone fixes the directory mode on VPS. +# +# (An empty-but-existing remote inbox — by far the most common case — is a plain +# rc=0 and never reaches here.) +_RSYNC_MISSING_SRC_RE = re.compile(r"change_dir .* failed: No such file or directory") + def _event_ts_from_filename(name: str): """Return the embedded from an event filename, or None if absent.""" @@ -951,14 +968,45 @@ class NodeAgent: ] try: result = subprocess.run(cmd, capture_output=True, text=True, timeout=30) - # rsync returns 23/24 ("partial transfer"/"vanished source files") - # when the remote dispatch dir is simply empty — the common case, - # not an error worth logging every cycle. - if result.returncode not in (0, 23, 24): - logger.warning(f"Dispatch pull failed: {result.stderr.strip()}") + self._log_dispatch_pull_result(result.returncode, result.stderr or "") except Exception as exc: logger.warning(f"Dispatch pull error: {exc}") + @staticmethod + def _log_dispatch_pull_result(returncode: int, stderr: str) -> None: + """Classify an rsync exit code from the dispatch pull. + + Visibility only — the caller retries on the next cycle either way, and + an action that was fetched is executed regardless of what the source + side did. Codes: + + 0 — clean, including "remote inbox exists and is empty". + 24 — a source file vanished between the file list and the transfer. + A benign race with the executor writing the inbox concurrently. + 23 — "some files were not transferred", which covers two situations + that must NOT be logged alike (see _RSYNC_MISSING_SRC_RE). + * — real transport failure (ssh down, auth, timeout). + + Before 2026-08-06 every one of these was benign-listed, which is how the + dispatch leak stayed invisible: the node re-pulled the same actions + every 60 s for days, silently bouncing them off the idempotency gate. + """ + stderr = stderr.strip() + if returncode in (0, 24): + return + if returncode == 23: + if _RSYNC_MISSING_SRC_RE.search(stderr) and "failed to remove" not in stderr: + logger.debug(f"Dispatch inbox not present on VPS yet: {stderr}") + return + logger.warning( + "Dispatch pull incomplete (rsync rc=23): action files were " + "fetched but their source copy on VPS was NOT removed, so they " + "will be re-pulled every cycle. Check the mode of " + f"actions/dispatch// on VPS (needs group write). {stderr}" + ) + return + logger.error(f"Dispatch pull failed (rsync rc={returncode}): {stderr}") + def process_dispatched_actions(self): """Execute every action currently sitting in this node's dispatch inbox.""" inbox = self._dispatch_inbox_dir() diff --git a/services/node-agent/tests/test_action_dispatch.py b/services/node-agent/tests/test_action_dispatch.py index 68249c1..e319681 100644 --- a/services/node-agent/tests/test_action_dispatch.py +++ b/services/node-agent/tests/test_action_dispatch.py @@ -238,13 +238,77 @@ def test_pull_invokes_rsync_pull_direction(agent, monkeypatch): assert cmd[-1] == str(agent._dispatch_inbox_dir()) + "/" -def test_pull_treats_empty_source_returncodes_as_non_error(agent, monkeypatch, caplog): - def fake_run(cmd, **kwargs): - return MagicMock(returncode=23, stderr="rsync: some vanished-source message") +# ---------------------------------------------------------------------- +# rsync exit-code classification (dispatch leak, 2026-08-06) +# +# rc=23 used to be benign-listed together with 0 and 24, which is why the +# leak — files fetched but never removed from VPS, so re-pulled every 60 s — +# produced no log line at all for days. These pin the four outcomes. +# ---------------------------------------------------------------------- - monkeypatch.setattr(node_agent.subprocess, "run", fake_run) +# Verbatim rsync 3.4.1 stderr for the two distinct rc=23 causes. +_STDERR_UNDELETABLE_SOURCE = ( + "rsync: [sender] sender failed to remove act-123.json: Permission denied (13)\n" + "rsync error: some files/attrs were not transferred " + "(see previous errors) (code 23) at main.c(1356) [sender=3.4.1]" +) +_STDERR_MISSING_INBOX = ( + 'rsync: [sender] change_dir "/opt/homelab/actions/dispatch/test-node" ' + "failed: No such file or directory (2)\n" + "rsync error: some files/attrs were not transferred " + "(see previous errors) (code 23) at main.c(1356) [sender=3.4.1]" +) + +def _pull_with(agent, monkeypatch, returncode, stderr=""): + monkeypatch.setattr( + node_agent.subprocess, "run", + lambda cmd, **kwargs: MagicMock(returncode=returncode, stderr=stderr), + ) + agent.pull_dispatched_actions() + + +def test_pull_rc0_logs_nothing(agent, monkeypatch, caplog): + with caplog.at_level("DEBUG"): + _pull_with(agent, monkeypatch, 0) + + assert "Dispatch pull" not in caplog.text + + +def test_pull_rc24_vanished_source_stays_benign(agent, monkeypatch, caplog): + """A file removed between file-list and transfer is a race with the + executor writing the inbox, not a fault.""" with caplog.at_level("WARNING"): - agent.pull_dispatched_actions() + _pull_with(agent, monkeypatch, 24, "rsync warning: some files vanished") - assert "Dispatch pull failed" not in caplog.text + assert caplog.text == "" + + +def test_pull_rc23_undeletable_source_warns_with_stderr(agent, monkeypatch, caplog): + """The leak itself: loud, and carrying the rsync stderr that names it.""" + with caplog.at_level("WARNING"): + _pull_with(agent, monkeypatch, 23, _STDERR_UNDELETABLE_SOURCE) + + assert "WARNING" in caplog.text + assert "rc=23" in caplog.text + # Full stderr forwarded, so the operator sees which file and why. + assert "sender failed to remove act-123.json: Permission denied" in caplog.text + + +def test_pull_rc23_missing_remote_inbox_is_quiet(agent, monkeypatch, caplog): + """A node that has never been dispatched to gets rc=23 on every cycle + because the executor has not created its inbox yet. Warning here would be + a line a minute on most of the fleet — and would bury the case above.""" + with caplog.at_level("WARNING"): + _pull_with(agent, monkeypatch, 23, _STDERR_MISSING_INBOX) + + assert caplog.text == "" + + +def test_pull_other_returncode_logs_error(agent, monkeypatch, caplog): + with caplog.at_level("WARNING"): + _pull_with(agent, monkeypatch, 255, "ssh: connect to host vps port 22: No route to host") + + assert "ERROR" in caplog.text + assert "rc=255" in caplog.text + assert "No route to host" in caplog.text