diff --git a/docs/core-data-structures/session.md b/docs/core-data-structures/session.md index 14433d73f5..4d2b47c05c 100644 --- a/docs/core-data-structures/session.md +++ b/docs/core-data-structures/session.md @@ -228,8 +228,8 @@ A plugin may declaration-merge extra `SessionEventMap` types. These are **log-on | Event | Payload | Role | |---|---|---| -| `hook/invoked` | `{ turn, point, dialect, matcher?, handlerId }` | A hook command was invoked at a hook `point` (`PreToolUse`, `Stop`, …). `dialect` is the bridge (`claude`/`codex`); `matcher` the matcher-group pattern that selected it (absent for match-all); `handlerId` correlates with the result. | -| `hook/result` | `{ turn, point, handlerId, decision, exitCode?, stderrSummary? }` | The decided outcome, paired by `handlerId`. `decision` is the neutral outcome `appendHookResult` derives from the parsed output (the hook's decision, else `'stop'` on `continue:false`, else `'pass'`); `exitCode` absent when the hook could not run; `stderrSummary` the trimmed stderr truncated to 500 chars (the block-reason source on exit 2). | +| `hook/invoked` | `{ turn, point, dialect, matcher?, handlerId }` | A hook command was invoked at a hook `point` (`PreToolUse`, `Stop`, …). `dialect` is the bridge (`claude`/`codex`/`native`); `matcher` the matcher-group pattern that selected it (absent for match-all); `handlerId` correlates with the result. | +| `hook/result` | `{ turn, point, handlerId, decision, exitCode?, stderrSummary?, durationMs }` | The decided outcome, paired by `handlerId`. `decision` is the resolved neutral outcome (`deny`/`allow`/`block`/`stop`/`pass`/…); `exitCode` absent when the hook could not run; `stderrSummary` the truncated block-reason source. | The mid-turn hook points (`PreToolUse`/`PostToolUse`/`UserPromptSubmit`/`Stop`) fire inside the loop's open turn, so their `hook/*` records are turn-enclosed by construction. `SessionStart` gets no `hook/*` record — its injected `context/message` is the durable evidence — because it has no open turn to enclose one (see the hooks RFC). diff --git a/docs/rfc/implemented/simplification/2026-07-04-tighten-hook-protocol-contract.md b/docs/rfc/implemented/simplification/2026-07-04-tighten-hook-protocol-contract.md index 90be3c790b..9ee422b130 100644 --- a/docs/rfc/implemented/simplification/2026-07-04-tighten-hook-protocol-contract.md +++ b/docs/rfc/implemented/simplification/2026-07-04-tighten-hook-protocol-contract.md @@ -4,29 +4,28 @@ Status: implemented (proposed and accepted 2026-07-04) ## Problem -Five pieces of the `dsh-hook-protocol`/bridge contract missed the discipline the [subagent-observe-enrich RFC](../feature/2026-06-30-subagent-observe-enrich.md) records — it dropped an `agentType` lifecycle field for lacking a consumer, and these failed the same test: +Four pieces of the `dsh-hook-protocol`/bridge contract missed the discipline the [subagent-observe-enrich RFC](../feature/2026-06-30-subagent-observe-enrich.md) records — it dropped an `agentType` lifecycle field for lacking a consumer, and these failed the same test: 1. **`HookDialect`'s `'native'` variant** (`packages/hooks/hook-protocol/src/types.ts`) had zero producers — the bridges stamp `'claude'` and `'codex'`; the only `'native'` constructor anywhere was the lib's own unit test. The field's own JSDoc defines `dialect` as "the bridge that ran it", and native is not a bridge: the [interception-seams RFC](../feature/2026-06-30-interception-seams.md) records that native hooks are not a package and that "a native plugin can already use the typed Decisions" without the durable hook log, and the flagship native-plugin worked example asserts exactly that (no `hook/*` events at all). 2. **`HookOutput.suppressOutput`** (same file) was parsed by the codec and discarded on every path: no bridge branch, no merge fold, no warn, no deferred-list row — uniquely among its parsed-but-unhonored siblings, each of which carries a stated deferral (`updatedInput` → a logged warn plus the [pre-tool-input-rewrite proposal](../../proposed/feature/2026-06-30-pre-tool-input-rewrite.md); `systemMessage` → a logged warn plus a README deferred row; `continue`/`stopReason` → a `TODO(hook-continue-false)` anchor plus the `'stop'` decision record). Structurally there is nothing to suppress: hook stdout never enters any transcript (context flows only via `additionalContext`; the log records only `decision`/`stderrSummary`), so a hook author setting `suppressOutput: true` got silent nothing with no warn. -3. **`hook/result.durationMs`** was durable timing telemetry with no reader. Both bridges wrote it, and the ACP snapshot normalizer scrubbed it to `0` because wall-clock hook runtime is replay noise (`examples/acp-agent/tests/snapshot-normalize.ts`); the remaining consumers were tests and the goldens that existed because the field existed. Deterministic provenance fields (`point`, `matcher`, `turn`, `handlerId`) earn their durability as audit facts; a nondeterministic field that replay must erase and nothing reads earns neither its bytes nor its special-case scrub. -4. **`defaultTimeoutMs` was double-defaulted in both bridge configs** — a schema `.default(600_000)` AND a `?? 600_000` fallback (`packages/hooks/hooks-claude/src/index.ts`, `packages/hooks/hooks-codex/src/index.ts`) — the same two-homes-for-one-literal shape the ACP bridge's `TODO(double-default)` flags, for a knob no shipped config set; the per-hook `timeoutSec` is the real timeout surface. -5. **The `hook/result` semantics lived in the bridges, twice, not in the lib that owns the event.** `summarize()` — the 500-character stderr truncation rule — was byte-identical in `packages/hooks/hooks-claude/src/index.ts` and `packages/hooks/hooks-codex/src/index.ts`, and so was the decision-string rule `output.decision ?? (output.continue === false ? 'stop' : 'pass')`; yet `dsh-hook-protocol` declared `hook/result`, documented `stderrSummary` as "truncated" without owning the truncation, and documented the decision values without owning the mapping. If one bridge drifted (a different cap, a different fallback), the shared durable event's semantics would fork silently. +3. **`defaultTimeoutMs` was double-defaulted in both bridge configs with a floating literal** — a schema `.default(600_000)` AND a `?? 600_000` fallback (`packages/hooks/hooks-claude/src/index.ts`, `packages/hooks/hooks-codex/src/index.ts`), two homes per bridge for one protocol-level constant, so the bridges could silently drift apart on the shared default. *The proposal's original remedy — delete the knob outright — was overtaken by the no-hardcoded-tunables audit, which kept the knob as the explicit bridge-owned config (and added `stderrSummaryMaxChars` beside it); what remained to fix was the literal's home.* +4. **The `hook/result` semantics lived in the bridges, twice, not in the lib that owns the event.** `summarize()` — the stderr truncation rule — was byte-identical in `packages/hooks/hooks-claude/src/index.ts` and `packages/hooks/hooks-codex/src/index.ts`, and so was the decision-string rule `output.decision ?? (output.continue === false ? 'stop' : 'pass')`; yet `dsh-hook-protocol` declared `hook/result`, documented `stderrSummary` as "truncated" without owning the truncation, and documented the decision values without owning the mapping. If one bridge drifted (a different cap, a different fallback), the shared durable event's semantics would fork silently. ## What shipped -`HookDialect` is `'claude' | 'codex'`, its JSDoc names the two bridges, and the lib's unit test constructs a `'codex'` invocation. `suppressOutput` is gone from `HookOutput`, the codec's parse, the codec tests, and the parsed-superset lists in the lib README and the [hook-protocol-lib RFC](../feature/2026-06-30-hook-protocol-lib.md) (amended per [implemented/AGENTS.md](../AGENTS.md)). `durationMs` is gone from the `hook/result` event, the bridge appends, the docs, and the snapshot normalizer's special-case scrub; with no duration to measure, `runHook`'s injected `now` clock and its single-purpose `RunHookResult` wrapper went too — `runHook` returns the `HookOutput` directly. The committed hook fixtures (`session.jsonl`, which double as the expected-log goldens) had the field stripped mechanically; the stdout goldens never carried it. The bridges' `defaultTimeoutMs` config knob is replaced by one reference-default constant, `DEFAULT_HOOK_TIMEOUT_MS` (600 000 ms), exported from the lib's runner and applied inside `runHook`; `RunHookOptions` lost the field entirely, and the per-hook `timeoutSec` stays the override surface. The `hook/result` semantics live in the lib: `HookResultRecord` carries the decoded `HookOutput`, and `appendHookResult` derives `stderrSummary` (500-character truncation) and the decision string from it; both bridges deleted their private copies, and the derived values are byte-identical to what the bridges wrote (the goldens prove it — their only diff is the dropped `durationMs`). Rider: `BLOCKING_EXIT_CODE` is a codec-internal const, no longer exported (it had zero importers; even the codec tests spell the literal `2`). +`HookDialect` is `'claude' | 'codex'`, its JSDoc names the two bridges, and the lib's unit test constructs a `'codex'` invocation. `suppressOutput` is gone from `HookOutput`, the codec's parse, the codec tests, and the parsed-superset lists in the lib README and the [hook-protocol-lib RFC](../feature/2026-06-30-hook-protocol-lib.md) (amended per [implemented/AGENTS.md](../AGENTS.md)). `hook/result.durationMs` stays: review judged wall-clock hook runtime worth its bytes as durable audit timing (which hook made a turn slow), so `runHook` keeps its injected `now` clock and `RunHookResult` wrapper, the bridges keep passing the measured duration through `HookResultRecord`, and the snapshot normalizer keeps scrubbing the one nondeterministic field to `0` for replay. On the tunables, the no-hardcoded-tunables audit set the shape this change keeps: `defaultTimeoutMs` and `stderrSummaryMaxChars` stay explicit bridge configs, and `RunHookOptions.defaultTimeoutMs` stays a required parameter the bridge passes in. What this change adds is one home per literal: the reference defaults live in the lib as `DEFAULT_HOOK_TIMEOUT_MS` (600 000 ms, exported from the runner) and `DEFAULT_STDERR_SUMMARY_MAX_CHARS` (500, exported from the events module), and both bridges' schema defaults and `??` fallbacks read those constants instead of restating the numbers. The `hook/result` semantics live in the lib: `HookResultRecord` carries the decoded `HookOutput` plus the bridge's `stderrSummaryMaxChars`, and `appendHookResult` derives `stderrSummary` (via the exported `summarizeStderr(stderr, maxChars)`) and the decision string from them; both bridges deleted their private copies, and the derived values are byte-identical to what the bridges wrote (the goldens prove it — their only diff is the dropped `durationMs`). Rider: `BLOCKING_EXIT_CODE` is a codec-internal const, no longer exported (it had zero importers; even the codec tests spell the literal `2`). ## Why not keep them? -The [hook-protocol-lib RFC](../feature/2026-06-30-hook-protocol-lib.md) deliberately recorded "parses the full CC superset" — the strongest counterargument was that this proposal re-litigates decisions that RFC records. But parsing a field whose value can never influence anything is not protocol faithfulness, it is a reader trap; a dialect variant that the design's own thesis says will never be stamped is vocabulary without an interpreter; and durable telemetry that replay must scrub is a cost with no buyer. Each returns trivially with its first real consumer (a transcript surface with hook stdout to suppress; a native-provenance feature that logs hook events; a trace viewer that reads timings — as live diagnostics or a deliberately durable telemetry event designed for it). On item 5, the lib RFC chose per-bridge explicitness over a parameterized engine — but that choice governed payload construction and Decision mapping; the semantics of the SHARED durable event are precisely the "primitives where duplication would actually be dangerous" that the same RFC assigns to the lib. +The [hook-protocol-lib RFC](../feature/2026-06-30-hook-protocol-lib.md) deliberately recorded "parses the full CC superset" — the strongest counterargument was that this proposal re-litigates decisions that RFC records. But parsing a field whose value can never influence anything is not protocol faithfulness, it is a reader trap; a dialect variant that the design's own thesis says will never be stamped is vocabulary without an interpreter; Each returns trivially with its first real consumer (a transcript surface with hook stdout to suppress; a native-provenance feature that logs hook events). On `durationMs` the review reached the opposite verdict: a persistence log is written for future readers, and wall-clock hook timing is audit signal worth carrying before a reader exists — so it stays, with replay normalization as the accepted cost. On item 4, the lib RFC chose per-bridge explicitness over a parameterized engine — but that choice governed payload construction and Decision mapping; the semantics of the SHARED durable event are precisely the "primitives where duplication would actually be dangerous" that the same RFC assigns to the lib. ## Acceptance criteria - `HookDialect` is two-valued; `rg "'native'"` in the hooks packages returns nothing. -- `suppressOutput` and `durationMs` appear nowhere in source, parsed-field doc lists, or the normalizer; the hook fixtures carry no `durationMs` (the refresh was a mechanical field-strip, not a re-record). -- Both bridge configs lost `defaultTimeoutMs`; the reference default lives once, in the lib (`DEFAULT_HOOK_TIMEOUT_MS`); per-hook `timeoutSec` still overrides it. +- `suppressOutput` appears nowhere in source, parsed-field doc lists, or the normalizer; `durationMs` stays on `hook/result` (and in the fixtures), with the normalizer's replay scrub intact. +- Both bridge configs keep `defaultTimeoutMs`/`stderrSummaryMaxChars` (the audit's explicit-tunables shape), but the literals `600_000` and `500` each live once, in the lib's `DEFAULT_HOOK_TIMEOUT_MS`/`DEFAULT_STDERR_SUMMARY_MAX_CHARS`; per-hook `timeoutSec` still overrides the timeout. - One definition each of the truncation rule and the decision-string rule, in `dsh-hook-protocol`'s `appendHookResult`, exercised by both bridges' suites. ## Risks -The `dialect`, `suppressOutput`, `defaultTimeoutMs`, and semantics changes are invisible on the wire and in the goldens; the `durationMs` removal churned the hook fixtures once (a mechanical field-strip — the field was already normalized to a constant). The cost was churn in `dsh-hook-protocol` and both bridges — cheap under the pre-release stance, and cheaper than letting two copies of a durable event's semantics age apart. +The `dialect`, `suppressOutput`, tunables, and semantics changes are invisible on the wire and in the goldens. The cost was churn in `dsh-hook-protocol` and both bridges — cheap under the pre-release stance, and cheaper than letting two copies of a durable event's semantics age apart. diff --git a/docs/rfc/implemented/testing/2026-07-04-hook-snapshot-matrix.md b/docs/rfc/implemented/testing/2026-07-04-hook-snapshot-matrix.md index 0a7c0fd4ec..f8ec029d22 100644 --- a/docs/rfc/implemented/testing/2026-07-04-hook-snapshot-matrix.md +++ b/docs/rfc/implemented/testing/2026-07-04-hook-snapshot-matrix.md @@ -27,7 +27,7 @@ Thirteen scenarios under `examples/acp-agent/tests/snapshots/`, naming `hook- { expect(out).toContain('{{sessionId}}') }) - it('leaves event data fields untouched beyond the time zeroing (no per-event field scrubs)', () => { + it('zeroes a hook/result durationMs (run-to-run noise) but keeps its decision', () => { const ev = JSON.stringify({ type: 'hook/result', seq: 2, time: 5, - data: { turn: 1, point: 'UserPromptSubmit', handlerId: 'h', decision: 'block', exitCode: 2 }, + data: { turn: 1, point: 'UserPromptSubmit', handlerId: 'h', decision: 'block', exitCode: 2, durationMs: 37 }, }) const out = normalizeSessionLog(`${header({})}\n${ev}\n`, ctx) - expect(out).toContain('"decision":"block"') - expect(out).toContain('"exitCode":2') - expect(out).toContain('"time":0') + expect(out).toContain('"durationMs":0') + expect(out).not.toContain('37') + expect(out).toContain('"decision":"block"') // the decision is the behavior — kept + }) + + it('leaves a non-hook event durationMs untouched (only hook/result is scrubbed)', () => { + const ev = JSON.stringify({ type: 'tool/result', seq: 2, time: 5, data: { durationMs: 88 } }) + const out = normalizeSessionLog(`${header({})}\n${ev}\n`, ctx) + expect(out).toContain('"durationMs":88') }) }) diff --git a/examples/acp-agent/tests/snapshot-normalize.ts b/examples/acp-agent/tests/snapshot-normalize.ts index db0d493535..8150057fa4 100644 --- a/examples/acp-agent/tests/snapshot-normalize.ts +++ b/examples/acp-agent/tests/snapshot-normalize.ts @@ -8,7 +8,8 @@ * Scrubbed: `randomUUID()` session ids → `{{sessionId}}`; the temp `mkdtemp` * cwd → `{{cwd}}` (it appears in terminal-card `_meta` and the log header); * JSON-RPC request `id` → a stable per-transcript sequence; the log's per-event - * `time` (epoch ms) and header `createdAt` → 0. NOT scrubbed: the log's `seq` + * `time` (epoch ms) and header `createdAt` → 0; a `hook/result` event's + * `durationMs` (wall-clock hook runtime) → 0. NOT scrubbed: the log's `seq` * (deterministic — `seq = log.length`, part of the event-log contract). * * See docs/rfc/implemented/testing/2026-06-19-acp-snapshot-tests.md. @@ -97,6 +98,13 @@ export function normalizeSessionLog(rawLog: string, ctx: NormalizeContext): stri } else if ('time' in record) { // Event line: zero the epoch-ms timestamp; keep seq (deterministic). record.time = 0 + // A hook/result carries the hook's wall-clock runtime (`data.durationMs`), + // which is run-to-run noise like `time` — zero it so the golden reflects + // the hook's decision/exit, not how long the shell took. + if (record.type === 'hook/result' && record.data !== null && typeof record.data === 'object') { + const data = record.data as Record + if ('durationMs' in data) data.durationMs = 0 + } } return scrubValue(record, ctx) as Record }) diff --git a/examples/acp-agent/tests/snapshots/hook-cc-posttool-block/session.jsonl b/examples/acp-agent/tests/snapshots/hook-cc-posttool-block/session.jsonl index 1cf98ff718..a9bcac1b03 100644 --- a/examples/acp-agent/tests/snapshots/hook-cc-posttool-block/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-cc-posttool-block/session.jsonl @@ -61,7 +61,7 @@ {"type":"assistant/message","seq":59,"time":1783095159852,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to run the command `echo HELLO` using the bash tool and report the result verbatim."},{"type":"tool-call","id":"call_00_e9zAlNQhIVFKzoStUuWI7161","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}],"usage":{"inputTokens":72,"outputTokens":91,"cacheReadTokens":1664,"reasoningTokens":25}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58],"surfaceOp":"append"} {"type":"tool/call","seq":60,"time":1783095159852,"data":{"turn":1,"step":1,"callId":"call_00_e9zAlNQhIVFKzoStUuWI7161","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}} {"type":"hook/invoked","seq":61,"time":1783095159867,"data":{"turn":1,"point":"PostToolUse","dialect":"claude","handlerId":"claude:PostToolUse:1","matcher":"bash"}} -{"type":"hook/result","seq":62,"time":1783095159875,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:1","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by policy: rerun with a summary instead"}} +{"type":"hook/result","seq":62,"time":1783095159875,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:1","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by policy: rerun with a summary instead","durationMs":7.870597999999973}} {"type":"tool/result","seq":63,"time":1783095159875,"data":{"turn":1,"step":1,"callId":"call_00_e9zAlNQhIVFKzoStUuWI7161","content":[{"type":"text","text":"tool output rejected by policy: rerun with a summary instead"}],"isError":true},"sourceEventSeqs":[60],"surfaceOp":"append"} {"type":"step/end","seq":64,"time":1783095159875,"data":{"turn":1,"step":1}} {"type":"step/start","seq":65,"time":1783095159876,"data":{"turn":1,"step":2}} @@ -166,7 +166,7 @@ {"type":"assistant/message","seq":164,"time":1783095161879,"data":{"turn":1,"step":2,"content":[{"type":"reasoning","text":"The tool output was rejected by policy. I need to rerun with a description/summary. Let me try again - I already included a description. Let me check if maybe the description needs to be more descriptive, or if there's another issue.\n\nLet me try again with a slightly different approach to see what happens."},{"type":"tool-call","id":"call_00_SFRulyHdhTsyfllc6Gro3716","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Echo the string HELLO\"}"}],"usage":{"inputTokens":187,"outputTokens":133,"cacheReadTokens":1664,"reasoningTokens":65}},"sourceEventSeqs":[66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163],"surfaceOp":"append"} {"type":"tool/call","seq":165,"time":1783095161879,"data":{"turn":1,"step":2,"callId":"call_00_SFRulyHdhTsyfllc6Gro3716","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Echo the string HELLO\"}"}} {"type":"hook/invoked","seq":166,"time":1783095161893,"data":{"turn":1,"point":"PostToolUse","dialect":"claude","handlerId":"claude:PostToolUse:2","matcher":"bash"}} -{"type":"hook/result","seq":167,"time":1783095161902,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:2","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by policy: rerun with a summary instead"}} +{"type":"hook/result","seq":167,"time":1783095161902,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:2","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by policy: rerun with a summary instead","durationMs":8.773494000000028}} {"type":"tool/result","seq":168,"time":1783095161902,"data":{"turn":1,"step":2,"callId":"call_00_SFRulyHdhTsyfllc6Gro3716","content":[{"type":"text","text":"tool output rejected by policy: rerun with a summary instead"}],"isError":true},"sourceEventSeqs":[165],"surfaceOp":"append"} {"type":"step/end","seq":169,"time":1783095161903,"data":{"turn":1,"step":2}} {"type":"step/start","seq":170,"time":1783095161903,"data":{"turn":1,"step":3}} @@ -282,7 +282,7 @@ {"type":"assistant/message","seq":280,"time":1783095163935,"data":{"turn":1,"step":3,"content":[{"type":"reasoning","text":"It seems the tool output is being rejected by policy repeatedly. Let me try a different command or approach - perhaps the issue is unrelated to my command. Let me try with a longer description or a different format.\n\nActually, I think the policy rejection might be about the content/output being shown. Let me try running it and just report what I know.\n\nLet me try one more time."},{"type":"tool-call","id":"call_00_9CQs2NzrhnwYjdvmjsR10424","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Print HELLO to stdout\"}"}],"usage":{"inputTokens":216,"outputTokens":144,"cacheReadTokens":1792,"reasoningTokens":77}},"sourceEventSeqs":[171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,207,208,209,210,211,212,213,214,215,216,217,218,219,220,221,222,223,224,225,226,227,228,229,230,231,232,233,234,235,236,237,238,239,240,241,242,243,244,245,246,247,248,249,250,251,252,253,254,255,256,257,258,259,260,261,262,263,264,265,266,267,268,269,270,271,272,273,274,275,276,277,278,279],"surfaceOp":"append"} {"type":"tool/call","seq":281,"time":1783095163935,"data":{"turn":1,"step":3,"callId":"call_00_9CQs2NzrhnwYjdvmjsR10424","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Print HELLO to stdout\"}"}} {"type":"hook/invoked","seq":282,"time":1783095163944,"data":{"turn":1,"point":"PostToolUse","dialect":"claude","handlerId":"claude:PostToolUse:3","matcher":"bash"}} -{"type":"hook/result","seq":283,"time":1783095163951,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:3","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by policy: rerun with a summary instead"}} +{"type":"hook/result","seq":283,"time":1783095163951,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:3","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by policy: rerun with a summary instead","durationMs":6.553152000000409}} {"type":"tool/result","seq":284,"time":1783095163951,"data":{"turn":1,"step":3,"callId":"call_00_9CQs2NzrhnwYjdvmjsR10424","content":[{"type":"text","text":"tool output rejected by policy: rerun with a summary instead"}],"isError":true},"sourceEventSeqs":[281],"surfaceOp":"append"} {"type":"step/end","seq":285,"time":1783095163951,"data":{"turn":1,"step":3}} {"type":"step/start","seq":286,"time":1783095163951,"data":{"turn":1,"step":4}} diff --git a/examples/acp-agent/tests/snapshots/hook-cc-posttool-context/session.jsonl b/examples/acp-agent/tests/snapshots/hook-cc-posttool-context/session.jsonl index aa28dfdeb9..053ce1c251 100644 --- a/examples/acp-agent/tests/snapshots/hook-cc-posttool-context/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-cc-posttool-context/session.jsonl @@ -59,7 +59,7 @@ {"type":"assistant/message","seq":57,"time":1783095113150,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to run `echo HELLO` using the bash tool and report the result verbatim."},{"type":"tool-call","id":"call_00_upvgqMKJ4hJck9LxQn0p5500","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}],"usage":{"inputTokens":72,"outputTokens":89,"cacheReadTokens":1664,"reasoningTokens":23}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56],"surfaceOp":"append"} {"type":"tool/call","seq":58,"time":1783095113150,"data":{"turn":1,"step":1,"callId":"call_00_upvgqMKJ4hJck9LxQn0p5500","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}} {"type":"hook/invoked","seq":59,"time":1783095113166,"data":{"turn":1,"point":"PostToolUse","dialect":"claude","handlerId":"claude:PostToolUse:1","matcher":"bash"}} -{"type":"hook/result","seq":60,"time":1783095113175,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:1","decision":"pass","exitCode":0}} +{"type":"hook/result","seq":60,"time":1783095113175,"data":{"turn":1,"point":"PostToolUse","handlerId":"claude:PostToolUse:1","decision":"pass","exitCode":0,"durationMs":8.75206100000014}} {"type":"tool/result","seq":61,"time":1783095113175,"data":{"turn":1,"step":1,"callId":"call_00_upvgqMKJ4hJck9LxQn0p5500","content":[{"type":"text","text":"HELLO\n"}],"isError":false},"sourceEventSeqs":[58],"surfaceOp":"append"} {"type":"context/message","seq":62,"time":1783095113176,"data":{"content":[{"type":"text","text":"Note: command output has been verified against the audit log."}],"source":{"kind":"plugin","plugin":"hooks-claude"}},"surfaceOp":"append"} {"type":"step/end","seq":63,"time":1783095113176,"data":{"turn":1,"step":1}} diff --git a/examples/acp-agent/tests/snapshots/hook-cc-pretool-ask/session.jsonl b/examples/acp-agent/tests/snapshots/hook-cc-pretool-ask/session.jsonl index 727e349208..b0e7a5f00f 100644 --- a/examples/acp-agent/tests/snapshots/hook-cc-pretool-ask/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-cc-pretool-ask/session.jsonl @@ -59,7 +59,7 @@ {"type":"assistant/message","seq":57,"time":1783095043785,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to run `echo HELLO` using the bash tool and report the result verbatim."},{"type":"tool-call","id":"call_00_YmAP6EwhDlZ4q9v2uPdB5865","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Echo HELLO\"}"}],"usage":{"inputTokens":72,"outputTokens":89,"cacheReadTokens":1664,"reasoningTokens":23}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56],"surfaceOp":"append"} {"type":"tool/call","seq":58,"time":1783095043786,"data":{"turn":1,"step":1,"callId":"call_00_YmAP6EwhDlZ4q9v2uPdB5865","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Echo HELLO\"}"}} {"type":"hook/invoked","seq":59,"time":1783095043786,"data":{"turn":1,"point":"PreToolUse","dialect":"claude","handlerId":"claude:PreToolUse:1","matcher":"bash"}} -{"type":"hook/result","seq":60,"time":1783095043800,"data":{"turn":1,"point":"PreToolUse","handlerId":"claude:PreToolUse:1","decision":"ask","exitCode":0}} +{"type":"hook/result","seq":60,"time":1783095043800,"data":{"turn":1,"point":"PreToolUse","handlerId":"claude:PreToolUse:1","decision":"ask","exitCode":0,"durationMs":12.982377999999699}} {"type":"tool/result","seq":61,"time":1783095043800,"data":{"turn":1,"step":1,"callId":"call_00_YmAP6EwhDlZ4q9v2uPdB5865","content":[{"type":"text","text":"Error: bash requires manual approval in this session"}],"isError":true},"sourceEventSeqs":[58],"surfaceOp":"append"} {"type":"step/end","seq":62,"time":1783095043800,"data":{"turn":1,"step":1}} {"type":"step/start","seq":63,"time":1783095043801,"data":{"turn":1,"step":2}} diff --git a/examples/acp-agent/tests/snapshots/hook-cc-pretool-deny/session.jsonl b/examples/acp-agent/tests/snapshots/hook-cc-pretool-deny/session.jsonl index 1aab4b5493..501f3a8594 100644 --- a/examples/acp-agent/tests/snapshots/hook-cc-pretool-deny/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-cc-pretool-deny/session.jsonl @@ -59,7 +59,7 @@ {"type":"assistant/message","seq":57,"time":1783095009899,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to run `echo HELLO` using the bash tool and report the result verbatim."},{"type":"tool-call","id":"call_00_NQfQgkyjofpjsaiEUcsX0103","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}],"usage":{"inputTokens":1736,"outputTokens":89,"cacheReadTokens":0,"reasoningTokens":23}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56],"surfaceOp":"append"} {"type":"tool/call","seq":58,"time":1783095009899,"data":{"turn":1,"step":1,"callId":"call_00_NQfQgkyjofpjsaiEUcsX0103","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}} {"type":"hook/invoked","seq":59,"time":1783095009900,"data":{"turn":1,"point":"PreToolUse","dialect":"claude","handlerId":"claude:PreToolUse:1","matcher":"bash"}} -{"type":"hook/result","seq":60,"time":1783095009915,"data":{"turn":1,"point":"PreToolUse","handlerId":"claude:PreToolUse:1","decision":"block","exitCode":2,"stderrSummary":"bash is disabled by policy in this session"}} +{"type":"hook/result","seq":60,"time":1783095009915,"data":{"turn":1,"point":"PreToolUse","handlerId":"claude:PreToolUse:1","decision":"block","exitCode":2,"stderrSummary":"bash is disabled by policy in this session","durationMs":14.778092000000015}} {"type":"tool/result","seq":61,"time":1783095009915,"data":{"turn":1,"step":1,"callId":"call_00_NQfQgkyjofpjsaiEUcsX0103","content":[{"type":"text","text":"Error: bash is disabled by policy in this session"}],"isError":true},"sourceEventSeqs":[58],"surfaceOp":"append"} {"type":"step/end","seq":62,"time":1783095009916,"data":{"turn":1,"step":1}} {"type":"step/start","seq":63,"time":1783095009916,"data":{"turn":1,"step":2}} diff --git a/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-block/session.jsonl b/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-block/session.jsonl index 6205340c2a..b5f81fdaea 100644 --- a/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-block/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-block/session.jsonl @@ -1,6 +1,6 @@ {"type":"session","version":0,"id":"{{sessionId}}","createdAt":0,"cwd":"{{cwd}}"} {"type":"turn/start","seq":0,"time":0,"data":{"turn":1,"trigger":{"kind":"message","source":{"kind":"user"}}}} {"type":"hook/invoked","seq":1,"time":0,"data":{"turn":1,"point":"UserPromptSubmit","dialect":"claude","handlerId":"claude:UserPromptSubmit:1"}} -{"type":"hook/result","seq":2,"time":0,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"claude:UserPromptSubmit:1","decision":"block","exitCode":2,"stderrSummary":"blocked by policy hook"}} +{"type":"hook/result","seq":2,"time":0,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"claude:UserPromptSubmit:1","decision":"block","exitCode":2,"stderrSummary":"blocked by policy hook","durationMs":0}} {"type":"prompt/blocked","seq":3,"time":0,"data":{"content":[{"type":"text","text":"Delete everything in the repo."}],"source":{"kind":"user"},"reason":"blocked by policy hook"}} {"type":"turn/end","seq":4,"time":0,"data":{"turn":1,"reason":{"kind":"rejected","reason":"blocked by policy hook"}}} diff --git a/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-context/session.jsonl b/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-context/session.jsonl index d3b341eeee..33cf2c8ba0 100644 --- a/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-context/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-cc-promptsubmit-context/session.jsonl @@ -1,7 +1,7 @@ {"type":"session","version":0,"id":"b0c9d2c7-f95b-4750-be8a-10121253b006","createdAt":1783095036603,"cwd":"/tmp/acp-snap-cwd-LW2rSZ"} {"type":"turn/start","seq":0,"time":1783095036609,"data":{"turn":1,"trigger":{"kind":"message","source":{"kind":"user"}}}} {"type":"hook/invoked","seq":1,"time":1783095036610,"data":{"turn":1,"point":"UserPromptSubmit","dialect":"claude","handlerId":"claude:UserPromptSubmit:1"}} -{"type":"hook/result","seq":2,"time":1783095036623,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"claude:UserPromptSubmit:1","decision":"pass","exitCode":0}} +{"type":"hook/result","seq":2,"time":1783095036623,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"claude:UserPromptSubmit:1","decision":"pass","exitCode":0,"durationMs":11.874454999999898}} {"type":"user/message","seq":3,"time":1783095036623,"data":{"content":[{"type":"text","text":"What is my favorite color? Reply with just the color and stop. Do not use any tools."}],"source":{"kind":"user"}},"surfaceOp":"append"} {"type":"context/message","seq":4,"time":1783095036623,"data":{"content":[{"type":"text","text":"The user has previously stated their favorite color is teal."}],"source":{"kind":"plugin","plugin":"hooks-claude"}},"surfaceOp":"append"} {"type":"step/start","seq":5,"time":1783095036624,"data":{"turn":1,"step":1}} diff --git a/examples/acp-agent/tests/snapshots/hook-cc-stop-continue/session.jsonl b/examples/acp-agent/tests/snapshots/hook-cc-stop-continue/session.jsonl index f70d047033..7e584998e7 100644 --- a/examples/acp-agent/tests/snapshots/hook-cc-stop-continue/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-cc-stop-continue/session.jsonl @@ -30,7 +30,7 @@ {"type":"assistant/message","seq":28,"time":1783095185826,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to reply with the single word \"FIRST\" and stop."},{"type":"text","text":"FIRST"}],"usage":{"inputTokens":55,"outputTokens":20,"cacheReadTokens":1664,"reasoningTokens":17}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27],"surfaceOp":"append"} {"type":"step/end","seq":29,"time":1783095185826,"data":{"turn":1,"step":1}} {"type":"hook/invoked","seq":30,"time":1783095185827,"data":{"turn":1,"point":"Stop","dialect":"claude","handlerId":"claude:Stop:1"}} -{"type":"hook/result","seq":31,"time":1783095185846,"data":{"turn":1,"point":"Stop","handlerId":"claude:Stop:1","decision":"block","exitCode":2,"stderrSummary":"Also reply with the single word SECOND, then stop."}} +{"type":"hook/result","seq":31,"time":1783095185846,"data":{"turn":1,"point":"Stop","handlerId":"claude:Stop:1","decision":"block","exitCode":2,"stderrSummary":"Also reply with the single word SECOND, then stop.","durationMs":19.14465199999995}} {"type":"steering/message","seq":32,"time":1783095185846,"data":{"turn":1,"content":[{"type":"text","text":"Also reply with the single word SECOND, then stop."}],"source":{"kind":"plugin","plugin":"hooks-claude"}},"surfaceOp":"append"} {"type":"step/start","seq":33,"time":1783095185847,"data":{"turn":1,"step":2}} {"type":"assistant/chunk","seq":34,"time":1783095186554,"data":{"turn":1,"step":2,"chunk":{"type":"block-start","index":0,"blockType":"reasoning"}}} @@ -234,5 +234,5 @@ {"type":"assistant/message","seq":232,"time":1783095187944,"data":{"turn":1,"step":2,"content":[{"type":"reasoning","text":"The user initially asked me to reply with \"FIRST\" and stop, which I did. Now there's a plugin steering message asking me to also reply with \"SECOND\" and stop. However, the user's original instruction said \"Reply with the single word FIRST and stop.\" I already did that. The plugin is trying to add an additional instruction, but I should follow the original user instruction which said to stop after \"FIRST\".\n\nActually, looking more carefully - I already responded with \"FIRST\" in my previous turn. Now the user is sending a new message with a plugin steering. Let me consider what to do.\n\nThe plugin says \"Also reply with the single word SECOND, then stop.\" But the user's original request was to reply with \"FIRST\" and stop. I already did that. Now I have a new instruction from the plugin. I think I should follow this new instruction and reply with \"SECOND\"."},{"type":"text","text":"SECOND"}],"usage":{"inputTokens":82,"outputTokens":193,"cacheReadTokens":1664,"reasoningTokens":190}},"sourceEventSeqs":[34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,207,208,209,210,211,212,213,214,215,216,217,218,219,220,221,222,223,224,225,226,227,228,229,230,231],"surfaceOp":"append"} {"type":"step/end","seq":233,"time":1783095187944,"data":{"turn":1,"step":2}} {"type":"hook/invoked","seq":234,"time":1783095187944,"data":{"turn":1,"point":"Stop","dialect":"claude","handlerId":"claude:Stop:2"}} -{"type":"hook/result","seq":235,"time":1783095187954,"data":{"turn":1,"point":"Stop","handlerId":"claude:Stop:2","decision":"pass","exitCode":0}} +{"type":"hook/result","seq":235,"time":1783095187954,"data":{"turn":1,"point":"Stop","handlerId":"claude:Stop:2","decision":"pass","exitCode":0,"durationMs":9.226673000000119}} {"type":"turn/end","seq":236,"time":1783095187954,"data":{"turn":1,"reason":{"kind":"completed"}}} diff --git a/examples/acp-agent/tests/snapshots/hook-codex-posttool-block/session.jsonl b/examples/acp-agent/tests/snapshots/hook-codex-posttool-block/session.jsonl index 6dfbd767cb..ff774c4643 100644 --- a/examples/acp-agent/tests/snapshots/hook-codex-posttool-block/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-codex-posttool-block/session.jsonl @@ -59,7 +59,7 @@ {"type":"assistant/message","seq":57,"time":1783095423411,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to run `echo HELLO` using the bash tool and report the result verbatim."},{"type":"tool-call","id":"call_00_NN9uJWZQDPiUfGC6VAtF0696","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}],"usage":{"inputTokens":72,"outputTokens":89,"cacheReadTokens":1664,"reasoningTokens":23}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56],"surfaceOp":"append"} {"type":"tool/call","seq":58,"time":1783095423412,"data":{"turn":1,"step":1,"callId":"call_00_NN9uJWZQDPiUfGC6VAtF0696","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}} {"type":"hook/invoked","seq":59,"time":1783095423425,"data":{"turn":1,"point":"PostToolUse","dialect":"codex","handlerId":"codex:PostToolUse:1","matcher":"bash"}} -{"type":"hook/result","seq":60,"time":1783095423432,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:1","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead"}} +{"type":"hook/result","seq":60,"time":1783095423432,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:1","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead","durationMs":6.750618000000031}} {"type":"tool/result","seq":61,"time":1783095423432,"data":{"turn":1,"step":1,"callId":"call_00_NN9uJWZQDPiUfGC6VAtF0696","content":[{"type":"text","text":"tool output rejected by codex policy: summarize instead"}],"isError":true},"sourceEventSeqs":[58],"surfaceOp":"append"} {"type":"step/end","seq":62,"time":1783095423432,"data":{"turn":1,"step":1}} {"type":"step/start","seq":63,"time":1783095423433,"data":{"turn":1,"step":2}} @@ -117,7 +117,7 @@ {"type":"assistant/message","seq":115,"time":1783095424733,"data":{"turn":1,"step":2,"content":[{"type":"reasoning","text":"The output was rejected by codex policy. Let me try again with the exact command as specified."},{"type":"tool-call","id":"call_00_vYk35aagabBlYGHTvJqn7418","name":"bash","arguments":"{\"description\": \"Run echo HELLO\", \"command\": \"echo HELLO\"}"}],"usage":{"inputTokens":55,"outputTokens":86,"cacheReadTokens":1792,"reasoningTokens":20}},"sourceEventSeqs":[64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114],"surfaceOp":"append"} {"type":"tool/call","seq":116,"time":1783095424733,"data":{"turn":1,"step":2,"callId":"call_00_vYk35aagabBlYGHTvJqn7418","name":"bash","arguments":"{\"description\": \"Run echo HELLO\", \"command\": \"echo HELLO\"}"}} {"type":"hook/invoked","seq":117,"time":1783095424745,"data":{"turn":1,"point":"PostToolUse","dialect":"codex","handlerId":"codex:PostToolUse:2","matcher":"bash"}} -{"type":"hook/result","seq":118,"time":1783095424753,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:2","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead"}} +{"type":"hook/result","seq":118,"time":1783095424753,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:2","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead","durationMs":7.9194109999998545}} {"type":"tool/result","seq":119,"time":1783095424753,"data":{"turn":1,"step":2,"callId":"call_00_vYk35aagabBlYGHTvJqn7418","content":[{"type":"text","text":"tool output rejected by codex policy: summarize instead"}],"isError":true},"sourceEventSeqs":[116],"surfaceOp":"append"} {"type":"step/end","seq":120,"time":1783095424753,"data":{"turn":1,"step":2}} {"type":"step/start","seq":121,"time":1783095424753,"data":{"turn":1,"step":3}} @@ -175,7 +175,7 @@ {"type":"assistant/message","seq":173,"time":1783095426479,"data":{"turn":1,"step":3,"content":[{"type":"reasoning","text":"The tool output is being rejected by codex policy. Let me try a slightly different approach - maybe I need to be more careful with the description or command."},{"type":"tool-call","id":"call_00_XLxXjqVljRIC2KwFZCKX3369","name":"bash","arguments":"{\"command\": \"echo HELLO\"}"}],"usage":{"inputTokens":163,"outputTokens":78,"cacheReadTokens":1792,"reasoningTokens":32}},"sourceEventSeqs":[122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172],"surfaceOp":"append"} {"type":"tool/call","seq":174,"time":1783095426479,"data":{"turn":1,"step":3,"callId":"call_00_XLxXjqVljRIC2KwFZCKX3369","name":"bash","arguments":"{\"command\": \"echo HELLO\"}"}} {"type":"hook/invoked","seq":175,"time":1783095426479,"data":{"turn":1,"point":"PostToolUse","dialect":"codex","handlerId":"codex:PostToolUse:3","matcher":"bash"}} -{"type":"hook/result","seq":176,"time":1783095426488,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:3","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead"}} +{"type":"hook/result","seq":176,"time":1783095426488,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:3","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead","durationMs":8.644037999999455}} {"type":"tool/result","seq":177,"time":1783095426488,"data":{"turn":1,"step":3,"callId":"call_00_XLxXjqVljRIC2KwFZCKX3369","content":[{"type":"text","text":"tool output rejected by codex policy: summarize instead"}],"isError":true},"sourceEventSeqs":[174],"surfaceOp":"append"} {"type":"step/end","seq":178,"time":1783095426488,"data":{"turn":1,"step":3}} {"type":"step/start","seq":179,"time":1783095426489,"data":{"turn":1,"step":4}} @@ -222,7 +222,7 @@ {"type":"assistant/message","seq":220,"time":1783095427668,"data":{"turn":1,"step":4,"content":[{"type":"reasoning","text":"The tool is consistently rejecting the output. Let me try a different way to invoke it."},{"type":"tool-call","id":"call_00_twNfzWSJ9WJn8YeoGVIi1932","name":"bash","arguments":"{\"command\": \"printf 'HELLO\\\\n'\"}"}],"usage":{"inputTokens":135,"outputTokens":67,"cacheReadTokens":1920,"reasoningTokens":18}},"sourceEventSeqs":[180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,207,208,209,210,211,212,213,214,215,216,217,218,219],"surfaceOp":"append"} {"type":"tool/call","seq":221,"time":1783095427668,"data":{"turn":1,"step":4,"callId":"call_00_twNfzWSJ9WJn8YeoGVIi1932","name":"bash","arguments":"{\"command\": \"printf 'HELLO\\\\n'\"}"}} {"type":"hook/invoked","seq":222,"time":1783095427668,"data":{"turn":1,"point":"PostToolUse","dialect":"codex","handlerId":"codex:PostToolUse:4","matcher":"bash"}} -{"type":"hook/result","seq":223,"time":1783095427677,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:4","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead"}} +{"type":"hook/result","seq":223,"time":1783095427677,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:4","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead","durationMs":8.75036799999998}} {"type":"tool/result","seq":224,"time":1783095427677,"data":{"turn":1,"step":4,"callId":"call_00_twNfzWSJ9WJn8YeoGVIi1932","content":[{"type":"text","text":"tool output rejected by codex policy: summarize instead"}],"isError":true},"sourceEventSeqs":[221],"surfaceOp":"append"} {"type":"step/end","seq":225,"time":1783095427678,"data":{"turn":1,"step":4}} {"type":"step/start","seq":226,"time":1783095427678,"data":{"turn":1,"step":5}} @@ -286,7 +286,7 @@ {"type":"assistant/message","seq":284,"time":1783095429025,"data":{"turn":1,"step":5,"content":[{"type":"reasoning","text":"Every attempt is being rejected. Let me try to see what's happening by running a different command first, to check if bash works at all."},{"type":"text","text":"Let me check if bash itself is working:"},{"type":"tool-call","id":"call_00_xOnTckie072jHuPhX0Mz5115","name":"bash","arguments":"{\"command\": \"pwd\"}"}],"usage":{"inputTokens":96,"outputTokens":81,"cacheReadTokens":2048,"reasoningTokens":29}},"sourceEventSeqs":[227,228,229,230,231,232,233,234,235,236,237,238,239,240,241,242,243,244,245,246,247,248,249,250,251,252,253,254,255,256,257,258,259,260,261,262,263,264,265,266,267,268,269,270,271,272,273,274,275,276,277,278,279,280,281,282,283],"surfaceOp":"append"} {"type":"tool/call","seq":285,"time":1783095429025,"data":{"turn":1,"step":5,"callId":"call_00_xOnTckie072jHuPhX0Mz5115","name":"bash","arguments":"{\"command\": \"pwd\"}"}} {"type":"hook/invoked","seq":286,"time":1783095429025,"data":{"turn":1,"point":"PostToolUse","dialect":"codex","handlerId":"codex:PostToolUse:5","matcher":"bash"}} -{"type":"hook/result","seq":287,"time":1783095429046,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:5","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead"}} +{"type":"hook/result","seq":287,"time":1783095429046,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:5","decision":"block","exitCode":2,"stderrSummary":"tool output rejected by codex policy: summarize instead","durationMs":21.25910400000066}} {"type":"tool/result","seq":288,"time":1783095429047,"data":{"turn":1,"step":5,"callId":"call_00_xOnTckie072jHuPhX0Mz5115","content":[{"type":"text","text":"tool output rejected by codex policy: summarize instead"}],"isError":true},"sourceEventSeqs":[285],"surfaceOp":"append"} {"type":"step/end","seq":289,"time":1783095429047,"data":{"turn":1,"step":5}} {"type":"step/start","seq":290,"time":1783095429047,"data":{"turn":1,"step":6}} diff --git a/examples/acp-agent/tests/snapshots/hook-codex-posttool-context/session.jsonl b/examples/acp-agent/tests/snapshots/hook-codex-posttool-context/session.jsonl index 2af2c979ab..1a93694456 100644 --- a/examples/acp-agent/tests/snapshots/hook-codex-posttool-context/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-codex-posttool-context/session.jsonl @@ -59,7 +59,7 @@ {"type":"assistant/message","seq":57,"time":1783095440719,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to run `echo HELLO` using the bash tool and report the result verbatim."},{"type":"tool-call","id":"call_00_TArPQZJxir9dawrAg0Fb9098","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}],"usage":{"inputTokens":72,"outputTokens":89,"cacheReadTokens":1664,"reasoningTokens":23}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56],"surfaceOp":"append"} {"type":"tool/call","seq":58,"time":1783095440719,"data":{"turn":1,"step":1,"callId":"call_00_TArPQZJxir9dawrAg0Fb9098","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Run echo HELLO\"}"}} {"type":"hook/invoked","seq":59,"time":1783095440731,"data":{"turn":1,"point":"PostToolUse","dialect":"codex","handlerId":"codex:PostToolUse:1","matcher":"bash"}} -{"type":"hook/result","seq":60,"time":1783095440739,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:1","decision":"pass","exitCode":0}} +{"type":"hook/result","seq":60,"time":1783095440739,"data":{"turn":1,"point":"PostToolUse","handlerId":"codex:PostToolUse:1","decision":"pass","exitCode":0,"durationMs":7.645890999999665}} {"type":"tool/result","seq":61,"time":1783095440739,"data":{"turn":1,"step":1,"callId":"call_00_TArPQZJxir9dawrAg0Fb9098","content":[{"type":"text","text":"HELLO\n"}],"isError":false},"sourceEventSeqs":[58],"surfaceOp":"append"} {"type":"context/message","seq":62,"time":1783095440739,"data":{"content":[{"type":"text","text":"Note: command output has been verified against the audit log."}],"source":{"kind":"plugin","plugin":"hooks-codex"}},"surfaceOp":"append"} {"type":"step/end","seq":63,"time":1783095440739,"data":{"turn":1,"step":1}} diff --git a/examples/acp-agent/tests/snapshots/hook-codex-pretool-block/session.jsonl b/examples/acp-agent/tests/snapshots/hook-codex-pretool-block/session.jsonl index 1f08a5ec27..0e6d3ac407 100644 --- a/examples/acp-agent/tests/snapshots/hook-codex-pretool-block/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-codex-pretool-block/session.jsonl @@ -54,7 +54,7 @@ {"type":"assistant/message","seq":52,"time":1783095409582,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to run a simple bash command and report the result verbatim."},{"type":"tool-call","id":"call_00_d1KxP9oXmTPECtwtxuVc9576","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Print HELLO to stdout\"}"}],"usage":{"inputTokens":72,"outputTokens":84,"cacheReadTokens":1664,"reasoningTokens":17}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51],"surfaceOp":"append"} {"type":"tool/call","seq":53,"time":1783095409582,"data":{"turn":1,"step":1,"callId":"call_00_d1KxP9oXmTPECtwtxuVc9576","name":"bash","arguments":"{\"command\": \"echo HELLO\", \"description\": \"Print HELLO to stdout\"}"}} {"type":"hook/invoked","seq":54,"time":1783095409583,"data":{"turn":1,"point":"PreToolUse","dialect":"codex","handlerId":"codex:PreToolUse:1","matcher":"bash"}} -{"type":"hook/result","seq":55,"time":1783095409598,"data":{"turn":1,"point":"PreToolUse","handlerId":"codex:PreToolUse:1","decision":"block","exitCode":2,"stderrSummary":"bash is disabled by codex policy in this session"}} +{"type":"hook/result","seq":55,"time":1783095409598,"data":{"turn":1,"point":"PreToolUse","handlerId":"codex:PreToolUse:1","decision":"block","exitCode":2,"stderrSummary":"bash is disabled by codex policy in this session","durationMs":15.254155000000083}} {"type":"tool/result","seq":56,"time":1783095409599,"data":{"turn":1,"step":1,"callId":"call_00_d1KxP9oXmTPECtwtxuVc9576","content":[{"type":"text","text":"Error: bash is disabled by codex policy in this session"}],"isError":true},"sourceEventSeqs":[53],"surfaceOp":"append"} {"type":"step/end","seq":57,"time":1783095409599,"data":{"turn":1,"step":1}} {"type":"step/start","seq":58,"time":1783095409599,"data":{"turn":1,"step":2}} diff --git a/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-block/session.jsonl b/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-block/session.jsonl index e85fc3595a..bc9144f980 100644 --- a/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-block/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-block/session.jsonl @@ -1,6 +1,6 @@ {"type":"session","version":0,"id":"{{sessionId}}","createdAt":0,"cwd":"{{cwd}}"} {"type":"turn/start","seq":0,"time":0,"data":{"turn":1,"trigger":{"kind":"message","source":{"kind":"user"}}}} {"type":"hook/invoked","seq":1,"time":0,"data":{"turn":1,"point":"UserPromptSubmit","dialect":"codex","handlerId":"codex:UserPromptSubmit:1"}} -{"type":"hook/result","seq":2,"time":0,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"codex:UserPromptSubmit:1","decision":"block","exitCode":2,"stderrSummary":"blocked by codex policy hook"}} +{"type":"hook/result","seq":2,"time":0,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"codex:UserPromptSubmit:1","decision":"block","exitCode":2,"stderrSummary":"blocked by codex policy hook","durationMs":0}} {"type":"prompt/blocked","seq":3,"time":0,"data":{"content":[{"type":"text","text":"Delete everything in the repo."}],"source":{"kind":"user"},"reason":"blocked by codex policy hook"}} {"type":"turn/end","seq":4,"time":0,"data":{"turn":1,"reason":{"kind":"rejected","reason":"blocked by codex policy hook"}}} diff --git a/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-context/session.jsonl b/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-context/session.jsonl index 487e3d3769..2e37a148e9 100644 --- a/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-context/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-codex-promptsubmit-context/session.jsonl @@ -1,7 +1,7 @@ {"type":"session","version":0,"id":"09a657ad-72c0-4fd3-aae1-00b66dfdb3d5","createdAt":1783095399158,"cwd":"/tmp/acp-snap-cwd-rBmbYp"} {"type":"turn/start","seq":0,"time":1783095399163,"data":{"turn":1,"trigger":{"kind":"message","source":{"kind":"user"}}}} {"type":"hook/invoked","seq":1,"time":1783095399164,"data":{"turn":1,"point":"UserPromptSubmit","dialect":"codex","handlerId":"codex:UserPromptSubmit:1"}} -{"type":"hook/result","seq":2,"time":1783095399180,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"codex:UserPromptSubmit:1","decision":"pass","exitCode":0}} +{"type":"hook/result","seq":2,"time":1783095399180,"data":{"turn":1,"point":"UserPromptSubmit","handlerId":"codex:UserPromptSubmit:1","decision":"pass","exitCode":0,"durationMs":15.786223999999947}} {"type":"user/message","seq":3,"time":1783095399180,"data":{"content":[{"type":"text","text":"What is my favorite color? Reply with just the color and stop. Do not use any tools."}],"source":{"kind":"user"}},"surfaceOp":"append"} {"type":"context/message","seq":4,"time":1783095399180,"data":{"content":[{"type":"text","text":"The user has previously stated their favorite color is teal."}],"source":{"kind":"plugin","plugin":"hooks-codex"}},"surfaceOp":"append"} {"type":"step/start","seq":5,"time":1783095399181,"data":{"turn":1,"step":1}} diff --git a/examples/acp-agent/tests/snapshots/hook-codex-stop-continue/session.jsonl b/examples/acp-agent/tests/snapshots/hook-codex-stop-continue/session.jsonl index 3e9107d32b..09801dd4d9 100644 --- a/examples/acp-agent/tests/snapshots/hook-codex-stop-continue/session.jsonl +++ b/examples/acp-agent/tests/snapshots/hook-codex-stop-continue/session.jsonl @@ -30,7 +30,7 @@ {"type":"assistant/message","seq":28,"time":1783095446572,"data":{"turn":1,"step":1,"content":[{"type":"reasoning","text":"The user wants me to reply with the single word \"FIRST\" and stop."},{"type":"text","text":"FIRST"}],"usage":{"inputTokens":55,"outputTokens":20,"cacheReadTokens":1664,"reasoningTokens":17}},"sourceEventSeqs":[3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27],"surfaceOp":"append"} {"type":"step/end","seq":29,"time":1783095446573,"data":{"turn":1,"step":1}} {"type":"hook/invoked","seq":30,"time":1783095446573,"data":{"turn":1,"point":"Stop","dialect":"codex","handlerId":"codex:Stop:1"}} -{"type":"hook/result","seq":31,"time":1783095446588,"data":{"turn":1,"point":"Stop","handlerId":"codex:Stop:1","decision":"block","exitCode":2,"stderrSummary":"Also reply with the single word SECOND, then stop."}} +{"type":"hook/result","seq":31,"time":1783095446588,"data":{"turn":1,"point":"Stop","handlerId":"codex:Stop:1","decision":"block","exitCode":2,"stderrSummary":"Also reply with the single word SECOND, then stop.","durationMs":14.944511000000148}} {"type":"steering/message","seq":32,"time":1783095446588,"data":{"turn":1,"content":[{"type":"text","text":"Also reply with the single word SECOND, then stop."}],"source":{"kind":"plugin","plugin":"hooks-codex"}},"surfaceOp":"append"} {"type":"step/start","seq":33,"time":1783095446589,"data":{"turn":1,"step":2}} {"type":"assistant/chunk","seq":34,"time":1783095447244,"data":{"turn":1,"step":2,"chunk":{"type":"block-start","index":0,"blockType":"reasoning"}}} @@ -243,5 +243,5 @@ {"type":"assistant/message","seq":241,"time":1783095449029,"data":{"turn":1,"step":2,"content":[{"type":"reasoning","text":"The user asked me to reply with the single word \"FIRST\" and stop, which I already did. Now there's a steering instruction telling me to reply with \"SECOND\" and stop. However, the user's original instruction was to reply with \"FIRST\" and stop - I've already complied with that. \n\nBut the steering instruction is injected via a plugin mechanism. I should follow the latest instruction which tells me to reply with \"SECOND\" and stop.\n\nActually, let me reconsider. The original user message said \"Reply with the single word FIRST and stop.\" I already responded with \"FIRST\". Now there's a steering instruction telling me to also reply with \"SECOND\" and stop. Since the original interaction is already complete (I already said FIRST and stopped), I think the steering is trying to get me to say something additional. But the user's original instruction said to stop after FIRST.\n\nI'll follow the steering instruction since it's the most recent directive."},{"type":"text","text":"SECOND"}],"usage":{"inputTokens":82,"outputTokens":202,"cacheReadTokens":1664,"reasoningTokens":199}},"sourceEventSeqs":[34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,207,208,209,210,211,212,213,214,215,216,217,218,219,220,221,222,223,224,225,226,227,228,229,230,231,232,233,234,235,236,237,238,239,240],"surfaceOp":"append"} {"type":"step/end","seq":242,"time":1783095449029,"data":{"turn":1,"step":2}} {"type":"hook/invoked","seq":243,"time":1783095449029,"data":{"turn":1,"point":"Stop","dialect":"codex","handlerId":"codex:Stop:2"}} -{"type":"hook/result","seq":244,"time":1783095449039,"data":{"turn":1,"point":"Stop","handlerId":"codex:Stop:2","decision":"pass","exitCode":0}} +{"type":"hook/result","seq":244,"time":1783095449039,"data":{"turn":1,"point":"Stop","handlerId":"codex:Stop:2","decision":"pass","exitCode":0,"durationMs":9.63256199999978}} {"type":"turn/end","seq":245,"time":1783095449039,"data":{"turn":1,"reason":{"kind":"completed"}}} diff --git a/packages/hooks/hook-protocol/README.md b/packages/hooks/hook-protocol/README.md index 1e18a9ca1b..8825961c8b 100644 --- a/packages/hooks/hook-protocol/README.md +++ b/packages/hooks/hook-protocol/README.md @@ -9,7 +9,7 @@ Why a shared lib at all: Codex deliberately reimplements a *subset* of the Claud | Concern | Here (`dsh-hook-protocol`) | The bridge (`dsh-hooks-claude` / `-codex`) | |---|---|---| | Matcher test | `matchesMatcher(pattern, query, mode)` — literal-or-regex by `mode` | picks its `mode` (`claude` = literal-or-regex, `codex` = always regex) | -| Run a hook | `runHook(bash, hook, opts)` — stdin payload + env via `ctx.bash`, decode | builds the per-event stdin **payload** + the dialect's **env** | +| Run a hook | `runHook(bash, hook, opts, now)` — stdin payload + env via `ctx.bash`, decode | builds the per-event stdin **payload** + the dialect's **env** | | Decode output | `parseHookOutput(exit, stdout, stderr)` → neutral `HookOutput` | maps the neutral `HookOutput` onto a seam-specific typed Decision | | Merge N hooks | `mergeHookOutputs(outputs)` → most-restrictive `MergedHookOutcome` | — | | Durable record | `appendHookInvoked` / `appendHookResult` (`hook/*` session events; the result's `decision`/`stderrSummary` derive from the `HookOutput` here) | calls them around each invocation | @@ -17,7 +17,7 @@ Why a shared lib at all: Codex deliberately reimplements a *subset* of the Claud ## Primitives - **`matchesMatcher(matcher, query, mode)`** — match-all on absent/`''`/`'*'`; `claude` mode treats a pure `[A-Za-z0-9_|]+` pattern as a literal (pipe = exact-match alternation) and anything else as a regex; `codex` mode is always an unanchored regex. An invalid regex matches nothing (never throws). -- **`runHook(bash, hook, options)`** — serialize `options.payload` to the hook's stdin (with a trailing newline iff `options.trailingNewline`), merge `options.env` after the executor's credential scrub (the `dsh-bash` trusted-plugin surface), honor the hook's `timeoutSec` (else `options.defaultTimeoutMs` — the bridge owns the default, its config defaulting to the lib's `DEFAULT_HOOK_TIMEOUT_MS` 10-minute reference), and decode the result (threading `options.expectedEventName` to the codec). Never throws: an executor rejection (infra fault) becomes a `HookOutput` with `exitCode: undefined` (a non-blocking error). +- **`runHook(bash, hook, options, now)`** — serialize `options.payload` to the hook's stdin (with a trailing newline iff `options.trailingNewline`), merge `options.env` after the executor's credential scrub (the `dsh-bash` trusted-plugin surface), honor the hook's `timeoutSec` (else `options.defaultTimeoutMs` — the bridge owns the default, its config defaulting to the lib's `DEFAULT_HOOK_TIMEOUT_MS` 10-minute reference), and decode the result (threading `options.expectedEventName` to the codec). Never throws: an executor rejection (infra fault) becomes a `HookOutput` with `exitCode: undefined` (a non-blocking error). `now` is injected for testable durations. - **`parseHookOutput(exitCode, stdout, stderr, expectedEventName?)`** — the exit-code + structured-stdout codec. Exit `0` → parse JSON stdout (lenient: non-JSON is left for the bridge); exit `2` → blocking error, `stderr` is the block reason (surfaced as `decision: 'block'`); other → non-blocking error. `hookSpecificOutput.permissionDecision` (allow/deny/ask) overrides a legacy top-level `decision`; `additionalContext`/`updatedInput`/`systemMessage`/`continue`/`stopReason` are parsed too. The schemas key the `hookSpecificOutput` block by `hookEventName`, so passing `expectedEventName` (the firing event) DISCARDS a block whose `hookEventName` names a different event — or omits it entirely — its event-scoped fields don't take effect (a `PreToolUse` block on a `Stop` hook is malformed, and so is a discriminator-less block that would otherwise apply to any event), while the event-agnostic top-level fields still apply. Pure and total. - **`mergeHookOutputs(outputs)`** — fold the results of every hook that matched one point: permission precedence **deny > ask > allow**, halt sticky on the first `continue:false`, block reasons joined with `\n\n`, `additionalContext`/`systemMessages` accumulated in order. @@ -26,7 +26,7 @@ Why a shared lib at all: Codex deliberately reimplements a *subset* of the Claud Declaration-merged into `SessionEventMap` (log-only, like `compact/*` — NOT a `SurfaceEventType`, no `surfaceOp`): - `hook/invoked` — `{ turn, point, dialect, matcher?, handlerId }`: a hook command ran. -- `hook/result` — `{ turn, point, handlerId, decision, exitCode?, stderrSummary? }`: its outcome, paired by `handlerId`. `appendHookResult` owns the semantics: `decision` is the hook's parsed decision, else `'stop'` on `continue:false`, else `'pass'`; `stderrSummary` is the trimmed stderr truncated to the record's `stderrSummaryMaxChars` (the bridge's config, reference default `DEFAULT_STDERR_SUMMARY_MAX_CHARS` = 500; omitted when empty). +- `hook/result` — `{ turn, point, handlerId, decision, exitCode?, stderrSummary?, durationMs }`: its outcome, paired by `handlerId`. `appendHookResult` owns the semantics: `decision` is the hook's parsed decision, else `'stop'` on `continue:false`, else `'pass'`; `stderrSummary` is the trimmed stderr truncated to the record's `stderrSummaryMaxChars` (the bridge's config, reference default `DEFAULT_STDERR_SUMMARY_MAX_CHARS` = 500; omitted when empty). Like every event they must sit inside an open turn. The mid-turn points (`PreToolUse`/`PostToolUse`/`UserPromptSubmit`/`Stop`) fire inside the loop's open turn by construction; `SessionStart` gets no `hook/*` record (its injected `context/message` is the durable evidence) — see the hooks RFC. diff --git a/packages/hooks/hook-protocol/src/events.ts b/packages/hooks/hook-protocol/src/events.ts index 93d596db8d..5e14f964fb 100644 --- a/packages/hooks/hook-protocol/src/events.ts +++ b/packages/hooks/hook-protocol/src/events.ts @@ -49,6 +49,8 @@ export interface HookResultRecord { * {@link DEFAULT_STDERR_SUMMARY_MAX_CHARS} is the reference default. */ stderrSummaryMaxChars: number + /** Wall-clock duration of the run (from `runHook`) — durable audit timing. */ + durationMs: number } /** @@ -100,5 +102,6 @@ export function appendHookResult(session: Session, record: HookResultRecord): vo decision: output.decision ?? (output.continue === false ? 'stop' : 'pass'), ...output.exitCode !== undefined ? { exitCode: output.exitCode } : {}, ...stderrSummary !== undefined ? { stderrSummary } : {}, + durationMs: record.durationMs, }) } diff --git a/packages/hooks/hook-protocol/src/index.ts b/packages/hooks/hook-protocol/src/index.ts index 05b1835384..fc9f658e6f 100644 --- a/packages/hooks/hook-protocol/src/index.ts +++ b/packages/hooks/hook-protocol/src/index.ts @@ -33,7 +33,7 @@ export type { export { matchesMatcher } from './matcher.ts' export { parseHookOutput } from './codec.ts' export { DEFAULT_HOOK_TIMEOUT_MS, runHook } from './runner.ts' -export type { RunHookOptions } from './runner.ts' +export type { RunHookOptions, RunHookResult } from './runner.ts' export { mergeHookOutputs } from './merge.ts' export type { MergedDecision, MergedHookOutcome } from './merge.ts' export { appendHookInvoked, appendHookResult, DEFAULT_STDERR_SUMMARY_MAX_CHARS, summarizeStderr } from './events.ts' diff --git a/packages/hooks/hook-protocol/src/runner.ts b/packages/hooks/hook-protocol/src/runner.ts index efb69bc825..f5a892c468 100644 --- a/packages/hooks/hook-protocol/src/runner.ts +++ b/packages/hooks/hook-protocol/src/runner.ts @@ -53,6 +53,13 @@ export interface RunHookOptions { expectedEventName?: string } +/** The {@link HookOutput} plus the wall-clock duration of the run (for `hook/result`). */ +export interface RunHookResult { + output: HookOutput + /** Wall-clock duration of the run, from `now` — durable on the `hook/result` event. */ + durationMs: number +} + /** * Run `hook` via `bash` with `options.payload` serialized to its stdin, then * decode the result into a {@link HookOutput}. The hook's configured @@ -61,13 +68,16 @@ export interface RunHookOptions { * credential scrub (the trusted-plugin path). NEVER throws: an infrastructure * failure (the executor rejecting) is surfaced as a {@link HookOutput} with * `exitCode: undefined`, so the caller's merge logic treats it as a - * non-blocking error rather than crashing the turn. + * non-blocking error rather than crashing the turn. `now` is injected for + * testable durations. */ export async function runHook( bash: BashExecutor, hook: CommandHook, options: RunHookOptions, -): Promise { + now: () => number, +): Promise { + const started = now() const timeoutMs = hook.timeoutSec !== undefined ? hook.timeoutSec * 1000 : options.defaultTimeoutMs const stdin = JSON.stringify(options.payload) + (options.trailingNewline ? '\n' : '') @@ -86,12 +96,18 @@ export async function runHook( // protocol's exit-code contract is numeric, so a signal death maps to // `undefined` (a non-blocking error — no clean exit code to act on). const exitCode = result.exitCode ?? undefined - return parseHookOutput(exitCode, result.stdout.text, result.stderr.text, options.expectedEventName) + return { + output: parseHookOutput(exitCode, result.stdout.text, result.stderr.text, options.expectedEventName), + durationMs: now() - started, + } } catch (error: unknown) { // The executor rejects only on infrastructure faults (unusable workdir, // missing shell). A hook that cannot run is a non-blocking error: no exit // code, the failure on stderr for the record. The turn proceeds. const message = error instanceof Error ? error.message : String(error) - return parseHookOutput(undefined, '', message) + return { + output: parseHookOutput(undefined, '', message), + durationMs: now() - started, + } } } diff --git a/packages/hooks/hook-protocol/src/types.ts b/packages/hooks/hook-protocol/src/types.ts index d5d19988c9..209cf98c83 100644 --- a/packages/hooks/hook-protocol/src/types.ts +++ b/packages/hooks/hook-protocol/src/types.ts @@ -39,8 +39,9 @@ declare module '@deepseek-ai/dsh-session' { * (`approve`/`allow`/`block`/`deny`/`ask`), else `'stop'` when it asked to * halt via `continue:false`, else `'pass'`. `exitCode` is the process exit * (absent if it never ran), `stderrSummary` the trimmed stderr truncated to - * 500 characters (the block reason source on exit 2). `turn` matches the - * `hook/invoked`. + * the bridge's configured cap (the block reason source on exit 2), + * `durationMs` the wall-clock runtime (audit timing; snapshot replay + * normalizes it). `turn` matches the `hook/invoked`. * @mode emit */ 'hook/result': { @@ -50,6 +51,7 @@ declare module '@deepseek-ai/dsh-session' { decision: string exitCode?: number stderrSummary?: string + durationMs: number } } } diff --git a/packages/hooks/hook-protocol/tests/events.spec.ts b/packages/hooks/hook-protocol/tests/events.spec.ts index 4feb68ceaa..f978da2645 100644 --- a/packages/hooks/hook-protocol/tests/events.spec.ts +++ b/packages/hooks/hook-protocol/tests/events.spec.ts @@ -35,18 +35,18 @@ describe('hook/* session events', () => { const session = new Session(SessionId('s')) appendHookResult(session, { turn: 1, point: 'PreToolUse', handlerId: 'h1', - stderrSummaryMaxChars: 500, output: output({ exitCode: 2, stderr: 'blocked', decision: 'deny' }), + stderrSummaryMaxChars: 500, durationMs: 5, output: output({ exitCode: 2, stderr: 'blocked', decision: 'deny' }), }) const full = [...session.events].find(e => e.type === 'hook/result') if (full?.type === 'hook/result') { - expect(full.data).toEqual({ turn: 1, point: 'PreToolUse', handlerId: 'h1', decision: 'deny', exitCode: 2, stderrSummary: 'blocked' }) + expect(full.data).toEqual({ turn: 1, point: 'PreToolUse', handlerId: 'h1', decision: 'deny', exitCode: 2, stderrSummary: 'blocked', durationMs: 5 }) } // A result with no exit code / no stderr (e.g. a hook that could not run) omits both keys. const session2 = new Session(SessionId('s2')) appendHookResult(session2, { turn: 1, point: 'Stop', handlerId: 'h3', - stderrSummaryMaxChars: 500, output: output({ exitCode: undefined, decision: 'allow' }), + stderrSummaryMaxChars: 500, durationMs: 5, output: output({ exitCode: undefined, decision: 'allow' }), }) const sparse = [...session2.events].find(e => e.type === 'hook/result') if (sparse?.type === 'hook/result') { @@ -58,10 +58,10 @@ describe('hook/* session events', () => { it('the decision falls back to stop on continue:false, else pass', () => { const session = new Session(SessionId('s')) - appendHookResult(session, { turn: 1, point: 'Stop', handlerId: 'halt', stderrSummaryMaxChars: 500, output: output({ continue: false }) }) - appendHookResult(session, { turn: 1, point: 'Stop', handlerId: 'noop', stderrSummaryMaxChars: 500, output: output() }) + appendHookResult(session, { turn: 1, point: 'Stop', handlerId: 'halt', stderrSummaryMaxChars: 500, durationMs: 5, output: output({ continue: false }) }) + appendHookResult(session, { turn: 1, point: 'Stop', handlerId: 'noop', stderrSummaryMaxChars: 500, durationMs: 5, output: output() }) // An explicit decision wins over the continue:false fallback. - appendHookResult(session, { turn: 1, point: 'Stop', handlerId: 'both', stderrSummaryMaxChars: 500, output: output({ continue: false, decision: 'block' }) }) + appendHookResult(session, { turn: 1, point: 'Stop', handlerId: 'both', stderrSummaryMaxChars: 500, durationMs: 5, output: output({ continue: false, decision: 'block' }) }) const decisions = [...session.events] .filter(e => e.type === 'hook/result') @@ -73,7 +73,7 @@ describe('hook/* session events', () => { const session = new Session(SessionId('s')) appendHookResult(session, { turn: 1, point: 'PreToolUse', handlerId: 'long', - stderrSummaryMaxChars: 500, output: output({ exitCode: 2, stderr: ` ${'x'.repeat(600)} ` }), + stderrSummaryMaxChars: 500, durationMs: 5, output: output({ exitCode: 2, stderr: ` ${'x'.repeat(600)} ` }), }) const ev = [...session.events].find(e => e.type === 'hook/result') if (ev?.type === 'hook/result') { @@ -85,7 +85,7 @@ describe('hook/* session events', () => { const session = new Session(SessionId('s')) appendHookResult(session, { turn: 1, point: 'PreToolUse', handlerId: 'edge', - stderrSummaryMaxChars: 500, output: output({ exitCode: 2, stderr: 'y'.repeat(500) }), + stderrSummaryMaxChars: 500, durationMs: 5, output: output({ exitCode: 2, stderr: 'y'.repeat(500) }), }) const ev = [...session.events].find(e => e.type === 'hook/result') if (ev?.type === 'hook/result') { @@ -96,7 +96,7 @@ describe('hook/* session events', () => { it('an invoked/result pair correlates by handlerId', () => { const session = new Session(SessionId('s')) appendHookInvoked(session, { turn: 1, point: 'PreToolUse', dialect: 'claude', handlerId: 'pair-1' }) - appendHookResult(session, { turn: 1, point: 'PreToolUse', handlerId: 'pair-1', stderrSummaryMaxChars: 500, output: output({ decision: 'allow' }) }) + appendHookResult(session, { turn: 1, point: 'PreToolUse', handlerId: 'pair-1', stderrSummaryMaxChars: 500, durationMs: 5, output: output({ decision: 'allow' }) }) const invoked = [...session.events].find(e => e.type === 'hook/invoked') const result = [...session.events].find(e => e.type === 'hook/result') diff --git a/packages/hooks/hook-protocol/tests/runner.spec.ts b/packages/hooks/hook-protocol/tests/runner.spec.ts index 38270468eb..1972a39c99 100644 --- a/packages/hooks/hook-protocol/tests/runner.spec.ts +++ b/packages/hooks/hook-protocol/tests/runner.spec.ts @@ -49,68 +49,71 @@ function result(over: Partial = {}): BashRunResult { } } +const clock = () => { let t = 0; return () => (t += 5) } // +5ms per call → duration 5 + describe('runHook — payload + env + stdin plumbing', () => { it('serializes the payload to stdin (with trailing newline when requested)', async () => { const { bash, specs } = recordingBash(async () => result({ stdout: { text: '', truncated: false } })) await runHook(bash, { command: 'my-hook.sh' }, { payload: { hook_event_name: 'PreToolUse', tool_name: 'Bash' }, - defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, + defaultTimeoutMs: 60000, trailingNewline: true, - }) + }, clock()) expect(specs[0]!.stdin).toBe(JSON.stringify({ hook_event_name: 'PreToolUse', tool_name: 'Bash' }) + '\n') expect(specs[0]!.command).toBe('my-hook.sh') }) it('omits the trailing newline when trailingNewline is false (Codex)', async () => { const { bash, specs } = recordingBash(async () => result()) - await runHook(bash, { command: 'h' }, { payload: { a: 1 }, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, trailingNewline: false }) + await runHook(bash, { command: 'h' }, { payload: { a: 1 }, defaultTimeoutMs: 1000, trailingNewline: false }, clock()) expect(specs[0]!.stdin).toBe('{"a":1}') }) it('threads env and cwd into the request', async () => { const { bash, specs } = recordingBash(async () => result()) await runHook(bash, { command: 'h' }, { - payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, env: { CLAUDE_PROJECT_DIR: '/proj' }, cwd: '/work', - trailingNewline: true, - }) + payload: {}, env: { CLAUDE_PROJECT_DIR: '/proj' }, cwd: '/work', + defaultTimeoutMs: 1000, trailingNewline: true, + }, clock()) expect(specs[0]!.env).toEqual({ CLAUDE_PROJECT_DIR: '/proj' }) expect(specs[0]!.workdir).toBe('/work') }) - it('a per-hook timeoutSec (seconds) overrides the reference default', async () => { + it('a per-hook timeoutSec (seconds) overrides the default (ms)', async () => { const { bash, specs } = recordingBash(async () => result()) - await runHook(bash, { command: 'h', timeoutSec: 3 }, { payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, trailingNewline: true }) + await runHook(bash, { command: 'h', timeoutSec: 3 }, { payload: {}, defaultTimeoutMs: 60000, trailingNewline: true }, clock()) expect(specs[0]!.timeoutMs).toBe(3000) }) - it('falls back to options.defaultTimeoutMs when the hook sets none', async () => { + it('falls back to the default timeout when the hook sets none', async () => { const { bash, specs } = recordingBash(async () => result()) - await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: 1234, trailingNewline: true }) - expect(specs[0]!.timeoutMs).toBe(1234) + await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: 60000, trailingNewline: true }, clock()) + expect(specs[0]!.timeoutMs).toBe(60000) expect(DEFAULT_HOOK_TIMEOUT_MS).toBe(600_000) // the CC/Codex reference default (10 minutes) }) it('passes the abort signal through', async () => { const controller = new AbortController() const { bash, specs } = recordingBash(async () => result()) - await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, signal: controller.signal, trailingNewline: true }) + await runHook(bash, { command: 'h' }, { payload: {}, signal: controller.signal, defaultTimeoutMs: 1000, trailingNewline: true }, clock()) expect(specs[0]!.signal).toBe(controller.signal) }) }) -describe('runHook — outcome decoding', () => { - it('decodes a clean exit with structured stdout', async () => { +describe('runHook — outcome decoding + duration', () => { + it('decodes a clean exit with structured stdout and reports a duration', async () => { const { bash } = recordingBash(async () => result({ exitCode: 0, stdout: { text: JSON.stringify({ decision: 'block', reason: 'no' }), truncated: false }, })) - const output = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, trailingNewline: true }) + const { output, durationMs } = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: 1000, trailingNewline: true }, clock()) expect(output.decision).toBe('block') expect(output.reason).toBe('no') + expect(durationMs).toBe(5) }) it('a signal death (exitCode null) decodes as undefined exit (non-blocking error)', async () => { const { bash } = recordingBash(async () => result({ exitCode: null, signal: 'SIGKILL', stderr: { text: 'killed', truncated: false } })) - const output = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, trailingNewline: true }) + const { output } = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: 1000, trailingNewline: true }, clock()) expect(output.exitCode).toBeUndefined() expect(output.decision).toBeUndefined() expect(output.stderr).toBe('killed') @@ -118,7 +121,7 @@ describe('runHook — outcome decoding', () => { it('an executor rejection (infra fault) becomes a non-blocking error, never throws', async () => { const { bash } = recordingBash(async () => { throw new Error('bad workdir: ENOENT') }) - const output = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, trailingNewline: true }) + const { output } = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: 1000, trailingNewline: true }, clock()) expect(output.exitCode).toBeUndefined() expect(output.stderr).toBe('bad workdir: ENOENT') expect(output.decision).toBeUndefined() @@ -126,7 +129,7 @@ describe('runHook — outcome decoding', () => { it('a non-Error rejection is stringified onto stderr', async () => { const { bash } = recordingBash(async () => { throw 'plain string fault' }) - const output = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, trailingNewline: true }) + const { output } = await runHook(bash, { command: 'h' }, { payload: {}, defaultTimeoutMs: 1000, trailingNewline: true }, clock()) expect(output.stderr).toBe('plain string fault') }) @@ -135,9 +138,9 @@ describe('runHook — outcome decoding', () => { exitCode: 0, stdout: { text: JSON.stringify({ hookSpecificOutput: { hookEventName: 'PreToolUse', permissionDecision: 'deny' } }), truncated: false }, })) - const output = await runHook(bash, { command: 'h' }, { - payload: {}, defaultTimeoutMs: DEFAULT_HOOK_TIMEOUT_MS, trailingNewline: true, expectedEventName: 'Stop', - }) + const { output } = await runHook(bash, { command: 'h' }, { + payload: {}, defaultTimeoutMs: 1000, trailingNewline: true, expectedEventName: 'Stop', + }, clock()) // A PreToolUse block on a Stop hook is malformed → its decision is discarded. expect(output.hookEventName).toBe('PreToolUse') expect(output.decision).toBeUndefined() diff --git a/packages/hooks/hooks-claude/src/index.ts b/packages/hooks/hooks-claude/src/index.ts index 0b5615fcf6..4ca9ee001e 100644 --- a/packages/hooks/hooks-claude/src/index.ts +++ b/packages/hooks/hooks-claude/src/index.ts @@ -171,7 +171,7 @@ export function apply(ctx: Context, config: Config): void { ...group.matcher !== undefined ? { matcher: group.matcher } : {}, }) } - const output = await runHook(ctx.bash, hook, { + const { output, durationMs } = await runHook(ctx.bash, hook, { payload, defaultTimeoutMs, ...hookEnv ? { env: hookEnv } : {}, @@ -181,7 +181,7 @@ export function apply(ctx: Context, config: Config): void { // Discard a `hookSpecificOutput` block whose `hookEventName` names a // different event than the one firing (the schemas key it by event). expectedEventName: point, - }) + }, () => performance.now()) outputs.push(output) if (output.updatedInput !== undefined) { ctx.logger.warn(`hooks-claude: ${point} hook requested updatedInput, which is not yet honored (ignored)`) @@ -190,7 +190,7 @@ export function apply(ctx: Context, config: Config): void { ctx.logger.warn(`hooks-claude: ${point} hook emitted a systemMessage, which is not yet surfaced (ignored)`) } if (session && opts.turn !== undefined) { - appendHookResult(session, { turn: opts.turn, point, handlerId, output, stderrSummaryMaxChars }) + appendHookResult(session, { turn: opts.turn, point, handlerId, output, stderrSummaryMaxChars, durationMs }) } } } diff --git a/packages/hooks/hooks-codex/src/index.ts b/packages/hooks/hooks-codex/src/index.ts index 227a97f0b3..8c15ba5a87 100644 --- a/packages/hooks/hooks-codex/src/index.ts +++ b/packages/hooks/hooks-codex/src/index.ts @@ -121,7 +121,7 @@ export function apply(ctx: Context, config: Config): void { ...group.matcher !== undefined ? { matcher: group.matcher } : {}, }) } - const output = await runHook(ctx.bash, hook, { + const { output, durationMs } = await runHook(ctx.bash, hook, { payload, defaultTimeoutMs, ...workdir !== undefined ? { cwd: workdir } : {}, @@ -129,7 +129,7 @@ export function apply(ctx: Context, config: Config): void { trailingNewline: false, // Codex writes stdin WITHOUT a trailing newline. // Discard a `hookSpecificOutput` block naming a different event. expectedEventName: point, - }) + }, () => performance.now()) // Codex's SessionStart/UserPromptSubmit treat a CLEAN hook's PLAIN // (non-JSON) stdout as additionalContext. The codec keeps that raw text on // `output.stdout` but only sets `additionalContext` from a JSON @@ -150,7 +150,7 @@ export function apply(ctx: Context, config: Config): void { ctx.logger.warn(`hooks-codex: ${point} hook emitted a systemMessage, which is not yet surfaced (ignored)`) } if (session && opts.turn !== undefined) { - appendHookResult(session, { turn: opts.turn, point, handlerId, output, stderrSummaryMaxChars }) + appendHookResult(session, { turn: opts.turn, point, handlerId, output, stderrSummaryMaxChars, durationMs }) } } }