From 4270beb41080a06d87d202f96f3e3948e009819c Mon Sep 17 00:00:00 2001 From: tanzhenxin Date: Thu, 11 Jun 2026 00:08:26 +0800 Subject: [PATCH] test(integration): harden flaky sleep-interception e2e against skipped tool calls (#4936) The model sometimes answered the old prompts without ever calling the shell tool, timing out waitForToolCall and burning ~230s per CI run with retries. Prompts now explicitly require a run_shell_command call, assertions key off recorded telemetry (blocked call with success: false and Monitor guidance in the error) instead of model narration, and failures print debug info. --- .../cli/sleep-interception.test.ts | 165 ++++++++++++++---- integration-tests/test-helper.ts | 8 + 2 files changed, 141 insertions(+), 32 deletions(-) diff --git a/integration-tests/cli/sleep-interception.test.ts b/integration-tests/cli/sleep-interception.test.ts index c8737f4646..cf2feb404b 100644 --- a/integration-tests/cli/sleep-interception.test.ts +++ b/integration-tests/cli/sleep-interception.test.ts @@ -5,7 +5,11 @@ */ import { describe, it, expect, afterEach } from 'vitest'; -import { TestRig, validateModelOutput } from '../test-helper.js'; +import { + TestRig, + printDebugInfo, + validateModelOutput, +} from '../test-helper.js'; describe('sleep-interception', () => { let rig: TestRig; @@ -16,24 +20,80 @@ describe('sleep-interception', () => { } }); + type ShellCall = { + args: string; + success: boolean; + error?: string; + }; + + /** + * Poll telemetry for a run_shell_command call matching the predicate. + * The model's narration is unreliable (it may retry, paraphrase, or skip + * the scripted reply), so assertions key off the recorded tool calls — + * blocked calls are logged too, with success: false and the block + * message in the error attribute. + */ + const waitForShellCall = (predicate: (call: ShellCall) => boolean) => + rig.poll( + () => + rig + .readToolLogs() + .some( + (log) => + log.toolRequest.name === 'run_shell_command' && + predicate(log.toolRequest), + ), + rig.getDefaultTimeout(), + 100, + ); + + const shellCalls = (): ShellCall[] => + rig + .readToolLogs() + .filter((log) => log.toolRequest.name === 'run_shell_command') + .map((log) => log.toolRequest); + it('should block sleep >= 2s and mention Monitor in guidance', async () => { rig = new TestRig(); await rig.setup('sleep-blocked'); const result = await rig.run( - 'Run this exact shell command: sleep 5. ' + - 'If the command is blocked, say "BLOCKED" and explain why. ' + - 'If it succeeds, say "SUCCESS".', + 'Use the run_shell_command tool to run this exact command in the ' + + 'foreground: sleep 5. You must actually call run_shell_command — ' + + 'do not predict the outcome without calling the tool, do not set ' + + 'is_background, and do not modify the command. If the tool reports ' + + 'the command was blocked, say "BLOCKED". If it executed ' + + 'successfully, say "SUCCESS".', ); - validateModelOutput(result, null, 'sleep blocked'); + const foundBlockedCall = await waitForShellCall( + (call) => call.args.includes('sleep 5') && !call.success, + ); - // The model should report being blocked, since sleep 5 triggers interception - const foundShell = await rig.waitForToolCall('run_shell_command'); - expect(foundShell).toBeTruthy(); + if (!foundBlockedCall) { + printDebugInfo(rig, result, { + 'Shell calls': JSON.stringify(shellCalls()), + }); + } - // The model's output should mention it was blocked - expect(result.toLowerCase()).toContain('blocked'); + expect( + foundBlockedCall, + 'Expected a blocked (success: false) run_shell_command call for sleep 5', + ).toBeTruthy(); + + // The block guidance must point the model at the Monitor tool. The + // error attribute is only available from file-based telemetry; the + // podman stdout fallback leaves it undefined. + const blockedCall = shellCalls().find( + (call) => call.args.includes('sleep 5') && !call.success, + ); + if (blockedCall?.error !== undefined) { + expect(blockedCall.error).toContain('Monitor'); + } + + // Narration is best-effort: warns instead of failing if the model + // phrases the block differently. + validateModelOutput(result, 'blocked', 'sleep blocked'); }); it('should allow sleep < 2s', async () => { @@ -41,16 +101,27 @@ describe('sleep-interception', () => { await rig.setup('sleep-allowed'); const result = await rig.run( - 'Run this exact shell command: sleep 1. Then say "DONE".', + 'Use the run_shell_command tool to run this exact command: sleep 1. ' + + 'You must actually call run_shell_command with that command — do ' + + 'not skip it. After it completes, say "DONE".', ); - validateModelOutput(result, null, 'sleep allowed'); + const foundSuccessfulCall = await waitForShellCall( + (call) => call.args.includes('sleep 1') && call.success, + ); - const foundShell = await rig.waitForToolCall('run_shell_command'); - expect(foundShell).toBeTruthy(); + if (!foundSuccessfulCall) { + printDebugInfo(rig, result, { + 'Shell calls': JSON.stringify(shellCalls()), + }); + } - // Should not be blocked — model should complete successfully - expect(result.toLowerCase()).not.toContain('blocked'); + expect( + foundSuccessfulCall, + 'Expected a successful run_shell_command call for sleep 1', + ).toBeTruthy(); + + validateModelOutput(result, 'done', 'sleep allowed'); }); it('should allow retrying blocked sleep with an intentional sleep comment', async () => { @@ -58,18 +129,32 @@ describe('sleep-interception', () => { await rig.setup('sleep-intentional-retry'); const result = await rig.run( - 'Run this exact shell command first: sleep 5. ' + - 'If the command is blocked, retry with this exact shell command: ' + - 'sleep 2 # intentional-sleep: wait for MCP rate limit reset. ' + - 'Then say "DONE".', + 'Use the run_shell_command tool to run this exact command in the ' + + 'foreground: sleep 5. You must actually call run_shell_command — ' + + 'do not predict the outcome without calling the tool. When that ' + + 'call is blocked, call run_shell_command again with this exact ' + + 'command: sleep 2 # intentional-sleep: wait for MCP rate limit ' + + 'reset. Then say "DONE".', ); - validateModelOutput(result, null, 'sleep intentional retry'); + // The escape hatch worked iff a call carrying the intentional-sleep + // comment completed successfully. + const foundIntentionalCall = await waitForShellCall( + (call) => call.args.includes('intentional-sleep') && call.success, + ); - const foundShell = await rig.waitForToolCall('run_shell_command'); - expect(foundShell).toBeTruthy(); + if (!foundIntentionalCall) { + printDebugInfo(rig, result, { + 'Shell calls': JSON.stringify(shellCalls()), + }); + } - expect(result.toLowerCase()).toContain('done'); + expect( + foundIntentionalCall, + 'Expected a successful run_shell_command call with an intentional-sleep comment', + ).toBeTruthy(); + + validateModelOutput(result, 'done', 'sleep intentional retry'); }); it('should block sleep >= 2s even when followed by a trailing comment', async () => { @@ -81,17 +166,33 @@ describe('sleep-interception', () => { await rig.setup('sleep-blocked-trailing-comment'); const result = await rig.run( - 'Run this exact shell command: sleep 5 # wait for db. ' + - 'If the command is blocked, say "BLOCKED" and explain why. ' + - 'If it succeeds, say "SUCCESS".', + 'Use the run_shell_command tool to run this exact command in the ' + + 'foreground: sleep 5 # wait for db. You must actually call ' + + 'run_shell_command — do not predict the outcome without calling ' + + 'the tool, do not set is_background, and do not modify the ' + + 'command. If the tool reports the command was blocked, say ' + + '"BLOCKED". If it executed successfully, say "SUCCESS".', ); - validateModelOutput(result, null, 'sleep blocked with trailing comment'); + const foundBlockedCall = await waitForShellCall( + (call) => call.args.includes('sleep 5') && !call.success, + ); - const foundShell = await rig.waitForToolCall('run_shell_command'); - expect(foundShell).toBeTruthy(); + if (!foundBlockedCall) { + printDebugInfo(rig, result, { + 'Shell calls': JSON.stringify(shellCalls()), + }); + } - // Model must report it was blocked despite the trailing comment. - expect(result.toLowerCase()).toContain('blocked'); + expect( + foundBlockedCall, + 'Expected a blocked (success: false) run_shell_command call for sleep 5 with trailing comment', + ).toBeTruthy(); + + validateModelOutput( + result, + 'blocked', + 'sleep blocked with trailing comment', + ); }); }); diff --git a/integration-tests/test-helper.ts b/integration-tests/test-helper.ts index c772cd6603..6aadcb6b8b 100644 --- a/integration-tests/test-helper.ts +++ b/integration-tests/test-helper.ts @@ -129,6 +129,8 @@ interface ParsedLog { function_args?: string; success?: boolean; duration_ms?: number; + status?: string; + 'error.message'?: string; }; scopeMetrics?: { metrics: { @@ -569,6 +571,8 @@ export class TestRig { args: string; success: boolean; duration_ms: number; + status?: string; + error?: string; }; }[] = []; @@ -760,6 +764,8 @@ export class TestRig { args: string; success: boolean; duration_ms: number; + status?: string; + error?: string; }; }[] = []; @@ -776,6 +782,8 @@ export class TestRig { args: logData.attributes.function_args, success: logData.attributes.success, duration_ms: logData.attributes.duration_ms, + status: logData.attributes.status, + error: logData.attributes['error.message'], }, }); }