fix(dispatch): inbox 0o775 + rsync rc=23 przestaje byc cichy
Wyciek plikow dispatch potwierdzony 2026-08-06 (session log, follow-up #1): LUSTRO re-pullowalo te same dwie akcje co 60 s przez wiele dni, odbijajac sie od bramki idempotencji, i nie zostawilo po sobie ani jednej linii w logach. Przyczyna zlozona z dwoch niezaleznych defektow: 1. Executor tworzyl actions/dispatch/<node>/ z 0o755 (aerbot:aerbot). Rsync-pull z noda uwierzytelnia sie jako inny uzytkownik, bedacy tylko *czlonkiem* tej grupy. --remove-source-files musi zrobic unlink pliku, a unlink wymaga prawa zapisu w katalogu nadrzednym, nie na samym pliku. Zrodlo przezywalo pobranie. (dispatch/piha mialo historycznie 775 i dlatego dzialalo.) 2. node-agent traktowal rc=23 jako benign obok 0 i 24, wiec rsync zglaszal porazke, a agent ja polykal. Executor: _ensure_inbox_dir() = mkdir + bezwarunkowy os.chmod(0o775). chmod jest bezwarunkowy z dwoch powodow: mkdir(mode=) jest maskowany przez umask procesu (przy 0o022 daje dokladnie feralne 0o755), a inboxy zalozone przez wczesniejszy build juz istnieja na flocie z 0o755. Naprawa w miejscu zapisu, a nie skanem przy starcie: jedno idempotentne wywolanie na tej samej sciezce kodu, ktora pisze plik dispatch, wiec nie da sie rozjechac z pisarzami. Blad chmod nie jest fatalny — akcja i tak sie wykonuje, a nieskasowane zrodlo widac teraz po stronie noda. Objete tez actions/deploy/<node>/ (deploy-runner): ten sam wzorzec drenowania tym samym rsync-pullem, ten sam defekt, jedno wywolanie obok. node-agent: klasyfikacja kodow wyjscia zamiast wspolnej listy benign. Weryfikacja empiryczna rsync 3.4.1 pokazala, ze rc=23 pokrywa dwa rozne przypadki, a rozroznia je dopiero stderr: * `change_dir ... No such file or directory` — executor zaklada inbox dopiero przy pierwszym dispatchu, wiec kazdy nod, do ktorego nic nie poszlo, dostaje rc=23 co cykl. DEBUG — inaczej byloby po linii na minute z wiekszosci floty i realny sygnal utonalby w szumie. * `sender failed to remove <plik>: Permission denied` — wlasnie ten wyciek. WARNING z pelnym stderr. Pusty (ale istniejacy) inbox to rc=0, nie 23 — dotychczasowy komentarz w kodzie mowil inaczej. rc=24 zostaje benign (wyscig z executorem piszacym inbox), pozostale kody to teraz ERROR, nie WARNING. Zachowanie funkcjonalne bez zmian: retry i idempotencja dzialaja jak dotad, zmienia sie wylacznie widocznosc. Testy: 4 nowe w test_executor_dispatch.py (oba inboxy 0o775 pod umask 0o022, naprawa istniejacego 0o755 in place, dispatch przezywa nieudany chmod), 5 w test_action_dispatch.py na klasyfikacje rc. Zastapiony test_pull_treats_empty_source_returncodes_as_non_error — kodyfikowal wlasnie to zalozenie, ktore okazalo sie bugiem. Oba zestawy sprawdzone mutacja: bez chmod padaja 3 testy executora, przy starej liscie benign pada test rc=23. node-agent 70 passed, control-plane 173 passed. Refs docs/sessions/2026-08-06.md (follow-up #1) Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
oskar
parent
b1b6692382
commit
52eca1c22a
|
|
@ -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",
|
||||
|
|
|
|||
|
|
@ -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")
|
||||
|
|
|
|||
|
|
@ -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/<node>/ 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 <file>: 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 <unixts> 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/<node>/ 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()
|
||||
|
|
|
|||
|
|
@ -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]"
|
||||
)
|
||||
|
||||
with caplog.at_level("WARNING"):
|
||||
|
||||
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()
|
||||
|
||||
assert "Dispatch pull failed" not in caplog.text
|
||||
|
||||
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"):
|
||||
_pull_with(agent, monkeypatch, 24, "rsync warning: some files vanished")
|
||||
|
||||
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
|
||||
|
|
|
|||
Loading…
Reference in a new issue