Compare commits

..

3 commits

Author SHA1 Message Date
oskar 75d96956a5 docs(recon): przyrostowka IMAP gmail + fastmail — Krok 7 fazy mailowej
Read-only recon (kb/audits/mail-sync-2026-08-06.md, OKF type: audit).

Stan wyjsciowy zmierzony na zywo: korpus gmail urywa sie 2026-06-19, dziura
48 dni ~ 1800 maili przy tempie ~37/dobe; zero kodu IMAP/JMAP w repo (tylko
dokumenty), brak modelu stanu synca — w bazie 3 tabele, zadnej z UID.

Ustalenia blokujace, ktore latwo przeoczyc (kazde zawodzi cicho, bez bledu):
- koperty bez entities[type=headers] daja prefiks chunka "(brak tematu) | ?"
  (build_prefix), wiec poller musi pisac headers przy INSERCIE, nie backfillem
- DEFAULT_SUMMARYLESS_SOURCES = ("gmail",) — fastmail zembeduje sie i zniknie
  z /search, bo galaz summaryless filtruje po source
- etap mailowy dopiety do kb-ingest.timer (03:30) zapali KbEmbedBacklogGrowing
  na stale: SOLARIA wtedy spi (potwierdzone: kb_ingest_embed_skipped 1)
- envelope.id = goly Message-ID globalnie, wiec mail obecny na obu kontach
  trafia do bazy raz, z source konta ktore wygralo wyscig

Architektura: fetch na PIHA co godzine (24/7, archiwum kanoniczne, bez GPU),
indeksowanie osobno bramkowane probe'em Ollamy (embed z PIHA zmierzony:
HTTP 200 w 8 ms, ~60 chunkow/dobe — rsync na SOLARIE zbedny). Spoiwem jest
kolejka "koperty bez chunkow", nie --since (ts to naglowek nadawcy).

Decyzje operatora (a)-(g) z rekomendacjami. Dwie korekty zalozen:
- POSTGRES_PASSWORD NIE lezy plaintextem w repo — service.yaml wymienia tylko
  nazwy zmiennych, env.example ma placeholdery, skan sledzonych YAML: 0 trafien.
  Rekomendacja uzywa istniejacego /opt/homelab/kb/.env (root:root 600,
  czytany przez systemd przed zrzuceniem uprawnien)
- Fastmail przez IMAP, nie JMAP — domyka otwarta od czerwca decyzje
  "unifikacja adaptera" (kb-mail-pillar.md §9); wymaga korekty §2/§7 tamtego
  dokumentu po zatwierdzeniu

Zaleznosci z reconem multiagentowym: zadnych blokujacych. Dyspozytor to
subsystem B (osobny projekt); jawna zaleznosc to wiki-kompilat
(kb-m5-faza3.md:620 — "pelna wiki po przyrostowce").

Aktualizacja kb-m5-faza-mailowa.md: Krok 7 = WYKONANE + wskaznik do reconu.
Nic nie zaimplementowano, nie zdeployowano ani nie pobrano.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-06 14:13:23 +02:00
oskar 1bab3219d6 revert(m1): zdjecie NODE_TYPE=lte_node na SOLARII i VPS po wdrozeniu R1
Warunek zdjecia M1 brzmial "R1 (prune filtrowany po restart policy / labelu
compose) wdrozony na tym nodzie". Zweryfikowane bezposrednio w kodzie dzialajacych
kontenerow, nie po datach deployu:

  SOLARIA  md5(/app/src/node_agent.py) = c9ac64e10b42b3e0ed9e4c168579bfaa,
           identyczny z origin/master.
  VPS      rozni sie od origin/master wylacznie trescia komentarzy (5 linii
           `docs/backlog.md` vs `kb/phases/backlog.md`, skutek migracji sciezek
           w 9128530) — zero roznic funkcjonalnych.

Na obu nodach `_prune_stopped_containers` jest obecny (te same numery linii:
635/700/717/725), a jedyne wystapienia `containers.prune()` to tekst docstringa
i komentarza — brak wykonywalnego niefiltrowanego prune. Sprawdzone dodatkowo,
ze scripts/monitor/health-monitor.sh (ktory nadal ma niefiltrowane
`docker container prune -f` — R1 objelo tylko node_agent.py) nie jest wpiety w
zaden crontab ani timer na SOLARII i VPS, wiec node-agent byl faktycznie jedynym
zrodlem prune i cleanup byl na obu nodach realnie wylaczony.

SOLARIA: przywrocone jawne NODE_TYPE=ai_node — stan sprzed M1 (1cd6401),
zgodnie z konwencja pozostalych hostow, ktore wszystkie ustawiaja NODE_TYPE
jawnie (piha/lustro sd_card, chelsty-infra lte_node). solaria jest w AI_NODES,
wiec default dalby to samo, ale jawny wpis nie zalezy od hostname'u.

VPS: linia usunieta w calosci wraz z komentarzem TEMPORARY — dokladny stan
sprzed 11f3f80, gdzie NODE_TYPE nie bylo ustawione wcale. Potwierdzone, ze
default daje `standard`, nie None: base compose przekazuje `NODE_TYPE=${NODE_TYPE:-}`,
czyli pusty string, ktory jest falsy, wiec _resolve_node_type() schodzi do
rozpoznania po nazwie, a `vps` nie nalezy do LTE_NODES/SD_CARD_NODES/AI_NODES.
Sprawdzone na zlozonym `docker compose config` (NODE_TYPE: "") i uruchomieniem
_resolve_node_type() -> 'standard'. Rotacja filesystemu control-plane jest
bramkowana node_name == VPS_NODE_NAME, nie node_type, wiec dziala niezaleznie.

UWAGA DO DEPLOYU: na obu nodach brak /opt/homelab/state/last-docker-cleanup,
a przy braku markera _cleanup_rate_ok() zwraca True — pierwszy cleanup pojdzie
w pierwszym cyklu po restarcie (<=60 s), nie po 24 h jak na LUSTRO.
W chwili sprawdzenia zero kontenerow `exited` na obu nodach, wiec galaz
kontenerowa nie ma czego usunac; do sprzatniecia sa 4 dangling images na SOLARII
(~553 MB) i 1 na VPS (395 MB) plus build cache. humanai-mailer i humanai-landing
maja restart=unless-stopped, wiec sa chronione pierwsza galezia filtra R1 nawet
gdyby zostaly zatrzymane.

node-agent: 70 passed.

Refs docs/incidents/2026-07-30-ollama-solaria-vanish.md (§7, M1),
docs/sessions/2026-08-06.md (follow-up #5)

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-06 13:47:09 +02:00
oskar 52eca1c22a 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>
2026-08-06 13:42:47 +02:00
6 changed files with 245 additions and 39 deletions

View file

@ -1,16 +1,3 @@
# MITYGACJA TYMCZASOWA (M1) — założona 2026-08-04.
# NODE_TYPE=lte_node wyłącza run_safe_cleanup() (niefiltrowany
# `docker container prune`) na czas backfillu embed (faza mailowa KB).
# Incydent: kb/incidents/2026-07-30-ollama-solaria-vanish.md (§7, M1).
# Bez tego każdy zatrzymany kontener na SOLARII znika w ≤60 s — również taki
# z `restart: unless-stopped`, zatrzymany świadomie przez operatora.
# Warunek zdjęcia: R1 (filtrowanie prune po restart policy / labelu compose)
# wdrożony na tym nodzie — R1R3 są w toku po stronie subsystemu A.
# Po zdjęciu przywrócić: NODE_TYPE=ai_node.
# Zakres wyłączenia: `lte_node` pomija CAŁY cleanup, więc na czas mitygacji
# nie są też sprzątane dangling images ani build cache — pilnować miejsca
# na dysku. Monitoring, eventy i dispatch akcji działają bez zmian
# (self.node_type jest czytane wyłącznie w run_safe_cleanup i dwóch liniach logu).
services: services:
node-agent: node-agent:
# Docker GID on SOLARIA is 996 (not the Debian default 999 the base compose # Docker GID on SOLARIA is 996 (not the Debian default 999 the base compose
@ -23,7 +10,11 @@ services:
- "996" # host docker gid, verified 2026-07-30 (getent group docker → 996) - "996" # host docker gid, verified 2026-07-30 (getent group docker → 996)
environment: environment:
- NODE_NAME=solaria - NODE_NAME=solaria
- NODE_TYPE=lte_node # M1 (2026-08-04) — było: ai_node; przywrócić po R1 # ai_node = dangling images + kontenery + build cache, ale NIGDY
# `image prune -a` (skasowałoby obrazy runtime Ollamy). Ustawione jawnie,
# zgodnie z konwencją pozostałych hostów, mimo że solaria jest w AI_NODES
# w node_agent.py i default dałby to samo.
- NODE_TYPE=ai_node
- VPS_EVENTS_HOST=100.95.58.48 - VPS_EVENTS_HOST=100.95.58.48
- VPS_EVENTS_USER=oskar - VPS_EVENTS_USER=oskar
- VPS_EVENTS_PATH=/opt/homelab/events - VPS_EVENTS_PATH=/opt/homelab/events

View file

@ -3,18 +3,11 @@ services:
environment: environment:
- NODE_NAME=vps - NODE_NAME=vps
- CHECK_INTERVAL=60 - CHECK_INTERVAL=60
# TEMPORARY mitigation (M1) for the unfiltered-prune incident # No NODE_TYPE here on purpose: `vps` is in none of node_agent.py's
# (kb/incidents/2026-07-30-ollama-solaria-vanish.md §7). node-agent runs # LTE_NODES / SD_CARD_NODES / AI_NODES sets, so _resolve_node_type() falls
# `docker container prune()` with NO filters every CHECK_INTERVAL, and the # through to "standard" — dangling images + stopped containers + build
# Docker API removes EVERY non-running container regardless of restart # cache, plus the control-plane filesystem rotation (that one is gated on
# policy or compose labels — this already destroyed ollama@solaria. On VPS # node_name == VPS_NODE_NAME, not on node_type). This is the pre-M1 state.
# the loss is worse: humanai-mailer and humanai-landing have no compose
# definition in this repo, so a pruned container cannot be recreated.
# node_type is read ONLY by run_safe_cleanup() (plus two log lines), so
# lte_node disables cleanup and nothing else — monitoring, event shipping
# and action dispatch keep working.
# REMOVE once R1 (explicit-enumeration prune) is deployed to VPS.
- NODE_TYPE=lte_node
# host network mode: node-agent on VPS shares the host's network namespace # host network mode: node-agent on VPS shares the host's network namespace
# so that localhost:18180 resolves to the control-plane's exposed port. # so that localhost:18180 resolves to the control-plane's exposed port.
# Without this, localhost inside the container is the container's own loopback # Without this, localhost inside the container is the container's own loopback

View file

@ -16,6 +16,7 @@ def _atomic_write_json(path: Path, data) -> None:
os.fsync(f.fileno()) os.fsync(f.fileno())
os.replace(tmp, path) os.replace(tmp, path)
# Constants and Paths # Constants and Paths
RUNTIME_PATH = os.getenv("RUNTIME_PATH", "/opt/homelab") RUNTIME_PATH = os.getenv("RUNTIME_PATH", "/opt/homelab")
ACTIONS_DIR = Path(RUNTIME_PATH) / "actions" 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 # failure-reports every file it finds in its inbox, so a redeploy landing there
# would be killed before the runner ever saw it. # would be killed before the runner ever saw it.
DEPLOY_DISPATCH_DIR = ACTIONS_DIR / "deploy" 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 # 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 # 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. # 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") 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: class Executor:
def __init__(self): def __init__(self):
self._ensure_dirs() self._ensure_dirs()
@ -217,7 +250,7 @@ class Executor:
logger.error(f"Action {action_id}: container_restart with no node set") logger.error(f"Action {action_id}: container_restart with no node set")
return return
inbox = DISPATCH_DIR / node inbox = DISPATCH_DIR / node
inbox.mkdir(parents=True, exist_ok=True) _ensure_inbox_dir(inbox)
payload = { payload = {
"action_id": action_id, "action_id": action_id,
"type": "container_restart", "type": "container_restart",
@ -249,7 +282,7 @@ class Executor:
Does not resolve the action itself; _reconcile_running_actions() does. Does not resolve the action itself; _reconcile_running_actions() does.
""" """
inbox = DEPLOY_DISPATCH_DIR / node inbox = DEPLOY_DISPATCH_DIR / node
inbox.mkdir(parents=True, exist_ok=True) _ensure_inbox_dir(inbox)
payload = { payload = {
"action_id": action_id, "action_id": action_id,
"type": "redeploy", "type": "redeploy",

View file

@ -9,9 +9,11 @@ forever.
from __future__ import annotations from __future__ import annotations
import json import json
import os
import sys import sys
import time import time
from pathlib import Path from pathlib import Path
from unittest.mock import MagicMock
import pytest 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 _exists(tmp_path, "completed", "alert-1")
assert not (tmp_path / "actions" / "dispatch").exists() or \ assert not (tmp_path / "actions" / "dispatch").exists() or \
not list((tmp_path / "actions" / "dispatch").glob("**/*.json")) 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")

View file

@ -169,6 +169,23 @@ def _utc_iso() -> str:
_EVENT_TS_RE = re.compile(r"-(\d{9,11})-") _EVENT_TS_RE = re.compile(r"-(\d{9,11})-")
_EVENT_TYPE_RE = re.compile(r"^evt-.+?-\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): def _event_ts_from_filename(name: str):
"""Return the embedded <unixts> from an event filename, or None if absent.""" """Return the embedded <unixts> from an event filename, or None if absent."""
@ -951,14 +968,45 @@ class NodeAgent:
] ]
try: try:
result = subprocess.run(cmd, capture_output=True, text=True, timeout=30) result = subprocess.run(cmd, capture_output=True, text=True, timeout=30)
# rsync returns 23/24 ("partial transfer"/"vanished source files") self._log_dispatch_pull_result(result.returncode, result.stderr or "")
# 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()}")
except Exception as exc: except Exception as exc:
logger.warning(f"Dispatch pull error: {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): def process_dispatched_actions(self):
"""Execute every action currently sitting in this node's dispatch inbox.""" """Execute every action currently sitting in this node's dispatch inbox."""
inbox = self._dispatch_inbox_dir() inbox = self._dispatch_inbox_dir()

View file

@ -238,13 +238,77 @@ def test_pull_invokes_rsync_pull_direction(agent, monkeypatch):
assert cmd[-1] == str(agent._dispatch_inbox_dir()) + "/" 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): # rsync exit-code classification (dispatch leak, 2026-08-06)
return MagicMock(returncode=23, stderr="rsync: some vanished-source message") #
# 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() 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