Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
52 changes: 51 additions & 1 deletion actions/setup/js/codex_harness.cjs
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Copy link
Copy Markdown
Contributor

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, and resolvePostResultWatchdogIdleTimeoutMs (lines 91-106) are byte-for-byte copies of the same block in copilot_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.:

// process_runner.cjs
function resolvePostResultWatchdogIdleTimeoutMs(env = process.env) { ... }
module.exports = { ..., resolvePostResultWatchdogIdleTimeoutMs, MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS, DEFAULT_POST_RESULT_WATCHDOG_IDLE_TIMEOUT_MS };

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

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

resolvePostResultWatchdogIdleTimeoutMs clamps only the lower bound — an absurdly large override effectively disables the watchdog.

💡 Details

Math.max(MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS, configuredTimeoutMs) only guards against too-small values. If GH_AW_HARNESS_WATCHDOG_TIMEOUT_MS is misconfigured (e.g. a stray extra zero, or Number.MAX_SAFE_INTEGER), the watchdog effectively never fires, silently reintroducing the exact hang-until-hard-timeout failure this PR exists to fix — with no warning logged.

Fix: clamp an upper bound too, e.g.:

const MAX_POST_RESULT_WATCHDOG_TIMEOUT_MS = 10 * 60 * 1000;
return Math.min(MAX_POST_RESULT_WATCHDOG_TIMEOUT_MS, Math.max(MIN_POST_RESULT_WATCHDOG_TIMEOUT_MS, configuredTimeoutMs));

}

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
Expand Down Expand Up @@ -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
Expand All @@ -530,6 +564,7 @@ async function main() {
log(
`attempt ${attempt + 1} failed:` +
` exitCode=${result.exitCode}` +
` watchdogFired=${result.watchdogFired}` +

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The "attempt failed" log line fires with watchdogFired=true even on runs later reclassified as success, making logs misleading.

💡 Details

When the watchdog fires and a terminal safe-output exists, the code at line ~594 converts the run into a success and breaks. But the generic failure log block at lines 564-578 already ran and printed attempt N failed: exitCode=... watchdogFired=true ... before that reclassification happens. Anyone grepping logs/alerts for "attempt failed" will see false positives for what are actually successful watchdog-suppressed runs, undermining log-based monitoring/alerting for this exact new code path.

Fix: move the watchdog-success check before the failure-log block (or explicitly log a follow-up line noting the reclassification), so the log stream doesn't contradict itself.

` isRateLimitError=${isRateLimit}` +
` isTokenPerMinuteRateLimitError=${isTokenPerMinuteRateLimit}` +
` isAuthenticationFailedError=${isAuthenticationFailed}` +
Expand All @@ -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.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[/diagnosing-bugs] The suppression check at line 590 duplicates the shouldArm predicate defined at lines 536–537 (hasExpectedSafeOutputs || hasNoopInSafeOutputs). If the arming condition ever changes, the two copies can silently drift out of sync, causing the watchdog to arm on one condition but suppress on a different one.

💡 Suggested fix

Extract 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_harness.cjs structures the same check.

@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 }))) {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The hasNoopInSafeOutputs(...) call here is unreachable dead code. The noop guard at line 583 always executes first and breaks the loop when a noop is present, so the noop branch of this condition can never be reached.

For consistency with copilot_harness.cjs (which uses a unified hasTerminalSafeOutput()), consider simplifying to:

if (result.watchdogFired && safeOutputsPath && hasExpectedSafeOutputs(safeOutputsPath, { logger: log })) {

or extracting a shared hasTerminalSafeOutput helper in safeoutputs_cli.cjs that covers both cases — matching how copilot_harness.cjs handles this.

This is non-blocking — runtime behavior is correct — but the dead code makes intent harder to follow. @copilot please address this.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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.

💡 Details

Line 583 already breaks out with lastExitCode = 0 whenever hasNoopInSafeOutputs is true, regardless of watchdogFired. So by the time line 594 runs, the noop half of its || condition can never be true — it only ever matters via hasExpectedSafeOutputs. Keeping the dead hasNoopInSafeOutputs re-check here does an unnecessary second synchronous read+parse of safe-outputs.jsonl on every failed attempt and muddies which branch actually owns the noop-suppression semantics.

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 = [];
Expand Down Expand Up @@ -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,
};
}

Expand Down
154 changes: 154 additions & 0 deletions actions/setup/js/codex_harness.test.cjs
Original file line number Diff line number Diff line change
Expand Up @@ -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");

Expand Down Expand Up @@ -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,
});

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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 post-result watchdog fired after terminal safe-output was emitted or the late-activity exit suppressed diagnostic, unlike the terminal-output test above it. This means a regression that silently swallows the watchdog path (e.g., exits 0 for the wrong reason) wouldn't be caught.

💡 Suggested addition

Add 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({
Expand Down