restore hook/result durationMs — review keeps wall-clock audit timing durable
Reverses item 3 of the tighten-hook-protocol-contract RFC per review: a persistence log is written for future readers, and hook wall-clock runtime is audit signal (which hook made a turn slow). runHook keeps its injected now clock and RunHookResult wrapper, the bridges pass the measured duration through HookResultRecord, the snapshot normalizer keeps its replay scrub, and the hook fixtures carry the field again. The RFC records the reversal; the other three prunes stand.
This commit is contained in:
Tianyi Cui
@@ -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')
|
||||
|
||||
@@ -49,68 +49,71 @@ function result(over: Partial<BashRunResult> = {}): 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()
|
||||
|
||||
Reference in New Issue
Block a user