-
Notifications
You must be signed in to change notification settings - Fork 466
fix: add post-result watchdog to codex_harness to prevent CLI hang-on-exit #48499
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
base: main
Are you sure you want to change the base?
Changes from all commits
537e558
e68b324
9f19c04
abd2ac1
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 |
|---|---|---|
|
|
@@ -84,6 +84,27 @@ const MISSING_API_KEY_PATTERN = /Missing environment variable:\s*`?(?:CODEX_API_ | |
| // These are transient infrastructure failures that may resolve on retry. | ||
| const SERVER_ERROR_PATTERN = /InternalServerError|ServiceUnavailableError|500 Internal Server Error|503 Service Unavailable/i; | ||
|
|
||
| // Post-result watchdog: once the agent writes a terminal safe-output the harness | ||
| // arms a watchdog timer and kills the Codex process if it is still running after | ||
| // POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS of inactivity. This prevents the step from | ||
| // hitting its hard timeout when Codex hangs on exit after completing its work. | ||
| const MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS = 50; | ||
| const DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS = 20 * 1000; | ||
|
|
||
| /** | ||
| * @param {NodeJS.ProcessEnv} [env] | ||
| * @returns {number} | ||
| */ | ||
| function resolvePostResultWatchdogIdleTimeoutMs(env = process.env) { | ||
| const configuredTimeoutMs = Number(env.GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS); | ||
| if (!Number.isFinite(configuredTimeoutMs) || configuredTimeoutMs <= 0) { | ||
| return DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS; | ||
| } | ||
| return Math.max(MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS, configuredTimeoutMs); | ||
|
Comment on lines
+98
to
+103
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.
|
||
| } | ||
|
|
||
| const POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS = resolvePostResultWatchdogIdleTimeoutMs(); | ||
|
|
||
| /** | ||
| * Emit a timestamped diagnostic log line to stderr. | ||
| * All driver messages are prefixed with "[codex-harness]" so they are easy to | ||
|
|
@@ -509,7 +530,20 @@ async function main() { | |
| } | ||
| } | ||
|
|
||
| const result = await runProcess({ command, args: resolvedArgs, attempt, log, logArgs: safeArgs, env: codexEnv }); | ||
| const result = await runProcess({ | ||
| command, | ||
| args: resolvedArgs, | ||
| attempt, | ||
| log, | ||
| logArgs: safeArgs, | ||
| env: codexEnv, | ||
| postResultWatchdog: safeOutputsPath | ||
| ? { | ||
| shouldArm: () => hasExpectedSafeOutputs(safeOutputsPath, { logger: log }) || hasNoopInSafeOutputs(safeOutputsPath, { logger: log }), | ||
|
Comment on lines
+540
to
+542
|
||
| inactivityTimeoutMs: POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS, | ||
| } | ||
| : undefined, | ||
| }); | ||
| lastExitCode = result.exitCode; | ||
|
|
||
| // Success — stop retrying | ||
|
|
@@ -530,6 +564,7 @@ async function main() { | |
| log( | ||
| `attempt ${attempt + 1} failed:` + | ||
| ` exitCode=${result.exitCode}` + | ||
| ` watchdogFired=${result.watchdogFired}` + | ||
|
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 "attempt failed" log line fires with
|
||
| ` isRateLimitError=${isRateLimit}` + | ||
| ` isTokenPerMinuteRateLimitError=${isTokenPerMinuteRateLimit}` + | ||
| ` isAuthenticationFailedError=${isAuthenticationFailed}` + | ||
|
|
@@ -551,6 +586,17 @@ async function main() { | |
| break; | ||
| } | ||
|
|
||
| // When the post-result watchdog fired (SIGTERM sent to a hanging Codex process) and the | ||
| // safe-outputs file already contains a terminal result, treat the run as a success. | ||
|
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 suppression check at line 590 duplicates the 💡 Suggested fixExtract the condition into a shared variable: const hasTerminalSafeOutput = () =>
hasExpectedSafeOutputs(safeOutputsPath, { logger: log }) ||
hasNoopInSafeOutputs(safeOutputsPath, { logger: log });
postResultWatchdog: safeOutputsPath
? { shouldArm: hasTerminalSafeOutput, inactivityTimeoutMs: POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS }
: undefined,
// later...
if (result.watchdogFired && safeOutputsPath && hasTerminalSafeOutput()) {This is one source of truth and mirrors how @copilot please address this. |
||
| // The agent completed its work and wrote its output — the hang on exit is a cosmetic | ||
| // failure, not a task failure. Retrying would reproduce the same hang pattern without | ||
| // producing a different output. | ||
| if (result.watchdogFired && safeOutputsPath && (hasExpectedSafeOutputs(safeOutputsPath, { logger: log }) || hasNoopInSafeOutputs(safeOutputsPath, { logger: log }))) { | ||
|
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 For consistency with if (result.watchdogFired && safeOutputsPath && hasExpectedSafeOutputs(safeOutputsPath, { logger: log })) {or extracting a shared This is non-blocking — runtime behavior is correct — but the dead code makes intent harder to follow. @copilot please address this.
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. Watchdog-fired success branch partially overlaps the noop check just above it, causing a redundant duplicate file read.💡 DetailsLine 583 already breaks out with Fix: drop the redundant call so this branch only checks what it can actually reach: if (result.watchdogFired && safeOutputsPath && hasExpectedSafeOutputs(safeOutputsPath, { logger: log })) { |
||
| log(`attempt ${attempt + 1}: post-result watchdog fired after terminal safe-output was emitted — treating as success (late-activity exit suppressed)`); | ||
| lastExitCode = 0; | ||
| break; | ||
| } | ||
|
|
||
| const nonRetryableGuard = detectNonRetryableHarnessGuard(result.output); | ||
| if (nonRetryableGuard.aiCreditsExceeded || nonRetryableGuard.awfAPIProxyBlockingRequests || nonRetryableGuard.goalAlreadyActive || nonRetryableGuard.maxRunsExceeded) { | ||
| const reasons = []; | ||
|
|
@@ -662,6 +708,10 @@ if (typeof module !== "undefined" && module.exports) { | |
| applyModelFallback, | ||
| injectModelFlagAfterExec, | ||
| getCodexModelEnvVar, | ||
| resolvePostResultWatchdogIdleTimeoutMs, | ||
| POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS, | ||
| DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS, | ||
| MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS, | ||
| }; | ||
| } | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -28,6 +28,9 @@ const { | |
| configureCodexProviderFromReflect, | ||
| hasNoopInSafeOutputs, | ||
| resolveRetryConfig, | ||
| resolvePostResultWatchdogIdleTimeoutMs, | ||
| DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS, | ||
| MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS, | ||
| } = require("./codex_harness.cjs"); | ||
| const { detectNonRetryableHarnessGuard } = require("./harness_retry_guard.cjs"); | ||
|
|
||
|
|
@@ -673,6 +676,157 @@ process.exit(1);`, | |
| }); | ||
| }); | ||
|
|
||
| describe("post-result watchdog suppression when terminal safe-output already produced", () => { | ||
| it("exits 0 without retrying when a terminal safe-output was produced and the process hangs on exit", () => { | ||
| const tempDir = makeHarnessTempDir("codex-watchdog-suppression-"); | ||
| const safeOutputsPath = path.join(tempDir, "safe-outputs.jsonl"); | ||
| const stubPath = path.join(tempDir, "stub.cjs"); | ||
| const promptPath = path.join(tempDir, "prompt.txt"); | ||
| const callsPath = path.join(tempDir, "calls.jsonl"); | ||
| // Stub writes a terminal safe-output, then remains alive until SIGTERM. | ||
| // This exercises the watchdog-fired path end-to-end. | ||
| fs.writeFileSync( | ||
| stubPath, | ||
| `const fs = require("fs"); | ||
| const callsPath = process.env.CODEX_HARNESS_STUB_CALLS; | ||
| const safeOutputsPath = process.env.GH_AW_SAFE_OUTPUTS; | ||
| fs.appendFileSync(callsPath, JSON.stringify({args: process.argv.slice(2)}) + "\\n"); | ||
| fs.appendFileSync(safeOutputsPath, JSON.stringify({type:"add-labels",labels:["spam"]}) + "\\n"); | ||
| process.stdout.write("Label applied. Continuing cleanup...\\n"); | ||
| process.on("SIGTERM", () => process.exit(1)); | ||
| setInterval(() => {}, 1000);`, | ||
| "utf8" | ||
| ); | ||
| fs.writeFileSync(promptPath, "moderate the issue", "utf8"); | ||
|
|
||
| const result = spawnSync(process.execPath, ["codex_harness.cjs", process.execPath, stubPath, "exec", "--prompt-file", promptPath], { | ||
| cwd: path.dirname(require.resolve("./codex_harness.cjs")), | ||
| env: { | ||
| ...process.env, | ||
| CODEX_HARNESS_STUB_CALLS: callsPath, | ||
| GH_AW_SAFE_OUTPUTS: safeOutputsPath, | ||
| CODEX_API_KEY: "fake-key-for-test", | ||
| GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS: "100", | ||
| }, | ||
| encoding: "utf8", | ||
| timeout: 15000, | ||
| }); | ||
| const callCount = fs.readFileSync(callsPath, "utf8").trim().split("\n").filter(Boolean).length; | ||
| // Only one attempt — no retries when watchdog suppression applies | ||
| expect(callCount).toBe(1); | ||
| // Harness exits 0 because the terminal safe-output was already produced | ||
| expect(result.status).toBe(0); | ||
| expect(result.stderr).toContain("post-result watchdog fired after terminal safe-output was emitted"); | ||
| expect(result.stderr).toContain("late-activity exit suppressed"); | ||
| }); | ||
|
|
||
| it("exits 0 without retrying when a noop safe-output was produced and the process hangs on exit", () => { | ||
| const tempDir = makeHarnessTempDir("codex-watchdog-noop-"); | ||
| const safeOutputsPath = path.join(tempDir, "safe-outputs.jsonl"); | ||
| const stubPath = path.join(tempDir, "stub.cjs"); | ||
| const promptPath = path.join(tempDir, "prompt.txt"); | ||
| const callsPath = path.join(tempDir, "calls.jsonl"); | ||
| // Stub writes a noop safe-output, then remains alive until SIGTERM. | ||
| fs.writeFileSync( | ||
| stubPath, | ||
| `const fs = require("fs"); | ||
| const callsPath = process.env.CODEX_HARNESS_STUB_CALLS; | ||
| const safeOutputsPath = process.env.GH_AW_SAFE_OUTPUTS; | ||
| fs.appendFileSync(callsPath, JSON.stringify({args: process.argv.slice(2)}) + "\\n"); | ||
| fs.appendFileSync(safeOutputsPath, JSON.stringify({type:"noop",message:"nothing to do"}) + "\\n"); | ||
| process.stdout.write("Noop recorded. Waiting...\\n"); | ||
| process.on("SIGTERM", () => process.exit(1)); | ||
| setInterval(() => {}, 1000);`, | ||
| "utf8" | ||
| ); | ||
| fs.writeFileSync(promptPath, "moderate the issue", "utf8"); | ||
|
|
||
| const result = spawnSync(process.execPath, ["codex_harness.cjs", process.execPath, stubPath, "exec", "--prompt-file", promptPath], { | ||
| cwd: path.dirname(require.resolve("./codex_harness.cjs")), | ||
| env: { | ||
| ...process.env, | ||
| CODEX_HARNESS_STUB_CALLS: callsPath, | ||
| GH_AW_SAFE_OUTPUTS: safeOutputsPath, | ||
| CODEX_API_KEY: "fake-key-for-test", | ||
| GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS: "100", | ||
| }, | ||
| encoding: "utf8", | ||
| timeout: 15000, | ||
| }); | ||
|
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] The noop integration test (lines 730–755) doesn't assert the log message 💡 Suggested additionAdd the same stderr assertions as the first watchdog test: expect(result.stderr).toContain('post-result watchdog fired after terminal safe-output was emitted');
expect(result.stderr).toContain('late-activity exit suppressed');@copilot please address this. |
||
| const callCount = fs.readFileSync(callsPath, "utf8").trim().split("\n").filter(Boolean).length; | ||
| expect(callCount).toBe(1); | ||
| expect(result.status).toBe(0); | ||
| }); | ||
|
|
||
| it("still retries partial_execution when no terminal safe-output was produced (watchdog not armed)", () => { | ||
| const tempDir = makeHarnessTempDir("codex-watchdog-no-output-"); | ||
| const safeOutputsPath = path.join(tempDir, "safe-outputs.jsonl"); | ||
| const stubPath = path.join(tempDir, "stub.cjs"); | ||
| const promptPath = path.join(tempDir, "prompt.txt"); | ||
| const callsPath = path.join(tempDir, "calls.jsonl"); | ||
| // Stub produces output but exits 1 without writing any safe-output. | ||
| // The watchdog cannot fire (no terminal safe-output to arm it), so this | ||
| // should fall through to the normal partial-execution retry path. | ||
| fs.writeFileSync( | ||
| stubPath, | ||
| `const fs = require("fs"); | ||
| const callsPath = process.env.CODEX_HARNESS_STUB_CALLS; | ||
| fs.appendFileSync(callsPath, JSON.stringify({args: process.argv.slice(2)}) + "\\n"); | ||
| process.stdout.write("partial work done\\n"); | ||
| process.exit(1);`, | ||
| "utf8" | ||
| ); | ||
| fs.writeFileSync(promptPath, "moderate the issue", "utf8"); | ||
|
|
||
| const result = spawnSync(process.execPath, ["codex_harness.cjs", process.execPath, stubPath, "exec", "--prompt-file", promptPath], { | ||
| cwd: path.dirname(require.resolve("./codex_harness.cjs")), | ||
| env: { | ||
| ...process.env, | ||
| CODEX_HARNESS_STUB_CALLS: callsPath, | ||
| GH_AW_SAFE_OUTPUTS: safeOutputsPath, | ||
| CODEX_API_KEY: "fake-key-for-test", | ||
| // Override retry config to keep the test fast. | ||
| GH_AW_HARNESS_MAX_RETRIES: "1", | ||
| GH_AW_HARNESS_INITIAL_DELAY_MS: "1", | ||
| }, | ||
| encoding: "utf8", | ||
| timeout: 15000, | ||
| }); | ||
| const callCount = fs.readFileSync(callsPath, "utf8").trim().split("\n").filter(Boolean).length; | ||
| // Should retry (2 attempts total with max_retries=1) | ||
| expect(callCount).toBeGreaterThan(1); | ||
| // Harness exits 1 because retries are exhausted with no output | ||
| expect(result.status).toBe(1); | ||
| expect(result.stderr).not.toContain("late-activity exit suppressed"); | ||
| }); | ||
| }); | ||
|
|
||
| describe("resolvePostResultWatchdogIdleTimeoutMs", () => { | ||
| it("returns the default when no env var is set", () => { | ||
| expect(resolvePostResultWatchdogIdleTimeoutMs({})).toBe(DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS); | ||
| }); | ||
|
|
||
| it("returns the configured value when GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS is a positive number", () => { | ||
| expect(resolvePostResultWatchdogIdleTimeoutMs({ GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS: "5000" })).toBe(5000); | ||
| }); | ||
|
|
||
| it("clamps to MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS when configured value is too small", () => { | ||
| expect(resolvePostResultWatchdogIdleTimeoutMs({ GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS: "1" })).toBe(MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS); | ||
| }); | ||
|
|
||
| it("returns the default for non-numeric input", () => { | ||
| expect(resolvePostResultWatchdogIdleTimeoutMs({ GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS: "not-a-number" })).toBe(DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS); | ||
| }); | ||
|
|
||
| it("returns the default for zero", () => { | ||
| expect(resolvePostResultWatchdogIdleTimeoutMs({ GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS: "0" })).toBe(DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS); | ||
| }); | ||
|
|
||
| it("returns the default for negative values", () => { | ||
| expect(resolvePostResultWatchdogIdleTimeoutMs({ GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS: "-100" })).toBe(DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS); | ||
| }); | ||
| }); | ||
|
|
||
| describe("retry configuration", () => { | ||
| it("uses the default retry settings when env vars are unset", () => { | ||
| expect(resolveRetryConfig({})).toEqual({ | ||
|
|
||
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.
Watchdog constants/logic duplicated verbatim from copilot_harness.cjs — drift risk.
💡 Details
MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS,DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS, andresolvePostResultWatchdogIdleTimeoutMs(lines 91-106) are byte-for-byte copies of the same block incopilot_harness.cjs(lines 85-107). Two independent copies of the same timeout-resolution logic will silently drift the next time one file is tuned (e.g. changing the default from 20s to 30s) and the other is forgotten — exactly the kind of subtle cross-harness inconsistency that is hard to catch in review.Fix: extract this into
process_runner.cjs(or a small shared module) and import it from both harnesses, e.g.: