-
Notifications
You must be signed in to change notification settings - Fork 454
Copilot harness: terminate idle process after terminal safe output #44440
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
101838f
96e20e6
959b39c
1ee9a45
d617ba6
e1e8fa6
8d9b9e5
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -76,6 +76,7 @@ const PROMPT_FILE_INLINE_THRESHOLD_LABEL = "100KB"; | |
| const MAX_ENV_VAR_PREVIEW_LENGTH = 120; | ||
| const OUTPUT_TAIL_MAX_CHARS = 600; | ||
| const OUTPUT_TAIL_MAX_LINES = 12; | ||
| const POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS = 20 * 1000; | ||
| const COPILOT_REQUESTS_PROXY_AUTH_403_TEMPLATE_NAME = "copilot_requests_proxy_auth_403.md"; | ||
| // Pattern to detect transient CAPIError 400 in copilot output | ||
| const CAPI_ERROR_400_PATTERN = /CAPIError:\s*400/; | ||
|
|
@@ -146,6 +147,39 @@ function log(message) { | |
| process.stderr.write(`[copilot-harness] ${message}\n`); | ||
| } | ||
|
|
||
| const NON_TERMINAL_SAFE_OUTPUT_TYPES = new Set(["missing_tool", "missing_data", "report_incomplete"]); | ||
|
|
||
| /** | ||
| * Detect whether safe-outputs already contain a terminal agent result. | ||
| * Terminal outputs include noop and any non-diagnostic task output types. | ||
| * @param {string} safeOutputsPath | ||
| * @returns {boolean} | ||
| */ | ||
| function hasTerminalSafeOutput(safeOutputsPath) { | ||
| if (!safeOutputsPath) return false; | ||
| let content = ""; | ||
| try { | ||
| content = fs.readFileSync(safeOutputsPath, "utf8"); | ||
| } catch { | ||
| return false; | ||
| } | ||
| for (const line of content.split("\n")) { | ||
| const trimmed = line.trim(); | ||
| if (!trimmed) continue; | ||
| try { | ||
| const parsed = JSON.parse(trimmed); | ||
| const type = parsed && typeof parsed.type === "string" ? parsed.type : ""; | ||
| if (!type) continue; | ||
| if (type === "noop" || !NON_TERMINAL_SAFE_OUTPUT_TYPES.has(type)) { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. [/diagnosing-bugs] The 💡 Suggested simplificationif (!NON_TERMINAL_SAFE_OUTPUT_TYPES.has(type)) {
return true;
}Removing the @copilot please address this. |
||
| return true; | ||
| } | ||
| } catch { | ||
| // Ignore malformed lines. | ||
| } | ||
| } | ||
| return false; | ||
| } | ||
|
|
||
| /** | ||
| * @param {NodeJS.ProcessEnv} [env] | ||
| * @param {(message: string) => void} [logger] | ||
|
|
@@ -911,7 +945,20 @@ async function main() { | |
| const safeArgs = currentArgs.map((arg, i) => (currentArgs[i - 1] === "--prompt" || currentArgs[i - 1] === "-p" ? "<redacted>" : arg)); | ||
| // Driver mode: run copilot_sdk_driver.cjs as a normal subprocess. The harness has | ||
| // already started the sidecar; the driver only opens an SDK client connection. | ||
| const result = await runProcess({ command, args: currentArgs, attempt, log, logArgs: safeArgs, env: childEnv }); | ||
| const result = await runProcess({ | ||
| command, | ||
| args: currentArgs, | ||
| attempt, | ||
| log, | ||
| logArgs: safeArgs, | ||
| env: childEnv, | ||
| postResultWatchdog: safeOutputsPath | ||
| ? { | ||
| shouldArm: () => hasTerminalSafeOutput(safeOutputsPath), | ||
| inactivityTimeoutMs: POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS, | ||
| } | ||
| : undefined, | ||
| }); | ||
| lastExitCode = result.exitCode; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. [/diagnosing-bugs] When the watchdog kills the process, The noop guard at line 1044 will catch the pure- 💡 Suggested fixCheck for terminal safe output at the top of the retry classifier (after if (result.exitCode !== 0 && safeOutputsPath && hasTerminalSafeOutput(safeOutputsPath)) {
log(`attempt ${attempt + 1}: terminal safe output present — treating watchdog-killed run as success`);
lastExitCode = 0;
break;
}This prevents a retry after a successful task output when the process lingered and was killed by the watchdog. @copilot please address this. |
||
| const attemptDetections = detectCopilotErrors(result.output); | ||
| detectedCopilotErrors.inferenceAccessError ||= attemptDetections.inferenceAccessError; | ||
|
|
@@ -1219,6 +1266,7 @@ if (typeof module !== "undefined" && module.exports) { | |
| resolveRetryConfig, | ||
| parseCopilotSDKServerArgsFromEnv, | ||
| isCAPIQuotaExceededError, | ||
| hasTerminalSafeOutput, | ||
| }; | ||
| } | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -28,6 +28,7 @@ const { | |
| extractDeniedCommands, | ||
| hasNumerousPermissionDeniedIssues, | ||
| hasNoopInSafeOutputs, | ||
| hasTerminalSafeOutput, | ||
| hasExpectedSafeOutputs, | ||
| INFERENCE_ACCESS_ERROR_PATTERN, | ||
| AGENTIC_ENGINE_TIMEOUT_PATTERN, | ||
|
|
@@ -229,6 +230,52 @@ describe("copilot_harness.cjs", () => { | |
| }); | ||
| }); | ||
|
|
||
| describe("hasTerminalSafeOutput", () => { | ||
| it("returns true for noop entries", () => { | ||
| const tempDir = makeHarnessTempDir("terminal-safeoutput-noop-"); | ||
| const filePath = path.join(tempDir, "safe-outputs.jsonl"); | ||
| try { | ||
| fs.writeFileSync(filePath, JSON.stringify({ type: "noop", reason: "nothing to do" }) + "\n", "utf8"); | ||
| expect(hasTerminalSafeOutput(filePath)).toBe(true); | ||
| } finally { | ||
| fs.rmSync(tempDir, { recursive: true, force: true }); | ||
| } | ||
| }); | ||
|
|
||
| it("returns true for non-diagnostic task outputs", () => { | ||
| const tempDir = makeHarnessTempDir("terminal-safeoutput-task-"); | ||
| const filePath = path.join(tempDir, "safe-outputs.jsonl"); | ||
| try { | ||
| fs.writeFileSync(filePath, JSON.stringify({ type: "comment_issue", body: "done" }) + "\n", "utf8"); | ||
| expect(hasTerminalSafeOutput(filePath)).toBe(true); | ||
| } finally { | ||
| fs.rmSync(tempDir, { recursive: true, force: true }); | ||
| } | ||
| }); | ||
|
|
||
| it("returns false for diagnostic-only output", () => { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. [/tdd] Missing test: a JSONL file containing a mix of diagnostic-only entries followed by a terminal entry should return 💡 Suggested additional testsit('returns true when terminal entry follows diagnostic entries', () => {
const lines = [
JSON.stringify({ type: 'missing_tool' }),
JSON.stringify({ type: 'noop', reason: 'done' }),
].join('\n');
fs.writeFileSync(filePath, lines, 'utf8');
expect(hasTerminalSafeOutput(filePath)).toBe(true);
});
it('returns false when file contains only multiple diagnostic entries', () => {
const lines = [
JSON.stringify({ type: 'missing_tool' }),
JSON.stringify({ type: 'report_incomplete' }),
].join('\n');
fs.writeFileSync(filePath, lines, 'utf8');
expect(hasTerminalSafeOutput(filePath)).toBe(false);
});@copilot please address this. |
||
| const tempDir = makeHarnessTempDir("terminal-safeoutput-diagnostic-"); | ||
| const filePath = path.join(tempDir, "safe-outputs.jsonl"); | ||
| try { | ||
| fs.writeFileSync(filePath, JSON.stringify({ type: "missing_tool", reason: "missing permission" }) + "\n", "utf8"); | ||
| expect(hasTerminalSafeOutput(filePath)).toBe(false); | ||
| } finally { | ||
| fs.rmSync(tempDir, { recursive: true, force: true }); | ||
| } | ||
| }); | ||
|
|
||
| it("returns false for missing_data diagnostic output", () => { | ||
| const tempDir = makeHarnessTempDir("terminal-safeoutput-missing-data-"); | ||
| const filePath = path.join(tempDir, "safe-outputs.jsonl"); | ||
| try { | ||
| fs.writeFileSync(filePath, JSON.stringify({ type: "missing_data", reason: "metadata only" }) + "\n", "utf8"); | ||
| expect(hasTerminalSafeOutput(filePath)).toBe(false); | ||
| } finally { | ||
| fs.rmSync(tempDir, { recursive: true, force: true }); | ||
| } | ||
| }); | ||
| }); | ||
|
|
||
| describe("retry policy: continue on partial execution", () => { | ||
| // Inline the same retry-eligibility logic as the driver for unit testing. | ||
| // The driver retries whenever the session produced output (hasOutput), regardless | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -55,7 +55,13 @@ function sleep(ms) { | |
| * attempt: number, | ||
| * log: (message: string) => void, | ||
| * logArgs?: string[], | ||
| * env?: NodeJS.ProcessEnv | ||
| * env?: NodeJS.ProcessEnv, | ||
| * postResultWatchdog?: { | ||
| * shouldArm: () => boolean, | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The expanded JSDoc for runner options is helpful. Ensure the terminate-on-idle behavior is covered by a unit test asserting the timeout path. |
||
| * inactivityTimeoutMs: number, | ||
| * pollIntervalMs?: number, | ||
| * termGraceMs?: number | ||
| * } | ||
| * }} options | ||
| * - command - The executable to run | ||
| * - args - Arguments to pass to the command | ||
|
|
@@ -65,7 +71,7 @@ function sleep(ms) { | |
| * Pass a redacted copy to avoid leaking sensitive values. | ||
| * @returns {Promise<{exitCode: number, output: string, hasOutput: boolean, durationMs: number}>} | ||
| */ | ||
| function runProcess({ command, args, attempt, log, logArgs, env }) { | ||
| function runProcess({ command, args, attempt, log, logArgs, env, postResultWatchdog }) { | ||
| return new Promise(resolve => { | ||
| const startTime = Date.now(); | ||
| // Guard against the promise being settled more than once. On some systems Node | ||
|
|
@@ -76,6 +82,7 @@ function runProcess({ command, args, attempt, log, logArgs, env }) { | |
| function settle(result) { | ||
| if (settled) return; | ||
| settled = true; | ||
| if (postResultWatchdogTimer) clearInterval(postResultWatchdogTimer); | ||
| resolve(result); | ||
| } | ||
|
|
||
|
|
@@ -94,13 +101,24 @@ function runProcess({ command, args, attempt, log, logArgs, env }) { | |
| let hasOutput = false; | ||
| let stdoutBytes = 0; | ||
| let stderrBytes = 0; | ||
| let lastActivityAt = Date.now(); | ||
| let watchdogArmed = false; | ||
| let sentSigtermAt = 0; | ||
| let sentSigkillAt = 0; | ||
| const watchdogPollIntervalMs = Math.max(50, Number(postResultWatchdog?.pollIntervalMs) || 1000); | ||
| const watchdogTermGraceMs = Math.max(50, Number(postResultWatchdog?.termGraceMs) || 5000); | ||
| const rawInactivityTimeout = Number(postResultWatchdog?.inactivityTimeoutMs); | ||
| const watchdogInactivityTimeoutMs = Number.isFinite(rawInactivityTimeout) && rawInactivityTimeout > 0 ? Math.max(50, rawInactivityTimeout) : 0; | ||
| /** @type {NodeJS.Timeout | null} */ | ||
| let postResultWatchdogTimer = null; | ||
|
|
||
| child.stdout.on( | ||
| "data", | ||
| /** @param {Buffer} data */ data => { | ||
| hasOutput = true; | ||
| stdoutBytes += data.length; | ||
| collectedOutput += data.toString(); | ||
| lastActivityAt = Date.now(); | ||
| process.stdout.write(data); | ||
| } | ||
| ); | ||
|
|
@@ -111,10 +129,41 @@ function runProcess({ command, args, attempt, log, logArgs, env }) { | |
| hasOutput = true; | ||
| stderrBytes += data.length; | ||
| collectedOutput += data.toString(); | ||
| lastActivityAt = Date.now(); | ||
| process.stderr.write(data); | ||
| } | ||
| ); | ||
|
|
||
| if (postResultWatchdog && watchdogInactivityTimeoutMs > 0) { | ||
| postResultWatchdogTimer = setInterval(() => { | ||
| if (settled) return; | ||
| if (!watchdogArmed) { | ||
| try { | ||
| watchdogArmed = postResultWatchdog.shouldArm(); | ||
| } catch { | ||
| watchdogArmed = false; | ||
| } | ||
| if (watchdogArmed) { | ||
| lastActivityAt = Date.now(); | ||
| log(`attempt ${attempt + 1}: post-result watchdog armed inactivityTimeout=${watchdogInactivityTimeoutMs}ms`); | ||
| } | ||
|
Copilot marked this conversation as resolved.
|
||
| } | ||
| if (!watchdogArmed) return; | ||
| const idleMs = Date.now() - lastActivityAt; | ||
| if (sentSigtermAt === 0 && idleMs >= watchdogInactivityTimeoutMs) { | ||
| sentSigtermAt = Date.now(); | ||
| log(`attempt ${attempt + 1}: post-result watchdog terminating idle process after ${idleMs}ms (SIGTERM)`); | ||
| child.kill("SIGTERM"); | ||
| return; | ||
| } | ||
| if (sentSigtermAt > 0 && sentSigkillAt === 0 && Date.now() - sentSigtermAt >= watchdogTermGraceMs) { | ||
| sentSigkillAt = Date.now(); | ||
| log(`attempt ${attempt + 1}: post-result watchdog forcing process exit after ${watchdogTermGraceMs}ms grace (SIGKILL)`); | ||
| child.kill("SIGKILL"); | ||
| } | ||
| }, watchdogPollIntervalMs); | ||
| } | ||
|
|
||
| child.on("exit", (code, signal) => { | ||
| log(`attempt ${attempt + 1}: process exit event` + ` exitCode=${code ?? 1}` + (signal ? ` signal=${signal}` : "")); | ||
| }); | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -181,6 +181,60 @@ describe("process_runner.cjs", () => { | |
| expect(result.durationMs).toBeGreaterThanOrEqual(0); | ||
| }); | ||
|
|
||
| it("terminates a hung process after terminal-result inactivity", async () => { | ||
| const logs = []; | ||
| const result = await runProcess({ | ||
| command: process.execPath, | ||
| args: ["-e", 'process.stdout.write("done"); setInterval(() => {}, 1000);'], | ||
| attempt: 0, | ||
| log: msg => logs.push(msg), | ||
| postResultWatchdog: { | ||
| shouldArm: () => true, | ||
| inactivityTimeoutMs: 100, | ||
| pollIntervalMs: 25, | ||
| termGraceMs: 200, | ||
| }, | ||
| }); | ||
| expect(result.exitCode).not.toBe(0); | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. [/tdd] Also missing: a test that verifies the SIGKILL escalation path (i.e., when SIGTERM is sent but the process ignores it and 💡 Suggested SIGKILL testit('escalates to SIGKILL when process ignores SIGTERM', async () => {
const logs = [];
const result = await runProcess({
command: process.execPath,
args: ['-e', 'process.on("SIGTERM", () => {}); setInterval(() => {}, 500);'],
attempt: 0,
log: msg => logs.push(msg),
postResultWatchdog: {
shouldArm: () => true,
inactivityTimeoutMs: 50,
pollIntervalMs: 25,
termGraceMs: 150,
},
});
expect(logs.some(l => l.includes('SIGKILL'))).toBe(true);
expect(result.exitCode).toBe(1);
});```
</details>
@copilot please address this. |
||
| expect(result.durationMs).toBeLessThan(5000); | ||
| expect(logs.some(line => line.includes("post-result watchdog armed"))).toBe(true); | ||
| expect(logs.some(line => line.includes("post-result watchdog terminating idle process"))).toBe(true); | ||
| }); | ||
|
|
||
| it("does not terminate processes when watchdog is not armed", async () => { | ||
| const logs = []; | ||
| const result = await runProcess({ | ||
| command: process.execPath, | ||
| args: ["-e", "setTimeout(() => process.exit(0), 250);"], | ||
| attempt: 0, | ||
| log: msg => logs.push(msg), | ||
| postResultWatchdog: { | ||
| shouldArm: () => false, | ||
| inactivityTimeoutMs: 50, | ||
| pollIntervalMs: 25, | ||
| termGraceMs: 100, | ||
| }, | ||
| }); | ||
| expect(result.exitCode).toBe(0); | ||
| expect(logs.some(line => line.includes("post-result watchdog terminating idle process"))).toBe(false); | ||
| }); | ||
|
|
||
| it("does not enable watchdog when inactivityTimeoutMs is missing or invalid", async () => { | ||
| const logs = []; | ||
| const result = await runProcess({ | ||
| command: process.execPath, | ||
| args: ["-e", "setTimeout(() => process.exit(0), 100);"], | ||
| attempt: 0, | ||
| log: msg => logs.push(msg), | ||
| postResultWatchdog: { | ||
| shouldArm: () => true, | ||
| // intentionally missing inactivityTimeoutMs | ||
| }, | ||
| }); | ||
| expect(result.exitCode).toBe(0); | ||
| expect(logs.some(line => line.includes("post-result watchdog armed"))).toBe(false); | ||
| }); | ||
|
|
||
| it("truncates logArgs to 200 chars in spawn log", async () => { | ||
| const logs = []; | ||
| const longArg = "x".repeat(300); | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Nice — introducing a named constant for the output tail improves readability. Consider documenting the unit (chars).