Skip to content

Commit 5164966

Browse files
mcp: the execute timeout no longer severs an approved mutating run
Three defects on one path, all from issue #113. **One budget covered the park and the work.** `approval_timeout + 120s` bounded the whole subprocess, so a human approving near the end of the park left roughly two minutes for the run itself -- and a governed run's agent phases delegate to Claude Code, which reads files, edits them and verifies. The likely outcome was not a wedged process being cleaned up, it was a human-approved, tree-mutating run being SIGKILLed partway through mutating the tree. The non-mutating branch passed `timeout=None` and was not bounded at all. Separate budgets now: `DEFAULT_WORK_TIMEOUT` is 1800s, the number `GRAPHARC_SLACK_WORK_TIMEOUT` already uses for this exact case, overridable via `GRAPHARC_MCP_WORK_TIMEOUT` -- which refuses a non-numeric or non-positive value rather than substituting a ceiling nobody chose. **plan.json could not catch the reissue.** `executed_run_id` is stamped after `loop.run()` returns, so a killed run never reaches it; the record said "never executed" and the #100 guard waved a second `go` through on one human approval. The guard now reads the trace, which is written as the run proceeds and is the only place that evidence survives a kill. Deliberately not a pre-stamp: that would mark a plan executed when it had merely parked and been denied. The phase vocabulary is pinned by a test, because the obvious spelling -- "not one of `observe.metrics`'s loop phases" -- counts `approval_response` as an execution and so refuses a denied plan forever. A torn trace reports no evidence rather than wedging the plan beside it. **The kill left grandchildren.** No new session and `process.kill()` signals the direct child only, so a delegated Claude Code process outlived the run and kept the workspace. `start_new_session=True` plus a process-group SIGKILL, falling back to the single process where `killpg` is unavailable. The docstring promised "a timeout leaves the plan unexecuted and this call safe to reissue", true of an unanswered park and false of everything else. It distinguishes them now and sends the agent to `show_graph` first; the `DriverError` says the same. Both asserted -- that docstring is the agent's whole briefing. Verified: 2171 selected, 13 deselected, ruff clean. Red without the fix (reverting only `grapharc/` fails the reissue test `assert 0 == 2`), while the two over-refusal guards pass on both sides. deep-dive.md's figure updated 2,151 -> 2,171. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent cf984f7 commit 5164966

6 files changed

Lines changed: 575 additions & 11 deletions

File tree

‎docs/deep-dive.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -254,7 +254,7 @@ A stable system is not one that claims to have no edges — it is one whose edge
254254
- **`.env` and `grapharc.toml` follow the same discovery rule: the working directory, and nowhere else.** Neither searches parent directories — a run must not be governed by a file you did not know about, and must not be *billed* to one either. **This is a behaviour change:** the credential loader used to walk up to `/`, so a `.env` in an ancestor directory (a `$HOME` one on a shared box, a client project one above a demo checkout) was picked up silently. If you relied on that, move the file into the directory you run from, `export` the variable, or pass `env_file=` to name it explicitly. A real environment variable still beats any file.
255255
- **`grapharc run` has no budget unless you give it one.** Set any of `--max-tokens`, `--max-iterations`, `--max-seconds`, or `--max-concurrency`; without them each dimension is unlimited and the gate admits a topology of any worst-case cost.
256256

257-
**Verified this pass:** `pytest` → green, 2,151 selected and 13 deselected (the live ones); `ruff check .` clean; all eight `grapharc demo` stages green, plus the `trace` / `metrics` / `viz` / `replay` tour against a freshly recorded demo trace; the wheel builds and imports all submodules in a clean virtualenv with `[all]`, and `0.1.7` on PyPI is that wheel. The counts are a snapshot, not a property of the project — `pytest` re-derives them in one command, which is the only reason they are quoted, and `tests/test_deep_dive.py` fails this line rather than letting it drift.
257+
**Verified this pass:** `pytest` → green, 2,171 selected and 13 deselected (the live ones); `ruff check .` clean; all eight `grapharc demo` stages green, plus the `trace` / `metrics` / `viz` / `replay` tour against a freshly recorded demo trace; the wheel builds and imports all submodules in a clean virtualenv with `[all]`, and `0.1.7` on PyPI is that wheel. The counts are a snapshot, not a property of the project — `pytest` re-derives them in one command, which is the only reason they are quoted, and `tests/test_deep_dive.py` fails this line rather than letting it drift.
258258

259259
[ROADMAP.md](../ROADMAP.md) tracks what is built and what is not, item by item.
260260

‎grapharc/cli/plan.py‎

Lines changed: 71 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -233,6 +233,58 @@ def _executed_run_ids(record: dict[str, Any]) -> list[str]:
233233
return [str(scalar)] if scalar else []
234234

235235

236+
237+
#: Phases that are *not* a node doing work. The loop's own bookkeeping
238+
#: (`plan`, `admission`, `round`), the shape events a viewer draws from
239+
#: (`topology`, `approval_request`, `approval_response`), and a bare `stop`,
240+
#: which is a driver saying why it finished rather than a path it took --
241+
#: the same three-way split `observe.metrics` makes to decide what counts as
242+
#: an execution. Anything else (`start`, `model`, `end`, `error`) is a node
243+
#: that ran, which is the only thing this file needs to know.
244+
_NON_EXECUTION_PHASES = frozenset(
245+
{
246+
"plan",
247+
"admission",
248+
"round",
249+
"topology",
250+
"approval_request",
251+
"approval_response",
252+
"stop",
253+
}
254+
)
255+
256+
257+
def _unfinished_execution(trace_path: Path, record: dict[str, Any]) -> str | None:
258+
"""A run whose nodes ran but which `plan.json` never recorded finishing.
259+
260+
`executed_run_id` is stamped *after* `loop.run()` returns, so a run that
261+
is killed partway through never reaches the stamp: the MCP `execute`
262+
work budget expiring, a SIGKILL, an OOM-kill. The record then says the
263+
plan was never executed while the tree may already have been changed,
264+
and the #100 reissue guard waves a second run through on the strength of
265+
one human approval -- which is the property #100 was closed to protect.
266+
267+
The trace is written *as the run proceeds*, so it is the only place that
268+
evidence survives a kill. Returns the offending run id, or None.
269+
"""
270+
if not trace_path.is_file():
271+
return None
272+
from grapharc.observe.trace import TraceReadError, TraceRecorder
273+
274+
known = {str(r) for r in _executed_run_ids(record)}
275+
try:
276+
events = TraceRecorder(trace_path).read_events()
277+
except (OSError, TraceReadError):
278+
# A torn or unreadable trace is not evidence of a half-run, and
279+
# refusing here would wedge every plan sitting beside a damaged file.
280+
# `grapharc trace` is what reports a trace that cannot be read.
281+
return None
282+
for event in events:
283+
if event.run_id not in known and event.phase not in _NON_EXECUTION_PHASES:
284+
return event.run_id
285+
return None
286+
287+
236288
def find_unexecuted_plan(runs_root: Path | None = None) -> Path | None:
237289
"""The newest saved plan `go` has not executed yet, or None."""
238290
import json
@@ -395,6 +447,25 @@ def execute_plan(
395447
run_dir = plan_file.parent
396448
trace_path = run_dir / "trace.jsonl"
397449

450+
# A previous attempt that began and never recorded finishing. Checked
451+
# after the `executed_run_id` guard above and separately from it, because
452+
# the two are different facts: that one is "this ran, cleanly, once", this
453+
# one is "something ran and we do not know how far it got".
454+
unfinished = _unfinished_execution(trace_path, record)
455+
if unfinished and not again:
456+
return fail(
457+
f"{plan_file} has an attempt, run {unfinished}, that began executing "
458+
"and never recorded finishing — it may have changed the tree partway "
459+
f"through. What it did reach is in the trace: `grapharc trace {trace_path}`. "
460+
"Pass --again to run the plan a second time anyway; an approval binds "
461+
"to the plan's fingerprint, which does not change between runs, so a "
462+
"re-run of a mutating plan spends an earlier yes.",
463+
as_json=as_json,
464+
command="go",
465+
plan=str(plan_file),
466+
unfinished_run_id=str(unfinished),
467+
)
468+
398469
try:
399470
settings = load_settings(config_path)
400471
model_spec = settings.resolve("model", model_spec, record.get("model"))

‎grapharc/mcp/driver.py‎

Lines changed: 75 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -21,18 +21,62 @@
2121
from __future__ import annotations
2222

2323
import asyncio
24+
import contextlib
2425
import json
26+
import os
27+
import signal
2528
import sys
2629
from pathlib import Path
2730
from typing import Any
2831

2932
PLAN_FILENAME = "plan.json"
3033

31-
#: A parked `execute` lives inside one MCP call, and hosts time tool calls
32-
#: out. The default stays under typical host limits; a timeout leaves the
33-
#: plan unexecuted and the call safe to reissue.
34+
#: How long a parked `execute` waits for a human to answer. A parked call
35+
#: lives inside one MCP call and hosts time tool calls out, so the default
36+
#: stays under typical host limits. This bounds *the wait*, nothing else:
37+
#: a park that expires without an answer leaves the plan unexecuted, and
38+
#: only that case is safe to reissue.
3439
DEFAULT_APPROVAL_TIMEOUT = 240.0
3540

41+
#: How long the *work* gets, once a plan is admitted and (if mutating) a
42+
#: human has said yes. Separate from the park on purpose. These used to be
43+
#: one budget of `approval_timeout + 120s` covering both, which meant a human
44+
#: approving near the end of the park left roughly two minutes for the run
45+
#: itself — and a governed run's agent phases delegate to Claude Code, which
46+
#: reads files, edits them and verifies. Killing an approved run at 120s does
47+
#: not protect anything; it severs an approved run partway through its work,
48+
#: which for a mutating plan means partway through mutating the tree.
49+
#:
50+
#: 1800s matches `GRAPHARC_SLACK_WORK_TIMEOUT`, which the Slack path carved
51+
#: out of one shared timeout for this exact reason. Overridable because the
52+
#: right ceiling is a property of the operator's machine, not of this file.
53+
DEFAULT_WORK_TIMEOUT = 1800.0
54+
55+
56+
def work_timeout(env: dict[str, str] | None = None) -> float:
57+
"""The work budget, from `GRAPHARC_MCP_WORK_TIMEOUT` or the default.
58+
59+
Refuses a non-numeric or non-positive override rather than falling back
60+
to the default: an operator who sets this has a ceiling in mind, and
61+
silently substituting a different one is how a run gets killed at a
62+
limit nobody chose.
63+
"""
64+
source = os.environ if env is None else env
65+
raw = source.get("GRAPHARC_MCP_WORK_TIMEOUT")
66+
if raw is None or raw == "":
67+
return DEFAULT_WORK_TIMEOUT
68+
try:
69+
seconds = float(raw)
70+
except ValueError:
71+
raise DriverError(
72+
f"GRAPHARC_MCP_WORK_TIMEOUT must be a number of seconds, not {raw!r}"
73+
) from None
74+
if seconds <= 0:
75+
raise DriverError(
76+
f"GRAPHARC_MCP_WORK_TIMEOUT must be positive, not {seconds!r}"
77+
)
78+
return seconds
79+
3680

3781
class DriverError(Exception):
3882
"""A tool call that cannot proceed, with the reason as the message."""
@@ -56,6 +100,23 @@ def confine_run_dir(root: Path, run_dir: str) -> Path:
56100
return resolved
57101

58102

103+
def _kill_tree(process: asyncio.subprocess.Process) -> None:
104+
"""SIGKILL the child's whole process group, falling back to the child.
105+
106+
The group is the point: see `start_new_session` in `run_cli`. A group
107+
that has already exited raises `ProcessLookupError`, which is the
108+
success case arriving early, and a platform without `killpg` still gets
109+
the old single-process behaviour rather than an exception.
110+
"""
111+
# `ProcessLookupError` and `PermissionError` are `OSError`; `AttributeError`
112+
# is a platform with no `killpg` at all.
113+
with contextlib.suppress(AttributeError, OSError):
114+
os.killpg(os.getpgid(process.pid), signal.SIGKILL)
115+
return
116+
with contextlib.suppress(ProcessLookupError):
117+
process.kill()
118+
119+
59120
async def run_cli(
60121
argv: list[str], *, cwd: Path, timeout: float | None = None
61122
) -> tuple[int, str, str]:
@@ -68,14 +129,23 @@ async def run_cli(
68129
cwd=cwd,
69130
stdout=asyncio.subprocess.PIPE,
70131
stderr=asyncio.subprocess.PIPE,
132+
# Its own process group, so the timeout below can kill the whole tree.
133+
# `process.kill()` signals the direct child only, and a governed run
134+
# delegates agent phases to Claude Code — so a killed run used to
135+
# leave that grandchild alive, still holding the workspace the next
136+
# call would run in. The CLI's own `deadline_guard` kills its group
137+
# deliberately, but that is the CLI's guard, not this outer one.
138+
start_new_session=True,
71139
)
72140
try:
73141
out, err = await asyncio.wait_for(process.communicate(), timeout=timeout)
74142
except TimeoutError:
75-
process.kill()
143+
_kill_tree(process)
76144
await process.wait()
77145
raise DriverError(
78-
f"grapharc {argv[0]} did not finish within {timeout}s and was stopped"
146+
f"grapharc {argv[0]} did not finish within {timeout}s and was stopped. "
147+
"Whether the plan ran is recorded in the run directory, not here: "
148+
"read it back with show_graph before reissuing anything."
79149
) from None
80150
return process.returncode or 0, out.decode(errors="replace"), err.decode(errors="replace")
81151

‎grapharc/mcp/server.py‎

Lines changed: 16 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -116,20 +116,31 @@ async def execute(
116116
117117
A plan with a mutating kind parks until a human answers
118118
`grapharc approve <run_dir>` out of band; tell the user, do not
119-
answer it yourself. A timeout leaves the plan unexecuted and this
120-
call safe to reissue.
119+
answer it yourself.
120+
121+
**Do not reissue this call after a timeout without reading the run
122+
back first.** A park that expires unanswered leaves the plan
123+
unexecuted, and that case alone is safe to retry. A timeout during
124+
the *work* is a different thing: the run may have been stopped
125+
partway through, and for a mutating plan that means partway through
126+
changing the tree. `show_graph` on the same `run_dir` says which
127+
happened, and `execute` refuses a plan whose trace shows an
128+
unfinished attempt rather than spending one human approval twice.
121129
"""
122130
resolved = driver.confine_run_dir(base, run_dir)
123131
record = driver.read_plan_record(resolved)
124132
mutating = driver.plan_is_mutating(record)
133+
# The park and the work get separate budgets. One budget covering both
134+
# meant a human approving near the end of the park left ~120s for the
135+
# run, and the non-mutating branch was unbounded -- a wedged run held
136+
# the call open forever. See DEFAULT_WORK_TIMEOUT for the reasoning.
137+
work = driver.work_timeout()
125138
code, out, err = await driver.run_cli(
126139
driver.build_execute_argv(
127140
resolved, mutating=mutating, approval_timeout=approval_timeout
128141
),
129142
cwd=base,
130-
# The subprocess bounds its own park via --approval-timeout; this
131-
# outer bound only catches a wedged process, generously.
132-
timeout=approval_timeout + 120.0 if mutating else None,
143+
timeout=(approval_timeout + work) if mutating else work,
133144
)
134145
document = driver.parse_document(out, command="go")
135146
document["mutating"] = mutating

0 commit comments

Comments
 (0)