diff --git a/decisions/2026-10-31-pm-agent-triage-exit.md b/decisions/2026-10-31-pm-agent-triage-exit.md new file mode 100644 index 0000000..25bb910 --- /dev/null +++ b/decisions/2026-10-31-pm-agent-triage-exit.md @@ -0,0 +1,77 @@ +--- +date: 2026-10-31 +branch: fix/pm-agent-triage-exit +title: pm-agent triage fails with "claude exited 1:" and no message; log the CLI's stdout envelope so the cause is visible +--- + +## What changed + +- `infra/agent/pm-dispatch.py`, `ask_pm()`: on a non-zero exit the error now comes from a new + `describe_cli_failure()`, not from `proc.stderr` alone. With `--output-format json` the CLI + reports its own failures as the result envelope on **stdout** and writes nothing to stderr, + which is why both failures today logged `claude exited 1: ` with an empty message. The new + line carries the envelope's `subtype`, `is_error`, `api_error_status`, `num_turns`, + `duration_ms`, `total_cost_usd`, `stop_reason`, its `result`/`error` text, and the tails of + stdout and stderr. It names silence explicitly when both streams are empty. +- `redact()`: everything in that message, and in `extract_decision()`'s "no decision object" + error, passes through it. It covers `sk-ant-…`, `Bearer`/`token` values, and `user:pass@` in + both `http://` and `https://` URLs. +- `PM_DECISION_MAX_TURNS`: a new knob. It defaults to 1, today's value, so behaviour is + unchanged, and it is bounded to 1–5. If the newly visible envelope says `error_max_turns`, + the remedy is a ConfigMap change rather than another image build. Documented in + `platform/pm-agent/README.md`. +- Selftest: four new assertions. They cover an empty stderr with the cause on stdout, a + stderr-only failure, total silence, and redaction. + +## What I verified + +- **Timeline (Loki, `{namespace="pm-agent"}`, and `kubectl logs`):** + - **16:37:38 to 16:38:00**: pod `pm-agent-898fd8f5f-dp5hs`, image **c4eba5b3**, + config-generation 2, dry run. It triaged #97 in **22 s**, logged `PM says comment`, and + posted the 16:38:00Z comment. The thread then held only the issue body. + - **16:43:09 to 16:44:00**: pod `pm-agent-f7c9b7fcf-j8mzn`, image **df36d9b7**, + config-generation 3, **still dry run**. It logged `claude exited 1: ` with an empty + message after **51 s**. + - **16:55:42 to 16:56:36**: pod `pm-agent-7796db8bcb-p5dsm`, df36d9b7, config-generation + 4, live. The same empty failure, after **54 s**. + - The only successful triage ever was the 16:38 one. Every earlier `898fd8f5f`/`5db55d558c` + log line is a startup crash (Gitea `GET /user` 401), not a triage. +- **Going live is NOT the cause.** The first failure happened in dry run. `ask_pm()` has no + dry-run branch: the prompt, flags, tools (`--tools ""`) and cwd are identical in both + modes. `PM_DRY_RUN` gates only `create_job()`, which runs after the model has answered. +- **Ruled out, with evidence:** + - **Timeout**: 51 to 54 s against a 900 s limit, and a timeout raises `TimeoutExpired`, + not rc 1. + - **Budget cap**: the PM call passes no `--max-budget-usd`. + - **Prompt size**: the thread is the issue body (293 chars) plus three comments + (1871 + 404 + 77 chars), and the persona is 8 KB. + - **Writable HOME**: HOME=`/workspace` (emptyDir), and `CLAUDE_CONFIG_DIR=/workspace/.claude` + was written at 16:56. + - **Egress**: a TLS 1.3 handshake to `api.anthropic.com:443` from the dispatcher pod + succeeds in 0.06 s. + - **Model name and CLI version**: the same `claude-opus-5` and CLI 2.1.285 succeeded at + 16:38. Between c4eba5b and df36d9b, `infra/agent/` differs only by a template selftest + assertion and the toolbox base digest. +- **A hint, not proof:** `/workspace/.claude/.claude.json` in the live pod has + `cachedExtraUsageDisabledReason: 'out_of_credits'`. No token was read or printed. +- Offline selftest: `PM_SELFTEST=1` against the worktree's template and persona prints + `selftest OK`, including the 4 new assertions. +- Toolbox gate: see the PR description for the rc and the stages that were skipped. + +## What I did NOT verify + +- **The root cause. UNVERIFIED.** The CLI's own message was discarded, `--no-session-persistence` + leaves no transcript, and I did not run `claude` in the pod. The candidates still open: + - **Usage or rate limit on the subscription seat.** The seat is shared with the operator's + interactive use. The `out_of_credits` extra-usage flag fits this. So does a ~50 s run, + which matches the CLI exhausting its 429/529 retries. + - **`error_max_turns`.** With `--max-turns 1` and `--json-schema`, an answer that fails the + schema cannot be retried. The failing thread now invites `implement` (a branch plus a + long brief), where the 16:38 one produced a short `comment`. ~50 s is about two + generations of the 22 s success. +- **The 17:11 retry will NOT reveal the cause.** It runs the old image, which still discards + stdout. The cause becomes visible only after this PR merges, CI re-publishes agent-runner, + and a follow-up PR bumps the dispatcher digest (`deployment.yaml` and the `PM_WORKER_IMAGE` + in `configmap.yaml`, plus a `config-generation` bump). +- That the CLI's error envelope carries exactly these key names. The parser takes whichever + keys are present and falls back to raw tails. diff --git a/infra/agent/pm-dispatch.py b/infra/agent/pm-dispatch.py index 37ff52d..dc9c443 100755 --- a/infra/agent/pm-dispatch.py +++ b/infra/agent/pm-dispatch.py @@ -214,6 +214,12 @@ class Config: # ConfigMap without rebuilding the image. self.push_on_red = env("PM_PUSH_ON_RED_GATE", "false") self.pm_timeout = env_int("PM_DECISION_TIMEOUT_SECONDS", 900) + # The PM holds no tools, so the only thing a second turn can be spent on is the CLI's + # structured-output step re-asking the model after an answer that failed the schema. + # 1 is the long-standing value; it is a knob so that, if the failure envelope now + # logged by describe_cli_failure() says `error_max_turns`, the remedy is a ConfigMap + # change rather than another image build. + self.pm_max_turns = env_int("PM_DECISION_MAX_TURNS", 1) # Opt-in gate. Empty (the default) means every open issue is in scope, which is the # behaviour the service was asked for. Setting it to a label name — `agent` is the # conventional one — narrows the agent to issues a human has explicitly handed it, @@ -231,6 +237,8 @@ class Config: if self.max_active_workers < 1: die("PM_MAX_ACTIVE_WORKERS must be >= 1") + if not 1 <= self.pm_max_turns <= 5: + die("PM_DECISION_MAX_TURNS must be between 1 and 5") if "@sha256:" not in self.worker_image: # The admission policy requires a digest too, so a tag here would produce a Job # that is created and then DENIED — a failure visible only in the dispatcher's @@ -437,7 +445,7 @@ def ask_pm(cfg: Config, thread: str) -> dict: "--system-prompt-file", cfg.persona_file, "--tools", "", "--permission-prompts", "none", - "--max-turns", "1", + "--max-turns", str(cfg.pm_max_turns), "--output-format", "json", "--json-schema", json.dumps(DECISION_SCHEMA), "--no-session-persistence", @@ -445,10 +453,76 @@ def ask_pm(cfg: Config, thread: str) -> dict: proc = subprocess.run(cmd, input=thread, capture_output=True, text=True, timeout=cfg.pm_timeout) if proc.returncode != 0: - raise RuntimeError(f"claude exited {proc.returncode}: {proc.stderr.strip()[:800]}") + raise RuntimeError(describe_cli_failure(proc.returncode, proc.stdout, proc.stderr)) return extract_decision(proc.stdout) +# Anything that could be a credential in the CLI's output. The CLI does not normally echo its +# token, but an API error body or a proxy's HTML page is not something to bet a leak on. Both +# schemes are matched (the http one is the lesson of a scheme-specific redaction that leaked +# ~/.git-credentials), and `token ...` is Gitea's own header scheme. +_SECRET_PATTERNS = [ + (re.compile(r"sk-ant-[A-Za-z0-9_\-]+"), "sk-ant-[REDACTED]"), + (re.compile(r"(?i)\b(bearer|token)(\s+|=|:\s*)[A-Za-z0-9._~+/=\-]{8,}"), r"\1\2[REDACTED]"), + (re.compile(r"(?i)(https?://)[^/\s:@]+:[^/\s@]+@"), r"\1[REDACTED]@"), +] + + +def redact(text: str) -> str: + for pat, repl in _SECRET_PATTERNS: + text = pat.sub(repl, text) + return text + + +def describe_cli_failure(rc: int, stdout: str, stderr: str, limit: int = 800) -> str: + """Say WHY `claude --print` failed, in the dispatcher log, redacted. + + WHY THIS EXISTS: with `--output-format json` the CLI reports its own failures — an API + error, a usage limit, `error_max_turns`, a schema the model could not satisfy — as the + JSON result envelope on STDOUT (`is_error`, `subtype`, `result`), and writes nothing to + stderr. Logging only stderr therefore produced `claude exited 1: ` with an empty message + on 2026-10-31, twice, with the cause sitting unread in stdout. So: the envelope's + diagnostic fields first, then the raw tails of both streams. + """ + parts = [f"claude exited {rc}"] + out = (stdout or "").strip() + env = None + if out: + try: + env = json.loads(out) + except ValueError: + # A stream of JSON lines, or a log line ahead of the envelope: the last line that + # parses as an object is the result. + for line in reversed(out.splitlines()): + try: + cand = json.loads(line) + except ValueError: + continue + if isinstance(cand, dict): + env = cand + break + if isinstance(env, dict): + fields = [] + for key in ("subtype", "is_error", "api_error_status", "num_turns", "duration_ms", + "duration_api_ms", "total_cost_usd", "stop_reason"): + if key in env: + fields.append(f"{key}={env[key]!r}") + if fields: + parts.append("envelope: " + " ".join(fields)) + for key in ("result", "error", "errors", "message"): + if env.get(key): + val = env[key] if isinstance(env[key], str) else json.dumps(env[key]) + parts.append(f"{key}: {val[:limit]}") + if out and not isinstance(env, dict): + parts.append(f"stdout tail: {out[-limit:]}") + err_text = (stderr or "").strip() + if err_text: + parts.append(f"stderr tail: {err_text[-limit:]}") + if len(parts) == 1: + parts.append("(no output on stdout or stderr)") + return redact(" | ".join(parts)) + + def extract_decision(stdout: str) -> dict: """Pull the decision object out of whatever `claude --print` wrapped it in. @@ -501,7 +575,7 @@ def extract_decision(stdout: str) -> dict: obj = as_obj(c) if obj and isinstance(obj.get("action"), str): return obj - raise RuntimeError(f"no decision object in claude output: {stdout[:400]!r}") + raise RuntimeError(redact(f"no decision object in claude output: {stdout[-800:]!r}")) # --------------------------------------------------------------------------- thread @@ -988,8 +1062,25 @@ def selftest() -> int: except RuntimeError: check(True, f"bad output refused: {label}") + # -- a failed CLI run must say why, and must not leak --------------------- + # The 2026-10-31 failure: rc 1, empty stderr, the cause in the stdout envelope. + env_err = json.dumps({"type": "result", "subtype": "error_max_turns", "is_error": True, + "num_turns": 2, "result": "API Error: 429 rate_limit_error"}) + msg = describe_cli_failure(1, env_err, "") + check("error_max_turns" in msg and "429" in msg, + "CLI failure: stdout envelope surfaced when stderr is empty") + msg = describe_cli_failure(1, "", "boom on stderr") + check("boom on stderr" in msg, "CLI failure: stderr tail surfaced") + msg = describe_cli_failure(1, "", "") + check("no output" in msg, "CLI failure: silence is named, not an empty message") + msg = describe_cli_failure(1, "plain text sk-ant-oat01-abcdefABCDEF_123 here", + "Authorization: Bearer abcdefghijklmnop " + "http://u:pw@gitea.example/x") + check("sk-ant-oat01" not in msg and "abcdefghijklmnop" not in msg and ":pw@" not in msg, + "CLI failure: token, bearer and URL credential redacted") + # -- the committed Job template ----------------------------------------- - tmpl = os.environ.get("PM_WORKER_JOB_TEMPLATE", "/etc/pm-agent/worker-job-template.yaml") + tmpl =os.environ.get("PM_WORKER_JOB_TEMPLATE", "/etc/pm-agent/worker-job-template.yaml") try: selftest_template(tmpl) check(True, f"worker Job template satisfies its contract ({tmpl})") diff --git a/platform/pm-agent/README.md b/platform/pm-agent/README.md index 07f5981..cda9904 100644 --- a/platform/pm-agent/README.md +++ b/platform/pm-agent/README.md @@ -250,6 +250,12 @@ five that matter: | `PM_MAX_ACTIVE_WORKERS` | `2` | concurrent workers. RAM is the binding constraint (2Gi limit each) and the subscription seat's rate limits are shared with every other use of that seat | | `PM_MAX_NEW_WORKERS_PER_CYCLE` | `1` | drains a backlog one issue at a time instead of in one stampede the first minute the credentials work | | `PM_PUSH_ON_RED_GATE` | `false` | a change the gate refused is not pushed; the issue gets the gate log instead | +| `PM_DECISION_MAX_TURNS` | `1` (unset) | turns the triage call may take (1–5). The PM holds no tools, so a second turn is only ever the CLI re-asking after an answer that failed the decision schema. Raise it if a triage error logs `subtype='error_max_turns'` | + +**When a triage fails**, the `[error] issue #N: claude exited …` line carries the CLI's result +envelope (`subtype`, `is_error`, `api_error_status`, `num_turns`, `result`) and the tails of +stdout and stderr, redacted. Before 2026-10-31 it logged stderr only, which is empty under +`--output-format json` — see `decisions/2026-10-31-pm-agent-triage-exit.md`. Changing a knob requires bumping the `config-generation` annotation in `deployment.yaml` in the same commit — the process reads its configuration once, at startup, so without the bump