From e12aa36c47caa1edd7e2c2225c0bfe3038cc392a Mon Sep 17 00:00:00 2001 From: "claude[bot]" <41898282+claude[bot]@users.noreply.github.com> Date: Tue, 14 Jul 2026 22:01:54 +0000 Subject: [PATCH 1/4] Add trace-log anomalies section to control-channel design doc MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Designs the affordances requested in issue #81: --json on `inspect trace anomalies`, an `inspect ctl process anomalies` verb (client-side trace-file read, deliberately no HTTP endpoint so it works against a wedged process), and stall-site pointers. Design only — no implementation. Co-authored-by: Ransom Richardson <1209015+ransomr@users.noreply.github.com> Co-Authored-By: Claude Fable 5 --- design/control-channel.md | 31 +++++++++++++++++++++++++++++++ 1 file changed, 31 insertions(+) diff --git a/design/control-channel.md b/design/control-channel.md index 8429d46236..e39dd71c66 100644 --- a/design/control-channel.md +++ b/design/control-channel.md @@ -488,6 +488,36 @@ Open question: which knobs are realistically directable mid-flight without rearc Each is a small surgical addition to the eval runner; the control channel is the wire that triggers them. +### Trace-log anomalies for stall diagnosis (planned) + +Field feedback from agent-driven eval babysitting (JJ, via issue #81): telling the LLM agent about `inspect trace anomalies` — what, if anything, is still running or hung in the process — was handy enough that it deserves first-class affordances rather than prompt lore. This section designs those affordances; nothing here is implemented yet. + +**The gap.** The control channel's read surface answers *what* is stalled but not *why*. `sample list` carries `last_activity_at` / idle time; `sample events` shows the transcript tail — but both share a documented blind spot (see the `GET /evals//samples` note in Phase 1): a single in-flight operation emits no transcript event until it returns, so a sample idle for twenty minutes reads identically whether it's a long-but-healthy model call, a hung sandbox exec, or a wedged process. The trace log is exactly the layer below the transcript: every `trace_action` in the process (model generates, subprocess execs, sandbox operations, log writes, ...) logs `enter` / `exit` / `cancel` / `error` / `timeout` records to a per-process file, and the `inspect trace anomalies` reconstruction derives from them **what is still running right now** (entered, never exited — with live durations) plus what was cancelled, errored, or timed out. "Sample 5 idle 21m" plus "one `Model` action running 21m" is a diagnosis; either alone is a symptom. + +**What exists today** (outside `ctl`): the `inspect trace` command group — `list` (has `--json`), `dump` (JSON records, `--filter`), `http [--failed]`, and `anomalies [TRACE_FILE] [--filter] [--all]` (default buckets: running + cancelled actions; `--all` adds errors and timeouts). Trace files live at `/traces/trace-.log` — **pid-keyed, the same key as the control discovery files** — with the last 10 rotated (gzipped). Measured against the agent shape constraints, two gaps: + +- **No `--json` on `anomalies` (or `http`).** The anomalies output is a rich table exported *with ANSI styles* — the worst case for an agent parser. Constraint 1 says the JSON schema is the canonical shape and the human table a rendering of it; here there is no JSON shape at all. +- **No join from the `ctl` surface.** Nothing in `inspect ctl` mentions traces: the agent has to know the subsystem exists, map its task to a pid, and map the pid to a file. Today that knowledge arrives via the agent's prompt ("try `inspect trace anomalies`"), which is exactly what surface-level discoverability (`--help`, teach-through-the-error) is supposed to replace. + +**Design shape.** Two decisions, then the affordances. + +1. **Client-side file read — deliberately no HTTP endpoint.** The prime scenario for anomalies is a process that is *unresponsive* — precisely the case where the control server (which shares the eval's loop; see "Busy is not absent") can't answer, so a `GET /trace/anomalies` would time out exactly when it matters most. The trace file needs no server participation: it's on local disk, pid-keyed, locatable from the same discovery files `ctl` already reads, and it outlives the process — a post-mortem "what was running when it died" works on a dead pid's file, which rotation preserves. So the affordance is CLI-side composition: resolve selector → pid → `trace-.log`, then run the same reconstruction `inspect trace anomalies` runs. Locality is not a new constraint — the CLI and the eval already share a machine by construction (AF_UNIX-only transport). If remote attach ever lands, the trace read is the one read that would need a server-side path; noted, not designed. + +2. **One reconstruction, two entry points.** The analysis stays in `inspect trace` (it isn't eval-specific — it works on any trace file, including rotated ones from long-dead processes); `ctl` adds a thin verb that resolves the selector and delegates to the same shared implementation function, so the two entry points can't drift into different answers. + +The affordances: + +- **`--json` on `inspect trace anomalies`** (the prerequisite for everything else; `http` should gain it in the same pass). An envelope, not bare buckets, per the agent output contract: `{"trace_file": ..., "as_of": , "running": [...], "cancelled": [...], "errors": [...], "timeouts": [...]}`, with per-action rows `{action, detail, start_time, duration, error?}`. `running` rows compute `duration` as now − `start_time` at read time (matching the human table). All four bucket keys always present — empty lists, never presence-conditional (same rule as unconditional `task_id` on sample rows). +- **`inspect ctl process anomalies [PID] [--all] [--json]`.** Noun placement per the CLI hierarchy: the object is the **process** — trace files are per-pid, and `trace_action` records carry no task or sample identity (a process hosts an eval-set's many tasks plus shared machinery: log writes, sandbox pulls, the control service itself), so attributing actions to a task would be guesswork the surface shouldn't fake. Selector conventions apply as a *read*: no `PID` widens over every discovered live process, one section (one JSON object) per pid, each carrying `pid` unconditionally (outputs feed inputs). Because the verb is client-side composition over discovery + the trace file, it — unlike every other `ctl` read — **works against a busy or hung process**: it is the natural escalation path for the "pid N busy — try again shortly" outcome documented under "Busy is not absent". Bucket defaults match `inspect trace anomalies` exactly (running + cancelled; `--all` opt-in), so the two entry points never answer the same question differently. +- **Teach through the surface at the stall site.** Where the human rendering already shows a stall — a `sample list` idle column in the tens of minutes, the busy-skip stderr note — print the pointer: "idle 27m — `inspect ctl process anomalies ` shows the process's in-flight actions". Same move as the group-level unknown-command handler: the surface teaches the escalation at the moment it's needed, instead of relying on the user (or the agent's system prompt) knowing the trace subsystem exists. On `--json` the hint is omitted (no prose inside envelopes); JSON consumers learn the verb from `--help`. + +**What this is not.** Not a new event stream — the trace file is already an append-only log with its own tooling (`trace dump --filter` remains the drill-down). Not a per-sample view — the records carry no sample identity, and if per-sample attribution ever matters the fix is upstream (stamp identity onto `trace_action` records), not heuristics in the reader. Not part of the HTTP API — deliberately, per decision 1. The `ctl` verb adds selector resolution and placement in the surface agents already discover; the analysis itself is unchanged. + +**Open questions.** + +- Should `sample show` on a long-idle sample *inline* the process's running actions (running the reconstruction server-side of the CLI, one fewer turn for the agent) rather than just printing the pointer? Inlining couples sample reads to trace-file parsing and re-raises the attribution problem (the actions shown belong to the process, not necessarily to that sample) — start with the pointer. +- Whether `ctl process anomalies` on a pid with *no* discovery file (process exited, file swept) should fall back to matching a rotated `trace-.log` for post-mortem reads, or leave dead-process forensics to `inspect trace anomalies ` directly. Leaning: allow it — the pid → file mapping is trivial and the post-mortem is a real agent scenario (eval died overnight; what was in flight?). + ### Security model The control endpoint is default-on and unauthenticated. That's a deliberate trade-off — given the threat model it's the right one, but it deserves a written account. @@ -878,6 +908,7 @@ Splitting push out from phase 2 keeps the agent-primary (cursored pull) surface - **Ordered eval-level lifecycle log** — a control-owned, hook-fed, cursored transition history (sample queued / started / finished / errored, eval finished, in order). Deliberately deferred from phase 2: the agent monitoring loop is served by the reads + the `samples` recency delta, so this is for audit / replay / a live-render TUI. When built it gets its own monotonic cursor (a sequence into the buffer, same opaque-token contract as the event stream) and feeds phase-4 push. Build it only when a concrete consumer needs the *ordered* history. - **TUI separation** — `inspect tui` as a standalone HTTP client of the control endpoint (plus an ACP client of the ACP socket for per-sample drill-down). Depends on the read + pull (phase 2) surfaces and, for live rendering, the phase-4 push surface (and, for an eval-level activity feed, the lifecycle log above). - **Eval-set-level read/direct** — an `EvalSetState` aggregate (doesn't exist today), `GET /eval-sets`, `GET /eval-sets/`, `POST /eval-sets//cancel`. Note eval-set *keep-alive* already works in phase 1 via the single-`eval()` lifecycle. +- **Trace-log anomalies affordances** — `--json` on `inspect trace anomalies`, an `inspect ctl process anomalies` verb (client-side trace-file read; deliberately no HTTP endpoint), and stall-site pointers — see "Trace-log anomalies for stall diagnosis". Independent of phases 3–4 (no server changes), so it can ship whenever prioritized. - **MCP server wrapper (`inspect mcp`)** — optional, built **only** if a specific gap emerges that Path A (CLI + `--json`) can't close. Reuses the phase 1–2 JSON schemas, so it's incremental rather than a parallel surface. ## Alternatives considered From b33253831579a5d46943383448f22ee158b012d3 Mon Sep 17 00:00:00 2001 From: Ransom Richardson Date: Thu, 16 Jul 2026 09:41:31 -0400 Subject: [PATCH 2/4] Address review: shared anomalies flags, dead-pid fallback, phase-3 slotting - ctl process anomalies mirrors every inspect trace anomalies flag (--filter included) via a shared click decorator so they can't drift - Resolve the dead-pid open question: fall back to trace-.log or .log.gz for post-mortem reads; fix the rotation-vs-gzip conflation - Slot the work into phase 3 (current phase), --json first; remove the post-phase-4 deferral and add the verb to the CLI listings Co-Authored-By: Claude Fable 5 --- design/control-channel.md | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/design/control-channel.md b/design/control-channel.md index e39dd71c66..e671adc819 100644 --- a/design/control-channel.md +++ b/design/control-channel.md @@ -8,7 +8,7 @@ This is **separate from** the [`agent-acp`](acp/agent-acp.md) work, even though The rudimentary control surface that fell out of the ACP work (per-sample cancellation, socket discovery via `--acp-server`) is a useful precedent but not the foundation — the control channel deserves its own protocol choice. -> **Status (phases 1–2 shipped).** The read surface, per-sample events, and process keep-alive are implemented: the embedded FastAPI server on AF_UNIX, discovery, the `GET /tasks` / `GET /evals//samples` (with an `active_since` recency delta) / `GET /evals//sample` / `GET /evals//sample/events` read endpoints, `POST /release`, the `inspect ctl` CLI (organized into resource-noun groups — `ctl task` / `ctl sample` / `ctl config` / `ctl process`; see "CLI command hierarchy" below), and the `--ctl-server` flag (on by default; `false` disables, `keep` parks the process after the eval). **Phase 2** added the cursored-pull per-sample transcript `events` API plus the recency-delta filter on `samples`. **Phase 3** (in progress) adds the state-mutating directives — the log-flush directive (`ctl task log-flush`), the dynamic-config directive (`ctl config` — the `max_samples` / `max_sandboxes` / `max_subprocesses` / `max_connections` concurrency knobs plus the `log_buffer` / `log_shared` buffer params), and the cancel directives (`ctl task cancel` / `ctl sample cancel`) are shipped; adding a task to a running eval, then drain / requeue and the per-sample time/token/message limits follow; **phase 4** adds the push (SSE / `--follow`) shape, including the eval-wide fan-in. Much of the prose below describes the full target surface — see [Implementation](#implementation) for what's built vs planned, which is the source of truth for phasing. +> **Status (phases 1–2 shipped).** The read surface, per-sample events, and process keep-alive are implemented: the embedded FastAPI server on AF_UNIX, discovery, the `GET /tasks` / `GET /evals//samples` (with an `active_since` recency delta) / `GET /evals//sample` / `GET /evals//sample/events` read endpoints, `POST /release`, the `inspect ctl` CLI (organized into resource-noun groups — `ctl task` / `ctl sample` / `ctl config` / `ctl process`; see "CLI command hierarchy" below), and the `--ctl-server` flag (on by default; `false` disables, `keep` parks the process after the eval). **Phase 2** added the cursored-pull per-sample transcript `events` API plus the recency-delta filter on `samples`. **Phase 3** (in progress) adds the state-mutating directives — the log-flush directive (`ctl task log-flush`), the dynamic-config directive (`ctl config` — the `max_samples` / `max_sandboxes` / `max_subprocesses` / `max_connections` concurrency knobs plus the `log_buffer` / `log_shared` buffer params), and the cancel directives (`ctl task cancel` / `ctl sample cancel`) are shipped; adding a task to a running eval, the trace-log anomalies affordances (`--json` on `inspect trace anomalies`, `ctl process anomalies`), then drain / requeue and the per-sample time/token/message limits follow; **phase 4** adds the push (SSE / `--follow`) shape, including the eval-wide fan-in. Much of the prose below describes the full target surface — see [Implementation](#implementation) for what's built vs planned, which is the source of truth for phasing. ## Goals @@ -83,7 +83,7 @@ inspect ctl process list # running Inspect processes (pid / k inspect ctl process keep [PID] # keep a running process alive after its eval finishes inspect ctl process release [PID] # release a lingering keep-alive process -# directives (phase 3; first slices shipped) +# directives + diagnostics (phase 3; first slices shipped) inspect ctl config [TASK] [--max-samples N] [--max-connections N] [--max-sandboxes N] [--max-subprocesses N] [--log-buffer N] [--log-shared S] [--model M] [--dry-run] # view / retune launch config mid-flight (shipped) @@ -94,6 +94,8 @@ inspect ctl task add SPEC [--model M] [-T k=v] [--dry-run] # add a task to a ru inspect ctl task drain TASK # stop accepting new samples; let in-flight finish inspect ctl sample requeue TASK SID EPOCH # re-add a failed sample to the queue inspect ctl config TASK --time-limit N # modify per-sample time/token/message limits (planned) +inspect ctl process anomalies [PID] [--filter TEXT] [--all] # in-flight / anomalous actions from the pid's trace file + # (client-side read — works against a busy or hung process) ``` Note the commands take a **task** selector (task-id prefix or task name), not a raw eval-id: a task id is stable across retries, whereas a per-attempt eval id is not. Process-lifecycle commands take a `PID` (optional when a single process is running). @@ -141,6 +143,7 @@ inspect ctl ├── config [TASK] [...] # was: limits + buffer; view/retune launch config, scope per knob ├── process # the running Inspect process itself (PID selector) │ ├── list # new: pids / keep-alive / hosted tasks (implied by bare `ctl process`) +│ ├── anomalies [PID] # planned: in-flight / anomalous actions from the trace file (client-side read) │ ├── keep [PID] # was: keep [--pid] │ └── release [PID] # was: release [--pid] └── eval-set # later, with the eval-set surface @@ -490,25 +493,26 @@ Each is a small surgical addition to the eval runner; the control channel is the ### Trace-log anomalies for stall diagnosis (planned) -Field feedback from agent-driven eval babysitting (JJ, via issue #81): telling the LLM agent about `inspect trace anomalies` — what, if anything, is still running or hung in the process — was handy enough that it deserves first-class affordances rather than prompt lore. This section designs those affordances; nothing here is implemented yet. +Field feedback from agent-driven eval babysitting (JJ, via issue #81): telling the LLM agent about `inspect trace anomalies` — what, if anything, is still running or hung in the process — was handy enough that it deserves first-class affordances rather than prompt lore. This section designs those affordances; nothing here is implemented yet. Slotted into **phase 3** (the current phase) rather than after phase 4 — it needs no server changes, so it doesn't have to wait on the push work; `--json` on `inspect trace anomalies` is the first slice, then the `ctl` verb and the stall-site pointers. **The gap.** The control channel's read surface answers *what* is stalled but not *why*. `sample list` carries `last_activity_at` / idle time; `sample events` shows the transcript tail — but both share a documented blind spot (see the `GET /evals//samples` note in Phase 1): a single in-flight operation emits no transcript event until it returns, so a sample idle for twenty minutes reads identically whether it's a long-but-healthy model call, a hung sandbox exec, or a wedged process. The trace log is exactly the layer below the transcript: every `trace_action` in the process (model generates, subprocess execs, sandbox operations, log writes, ...) logs `enter` / `exit` / `cancel` / `error` / `timeout` records to a per-process file, and the `inspect trace anomalies` reconstruction derives from them **what is still running right now** (entered, never exited — with live durations) plus what was cancelled, errored, or timed out. "Sample 5 idle 21m" plus "one `Model` action running 21m" is a diagnosis; either alone is a symptom. -**What exists today** (outside `ctl`): the `inspect trace` command group — `list` (has `--json`), `dump` (JSON records, `--filter`), `http [--failed]`, and `anomalies [TRACE_FILE] [--filter] [--all]` (default buckets: running + cancelled actions; `--all` adds errors and timeouts). Trace files live at `/traces/trace-.log` — **pid-keyed, the same key as the control discovery files** — with the last 10 rotated (gzipped). Measured against the agent shape constraints, two gaps: +**What exists today** (outside `ctl`): the `inspect trace` command group — `list` (has `--json`), `dump` (JSON records, `--filter`), `http [--failed]`, and `anomalies [TRACE_FILE] [--filter] [--all]` (default buckets: running + cancelled actions; `--all` adds errors and timeouts). Trace files live at `/traces/trace-.log` — **pid-keyed, the same key as the control discovery files**. Two separate housekeeping mechanisms apply (easy to conflate): a keep-newest-10 **rotation** sweep at logger init deletes the oldest files, and an `atexit` hook **gzips** the file to `trace-.log.gz` on clean exit — so a live or hard-killed process leaves a bare `.log`, a cleanly-exited one a `.log.gz` (which `read_trace_file` reads transparently). Measured against the agent shape constraints, two gaps: - **No `--json` on `anomalies` (or `http`).** The anomalies output is a rich table exported *with ANSI styles* — the worst case for an agent parser. Constraint 1 says the JSON schema is the canonical shape and the human table a rendering of it; here there is no JSON shape at all. - **No join from the `ctl` surface.** Nothing in `inspect ctl` mentions traces: the agent has to know the subsystem exists, map its task to a pid, and map the pid to a file. Today that knowledge arrives via the agent's prompt ("try `inspect trace anomalies`"), which is exactly what surface-level discoverability (`--help`, teach-through-the-error) is supposed to replace. **Design shape.** Two decisions, then the affordances. -1. **Client-side file read — deliberately no HTTP endpoint.** The prime scenario for anomalies is a process that is *unresponsive* — precisely the case where the control server (which shares the eval's loop; see "Busy is not absent") can't answer, so a `GET /trace/anomalies` would time out exactly when it matters most. The trace file needs no server participation: it's on local disk, pid-keyed, locatable from the same discovery files `ctl` already reads, and it outlives the process — a post-mortem "what was running when it died" works on a dead pid's file, which rotation preserves. So the affordance is CLI-side composition: resolve selector → pid → `trace-.log`, then run the same reconstruction `inspect trace anomalies` runs. Locality is not a new constraint — the CLI and the eval already share a machine by construction (AF_UNIX-only transport). If remote attach ever lands, the trace read is the one read that would need a server-side path; noted, not designed. +1. **Client-side file read — deliberately no HTTP endpoint.** The prime scenario for anomalies is a process that is *unresponsive* — precisely the case where the control server (which shares the eval's loop; see "Busy is not absent") can't answer, so a `GET /trace/anomalies` would time out exactly when it matters most. The trace file needs no server participation: it's on local disk, pid-keyed, locatable from the same discovery files `ctl` already reads, and it outlives the process — a post-mortem "what was running when it died" works on a dead pid's file (as `.log` or, after a clean exit, `.log.gz`), which survives until the keep-newest-10 rotation sweep reaches it. So the affordance is CLI-side composition: resolve selector → pid → `trace-.log`, then run the same reconstruction `inspect trace anomalies` runs. Locality is not a new constraint — the CLI and the eval already share a machine by construction (AF_UNIX-only transport). If remote attach ever lands, the trace read is the one read that would need a server-side path; noted, not designed. 2. **One reconstruction, two entry points.** The analysis stays in `inspect trace` (it isn't eval-specific — it works on any trace file, including rotated ones from long-dead processes); `ctl` adds a thin verb that resolves the selector and delegates to the same shared implementation function, so the two entry points can't drift into different answers. The affordances: - **`--json` on `inspect trace anomalies`** (the prerequisite for everything else; `http` should gain it in the same pass). An envelope, not bare buckets, per the agent output contract: `{"trace_file": ..., "as_of": , "running": [...], "cancelled": [...], "errors": [...], "timeouts": [...]}`, with per-action rows `{action, detail, start_time, duration, error?}`. `running` rows compute `duration` as now − `start_time` at read time (matching the human table). All four bucket keys always present — empty lists, never presence-conditional (same rule as unconditional `task_id` on sample rows). -- **`inspect ctl process anomalies [PID] [--all] [--json]`.** Noun placement per the CLI hierarchy: the object is the **process** — trace files are per-pid, and `trace_action` records carry no task or sample identity (a process hosts an eval-set's many tasks plus shared machinery: log writes, sandbox pulls, the control service itself), so attributing actions to a task would be guesswork the surface shouldn't fake. Selector conventions apply as a *read*: no `PID` widens over every discovered live process, one section (one JSON object) per pid, each carrying `pid` unconditionally (outputs feed inputs). Because the verb is client-side composition over discovery + the trace file, it — unlike every other `ctl` read — **works against a busy or hung process**: it is the natural escalation path for the "pid N busy — try again shortly" outcome documented under "Busy is not absent". Bucket defaults match `inspect trace anomalies` exactly (running + cancelled; `--all` opt-in), so the two entry points never answer the same question differently. +- **`inspect ctl process anomalies [PID] [--filter TEXT] [--all] [--json]`.** Noun placement per the CLI hierarchy: the object is the **process** — trace files are per-pid, and `trace_action` records carry no task or sample identity (a process hosts an eval-set's many tasks plus shared machinery: log writes, sandbox pulls, the control service itself), so attributing actions to a task would be guesswork the surface shouldn't fake. Selector conventions apply as a *read*: no `PID` widens over every discovered live process, one section (one JSON object) per pid, each carrying `pid` unconditionally (outputs feed inputs). Because the verb is client-side composition over discovery + the trace file, it — unlike every other `ctl` read — **works against a busy or hung process**: it is the natural escalation path for the "pid N busy — try again shortly" outcome documented under "Busy is not absent". The verb mirrors **every** `inspect trace anomalies` flag — `--filter` (substring match on the message field), `--all` (running + cancelled by default; errors and timeouts opt-in), and the new `--json` — and the mirroring is structural, not conventional: the options are defined once as a shared click decorator applied to both commands (the same "one reconstruction" move as decision 2, at the flag layer), so the two entry points can't drift as flags are added. +- **Dead-pid post-mortem fallback.** `ctl process anomalies ` on a pid with *no* discovery file (process exited, discovery swept) falls back to the trace file directly when it can find one — matching both `trace-.log` (still-live or hard-killed process) and `trace-.log.gz` (clean exit gzips via the `atexit` hook; the shared reader handles `.gz` transparently). The pid → file mapping is trivial and the post-mortem is a real agent scenario: eval died overnight — what was in flight when it died? Only when neither file exists (swept by rotation) does the verb error, naming the path it looked for so the user can hunt for a copy and hand it to `inspect trace anomalies ` directly. - **Teach through the surface at the stall site.** Where the human rendering already shows a stall — a `sample list` idle column in the tens of minutes, the busy-skip stderr note — print the pointer: "idle 27m — `inspect ctl process anomalies ` shows the process's in-flight actions". Same move as the group-level unknown-command handler: the surface teaches the escalation at the moment it's needed, instead of relying on the user (or the agent's system prompt) knowing the trace subsystem exists. On `--json` the hint is omitted (no prose inside envelopes); JSON consumers learn the verb from `--help`. **What this is not.** Not a new event stream — the trace file is already an append-only log with its own tooling (`trace dump --filter` remains the drill-down). Not a per-sample view — the records carry no sample identity, and if per-sample attribution ever matters the fix is upstream (stamp identity onto `trace_action` records), not heuristics in the reader. Not part of the HTTP API — deliberately, per decision 1. The `ctl` verb adds selector resolution and placement in the surface agents already discover; the analysis itself is unchanged. @@ -516,7 +520,6 @@ The affordances: **Open questions.** - Should `sample show` on a long-idle sample *inline* the process's running actions (running the reconstruction server-side of the CLI, one fewer turn for the agent) rather than just printing the pointer? Inlining couples sample reads to trace-file parsing and re-raises the attribution problem (the actions shown belong to the process, not necessarily to that sample) — start with the pointer. -- Whether `ctl process anomalies` on a pid with *no* discovery file (process exited, file swept) should fall back to matching a rotated `trace-.log` for post-mortem reads, or leave dead-process forensics to `inspect trace anomalies ` directly. Leaning: allow it — the pid → file mapping is trivial and the post-mortem is a real agent scenario (eval died overnight; what was in flight?). ### Security model @@ -775,6 +778,8 @@ Unlocks watchdog agents (cursored polling). Live-render TUIs follow once phase-4 The first endpoints that **mutate the run**, each idempotent and supporting `?dry_run=true` / `--dry-run` from day one. Shipped so far: the log-flush and buffer-params directives, the concurrency-config directive (`max_samples` / `max_sandboxes` / `max_subprocesses` / `max_connections`) — surfaced through `ctl task log-flush` and `ctl config` — and the cancel directives (`ctl task cancel` / `ctl sample cancel`); adding a task to a running eval, then drain / requeue and the per-sample time/token/message limits follow. The Security model's "future hardening" (SO_PEERCRED UID check, self-targeting guard) lands with this phase, since it introduces the first state-mutating writes. +This phase also carries the **trace-log anomalies affordances** (see "Trace-log anomalies for stall diagnosis") — not a directive, but scheduled here because the diagnosis need is current and the work touches no server code: `--json` on `inspect trace anomalies` (and `http`) first, then `inspect ctl process anomalies` (client-side trace-file read; deliberately no HTTP endpoint) and the stall-site pointers. + #### Flush buffered samples + tune buffer params (shipped) Two small, naturally-idempotent buffer directives shipped ahead of the larger phase-3 work, motivated by long S3-backed runs whose completed samples sit in the local flush buffer (and aren't analyzable in the log) until enough queue up to trigger a write: @@ -908,7 +913,6 @@ Splitting push out from phase 2 keeps the agent-primary (cursored pull) surface - **Ordered eval-level lifecycle log** — a control-owned, hook-fed, cursored transition history (sample queued / started / finished / errored, eval finished, in order). Deliberately deferred from phase 2: the agent monitoring loop is served by the reads + the `samples` recency delta, so this is for audit / replay / a live-render TUI. When built it gets its own monotonic cursor (a sequence into the buffer, same opaque-token contract as the event stream) and feeds phase-4 push. Build it only when a concrete consumer needs the *ordered* history. - **TUI separation** — `inspect tui` as a standalone HTTP client of the control endpoint (plus an ACP client of the ACP socket for per-sample drill-down). Depends on the read + pull (phase 2) surfaces and, for live rendering, the phase-4 push surface (and, for an eval-level activity feed, the lifecycle log above). - **Eval-set-level read/direct** — an `EvalSetState` aggregate (doesn't exist today), `GET /eval-sets`, `GET /eval-sets/`, `POST /eval-sets//cancel`. Note eval-set *keep-alive* already works in phase 1 via the single-`eval()` lifecycle. -- **Trace-log anomalies affordances** — `--json` on `inspect trace anomalies`, an `inspect ctl process anomalies` verb (client-side trace-file read; deliberately no HTTP endpoint), and stall-site pointers — see "Trace-log anomalies for stall diagnosis". Independent of phases 3–4 (no server changes), so it can ship whenever prioritized. - **MCP server wrapper (`inspect mcp`)** — optional, built **only** if a specific gap emerges that Path A (CLI + `--json`) can't close. Reuses the phase 1–2 JSON schemas, so it's incremental rather than a parallel surface. ## Alternatives considered From 0ef100dba00e28d576bc5e723c288b522c0945df Mon Sep 17 00:00:00 2001 From: "claude[bot]" <41898282+claude[bot]@users.noreply.github.com> Date: Thu, 16 Jul 2026 14:13:11 +0000 Subject: [PATCH 3/4] Add --json to inspect trace anomalies and http First slice of the trace-log anomalies design (issue #81): both commands emit `{trace_file, as_of, ...}` envelopes per the agent output contract. Anomalies buckets (running/cancelled/errors/timeouts) are always present, rows are `{action, detail, start_time, duration, error?}` with running durations computed against `as_of`. Flags live in a shared `anomalies_options` decorator and the reconstruction in a shared `_trace_anomalies` function, ready for the planned `inspect ctl process anomalies` to reuse. Co-authored-by: Ransom Richardson <1209015+ransomr@users.noreply.github.com> Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 1 + design/control-channel.md | 8 +- src/inspect_ai/_cli/trace.py | 252 ++++++++++++++++++++++++++--------- tests/cli/test_cli_trace.py | 203 ++++++++++++++++++++++++++++ 4 files changed, 394 insertions(+), 70 deletions(-) create mode 100644 tests/cli/test_cli_trace.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 9fcedf9205..09ebbf5fca 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,7 @@ - Control Channel: `inspect ctl sample events` now accepts `--type all` (shell-safe spelling of `--type '*'`) and `--from-start` to read the full backlog from the first event. - Control Channel: `inspect ctl sample events` gains `--limit N` to cap the events returned per page (combinable with `--from-start`, `--tail`, or a cursor). - Control Channel: New `--json` flag for `inspect eval`, `inspect eval-set`, and `inspect eval-retry` emits machine-readable launch-handoff and `done` JSON lines on stdout, so agents can use `inspect ctl` immediately after launch instead of sleep-and-retrying. +- CLI: `inspect trace anomalies` and `inspect trace http` gain a `--json` flag emitting machine-readable output for agents and shell pipelines. - CLI: `--debug` attach diagnostics ("Waiting for debugger attach") now print to stderr, keeping stdout clean for machine-readable output such as `--json`. - Control Channel: `inspect ctl sample show` now reads the sample's summary and error detail in one atomic request, so its output can no longer mix data from different attempts. - Control Channel: `inspect ctl sample show` now reports a cancelled sample as `cancelled`/`pending` (matching `sample list`) instead of `error` with the cancellation as its error. diff --git a/design/control-channel.md b/design/control-channel.md index ec6911a777..931ce7be81 100644 --- a/design/control-channel.md +++ b/design/control-channel.md @@ -494,13 +494,13 @@ Each is a small surgical addition to the eval runner; the control channel is the ### Trace-log anomalies for stall diagnosis (planned) -Field feedback from agent-driven eval babysitting (JJ, via issue #81): telling the LLM agent about `inspect trace anomalies` — what, if anything, is still running or hung in the process — was handy enough that it deserves first-class affordances rather than prompt lore. This section designs those affordances; nothing here is implemented yet. Slotted into **phase 3** (the current phase) rather than after phase 4 — it needs no server changes, so it doesn't have to wait on the push work; `--json` on `inspect trace anomalies` is the first slice, then the `ctl` verb and the stall-site pointers. +Field feedback from agent-driven eval babysitting (JJ, via issue #81): telling the LLM agent about `inspect trace anomalies` — what, if anything, is still running or hung in the process — was handy enough that it deserves first-class affordances rather than prompt lore. This section designs those affordances; the first slice — `--json` on `inspect trace anomalies` and `http` — has shipped, the rest is not implemented yet. Slotted into **phase 3** (the current phase) rather than after phase 4 — it needs no server changes, so it doesn't have to wait on the push work; the `ctl` verb and the stall-site pointers follow. **The gap.** The control channel's read surface answers *what* is stalled but not *why*. `sample list` carries `last_activity_at` / idle time; `sample events` shows the transcript tail — but both share a documented blind spot (see the `GET /evals//samples` note in Phase 1): a single in-flight operation emits no transcript event until it returns, so a sample idle for twenty minutes reads identically whether it's a long-but-healthy model call, a hung sandbox exec, or a wedged process. The trace log is exactly the layer below the transcript: every `trace_action` in the process (model generates, subprocess execs, sandbox operations, log writes, ...) logs `enter` / `exit` / `cancel` / `error` / `timeout` records to a per-process file, and the `inspect trace anomalies` reconstruction derives from them **what is still running right now** (entered, never exited — with live durations) plus what was cancelled, errored, or timed out. "Sample 5 idle 21m" plus "one `Model` action running 21m" is a diagnosis; either alone is a symptom. **What exists today** (outside `ctl`): the `inspect trace` command group — `list` (has `--json`), `dump` (JSON records, `--filter`), `http [--failed]`, and `anomalies [TRACE_FILE] [--filter] [--all]` (default buckets: running + cancelled actions; `--all` adds errors and timeouts). Trace files live at `/traces/trace-.log` — **pid-keyed, the same key as the control discovery files**. Two separate housekeeping mechanisms apply (easy to conflate): a keep-newest-10 **rotation** sweep at logger init deletes the oldest files, and an `atexit` hook **gzips** the file to `trace-.log.gz` on clean exit — so a live or hard-killed process leaves a bare `.log`, a cleanly-exited one a `.log.gz` (which `read_trace_file` reads transparently). Measured against the agent shape constraints, two gaps: -- **No `--json` on `anomalies` (or `http`).** The anomalies output is a rich table exported *with ANSI styles* — the worst case for an agent parser. Constraint 1 says the JSON schema is the canonical shape and the human table a rendering of it; here there is no JSON shape at all. +- **No `--json` on `anomalies` (or `http`).** The anomalies output is a rich table exported *with ANSI styles* — the worst case for an agent parser. Constraint 1 says the JSON schema is the canonical shape and the human table a rendering of it; here there is no JSON shape at all. *(Closed: both commands now take `--json`, per the first affordance below.)* - **No join from the `ctl` surface.** Nothing in `inspect ctl` mentions traces: the agent has to know the subsystem exists, map its task to a pid, and map the pid to a file. Today that knowledge arrives via the agent's prompt ("try `inspect trace anomalies`"), which is exactly what surface-level discoverability (`--help`, teach-through-the-error) is supposed to replace. **Design shape.** Two decisions, then the affordances. @@ -511,7 +511,7 @@ Field feedback from agent-driven eval babysitting (JJ, via issue #81): telling t The affordances: -- **`--json` on `inspect trace anomalies`** (the prerequisite for everything else; `http` should gain it in the same pass). An envelope, not bare buckets, per the agent output contract: `{"trace_file": ..., "as_of": , "running": [...], "cancelled": [...], "errors": [...], "timeouts": [...]}`, with per-action rows `{action, detail, start_time, duration, error?}`. `running` rows compute `duration` as now − `start_time` at read time (matching the human table). All four bucket keys always present — empty lists, never presence-conditional (same rule as unconditional `task_id` on sample rows). +- **`--json` on `inspect trace anomalies`** (the prerequisite for everything else; `http` gained it in the same pass). **Shipped.** An envelope, not bare buckets, per the agent output contract: `{"trace_file": ..., "as_of": , "running": [...], "cancelled": [...], "errors": [...], "timeouts": [...]}`, with per-action rows `{action, detail, start_time, duration, error?}`. `running` rows compute `duration` as now − `start_time` at read time (matching the human table). All four bucket keys always present — empty lists, never presence-conditional (same rule as unconditional `task_id` on sample rows). - **`inspect ctl process anomalies [PID] [--filter TEXT] [--all] [--json]`.** Noun placement per the CLI hierarchy: the object is the **process** — trace files are per-pid, and `trace_action` records carry no task or sample identity (a process hosts an eval-set's many tasks plus shared machinery: log writes, sandbox pulls, the control service itself), so attributing actions to a task would be guesswork the surface shouldn't fake. Selector conventions apply as a *read*: no `PID` widens over every discovered live process, one section (one JSON object) per pid, each carrying `pid` unconditionally (outputs feed inputs). Because the verb is client-side composition over discovery + the trace file, it — unlike every other `ctl` read — **works against a busy or hung process**: it is the natural escalation path for the "pid N busy — try again shortly" outcome documented under "Busy is not absent". The verb mirrors **every** `inspect trace anomalies` flag — `--filter` (substring match on the message field), `--all` (running + cancelled by default; errors and timeouts opt-in), and the new `--json` — and the mirroring is structural, not conventional: the options are defined once as a shared click decorator applied to both commands (the same "one reconstruction" move as decision 2, at the flag layer), so the two entry points can't drift as flags are added. - **Dead-pid post-mortem fallback.** `ctl process anomalies ` on a pid with *no* discovery file (process exited, discovery swept) falls back to the trace file directly when it can find one — matching both `trace-.log` (still-live or hard-killed process) and `trace-.log.gz` (clean exit gzips via the `atexit` hook; the shared reader handles `.gz` transparently). The pid → file mapping is trivial and the post-mortem is a real agent scenario: eval died overnight — what was in flight when it died? Only when neither file exists (swept by rotation) does the verb error, naming the path it looked for so the user can hunt for a copy and hand it to `inspect trace anomalies ` directly. - **Teach through the surface at the stall site.** Where the human rendering already shows a stall — a `sample list` idle column in the tens of minutes, the busy-skip stderr note — print the pointer: "idle 27m — `inspect ctl process anomalies ` shows the process's in-flight actions". Same move as the group-level unknown-command handler: the surface teaches the escalation at the moment it's needed, instead of relying on the user (or the agent's system prompt) knowing the trace subsystem exists. On `--json` the hint is omitted (no prose inside envelopes); JSON consumers learn the verb from `--help`. @@ -779,7 +779,7 @@ Unlocks watchdog agents (cursored polling). Live-render TUIs follow once phase-4 The first endpoints that **mutate the run**, each idempotent and supporting `?dry_run=true` / `--dry-run` from day one. Shipped so far: the log-flush and buffer-params directives, the concurrency-config directive (`max_samples` / `max_sandboxes` / `max_subprocesses` / `max_connections`) — surfaced through `ctl task log-flush` and `ctl config` — and the cancel directives (`ctl task cancel` / `ctl sample cancel`); adding a task to a running eval, then drain / requeue and the per-sample time/token/message limits follow. The Security model's "future hardening" (SO_PEERCRED UID check, self-targeting guard) lands with this phase, since it introduces the first state-mutating writes. -This phase also carries the **trace-log anomalies affordances** (see "Trace-log anomalies for stall diagnosis") — not a directive, but scheduled here because the diagnosis need is current and the work touches no server code: `--json` on `inspect trace anomalies` (and `http`) first, then `inspect ctl process anomalies` (client-side trace-file read; deliberately no HTTP endpoint) and the stall-site pointers. +This phase also carries the **trace-log anomalies affordances** (see "Trace-log anomalies for stall diagnosis") — not a directive, but scheduled here because the diagnosis need is current and the work touches no server code: `--json` on `inspect trace anomalies` (and `http`) first (shipped), then `inspect ctl process anomalies` (client-side trace-file read; deliberately no HTTP endpoint) and the stall-site pointers. #### Flush buffered samples + tune buffer params (shipped) diff --git a/src/inspect_ai/_cli/trace.py b/src/inspect_ai/_cli/trace.py index 537b4e2e8e..69cab28fde 100644 --- a/src/inspect_ai/_cli/trace.py +++ b/src/inspect_ai/_cli/trace.py @@ -4,9 +4,10 @@ from datetime import datetime from json import dumps from pathlib import Path -from typing import Callable +from typing import Callable, NamedTuple import click +from pydantic import JsonValue from pydantic_core import to_json from rich import print as r_print from rich.console import Console, RenderableType @@ -111,25 +112,51 @@ def dump_command_impl( default=False, help="Show only failed HTTP requests (non-200 status)", ) -def http_command(trace_file: str | None, filter: str | None, failed: bool) -> None: +@click.option( + "--json", + type=bool, + is_flag=True, + default=False, + help="Output as JSON (a `{trace_file, as_of, requests}` envelope).", +) +def http_command( + trace_file: str | None, filter: str | None, failed: bool, json: bool +) -> None: """View all HTTP requests in the trace log.""" - http_command_impl(trace_file, filter, failed) + http_command_impl(trace_file, filter, failed, json) def http_command_impl( trace_file: str | None, filter: str | None, failed: bool, + json: bool = False, trace_dir: Path | None = None, ) -> None: """View all HTTP requests in the trace log.""" - _, traces = _read_traces(trace_file, "HTTP", filter, trace_dir) + trace_file_path, traces = _read_traces(trace_file, "HTTP", filter, trace_dir) + + requests = [trace for trace in traces if not (failed and "200 OK" in trace.message)] + + if json: + print( + dumps( + { + "trace_file": trace_file_path.as_posix(), + "as_of": time.time(), + "requests": [ + {"timestamp": trace.timestamp, "message": trace.message} + for trace in requests + ], + }, + indent=2, + ) + ) + return last_timestamp = "" table = Table(Column(), Column(), box=None) - for trace in traces: - if failed and "200 OK" in trace.message: - continue + for trace in requests: timestamp = trace.timestamp.split(".")[0] if timestamp == last_timestamp: timestamp = "" @@ -142,30 +169,131 @@ def http_command_impl( r_print(table) +def anomalies_options(func: Callable[..., None]) -> Callable[..., None]: + """Flags for anomaly-reading commands. + + Single home for the options of `inspect trace anomalies` and the planned + `inspect ctl process anomalies` so the two entry points cannot drift as + flags are added (see "Trace-log anomalies for stall diagnosis" in + design/control-channel.md). + """ + func = click.option( + "--json", + type=bool, + is_flag=True, + default=False, + help="Output as JSON (a `{trace_file, as_of, running, cancelled, errors, timeouts}` envelope).", + )(func) + func = click.option( + "--all", + is_flag=True, + default=False, + help="Show all anomolies including errors and timeouts (by default only still running and cancelled actions are shown).", + )(func) + func = click.option( + "--filter", + type=str, + help="Filter (applied to trace message field).", + )(func) + return func + + @trace_command.command("anomalies") @click.argument("trace-file", type=str, required=False) -@click.option( - "--filter", - type=str, - help="Filter (applied to trace message field).", -) -@click.option( - "--all", - is_flag=True, - default=False, - help="Show all anomolies including errors and timeouts (by default only still running and cancelled actions are shown).", -) -def anomolies_command(trace_file: str | None, filter: str | None, all: bool) -> None: +@anomalies_options +def anomolies_command( + trace_file: str | None, filter: str | None, all: bool, json: bool +) -> None: """Look for anomalies in a trace file (never completed or cancelled actions).""" - anomolies_command_impl(trace_file, filter, all) + anomolies_command_impl(trace_file, filter, all, json) + + +class TraceAnomalies(NamedTuple): + """Anomalous actions from a trace file, bucketed by outcome. + + Buckets are sorted most recently finished first (running actions by start + time). ``errors`` and ``timeouts`` are collected only when requested via + ``all`` (they are empty lists otherwise). + """ + + running: list[ActionTraceRecord] + cancelled: list[ActionTraceRecord] + errors: list[ActionTraceRecord] + timeouts: list[ActionTraceRecord] def anomolies_command_impl( - trace_file: str | None, filter: str | None, all: bool, trace_dir: Path | None = None + trace_file: str | None, + filter: str | None, + all: bool, + json: bool = False, + trace_dir: Path | None = None, ) -> None: """Look for anomalies in a trace file (never completed or cancelled actions).""" trace_file_path, traces = _read_traces(trace_file, None, filter, trace_dir) + anomalies = _trace_anomalies(traces, all) + if json: + # stamp as_of once and compute running durations against it so the + # envelope timestamp and the durations it dates are consistent + as_of = time.time() + print( + dumps( + { + "trace_file": trace_file_path.as_posix(), + "as_of": as_of, + "running": [_anomaly_row(a, as_of) for a in anomalies.running], + "cancelled": [_anomaly_row(a, as_of) for a in anomalies.cancelled], + "errors": [_anomaly_row(a, as_of) for a in anomalies.errors], + "timeouts": [_anomaly_row(a, as_of) for a in anomalies.timeouts], + }, + indent=2, + ) + ) + return + + # do we have any traces? + if ( + len(anomalies.running) + + len(anomalies.cancelled) + + len(anomalies.errors) + + len(anomalies.timeouts) + == 0 + ): + print(f"TRACE: {shlex.quote(trace_file_path.as_posix())}\n") + if all: + print("No anomalies found in trace log.") + else: + print( + "No running or cancelled actions found in trace log (pass --all to see errors and timeouts)." + ) + return + + with open(os.devnull, "w") as f: + # generate output + console = Console(record=True, file=f) + + def print_fn(o: RenderableType) -> None: + console.print(o, highlight=False) + + print_fn(f"[bold]TRACE: {shlex.quote(trace_file_path.as_posix())}[/bold]") + + _print_bucket(print_fn, "Running Actions", anomalies.running) + _print_bucket(print_fn, "Cancelled Actions", anomalies.cancelled) + _print_bucket(print_fn, "Error Actions", anomalies.errors) + _print_bucket(print_fn, "Timeout Actions", anomalies.timeouts) + + # print + print(console.export_text(styles=True).strip()) + + +def _trace_anomalies(traces: list[TraceRecord], all: bool) -> TraceAnomalies: + """Reconstruct anomalous actions (never exited, cancelled, errored, timed out) from trace records. + + Shared by the human and JSON renderings of `inspect trace anomalies` (and, + per the design, the planned `inspect ctl process anomalies`) so every entry + point derives the same answer from the same records. + """ # Track started actions running_actions: dict[str, ActionTraceRecord] = {} canceled_actions: dict[str, ActionTraceRecord] = {} @@ -224,39 +352,44 @@ def action_timeout(trace: ActionTraceRecord) -> None: case _: print(f"Unknown event type: {trace.event}") - # do we have any traces? - if ( - len(running_actions) - + len(canceled_actions) - + len(error_actions) - + len(timeout_actions) - == 0 - ): - print(f"TRACE: {shlex.quote(trace_file_path.as_posix())}\n") - if all: - print("No anomalies found in trace log.") - else: - print( - "No running or cancelled actions found in trace log (pass --all to see errors and timeouts)." - ) - return + return TraceAnomalies( + running=_sorted_actions(running_actions), + cancelled=_sorted_actions(canceled_actions), + errors=_sorted_actions(error_actions), + timeouts=_sorted_actions(timeout_actions), + ) - with open(os.devnull, "w") as f: - # generate output - console = Console(record=True, file=f) - def print_fn(o: RenderableType) -> None: - console.print(o, highlight=False) +def _sorted_actions(bucket: dict[str, ActionTraceRecord]) -> list[ActionTraceRecord]: + # Sort the items in chronological order of when + # they finished so the first finished item is at the top + return sorted( + bucket.values(), + key=lambda record: (record.start_time or 0) + (record.duration or 0), + reverse=True, + ) - print_fn(f"[bold]TRACE: {shlex.quote(trace_file_path.as_posix())}[/bold]") - _print_bucket(print_fn, "Running Actions", running_actions) - _print_bucket(print_fn, "Cancelled Actions", canceled_actions) - _print_bucket(print_fn, "Error Actions", error_actions) - _print_bucket(print_fn, "Timeout Actions", timeout_actions) +def _action_duration(action: ActionTraceRecord, as_of: float) -> float: + """Duration of the action: the recorded duration for finished actions, time since start (as of `as_of`) for still-running ones.""" + if action.duration is not None: + return action.duration + elif action.start_time is not None: + return as_of - action.start_time + else: + return 0.0 + - # print - print(console.export_text(styles=True).strip()) +def _anomaly_row(action: ActionTraceRecord, as_of: float) -> dict[str, JsonValue]: + row: dict[str, JsonValue] = { + "action": action.action, + "detail": action.detail or action.message, + "start_time": action.start_time, + "duration": _action_duration(action, as_of), + } + if action.error is not None: + row["error"] = action.error + return row def _read_traces( @@ -281,17 +414,9 @@ def _read_traces( def _print_bucket( print_fn: Callable[[RenderableType], None], label: str, - bucket: dict[str, ActionTraceRecord], + sorted_actions: list[ActionTraceRecord], ) -> None: - if len(bucket) > 0: - # Sort the items in chronological order of when - # they finished so the first finished item is at the top - sorted_actions = sorted( - bucket.values(), - key=lambda record: (record.start_time or 0) + (record.duration or 0), - reverse=True, - ) - + if len(sorted_actions) > 0: # create table table = Table( Column(""), @@ -306,15 +431,10 @@ def _print_bucket( padding=(0, 1), ) + now = time.time() for action in sorted_actions: # Compute duration (use the event duration or time since started) - duration = ( - action.duration - if action.duration is not None - else time.time() - action.start_time - if action.start_time is not None - else 0.0 - ) + duration = _action_duration(action, now) # The event start time start_time = formatTime(action.start_time) if action.start_time else "None" diff --git a/tests/cli/test_cli_trace.py b/tests/cli/test_cli_trace.py new file mode 100644 index 0000000000..d94376d111 --- /dev/null +++ b/tests/cli/test_cli_trace.py @@ -0,0 +1,203 @@ +import json +import time +from pathlib import Path +from typing import Any + +import pytest + +from inspect_ai._cli.trace import anomolies_command_impl, http_command_impl + + +def write_trace_log(file: Path, records: list[dict[str, Any]]) -> None: + with open(file, "w") as f: + for record in records: + f.write(json.dumps(record) + "\n") + + +def action_record( + trace_id: str, + action: str, + event: str, + *, + detail: str = "", + start_time: float | None = None, + duration: float | None = None, + error: str | None = None, +) -> dict[str, Any]: + record: dict[str, Any] = { + "timestamp": "2026-07-16T12:00:00+00:00", + "level": "TRACE", + "message": f"{action}: {detail} ({event})", + "action": action, + "detail": detail, + "event": event, + "trace_id": trace_id, + } + if start_time is not None: + record["start_time"] = start_time + if duration is not None: + record["duration"] = duration + if error is not None: + record["error"] = error + return record + + +@pytest.fixture +def anomalies_trace_file(tmp_path: Path) -> Path: + start = time.time() - 120 + trace_file = tmp_path / "trace-123.log" + write_trace_log( + trace_file, + [ + # still running (enter, never exited) + action_record( + "run1", "Model", "enter", detail="generate", start_time=start + ), + # cancelled + action_record( + "can1", "Subprocess", "enter", detail="bash", start_time=start + ), + action_record("can1", "Subprocess", "cancel", detail="bash", duration=5.0), + # errored + action_record("err1", "Sandbox", "enter", detail="exec", start_time=start), + action_record( + "err1", "Sandbox", "error", detail="exec", duration=7.0, error="boom" + ), + # timed out + action_record( + "tmo1", "Model", "enter", detail="generate", start_time=start + ), + action_record("tmo1", "Model", "timeout", detail="generate", duration=9.0), + # completed normally (should never appear) + action_record("ok1", "Log", "enter", detail="write", start_time=start), + action_record("ok1", "Log", "exit", detail="write", duration=1.0), + ], + ) + return trace_file + + +def test_trace_anomalies_json( + anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] +) -> None: + anomolies_command_impl( + str(anomalies_trace_file), + filter=None, + all=False, + json=True, + trace_dir=anomalies_trace_file.parent, + ) + envelope = json.loads(capsys.readouterr().out) + + assert envelope["trace_file"] == anomalies_trace_file.as_posix() + assert isinstance(envelope["as_of"], float) + + # all four bucket keys always present; errors/timeouts empty without --all + assert [row["action"] for row in envelope["running"]] == ["Model"] + assert [row["action"] for row in envelope["cancelled"]] == ["Subprocess"] + assert envelope["errors"] == [] + assert envelope["timeouts"] == [] + + # running rows compute duration as as_of - start_time + running = envelope["running"][0] + assert running["detail"] == "generate" + assert running["duration"] == pytest.approx( + envelope["as_of"] - running["start_time"] + ) + assert "error" not in running + + # finished rows carry the recorded duration and the enter start_time + cancelled = envelope["cancelled"][0] + assert cancelled["duration"] == 5.0 + assert cancelled["start_time"] is not None + + +def test_trace_anomalies_json_all( + anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] +) -> None: + anomolies_command_impl( + str(anomalies_trace_file), + filter=None, + all=True, + json=True, + trace_dir=anomalies_trace_file.parent, + ) + envelope = json.loads(capsys.readouterr().out) + + assert [row["action"] for row in envelope["errors"]] == ["Sandbox"] + assert envelope["errors"][0]["error"] == "boom" + assert [row["action"] for row in envelope["timeouts"]] == ["Model"] + assert envelope["timeouts"][0]["duration"] == 9.0 + + +def test_trace_anomalies_json_empty( + tmp_path: Path, capsys: pytest.CaptureFixture[str] +) -> None: + trace_file = tmp_path / "trace-456.log" + write_trace_log( + trace_file, + [ + action_record("ok1", "Log", "enter", detail="write", start_time=1.0), + action_record("ok1", "Log", "exit", detail="write", duration=1.0), + ], + ) + anomolies_command_impl( + str(trace_file), filter=None, all=False, json=True, trace_dir=tmp_path + ) + envelope = json.loads(capsys.readouterr().out) + + # the envelope is emitted (not the human "no anomalies" prose), with all + # bucket keys present as empty lists + assert envelope["running"] == [] + assert envelope["cancelled"] == [] + assert envelope["errors"] == [] + assert envelope["timeouts"] == [] + + +def test_trace_anomalies_human_output( + anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] +) -> None: + anomolies_command_impl( + str(anomalies_trace_file), + filter=None, + all=False, + json=False, + trace_dir=anomalies_trace_file.parent, + ) + out = capsys.readouterr().out + assert "Running Actions" in out + assert "Cancelled Actions" in out + + +def http_record(timestamp: str, message: str) -> dict[str, Any]: + return {"timestamp": timestamp, "level": "HTTP", "message": message} + + +def test_trace_http_json(tmp_path: Path, capsys: pytest.CaptureFixture[str]) -> None: + trace_file = tmp_path / "trace-789.log" + write_trace_log( + trace_file, + [ + http_record("2026-07-16T12:00:00+00:00", "POST https://api - 200 OK"), + http_record("2026-07-16T12:00:01+00:00", "POST https://api - 429"), + ], + ) + + http_command_impl( + str(trace_file), filter=None, failed=False, json=True, trace_dir=tmp_path + ) + envelope = json.loads(capsys.readouterr().out) + assert envelope["trace_file"] == trace_file.as_posix() + assert isinstance(envelope["as_of"], float) + assert [request["message"] for request in envelope["requests"]] == [ + "POST https://api - 200 OK", + "POST https://api - 429", + ] + + # --failed drops 200 OK requests from the JSON output too + http_command_impl( + str(trace_file), filter=None, failed=True, json=True, trace_dir=tmp_path + ) + envelope = json.loads(capsys.readouterr().out) + assert [request["message"] for request in envelope["requests"]] == [ + "POST https://api - 429" + ] From 63b67f32d643aa36816027857ad358ac4647b6c6 Mon Sep 17 00:00:00 2001 From: "claude[bot]" <41898282+claude[bot]@users.noreply.github.com> Date: Thu, 16 Jul 2026 14:35:51 +0000 Subject: [PATCH 4/4] Address review: JSON always populates all buckets, help typo, filter crash - `inspect trace anomalies --json` now always populates the errors/timeouts buckets so an empty list always means "none occurred"; --all gates only the human rendering (design doc updated to match) - fix "anomolies" typo in the shared --all help text and rename the internal anomolies_command* functions - tolerate exit-side action records with no matching enter record (e.g. --filter matching only the exit side, or a truncated log) instead of crashing with RuntimeError Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 3 +- design/control-channel.md | 4 +- src/inspect_ai/_cli/trace.py | 117 ++++++++++++++--------------------- tests/cli/test_cli_trace.py | 52 +++++++++++++--- 4 files changed, 93 insertions(+), 83 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 09ebbf5fca..cc3e2a37e3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,7 +15,8 @@ - Control Channel: `inspect ctl sample events` now accepts `--type all` (shell-safe spelling of `--type '*'`) and `--from-start` to read the full backlog from the first event. - Control Channel: `inspect ctl sample events` gains `--limit N` to cap the events returned per page (combinable with `--from-start`, `--tail`, or a cursor). - Control Channel: New `--json` flag for `inspect eval`, `inspect eval-set`, and `inspect eval-retry` emits machine-readable launch-handoff and `done` JSON lines on stdout, so agents can use `inspect ctl` immediately after launch instead of sleep-and-retrying. -- CLI: `inspect trace anomalies` and `inspect trace http` gain a `--json` flag emitting machine-readable output for agents and shell pipelines. +- CLI: `inspect trace anomalies` and `inspect trace http` gain a `--json` flag emitting machine-readable output for agents and shell pipelines; the JSON always includes error/timeout buckets (no `--all` needed). +- CLI: `inspect trace anomalies` no longer errors when `--filter` matches an action's completion record but not its start record. - CLI: `--debug` attach diagnostics ("Waiting for debugger attach") now print to stderr, keeping stdout clean for machine-readable output such as `--json`. - Control Channel: `inspect ctl sample show` now reads the sample's summary and error detail in one atomic request, so its output can no longer mix data from different attempts. - Control Channel: `inspect ctl sample show` now reports a cancelled sample as `cancelled`/`pending` (matching `sample list`) instead of `error` with the cancellation as its error. diff --git a/design/control-channel.md b/design/control-channel.md index 931ce7be81..c4aec0de9a 100644 --- a/design/control-channel.md +++ b/design/control-channel.md @@ -511,8 +511,8 @@ Field feedback from agent-driven eval babysitting (JJ, via issue #81): telling t The affordances: -- **`--json` on `inspect trace anomalies`** (the prerequisite for everything else; `http` gained it in the same pass). **Shipped.** An envelope, not bare buckets, per the agent output contract: `{"trace_file": ..., "as_of": , "running": [...], "cancelled": [...], "errors": [...], "timeouts": [...]}`, with per-action rows `{action, detail, start_time, duration, error?}`. `running` rows compute `duration` as now − `start_time` at read time (matching the human table). All four bucket keys always present — empty lists, never presence-conditional (same rule as unconditional `task_id` on sample rows). -- **`inspect ctl process anomalies [PID] [--filter TEXT] [--all] [--json]`.** Noun placement per the CLI hierarchy: the object is the **process** — trace files are per-pid, and `trace_action` records carry no task or sample identity (a process hosts an eval-set's many tasks plus shared machinery: log writes, sandbox pulls, the control service itself), so attributing actions to a task would be guesswork the surface shouldn't fake. Selector conventions apply as a *read*: no `PID` widens over every discovered live process, one section (one JSON object) per pid, each carrying `pid` unconditionally (outputs feed inputs). Because the verb is client-side composition over discovery + the trace file, it — unlike every other `ctl` read — **works against a busy or hung process**: it is the natural escalation path for the "pid N busy — try again shortly" outcome documented under "Busy is not absent". The verb mirrors **every** `inspect trace anomalies` flag — `--filter` (substring match on the message field), `--all` (running + cancelled by default; errors and timeouts opt-in), and the new `--json` — and the mirroring is structural, not conventional: the options are defined once as a shared click decorator applied to both commands (the same "one reconstruction" move as decision 2, at the flag layer), so the two entry points can't drift as flags are added. +- **`--json` on `inspect trace anomalies`** (the prerequisite for everything else; `http` gained it in the same pass). **Shipped.** An envelope, not bare buckets, per the agent output contract: `{"trace_file": ..., "as_of": , "running": [...], "cancelled": [...], "errors": [...], "timeouts": [...]}`, with per-action rows `{action, detail, start_time, duration, error?}`. `running` rows compute `duration` as now − `start_time` at read time (matching the human table). All four bucket keys always present **and always populated** — `--all` gates only the human rendering, so in the envelope an empty list always means "none occurred", never "not collected" (an agent diagnosing a stall must not read "not asked" as "no errors"). Empty lists, never presence-conditional (same rule as unconditional `task_id` on sample rows). +- **`inspect ctl process anomalies [PID] [--filter TEXT] [--all] [--json]`.** Noun placement per the CLI hierarchy: the object is the **process** — trace files are per-pid, and `trace_action` records carry no task or sample identity (a process hosts an eval-set's many tasks plus shared machinery: log writes, sandbox pulls, the control service itself), so attributing actions to a task would be guesswork the surface shouldn't fake. Selector conventions apply as a *read*: no `PID` widens over every discovered live process, one section (one JSON object) per pid, each carrying `pid` unconditionally (outputs feed inputs). Because the verb is client-side composition over discovery + the trace file, it — unlike every other `ctl` read — **works against a busy or hung process**: it is the natural escalation path for the "pid N busy — try again shortly" outcome documented under "Busy is not absent". The verb mirrors **every** `inspect trace anomalies` flag — `--filter` (substring match on the message field), `--all` (human table shows running + cancelled by default, errors and timeouts opt-in; the JSON envelope always carries all four buckets), and the new `--json` — and the mirroring is structural, not conventional: the options are defined once as a shared click decorator applied to both commands (the same "one reconstruction" move as decision 2, at the flag layer), so the two entry points can't drift as flags are added. - **Dead-pid post-mortem fallback.** `ctl process anomalies ` on a pid with *no* discovery file (process exited, discovery swept) falls back to the trace file directly when it can find one — matching both `trace-.log` (still-live or hard-killed process) and `trace-.log.gz` (clean exit gzips via the `atexit` hook; the shared reader handles `.gz` transparently). The pid → file mapping is trivial and the post-mortem is a real agent scenario: eval died overnight — what was in flight when it died? Only when neither file exists (swept by rotation) does the verb error, naming the path it looked for so the user can hunt for a copy and hand it to `inspect trace anomalies ` directly. - **Teach through the surface at the stall site.** Where the human rendering already shows a stall — a `sample list` idle column in the tens of minutes, the busy-skip stderr note — print the pointer: "idle 27m — `inspect ctl process anomalies ` shows the process's in-flight actions". Same move as the group-level unknown-command handler: the surface teaches the escalation at the moment it's needed, instead of relying on the user (or the agent's system prompt) knowing the trace subsystem exists. On `--json` the hint is omitted (no prose inside envelopes); JSON consumers learn the verb from `--help`. diff --git a/src/inspect_ai/_cli/trace.py b/src/inspect_ai/_cli/trace.py index 69cab28fde..eb44c38afc 100644 --- a/src/inspect_ai/_cli/trace.py +++ b/src/inspect_ai/_cli/trace.py @@ -188,7 +188,7 @@ def anomalies_options(func: Callable[..., None]) -> Callable[..., None]: "--all", is_flag=True, default=False, - help="Show all anomolies including errors and timeouts (by default only still running and cancelled actions are shown).", + help="Show all anomalies including errors and timeouts (by default only still running and cancelled actions are shown; JSON output always includes all buckets).", )(func) func = click.option( "--filter", @@ -201,19 +201,20 @@ def anomalies_options(func: Callable[..., None]) -> Callable[..., None]: @trace_command.command("anomalies") @click.argument("trace-file", type=str, required=False) @anomalies_options -def anomolies_command( +def anomalies_command( trace_file: str | None, filter: str | None, all: bool, json: bool ) -> None: """Look for anomalies in a trace file (never completed or cancelled actions).""" - anomolies_command_impl(trace_file, filter, all, json) + anomalies_command_impl(trace_file, filter, all, json) class TraceAnomalies(NamedTuple): """Anomalous actions from a trace file, bucketed by outcome. Buckets are sorted most recently finished first (running actions by start - time). ``errors`` and ``timeouts`` are collected only when requested via - ``all`` (they are empty lists otherwise). + time). All four buckets are always collected; whether ``errors`` and + ``timeouts`` are *shown* is a rendering concern (the human table gates + them behind ``--all``, the JSON envelope always carries them). """ running: list[ActionTraceRecord] @@ -222,7 +223,7 @@ class TraceAnomalies(NamedTuple): timeouts: list[ActionTraceRecord] -def anomolies_command_impl( +def anomalies_command_impl( trace_file: str | None, filter: str | None, all: bool, @@ -231,7 +232,7 @@ def anomolies_command_impl( ) -> None: """Look for anomalies in a trace file (never completed or cancelled actions).""" trace_file_path, traces = _read_traces(trace_file, None, filter, trace_dir) - anomalies = _trace_anomalies(traces, all) + anomalies = _trace_anomalies(traces) if json: # stamp as_of once and compute running durations against it so the @@ -252,14 +253,22 @@ def anomolies_command_impl( ) return + # the buckets shown in the human rendering (--all gates errors/timeouts + # here only; the JSON envelope above always carries all four) + shown_buckets = [ + ("Running Actions", anomalies.running), + ("Cancelled Actions", anomalies.cancelled), + ] + if all: + shown_buckets.extend( + [ + ("Error Actions", anomalies.errors), + ("Timeout Actions", anomalies.timeouts), + ] + ) + # do we have any traces? - if ( - len(anomalies.running) - + len(anomalies.cancelled) - + len(anomalies.errors) - + len(anomalies.timeouts) - == 0 - ): + if sum(len(actions) for _, actions in shown_buckets) == 0: print(f"TRACE: {shlex.quote(trace_file_path.as_posix())}\n") if all: print("No anomalies found in trace log.") @@ -278,85 +287,49 @@ def print_fn(o: RenderableType) -> None: print_fn(f"[bold]TRACE: {shlex.quote(trace_file_path.as_posix())}[/bold]") - _print_bucket(print_fn, "Running Actions", anomalies.running) - _print_bucket(print_fn, "Cancelled Actions", anomalies.cancelled) - _print_bucket(print_fn, "Error Actions", anomalies.errors) - _print_bucket(print_fn, "Timeout Actions", anomalies.timeouts) + for label, actions in shown_buckets: + _print_bucket(print_fn, label, actions) # print print(console.export_text(styles=True).strip()) -def _trace_anomalies(traces: list[TraceRecord], all: bool) -> TraceAnomalies: +def _trace_anomalies(traces: list[TraceRecord]) -> TraceAnomalies: """Reconstruct anomalous actions (never exited, cancelled, errored, timed out) from trace records. Shared by the human and JSON renderings of `inspect trace anomalies` (and, per the design, the planned `inspect ctl process anomalies`) so every entry - point derives the same answer from the same records. + point derives the same answer from the same records. Exit-side records + with no matching enter record (e.g. `--filter` matched only the exit side, + or the log start was truncated) are still bucketed, without a + reconstructed start time. """ - # Track started actions running_actions: dict[str, ActionTraceRecord] = {} - canceled_actions: dict[str, ActionTraceRecord] = {} - error_actions: dict[str, ActionTraceRecord] = {} - timeout_actions: dict[str, ActionTraceRecord] = {} - start_trace: ActionTraceRecord | None = None - - def action_started(trace: ActionTraceRecord) -> None: - running_actions[trace.trace_id] = trace - - def action_completed(trace: ActionTraceRecord) -> ActionTraceRecord: - nonlocal start_trace - start_trace = running_actions.get(trace.trace_id) - if start_trace: - del running_actions[trace.trace_id] - return start_trace - else: - raise RuntimeError(f"Expected {trace.trace_id} in action dictionary.") - - def action_failed(trace: ActionTraceRecord) -> None: - nonlocal start_trace - if all: - assert start_trace - error_actions[start_trace.trace_id] = trace - - def action_canceled(trace: ActionTraceRecord) -> None: - nonlocal start_trace - assert start_trace - canceled_actions[start_trace.trace_id] = trace - - def action_timeout(trace: ActionTraceRecord) -> None: - nonlocal start_trace - if all: - assert start_trace - timeout_actions[start_trace.trace_id] = trace + finished_buckets: dict[str, dict[str, ActionTraceRecord]] = { + "cancel": {}, + "error": {}, + "timeout": {}, + } for trace in traces: if isinstance(trace, ActionTraceRecord): match trace.event: case "enter": - action_started(trace) - case "exit": - action_completed(trace) - case "cancel": - start_trace = action_completed(trace) - trace.start_time = start_trace.start_time - action_canceled(trace) - case "error": - start_trace = action_completed(trace) - trace.start_time = start_trace.start_time - action_failed(trace) - case "timeout": - start_trace = action_completed(trace) - trace.start_time = start_trace.start_time - action_timeout(trace) + running_actions[trace.trace_id] = trace + case "exit" | "cancel" | "error" | "timeout": + start_trace = running_actions.pop(trace.trace_id, None) + if trace.event != "exit": + if start_trace is not None: + trace.start_time = start_trace.start_time + finished_buckets[trace.event][trace.trace_id] = trace case _: print(f"Unknown event type: {trace.event}") return TraceAnomalies( running=_sorted_actions(running_actions), - cancelled=_sorted_actions(canceled_actions), - errors=_sorted_actions(error_actions), - timeouts=_sorted_actions(timeout_actions), + cancelled=_sorted_actions(finished_buckets["cancel"]), + errors=_sorted_actions(finished_buckets["error"]), + timeouts=_sorted_actions(finished_buckets["timeout"]), ) diff --git a/tests/cli/test_cli_trace.py b/tests/cli/test_cli_trace.py index d94376d111..7fd99dd863 100644 --- a/tests/cli/test_cli_trace.py +++ b/tests/cli/test_cli_trace.py @@ -5,7 +5,7 @@ import pytest -from inspect_ai._cli.trace import anomolies_command_impl, http_command_impl +from inspect_ai._cli.trace import anomalies_command_impl, http_command_impl def write_trace_log(file: Path, records: list[dict[str, Any]]) -> None: @@ -79,7 +79,7 @@ def anomalies_trace_file(tmp_path: Path) -> Path: def test_trace_anomalies_json( anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] ) -> None: - anomolies_command_impl( + anomalies_command_impl( str(anomalies_trace_file), filter=None, all=False, @@ -91,11 +91,12 @@ def test_trace_anomalies_json( assert envelope["trace_file"] == anomalies_trace_file.as_posix() assert isinstance(envelope["as_of"], float) - # all four bucket keys always present; errors/timeouts empty without --all + # all four buckets always populated, even without --all (which gates only + # the human rendering), so empty always means "none occurred" assert [row["action"] for row in envelope["running"]] == ["Model"] assert [row["action"] for row in envelope["cancelled"]] == ["Subprocess"] - assert envelope["errors"] == [] - assert envelope["timeouts"] == [] + assert [row["action"] for row in envelope["errors"]] == ["Sandbox"] + assert [row["action"] for row in envelope["timeouts"]] == ["Model"] # running rows compute duration as as_of - start_time running = envelope["running"][0] @@ -114,7 +115,7 @@ def test_trace_anomalies_json( def test_trace_anomalies_json_all( anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] ) -> None: - anomolies_command_impl( + anomalies_command_impl( str(anomalies_trace_file), filter=None, all=True, @@ -140,7 +141,7 @@ def test_trace_anomalies_json_empty( action_record("ok1", "Log", "exit", detail="write", duration=1.0), ], ) - anomolies_command_impl( + anomalies_command_impl( str(trace_file), filter=None, all=False, json=True, trace_dir=tmp_path ) envelope = json.loads(capsys.readouterr().out) @@ -156,7 +157,7 @@ def test_trace_anomalies_json_empty( def test_trace_anomalies_human_output( anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] ) -> None: - anomolies_command_impl( + anomalies_command_impl( str(anomalies_trace_file), filter=None, all=False, @@ -166,6 +167,41 @@ def test_trace_anomalies_human_output( out = capsys.readouterr().out assert "Running Actions" in out assert "Cancelled Actions" in out + # errors/timeouts are gated behind --all in the human rendering + assert "Error Actions" not in out + assert "Timeout Actions" not in out + + +def test_trace_anomalies_human_output_all( + anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] +) -> None: + anomalies_command_impl( + str(anomalies_trace_file), + filter=None, + all=True, + json=False, + trace_dir=anomalies_trace_file.parent, + ) + out = capsys.readouterr().out + assert "Error Actions" in out + assert "Timeout Actions" in out + + +def test_trace_anomalies_filter_matches_only_exit_record( + anomalies_trace_file: Path, capsys: pytest.CaptureFixture[str] +) -> None: + # "(error)" matches only the error (exit-side) record, not its enter + # record; the reconstruction must tolerate the missing enter, not crash + anomalies_command_impl( + str(anomalies_trace_file), + filter="(error)", + all=True, + json=True, + trace_dir=anomalies_trace_file.parent, + ) + envelope = json.loads(capsys.readouterr().out) + assert [row["action"] for row in envelope["errors"]] == ["Sandbox"] + assert envelope["errors"][0]["start_time"] is None def http_record(timestamp: str, message: str) -> dict[str, Any]: