test(snapshot): await cancelled turn durability

This commit is contained in:
Tianyi Cui
2026-07-22 22:00:48 +08:00
parent 3679b4d829
commit ad4c37013a
6 changed files with 116 additions and 6 deletions

View File

@@ -7,6 +7,7 @@
"text": "Run two shell commands: wait for cancellation, then write skipped.txt.", "text": "Run two shell commands: wait for cancellation, then write skipped.txt.",
"afterUpdate": "tool_call", "afterUpdate": "tool_call",
"waitForToolCallUpdate": "call_skipped" "waitForToolCallUpdate": "call_skipped"
} },
{ "op": "waitForTurnEnd" }
] ]
} }

View File

@@ -18,4 +18,4 @@
{"type":"tool/call","seq":16,"time":1784437195089,"data":{"turn":1,"step":1,"callId":"call_skipped","name":"bash","arguments":"{\"command\":\"printf skipped > skipped.txt\",\"description\":\"Write skipped marker\"}"}} {"type":"tool/call","seq":16,"time":1784437195089,"data":{"turn":1,"step":1,"callId":"call_skipped","name":"bash","arguments":"{\"command\":\"printf skipped > skipped.txt\",\"description\":\"Write skipped marker\"}"}}
{"type":"tool/result","seq":17,"time":1784437195089,"data":{"turn":1,"step":1,"callId":"call_skipped","content":[{"type":"text","text":"Error: tool call aborted before dispatch"}],"isError":true,"error":{"name":"AbortError","code":"ABORTED_BEFORE_DISPATCH"}},"sourceEventSeqs":[16],"surfaceOp":"append"} {"type":"tool/result","seq":17,"time":1784437195089,"data":{"turn":1,"step":1,"callId":"call_skipped","content":[{"type":"text","text":"Error: tool call aborted before dispatch"}],"isError":true,"error":{"name":"AbortError","code":"ABORTED_BEFORE_DISPATCH"}},"sourceEventSeqs":[16],"surfaceOp":"append"}
{"type":"step/end","seq":18,"time":1784437195090,"data":{"turn":1,"step":1}} {"type":"step/end","seq":18,"time":1784437195090,"data":{"turn":1,"step":1}}
{"type":"turn/end","seq":19,"time":1784437195090,"data":{"turn":1,"reason":{"kind":"disposed"}}} {"type":"turn/end","seq":19,"time":1784437195090,"data":{"turn":1,"reason":{"kind":"aborted"}}}

View File

@@ -2,6 +2,7 @@
"steps": [ "steps": [
{ "op": "initialize" }, { "op": "initialize" },
{ "op": "newSession" }, { "op": "newSession" },
{ "op": "promptAndCancel", "text": "Start a long task; this turn will be cancelled mid-stream." } { "op": "promptAndCancel", "text": "Start a long task; this turn will be cancelled mid-stream." },
{ "op": "waitForTurnEnd" }
] ]
} }

View File

@@ -21,6 +21,7 @@ import { existsSync } from 'node:fs'
import { createHash } from 'node:crypto' import { createHash } from 'node:crypto'
import { tmpdir } from 'node:os' import { tmpdir } from 'node:os'
import { basename, dirname, join, delimiter } from 'node:path' import { basename, dirname, join, delimiter } from 'node:path'
import { setTimeout as delay } from 'node:timers/promises'
import { import {
ClientSideConnection, ClientSideConnection,
PROTOCOL_VERSION, PROTOCOL_VERSION,
@@ -34,6 +35,9 @@ import { launchAcpTestAgent, type AgentUnderTest, type LaunchedAcpTestAgent } fr
export type { AgentUnderTest } from './launcher.ts' export type { AgentUnderTest } from './launcher.ts'
const DEFAULT_TURN_END_TIMEOUT_MS = 10_000
const TURN_END_POLL_INTERVAL_MS = 10
/** /**
* One step of a scenario's deterministic input script (`input.json`). The * One step of a scenario's deterministic input script (`input.json`). The
* harness interprets these in order. `newSession` captures the server-issued * harness interprets these in order. `newSession` captures the server-issued
@@ -46,6 +50,8 @@ export type { AgentUnderTest } from './launcher.ts'
* step open for a terminal tool update that may follow the prompt response. * step open for a terminal tool update that may follow the prompt response.
* `promptAndWaitForAgentMessage` arms an exact text-chunk waiter before sending * `promptAndWaitForAgentMessage` arms an exact text-chunk waiter before sending
* the prompt, then keeps the application live until that later update arrives. * the prompt, then keeps the application live until that later update arrives.
* `waitForTurnEnd` holds the subprocess open until the selected session's latest
* complete raw-JSONL turn boundary is `turn/end`; its timeout defaults to 10s.
*/ */
export type InputStep = export type InputStep =
| { op: 'initialize'; terminalOutput?: boolean } | { op: 'initialize'; terminalOutput?: boolean }
@@ -60,6 +66,7 @@ export type InputStep =
afterUpdate?: 'agent_message_chunk' | 'tool_call' afterUpdate?: 'agent_message_chunk' | 'tool_call'
waitForToolCallUpdate?: string waitForToolCallUpdate?: string
} }
| { op: 'waitForTurnEnd'; timeoutMs?: number }
| { op: 'cancel' } | { op: 'cancel' }
| { op: 'setMode'; modeId: string } | { op: 'setMode'; modeId: string }
| { op: 'setModeExpectError'; modeId: string } | { op: 'setModeExpectError'; modeId: string }
@@ -295,7 +302,15 @@ export async function runScenario(input: InputScript, opts: RunOptions): Promise
const { client } = active const { client } = active
for (const step of input.steps) { for (const step of input.steps) {
await runStep(client, step, cwd, match => active.waitForUpdate(match), () => sessionId, (id) => { sessionId = id }) await runStep(
client,
step,
cwd,
match => active.waitForUpdate(match),
() => sessionId,
(id) => { sessionId = id },
(id, timeoutMs) => waitForPersistedTurnEnd(sessionsRoot, id, timeoutMs),
)
// A permission exchange happens while a step's request is in flight, so // A permission exchange happens while a step's request is in flight, so
// by the time the step settles any script bug it exposed is captured — // by the time the step settles any script bug it exposed is captured —
// fail the run HERE, as a harness error, rather than hoping the agent's // fail the run HERE, as a harness error, rather than hoping the agent's
@@ -365,6 +380,7 @@ async function runStep(
waitForUpdate: (match: (u: SessionNotification['update']) => boolean) => Promise<SessionNotification['update']>, waitForUpdate: (match: (u: SessionNotification['update']) => boolean) => Promise<SessionNotification['update']>,
getSessionId: () => string | undefined, getSessionId: () => string | undefined,
setSessionId: (id: string) => void, setSessionId: (id: string) => void,
waitForTurnEnd: (sessionId: string, timeoutMs?: number) => Promise<void>,
): Promise<void> { ): Promise<void> {
switch (step.op) { switch (step.op) {
case 'initialize': case 'initialize':
@@ -438,6 +454,12 @@ async function runStep(
if (toolCallUpdateDone !== undefined) await toolCallUpdateDone if (toolCallUpdateDone !== undefined) await toolCallUpdateDone
return return
} }
case 'waitForTurnEnd': {
const sessionId = getSessionId()
if (sessionId === undefined) throw new Error('snapshot-harness: waitForTurnEnd before newSession')
await waitForTurnEnd(sessionId, step.timeoutMs)
return
}
case 'cancel': { case 'cancel': {
const sessionId = getSessionId() const sessionId = getSessionId()
if (sessionId === undefined) throw new Error('snapshot-harness: cancel before newSession') if (sessionId === undefined) throw new Error('snapshot-harness: cancel before newSession')
@@ -485,6 +507,35 @@ async function runStep(
} }
} }
/**
* Wait until the raw JSONL backend exposes one complete closing turn boundary.
* The ACP cancel notification settles its prompt before the agent necessarily
* reaches quiescence, so cancellation snapshots use this external boundary to
* keep subprocess disposal from changing an `aborted` turn into `disposed`.
*/
async function waitForPersistedTurnEnd(
root: string,
sessionId: string,
timeoutMs = DEFAULT_TURN_END_TIMEOUT_MS,
): Promise<void> {
const deadline = Date.now() + timeoutMs
while (true) {
const log = (await harvestSessionLogs(root)).find(candidate => candidate.id === sessionId)
if (log !== undefined && latestTurnIsClosed(log.content)) return
if (Date.now() >= deadline) {
throw new Error(`snapshot-harness: session "${sessionId}" did not persist turn/end within ${timeoutMs}ms`)
}
await delay(TURN_END_POLL_INTERVAL_MS)
}
}
/** Return whether the last complete raw-JSONL turn boundary closes its turn. */
function latestTurnIsClosed(content: string): boolean {
const complete = content.slice(0, content.lastIndexOf('\n') + 1)
return complete.lastIndexOf('\n{"type":"turn/end",')
> complete.lastIndexOf('\n{"type":"turn/start",')
}
/** /**
* Harvest EVERY persisted `.jsonl` session log under a sessions root, parse each * Harvest EVERY persisted `.jsonl` session log under a sessions root, parse each
* header line, and return them ordered primary-first: the top-level session (no * header line, and return them ordered primary-first: the top-level session (no

View File

@@ -49,6 +49,8 @@ interface Behavior {
cancelAtToolCall?: boolean cancelAtToolCall?: boolean
/** Emit the parked tool call's terminal update after answering cancellation. */ /** Emit the parked tool call's terminal update after answering cancellation. */
cancelToolCallUpdate?: boolean cancelToolCallUpdate?: boolean
/** Persist the scripted logs while handling cancellation, before stdin EOF. */
persistLogsOnCancel?: boolean
/** Before responding to a prompt, send a `session/request_permission` request and echo its outcome as a chunk. */ /** Before responding to a prompt, send a `session/request_permission` request and echo its outcome as a chunk. */
permissionProbe?: boolean permissionProbe?: boolean
/** Before responding to a prompt, send an `elicitation/create` request and echo its response as a chunk. */ /** Before responding to a prompt, send an `elicitation/create` request and echo its response as a chunk. */
@@ -63,7 +65,7 @@ interface Behavior {
stderrNote?: string stderrNote?: string
/** Let a short-lived descendant retain stdio and emit one final ACP update plus stderr line after this parent exits. */ /** Let a short-lived descendant retain stdio and emit one final ACP update plus stderr line after this parent exits. */
lateInheritedOutput?: boolean lateInheritedOutput?: boolean
/** Session logs to persist on stdin EOF. */ /** Session logs to persist on stdin EOF and, when selected, on cancellation. */
logs?: ScriptedLog[] logs?: ScriptedLog[]
/** Leave a stray FILE directly under the sessions root (harvest must skip it). */ /** Leave a stray FILE directly under the sessions root (harvest must skip it). */
strayRootFile?: boolean strayRootFile?: boolean
@@ -304,6 +306,7 @@ function handleFrame(frame: Record<string, unknown>): void {
}, },
}) })
} }
if (behavior.persistLogsOnCancel === true) writeLogs()
} }
return return
default: default:
@@ -313,12 +316,16 @@ function handleFrame(frame: Record<string, unknown>): void {
} }
} }
function flushLogsAndExit(): void { function writeLogs(): void {
for (const log of behavior.logs ?? []) { for (const log of behavior.logs ?? []) {
const target = join(sessionsRoot, log.file) const target = join(sessionsRoot, log.file)
mkdirSync(dirname(target), { recursive: true }) mkdirSync(dirname(target), { recursive: true })
writeFileSync(target, log.lines.map(l => JSON.stringify(instantiate(l))).join('\n') + '\n') writeFileSync(target, log.lines.map(l => JSON.stringify(instantiate(l))).join('\n') + '\n')
} }
}
function flushLogsAndExit(): void {
writeLogs()
if (behavior.strayRootFile === true) writeFileSync(join(sessionsRoot, 'stray.txt'), 'not a bucket\n') if (behavior.strayRootFile === true) writeFileSync(join(sessionsRoot, 'stray.txt'), 'not a bucket\n')
if (behavior.strayBucketFile === true) { if (behavior.strayBucketFile === true) {
mkdirSync(join(sessionsRoot, 'bucket-noise'), { recursive: true }) mkdirSync(join(sessionsRoot, 'bucket-noise'), { recursive: true })

View File

@@ -530,6 +530,55 @@ describe('runScenario', () => {
expect(result.rawStdout.indexOf('cancelled')).toBeLessThan(result.rawStdout.indexOf('"sessionUpdate":"tool_call_update"')) expect(result.rawStdout.indexOf('cancelled')).toBeLessThan(result.rawStdout.indexOf('"sessionUpdate":"tool_call_update"'))
}) })
it('waitForTurnEnd holds cancellation open through the persisted closing boundary', { timeout: 20_000 }, async () => {
const { fixtureFile } = await scenario({
prompt: 'hang-until-cancel',
persistLogsOnCancel: true,
logs: [{
file: 'bucket/session.jsonl',
lines: [
{ type: 'session', version: 0, id: '{{SID}}', createdAt: 1, delegationDepth: 0 },
{ type: 'turn/end', seq: 1, time: 2, data: { turn: 1, reason: { kind: 'aborted' } } },
],
}],
})
const result = await runScenario(
{ steps: [...boot, { op: 'promptAndCancel', text: 'hang' }, { op: 'waitForTurnEnd' }] },
{ agent: AGENT, mode: 'replay', fixtureFile },
)
expect(result.sessionLogs[0]?.content).toContain('"type":"turn/end"')
})
it('waitForTurnEnd times out for a missing log and an open logged turn', { timeout: 20_000 }, async () => {
const missing = await scenario({})
await expect(runScenario(
{ steps: [...boot, { op: 'waitForTurnEnd', timeoutMs: 20 }] },
{ agent: AGENT, mode: 'replay', fixtureFile: missing.fixtureFile },
)).rejects.toThrow(/did not persist turn\/end within 20ms/)
const open = await scenario({
prompt: 'hang-until-cancel',
persistLogsOnCancel: true,
logs: [{
file: 'bucket/session.jsonl',
lines: [
{ type: 'session', version: 0, id: '{{SID}}', createdAt: 1, delegationDepth: 0 },
{ type: 'turn/start', seq: 0, time: 1, data: { turn: 1 } },
],
}],
})
await expect(runScenario(
{
steps: [
...boot,
{ op: 'promptAndCancel', text: 'hang' },
{ op: 'waitForTurnEnd', timeoutMs: 20 },
],
},
{ agent: AGENT, mode: 'replay', fixtureFile: open.fixtureFile },
)).rejects.toThrow(/did not persist turn\/end within 20ms/)
})
it('promptExpectError swallows a model-error response as the expected outcome', { timeout: 20_000 }, async () => { it('promptExpectError swallows a model-error response as the expected outcome', { timeout: 20_000 }, async () => {
const { fixtureFile } = await scenario({ prompt: 'error' }) const { fixtureFile } = await scenario({ prompt: 'error' })
const result = await runScenario( const result = await runScenario(
@@ -620,6 +669,7 @@ describe('runScenario', () => {
[{ op: 'promptAndWaitForAgentMessage', text: 'x', waitForText: 'later' }, /promptAndWaitForAgentMessage before newSession/], [{ op: 'promptAndWaitForAgentMessage', text: 'x', waitForText: 'later' }, /promptAndWaitForAgentMessage before newSession/],
[{ op: 'promptExpectError', text: 'x' }, /promptExpectError before newSession/], [{ op: 'promptExpectError', text: 'x' }, /promptExpectError before newSession/],
[{ op: 'promptAndCancel', text: 'x' }, /promptAndCancel before newSession/], [{ op: 'promptAndCancel', text: 'x' }, /promptAndCancel before newSession/],
[{ op: 'waitForTurnEnd' }, /waitForTurnEnd before newSession/],
[{ op: 'cancel' }, /cancel before newSession/], [{ op: 'cancel' }, /cancel before newSession/],
[{ op: 'setConfigOption', configId: 'sandbox-mode', value: 'read-only' }, /setConfigOption before newSession/], [{ op: 'setConfigOption', configId: 'sandbox-mode', value: 'read-only' }, /setConfigOption before newSession/],
[{ op: 'setConfigOptionExpectError', configId: 'sandbox-mode', value: 'yolo' }, /setConfigOptionExpectError before newSession/], [{ op: 'setConfigOptionExpectError', configId: 'sandbox-mode', value: 'yolo' }, /setConfigOptionExpectError before newSession/],