From 81935cfa98a0b74d0ea56af3e3c949c740cefd27 Mon Sep 17 00:00:00 2001 From: Dimitri Krattiger Date: Tue, 14 Jul 2026 12:14:39 -0600 Subject: [PATCH] fix(sessionservice): close the spawn/remap race; surface container failures Two related reliability fixes for task-container spawns, both diagnosed live under load (~26 concurrent tasks): 1. The spawn race: `docker run --detach` returns at PID-1 start, not after the entrypoint's usermod/chown remap, so the tmux pane's `docker exec --user panopticon` could resolve the user to the pre-remap uid and die on a PermissionError writing the (post-remap-owned) home dir. The entrypoint now touches /run/panopticon-ready once the remap is done, and the pane command is a bounded host-shell wait for that marker (150 x 0.2 s, then proceeds so pre-marker images still launch) before exec'ing in. The guard lives in the pane command itself, so heal respawns, dashboard `R`, and a manual `respawn-pane` are all covered. 2. Failure surfacing: a container the kernel OOM-killed (or that exited nonzero) read as a bare `down` -- or `live` -- with the reason only in `docker inspect`. `LocalRunner.exit_reason` now asks the stopped container why (OOMKilled checked before the exit code, which an OOM kill can leave at a deceptively clean 0); `Spawner.reconcile` reports it as a `failed` lifecycle with that detail, including for an already-`down` task. The heal crash-loop cap is likewise reported as `failed` with a press-R pointer -- once, instead of a log line every pass. Co-Authored-By: Claude Fable 5 --- AGENTS.md | 15 +++-- docker/entrypoint.sh | 7 ++ src/panopticon/sessionservice/local_runner.py | 60 ++++++++++++++--- src/panopticon/sessionservice/spawner.py | 37 ++++++---- tests/test_local_runner.py | 41 ++++++++++-- tests/test_spawner.py | 67 ++++++++++++++++++- 6 files changed, 193 insertions(+), 34 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 13259163..d7a5f4a2 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -51,7 +51,9 @@ src/panopticon/ docker/Dockerfile # base task-container image (ADR 0005 base layer): python + git + bash + # the panopticon package + the `claude` CLI the agent execs; runs as the # unprivileged `panopticon` user. docker/entrypoint.sh = remap that user to the - # invoking host uid/gid (PANOPTICON_PUID/PGID) then drop via gosu + # invoking host uid/gid (PANOPTICON_PUID/PGID), touch /run/panopticon-ready (the + # remap-complete marker the runner's tmux pane waits for before exec'ing in — + # exec'ing earlier resolves --user to the pre-remap uid), then drop via gosu ``` ## Conventions @@ -168,9 +170,11 @@ commands the Makefile wraps). skip terminal/claimed, skip on a 409 lost claim), the **reported phase sequence** (claiming → preparing → building → starting → awaiting, and `failed` with the error when a step raises), the `reconcile` down-detection (a claimed-by-us in-flight task whose container is gone → clear the - phase → composes `down`), `heal` **self-heal** (a claimed-by-us non-terminal task whose tmux - session is gone → respawn via the idempotent spawn path; skips healthy/unclaimed/terminal tasks; - the crash-loop cap + survivor-window budget reset), and the `spawnable_tasks` filter; an + phase → composes `down`; a stopped container still present → report `failed` with its + `exit_reason` — OOM kill/exit code — including for an already-`down` task), `heal` **self-heal** + (a claimed-by-us non-terminal task whose tmux session is gone → respawn via the idempotent spawn + path; skips healthy/unclaimed/terminal tasks; the crash-loop cap — surfaced once as `failed` + with a press-R detail — + survivor-window budget reset), and the `spawnable_tasks` filter; an integration test claims + spawns against the real task service over REST (fake git/runner). - `tests/test_host.py` — the unified per-host daemon (ADR 0008/0011): a unit test isolates a failing task and another pins that each pass also `heal`s every task; an integration test drives @@ -187,7 +191,8 @@ commands the Makefile wraps). transition → history) over the REST API, no Docker. - `tests/test_local_runner.py` / `tests/test_entrypoint.py` — the runner's emitted docker/tmux commands (incl. the ADR 0011 `/workspace` mount + the CLI's spawn-prep→spawn flow, `is_running`'s - `docker ps` probe + `has_session`'s `tmux list-sessions` probe for self-heal) and the container + `docker ps` probe + `has_session`'s `tmux list-sessions` probe for self-heal, `exit_reason`'s + `docker inspect` of a stopped container — OOM-kill before exit code) and the container entrypoint loop (fakes; no Docker/LLM), plus a `skipif` docker integration test. - `tests/test_spawn.py` — spawn-prep (ADR 0011): unit tests pin the `clone --local` of the per-task checkout and the idempotency gate (skips when the checkout already exists). diff --git a/docker/entrypoint.sh b/docker/entrypoint.sh index f37395c9..6d58427a 100644 --- a/docker/entrypoint.sh +++ b/docker/entrypoint.sh @@ -57,4 +57,11 @@ if [ "${PANOPTICON_DOCKER_IN_DOCKER:-0}" = "1" ]; then fi fi +# Signal that the remap is complete. The runner's tmux pane waits for this marker before its +# `docker exec --user panopticon` — exec'ing earlier resolves the user to the *pre-remap* uid, +# and the agent launcher then can't write the (post-remap-owned) home dir. `docker run --detach` +# returns at PID-1 start, not here, so without the marker the pane races the remap and loses +# under load. +touch /run/panopticon-ready + exec gosu panopticon "$@" diff --git a/src/panopticon/sessionservice/local_runner.py b/src/panopticon/sessionservice/local_runner.py index 3a73599d..7a1ade88 100644 --- a/src/panopticon/sessionservice/local_runner.py +++ b/src/panopticon/sessionservice/local_runner.py @@ -12,6 +12,7 @@ from __future__ import annotations import os +import shlex import subprocess from collections.abc import Callable, Mapping, Sequence from typing import Protocol @@ -45,6 +46,18 @@ #: spawn, but the volume persists. Per-task (not per-repo) so concurrent tasks don't share state. CONFIG_MOUNT = "/home/panopticon/.claude" +#: The entrypoint touches this in-container marker once it has remapped the ``panopticon`` user +#: (just before dropping privileges). The tmux pane waits for it before its +#: ``docker exec --user panopticon``: exec'ing earlier resolves the user to the *pre-remap* uid, +#: and the agent launcher then dies on a ``PermissionError`` writing the post-remap-owned home +#: (``docker run --detach`` returns at PID-1 start, not after the remap). The wait is bounded +#: (:data:`READY_WAIT_POLLS` × 0.2 s) so a pre-marker image still launches, just unguarded. +READY_MARKER = "/run/panopticon-ready" + +#: How many 0.2 s polls the pane waits for :data:`READY_MARKER` before proceeding anyway (30 s — +#: far beyond any remap, so the fallback only fires for images that predate the marker). +READY_WAIT_POLLS = 150 + class CommandRunner(Protocol): """Runs an external command and returns its stdout; ``check`` raises on non-zero exit. @@ -185,16 +198,21 @@ def _report(phase: LifecyclePhase) -> None: self._run(["docker", "rm", "--force", container], check=False) _report(LifecyclePhase.STARTING) # docker run + the tmux session coming up self._run(docker_run) - # `docker run --detach` returns once the container is running (the entrypoint has remapped + - # dropped), so the pane execs in as the unprivileged `panopticon` user — `tmux attach` and - # the agent's `whoami` see that named user, not root. - self._run( - self._tmux( - "new-session", "-d", "-s", container, - "docker", "exec", "--interactive", "--tty", "--user", CONTAINER_USER, - container, *self._agent_command, - ) + # The pane is a host shell command: wait (bounded) for the entrypoint's READY_MARKER — the + # remap-complete signal — then exec in as the unprivileged `panopticon` user, so `tmux + # attach` and the agent's `whoami` see that named user, not root (and never the pre-remap + # uid — the wait is what closes that race; it also covers heal/`R` respawns and a manual + # `respawn-pane`, which rerun this same pane command). + agent_exec = shlex.join( + ["docker", "exec", "--interactive", "--tty", "--user", CONTAINER_USER, + container, *self._agent_command] ) + pane = ( + f"i=0; until docker exec {container} test -f {READY_MARKER}; " + f"do i=$((i+1)); [ $i -ge {READY_WAIT_POLLS} ] && break; sleep 0.2; done; " + f"exec {agent_exec}" + ) + self._run(self._tmux("new-session", "-d", "-s", container, pane)) _report(LifecyclePhase.AWAITING) # container + tmux up; waiting for its /live registration return container @@ -212,6 +230,30 @@ def is_running(self, task_id: str) -> bool: ) return bool(names.strip()) + def exit_reason(self, task_id: str) -> str | None: + """Why the task's container stopped, as a display-ready detail string — or ``None``. + + A ``docker inspect`` of the container's exit state, for the host daemon to surface *why* + a task went down instead of a bare ``down``: ``None`` when the container is still running + or gone entirely (nothing left to explain); ``"container OOM-killed (exit N)"`` when the + kernel's out-of-memory killer shot it — checked before the exit code, which an OOM kill + can leave at a deceptively clean ``0``; otherwise ``"container exited (exit N)"``.""" + container = f"panopticon-{task_id}" + state = self._run( + [ + "docker", "inspect", "--format", + "{{.State.Running}} {{.State.OOMKilled}} {{.State.ExitCode}}", container, + ], + check=False, + ) + parts = state.split() + if len(parts) != 3 or parts[0] == "true": + return None # inspect errored (container gone entirely) or still running + _running, oom_killed, exit_code = parts + if oom_killed == "true": + return f"container OOM-killed (exit {exit_code})" + return f"container exited (exit {exit_code})" + def has_session(self, task_id: str) -> bool: """Whether the task's host tmux session exists on this runner's tmux server. diff --git a/src/panopticon/sessionservice/spawner.py b/src/panopticon/sessionservice/spawner.py index 7048c1db..d4871d86 100644 --- a/src/panopticon/sessionservice/spawner.py +++ b/src/panopticon/sessionservice/spawner.py @@ -184,7 +184,7 @@ def _report(self, task_id: str, phase: LifecyclePhase, detail: str | None = None elif phase == LifecyclePhase.AWAITING: _log.info("task %s: awaiting registration", task_id) elif phase == LifecyclePhase.FAILED: - _log.error("task %s: spawn failed — %s", task_id, detail) + _log.error("task %s: failed — %s", task_id, detail) # a spawn step, an exit, a crash loop try: self._client.report_lifecycle(task_id, self._runner_id, phase.value, detail) except httpx.HTTPError: @@ -194,17 +194,28 @@ def reconcile(self, task: JsonObj) -> None: """Reconcile a task this runner claims into the right lifecycle status (down-detection). For a task claimed by **this** runner whose reported spawn is still in flight (``CLAIMING`` … - ``AWAITING``) but whose container isn't actually running, clear the stale phase so the task - service composes ``down`` — the authoritative replacement for the dashboard's old guess. A - registered (``live``) or already-``down``/``failed`` task is left alone; an in-flight one - whose container *is* still running is left to keep coming up.""" + ``AWAITING``) but whose container isn't actually running, surface *why* when the stopped + container is still around to ask (:meth:`~panopticon.sessionservice.local_runner.LocalRunner.exit_reason` + — an OOM kill, a nonzero exit): report ``FAILED`` with that reason so the dashboard shows + the cause. When the container is gone entirely, clear the stale phase so the task service + composes ``down`` — the authoritative replacement for the dashboard's old guess. An + already-``down`` task gets the same exit-reason check (its container may have died *after* + going live — e.g. OOM-killed — leaving the registration to lapse into ``down`` with the + evidence still in ``docker inspect``); with no reason to add it is left alone. A registered + (``live``) or already-``failed`` task is left alone; an in-flight one whose container *is* + still running is left to keep coming up.""" if task.get("claimed_by") != self._runner_id: return # not ours (or unclaimed) — spawn_one handles the unclaimed case - if task.get("container_status") not in _IN_PROGRESS: - return # live / down / failed / queued / disconnected — nothing to reconcile + status = task.get("container_status") + if status not in _IN_PROGRESS and status != ContainerStatus.DOWN.value: + return # live / failed / queued / disconnected — nothing to reconcile if self._runner.is_running(task["id"]): return # container present, just not registered yet — still coming up - self._client.clear_lifecycle(task["id"]) # container gone → composes `down` + reason = self._runner.exit_reason(task["id"]) + if reason is not None: + self._report(task["id"], LifecyclePhase.FAILED, detail=reason) # composes `failed` + why + elif status in _IN_PROGRESS: + self._client.clear_lifecycle(task["id"]) # container gone without a trace → composes `down` def _is_orphan(self, task: JsonObj) -> bool: """Whether ``task`` is an orphan **this** runner should self-heal: claimed by us, @@ -276,10 +287,12 @@ def heal(self, task: JsonObj) -> str | None: now = self._now() count = self._respawn_count(task_id, now) if count >= self._max_respawns: - _log.error( - "task %s keeps losing its tmux session (%d respawns) — leaving it for attention", - task_id, count, - ) + # Surface the crash loop where the user looks (the dashboard's detail pane), not just + # the runner log — and only once: a task already reading `failed` is left alone rather + # than re-reported (and re-logged) every pass. + if task.get("container_status") != ContainerStatus.FAILED.value: + detail = f"keeps losing its tmux session ({count} respawns) — press R to respawn" + self._report(task_id, LifecyclePhase.FAILED, detail=detail) # _report logs it too return None self._respawns[task_id] = (count + 1, now) _log.warning("self-healing orphaned task %s (no tmux session) — respawn %d", task_id, count + 1) diff --git a/tests/test_local_runner.py b/tests/test_local_runner.py index 13c8593c..ae535c7e 100644 --- a/tests/test_local_runner.py +++ b/tests/test_local_runner.py @@ -58,11 +58,17 @@ def test_spawn_runs_detached_container_then_tmux_pane_execing_in() -> None: # pane execs the in-container agent launcher (so `tmux attach` reaches the live agent) assert tmux_new[:4] == ["tmux", "-L", "panopticon", "new-session"] assert tmux_new[tmux_new.index("-s") + 1] == "panopticon-t1" - # the pane execs in as the unprivileged `panopticon` user (so the agent's whoami isn't root) - assert tmux_new[-10:] == [ - "docker", "exec", "--interactive", "--tty", "--user", "panopticon", "panopticon-t1", - "python", "-m", "panopticon.container.agent", - ] + # The pane is one host shell command: a bounded wait for the entrypoint's remap-complete + # marker (exec'ing in earlier resolves `--user panopticon` to the pre-remap uid — the spawn + # race), then the exec in as the unprivileged `panopticon` user (the agent's whoami isn't + # root). Manual `respawn-pane`/heal reruns get the same guard since it *is* the pane command. + pane = tmux_new[-1] + assert pane.startswith("i=0; until docker exec panopticon-t1 test -f /run/panopticon-ready; ") + assert "[ $i -ge 150 ] && break; sleep 0.2" in pane # bounded — a pre-marker image still launches + assert pane.endswith( + "exec docker exec --interactive --tty --user panopticon panopticon-t1" + " python -m panopticon.container.agent" + ) def test_spawn_reports_starting_then_awaiting_via_the_progress_callback() -> None: @@ -99,6 +105,31 @@ def test_is_running_is_false_when_no_container_is_listed() -> None: assert runner.is_running("t1") is False +def test_exit_reason_inspects_the_containers_exit_state() -> None: + rec = _ReturningRecorder("false false 137\n") + runner = LocalRunner("http://svc:8000", run=rec) + assert runner.exit_reason("t1") == "container exited (exit 137)" + (inspect, check), = rec.calls + assert inspect == [ + "docker", "inspect", "--format", + "{{.State.Running}} {{.State.OOMKilled}} {{.State.ExitCode}}", "panopticon-t1", + ] + assert check is False # a missing container prints nothing — that's an answer, not an error + + +def test_exit_reason_names_an_oom_kill_over_the_exit_code() -> None: + # The kernel's OOM killer can leave a deceptively clean exit code 0 — OOMKilled is the truth. + runner = LocalRunner("http://svc:8000", run=_ReturningRecorder("false true 0\n")) + assert runner.exit_reason("t1") == "container OOM-killed (exit 0)" + + +def test_exit_reason_is_none_when_running_or_gone() -> None: + # Still running → nothing to explain. + assert LocalRunner("http://svc:8000", run=_ReturningRecorder("true false 0\n")).exit_reason("t1") is None + # Container gone entirely (inspect errors → empty stdout) → nothing left to ask. + assert LocalRunner("http://svc:8000", run=_Recorder()).exit_reason("t1") is None + + def test_has_session_lists_the_tmux_server_and_matches_the_session_name() -> None: rec = _ReturningRecorder("panopticon-t1\npanopticon-t2\n") # two sessions on the server runner = LocalRunner("http://svc:8000", run=rec) diff --git a/tests/test_spawner.py b/tests/test_spawner.py index 8dcaa773..32c2ea8c 100644 --- a/tests/test_spawner.py +++ b/tests/test_spawner.py @@ -30,13 +30,14 @@ def _no_op_run(args: object, *, check: bool = True) -> str: class _FakeRunner: """Records spawn calls; stands in for LocalRunner. Mimics its ``progress`` callbacks (STARTING - then AWAITING), ``is_running`` (for reconcile/down-detection) and ``has_session`` (for heal/ - self-heal) — both configurable.""" + then AWAITING), ``is_running`` (for reconcile/down-detection), ``has_session`` (for heal/ + self-heal) and ``exit_reason`` (why a stopped container died) — all configurable.""" - def __init__(self, *, running: bool = True, session: bool = True) -> None: + def __init__(self, *, running: bool = True, session: bool = True, exit_reason: str | None = None) -> None: self.spawned: list[dict[str, object]] = [] self._running = running self._session = session + self._exit_reason = exit_reason def spawn(self, task_id: str, *, env_file: str | None = None, workspace: str | None = None, image: str | None = None, docker_in_docker: bool = False, initial_prompt: str | None = None, turn: str | None = None, progress: Callable[[LifecyclePhase], None] | None = None) -> str: self.spawned.append({"task_id": task_id, "env_file": env_file, "workspace": workspace, "image": image, "docker_in_docker": docker_in_docker, "initial_prompt": initial_prompt, "turn": turn}) @@ -51,6 +52,9 @@ def is_running(self, task_id: str) -> bool: def has_session(self, task_id: str) -> bool: return self._session + def exit_reason(self, task_id: str) -> str | None: + return self._exit_reason + def stop(self, container_id: str) -> None: pass @@ -256,6 +260,39 @@ def test_reconcile_ignores_tasks_not_in_flight_or_not_ours() -> None: assert client.cleared == [] # live/failed are left as-is; t3 belongs to another runner +def test_reconcile_surfaces_why_the_container_died() -> None: + # The container stopped but is still around to ask (e.g. the kernel OOM-killed it): report + # `failed` with the exit reason — the dashboard shows the cause, not a bare `down`. + client = _FakeClient(repo=_REPO) + runner = _FakeRunner(running=False, exit_reason="container OOM-killed (exit 0)") + _spawner(client, runner).reconcile( + {"id": "t1", "claimed_by": "host-1", "container_status": "awaiting", "state": "ITERATING"} + ) + assert client.phases == [("t1", "failed", "container OOM-killed (exit 0)")] + assert client.cleared == [] # surfaced as failed+why, not cleared to an unexplained `down` + + +def test_reconcile_surfaces_a_down_tasks_exit_reason() -> None: + # A task can go `down` *after* being live (its registration lapsed when the container died) — + # the evidence is still in the stopped container, so the same exit-reason check applies. + client = _FakeClient(repo=_REPO) + runner = _FakeRunner(running=False, exit_reason="container exited (exit 137)") + _spawner(client, runner).reconcile( + {"id": "t1", "claimed_by": "host-1", "container_status": "down", "state": "ITERATING"} + ) + assert client.phases == [("t1", "failed", "container exited (exit 137)")] + + +def test_reconcile_leaves_a_down_task_alone_without_an_exit_reason() -> None: + # `down` with the container gone entirely: nothing to add and nothing to clear — no feed churn. + client, runner = _FakeClient(repo=_REPO), _FakeRunner(running=False) + _spawner(client, runner).reconcile( + {"id": "t1", "claimed_by": "host-1", "container_status": "down", "state": "ITERATING"} + ) + assert client.phases == [] + assert client.cleared == [] + + def test_heal_respawns_an_orphan_claimed_by_us_with_no_session() -> None: # The orphan case (e.g. the tmux server crashed, or `make stop` tore everything down but the # task stays claimed): claimed by us, non-terminal, but its tmux session is gone → respawn it @@ -314,6 +351,30 @@ def test_heal_caps_respawns_then_surfaces_a_crash_looping_task() -> None: assert len(runner.spawned) == 3 # capped at max_respawns; further attempts are surfaced, not spawned +def test_heal_cap_reports_failed_once_with_a_pointer_to_respawn() -> None: + # Hitting the crash-loop cap is surfaced where the user looks — a `failed` report whose detail + # says what happened and what to do — not just the runner log. And only once: a task already + # reading `failed` is left alone rather than re-reported (feed churn) every pass. + clock = {"t": 0.0} + client, runner = _FakeClient(repo=_REPO), _FakeRunner(session=False) + spawner = Spawner( + client, runner, runner_id="host-1", # type: ignore[arg-type] + cache=CloneCache("/cache", run=_no_op_run, exists=lambda _p: True, makedirs=lambda _p: None), tasks_root="/tasks", + git=GitClones(run=_no_op_run), images=_FakeImageBuilder(), # type: ignore[arg-type] + makedirs=lambda _p: None, now=lambda: clock["t"], max_respawns=2, respawn_reset=60.0, + ) + spawner.heal(_orphan()) # respawn 1 + clock["t"] += 1.0 + spawner.heal(_orphan()) # respawn 2 → budget exhausted + clock["t"] += 1.0 + spawner.heal(_orphan()) # capped → surfaced as failed + failed = [p for p in client.phases if p[1] == "failed"] + assert failed == [("t1", "failed", "keeps losing its tmux session (2 respawns) — press R to respawn")] + clock["t"] += 1.0 + spawner.heal({**_orphan(), "container_status": "failed"}) # already surfaced on a later pass + assert [p for p in client.phases if p[1] == "failed"] == failed # reported once, not every pass + + def test_heal_resets_the_respawn_budget_after_a_survivor_window() -> None: # An isolated orphan that recovers (survives past the reset window) heals again on a later, # unrelated failure rather than being counted toward the earlier burst.