-
Notifications
You must be signed in to change notification settings - Fork 446
Harden Claude startup failure handling for empty-log Avenger runs #44332
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
b9799ee
4309195
0ccd4ab
c87d280
2da23d0
237a394
d8e40a8
9cd8ddd
ee6d3be
edf96e7
12828fb
a120adc
dafe82e
833c290
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 |
|---|---|---|
|
|
@@ -78,6 +78,7 @@ const MAX_TURNS_EXIT_PATTERN = /"subtype"\s*:\s*"error_max_turns"/; | |
| // this path must not be retried via --continue (fall back to a fresh run if budget remains). | ||
| const NO_DEFERRED_MARKER_PATTERN = /No deferred tool marker found/i; | ||
| const SIGNAL_TERMINATION_EXIT_CODES = new Set([137, 143]); | ||
| const MAX_STARTUP_RETRIES = 2; | ||
|
|
||
| /** | ||
| * Emit a timestamped diagnostic log line to stderr. | ||
|
|
@@ -99,6 +100,35 @@ function resolveRetryConfig(env = process.env, logger = log) { | |
| return resolveSharedRetryConfig(env, logger); | ||
| } | ||
|
|
||
| /** | ||
| * Parse bounded startup retries for zero-output startup failures. | ||
| * Retries are always fresh runs (never --continue). | ||
| * | ||
| * @param {NodeJS.ProcessEnv} [env] | ||
| * @param {(message: string) => void} [logger] | ||
| * @returns {number} | ||
| */ | ||
| function resolveStartupRetryLimit(env = process.env, logger = log) { | ||
| const raw = env.GH_AW_CLAUDE_STARTUP_RETRIES; | ||
| if (raw == null || raw === "") { | ||
| return 1; | ||
| } | ||
| if (!/^[+-]?\d+$/.test(raw)) { | ||
| logger(`invalid GH_AW_CLAUDE_STARTUP_RETRIES='${raw}' (expected integer); using default startup retries=1`); | ||
| return 1; | ||
| } | ||
| const parsed = Number.parseInt(raw, 10); | ||
| if (!Number.isFinite(parsed)) { | ||
| logger(`invalid GH_AW_CLAUDE_STARTUP_RETRIES='${raw}' (not finite); using default startup retries=1`); | ||
| return 1; | ||
| } | ||
| const clamped = Math.min(Math.max(parsed, 0), MAX_STARTUP_RETRIES); | ||
| if (clamped !== parsed) { | ||
| logger(`GH_AW_CLAUDE_STARTUP_RETRIES=${parsed} out of range; clamped to ${clamped}`); | ||
| } | ||
| return clamped; | ||
| } | ||
|
|
||
| /** | ||
| * Determines if the collected output contains an Anthropic overload error. | ||
| * @param {string} output - Collected stdout+stderr from the process | ||
|
|
@@ -297,6 +327,7 @@ async function main() { | |
| const [, , command, ...args] = process.argv; | ||
| const retryConfig = resolveRetryConfig(process.env, log); | ||
| const { maxRetries, initialDelayMs, backoffMultiplier, maxDelayMs } = retryConfig; | ||
| const startupRetryLimit = resolveStartupRetryLimit(process.env, log); | ||
|
|
||
| if (!command) { | ||
| process.stderr.write("claude-harness: Usage: node claude_harness.cjs <command> [args...]\n"); | ||
|
|
@@ -347,6 +378,7 @@ async function main() { | |
| let lastExitCode = 1; | ||
| let useContinueOnRetry = false; | ||
| let continueDisabledPermanently = false; | ||
| let startupRetriesUsed = 0; | ||
| const driverStartTime = Date.now(); | ||
| // Soft-timeout guard: polled at the top of the retry loop and after each backoff sleep. | ||
| // It does not preempt a running attempt — if a single invocation runs past the soft | ||
|
|
@@ -519,7 +551,19 @@ async function main() { | |
| if (attempt >= maxRetries) { | ||
| log(`all ${maxRetries} retries exhausted — giving up (exitCode=${lastExitCode})`); | ||
| } else { | ||
| log(`attempt ${attempt + 1}: no output produced — not retrying` + ` (possible causes: binary not found, permission denied, auth failure, or silent startup crash)`); | ||
| if (startupRetriesUsed < startupRetryLimit) { | ||
| startupRetriesUsed++; | ||
| useContinueOnRetry = false; | ||
| delay = initialDelayMs; | ||
| // attempt is 0-based; logs are 1-based, so "next attempt" is +2. | ||
| const nextAttemptNumber = attempt + 2; | ||
| const totalAttempts = maxRetries + 1; | ||
| log(`attempt ${attempt + 1}: no output produced — retrying startup as fresh run ` + `(startup retry ${startupRetriesUsed}/${startupRetryLimit}, next attempt ${nextAttemptNumber} of ${totalAttempts} total attempts)`); | ||
|
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 a startup retry succeeds (exits 0), the 💡 SuggestionReset if (startupRetriesUsed < startupRetryLimit) {
startupRetriesUsed++;
useContinueOnRetry = false;
delay = initialDelayMs; // reset backoff for startup retry
...
}This is low risk now since @copilot please address this. |
||
| continue; | ||
| } | ||
| log( | ||
| `attempt ${attempt + 1}: no output produced — not retrying (startup retry budget exhausted: ${startupRetriesUsed}/${startupRetryLimit}; possible causes: binary not found, permission denied, auth failure, or silent startup crash)` | ||
| ); | ||
| } | ||
|
|
||
| break; | ||
|
|
@@ -551,6 +595,7 @@ if (typeof module !== "undefined" && module.exports) { | |
| hasNoopInSafeOutputs, | ||
| hasExpectedSafeOutputs, | ||
| resolveRetryConfig, | ||
| resolveStartupRetryLimit, | ||
| }; | ||
| } | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -21,6 +21,7 @@ const { | |
| extractDeniedCommands, | ||
| buildMissingToolPermissionIssuePayload, | ||
| resolveRetryConfig, | ||
| resolveStartupRetryLimit, | ||
| } = require("./claude_harness.cjs"); | ||
|
|
||
| const agentTempDir = "/tmp/gh-aw/agent"; | ||
|
|
@@ -30,7 +31,7 @@ function makeHarnessTempDir(name) { | |
| return fs.mkdtempSync(path.join(agentTempDir, name)); | ||
| } | ||
|
|
||
| function runHarnessWithStub({ stubScript, prompt = "fix the bug", extraArgs = [] }) { | ||
| function runHarnessWithStub({ stubScript, prompt = "fix the bug", extraArgs = [], extraEnv = {} }) { | ||
| const tempDir = makeHarnessTempDir("claude-harness-"); | ||
| const stubPath = path.join(tempDir, "stub.cjs"); | ||
| const promptPath = path.join(tempDir, "prompt.txt"); | ||
|
|
@@ -40,7 +41,7 @@ function runHarnessWithStub({ stubScript, prompt = "fix the bug", extraArgs = [] | |
|
|
||
| const result = spawnSync(process.execPath, ["claude_harness.cjs", process.execPath, stubPath, "--print", ...extraArgs, "--prompt-file", promptPath], { | ||
| cwd: path.dirname(require.resolve("./claude_harness.cjs")), | ||
| env: { ...process.env, CLAUDE_HARNESS_STUB_CALLS: callsPath }, | ||
| env: { ...process.env, ...extraEnv, CLAUDE_HARNESS_STUB_CALLS: callsPath }, | ||
| encoding: "utf8", | ||
| timeout: 45000, | ||
| }); | ||
|
|
@@ -448,6 +449,41 @@ process.exit(0); | |
| expect(result.stderr).toContain("failure_reason=cancelled_or_timed_out"); | ||
| }, 30000); | ||
|
|
||
| it("retries one no-output startup failure as a fresh run by default", () => { | ||
| const stubScript = ` | ||
| const fs = require("fs"); | ||
| const callsPath = process.env.CLAUDE_HARNESS_STUB_CALLS; | ||
| const args = process.argv.slice(2); | ||
| const priorCalls = fs.existsSync(callsPath) ? fs.readFileSync(callsPath, "utf8").trim().split("\\n").filter(Boolean).length : 0; | ||
| fs.appendFileSync(callsPath, JSON.stringify({ args }) + "\\n", "utf8"); | ||
| if (priorCalls === 0) process.exit(1); | ||
| process.stdout.write("startup retry succeeded\\n"); | ||
| process.exit(0); | ||
| `; | ||
| const { result, calls } = runHarnessWithStub({ stubScript }); | ||
| expect(result.status, result.stderr).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] The integration test verifies the success path but has no coverage for: (a) startup retry budget exhausted after 💡 Suggested additional testsit("does not retry startup failure when GH_AW_CLAUDE_STARTUP_RETRIES=0", () => {
const stubScript = `
const fs = require("fs");
fs.appendFileSync(process.env.CLAUDE_HARNESS_STUB_CALLS, JSON.stringify({ args: process.argv.slice(2) }) + "\\n");
process.exit(1);
`;
const { result, calls } = runHarnessWithStub({ stubScript,
extraEnv: { GH_AW_CLAUDE_STARTUP_RETRIES: "0" } });
expect(result.status).not.toBe(0);
expect(calls.length).toBe(1); // no retry
expect(result.stderr).toContain("startup retry budget exhausted");
});Without this, a regression that ignores the @copilot please address this. |
||
| expect(calls.length).toBe(2); | ||
| expect(calls[1].args.includes("--continue")).toBe(false); | ||
| expect(result.stderr).toContain("no output produced — retrying startup as fresh run"); | ||
| }); | ||
|
|
||
| it("does not retry no-output startup failure when GH_AW_CLAUDE_STARTUP_RETRIES=0", () => { | ||
| const stubScript = ` | ||
| const fs = require("fs"); | ||
| const callsPath = process.env.CLAUDE_HARNESS_STUB_CALLS; | ||
| fs.appendFileSync(callsPath, JSON.stringify({ args: process.argv.slice(2) }) + "\\n", "utf8"); | ||
| process.exit(1); | ||
| `; | ||
| const { result, calls } = runHarnessWithStub({ | ||
| stubScript, | ||
| extraEnv: { GH_AW_CLAUDE_STARTUP_RETRIES: "0" }, | ||
| }); | ||
| expect(result.status).toBe(1); | ||
| expect(calls.length).toBe(1); | ||
| expect(calls[0].args).toContain("fix the bug"); | ||
| expect(result.stderr).toContain("startup retry budget exhausted: 0/0"); | ||
| }); | ||
|
|
||
| it("returns true for normal partial-execution retry", () => { | ||
| const result = shouldRetryWithContinue({ | ||
| attempt: 0, | ||
|
|
@@ -559,6 +595,14 @@ process.exit(0); | |
| const config2 = resolveRetryConfig({ GH_AW_HARNESS_INITIAL_DELAY_MS: "0x10" }); | ||
| expect(config2.initialDelayMs).toBe(5000); | ||
| }); | ||
|
|
||
| it("uses startup retry default and clamps overrides to [0..2]", () => { | ||
| expect(resolveStartupRetryLimit({})).toBe(1); | ||
| expect(resolveStartupRetryLimit({ GH_AW_CLAUDE_STARTUP_RETRIES: "2" })).toBe(2); | ||
| expect(resolveStartupRetryLimit({ GH_AW_CLAUDE_STARTUP_RETRIES: "-5" })).toBe(0); | ||
| expect(resolveStartupRetryLimit({ GH_AW_CLAUDE_STARTUP_RETRIES: "9" })).toBe(2); | ||
| expect(resolveStartupRetryLimit({ GH_AW_CLAUDE_STARTUP_RETRIES: "nope" })).toBe(1); | ||
| }); | ||
| }); | ||
|
|
||
| describe("noop pre-flight and retry guard", () => { | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -4,6 +4,90 @@ | |
| const { generatePlainTextSummary, generateCopilotCliStyleSummary, wrapAgentLogInSection, formatSafeOutputsPreview } = require("./log_parser_shared.cjs"); | ||
| const { getErrorMessage } = require("./error_helpers.cjs"); | ||
| const { ERR_API, ERR_CONFIG, ERR_VALIDATION } = require("./error_codes.cjs"); | ||
| const INFERENCE_ACCESS_ERROR_PATTERN = /Access denied by policy settings|invalid access to inference/i; | ||
|
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. [/codebase-design] These six module-level regex constants are defined at the file top but are only used inside 💡 TradeoffModule-scope is fine if you expect these patterns to be reused by future functions in this file (e.g. a live-tail classifier). If that is the intent, add a brief comment explaining their intended reuse. Otherwise, moving them inside @copilot please address this. |
||
| const CLAUDE_RATE_LIMIT_PATTERN = /rate_limit_error|429 Too Many Requests|"api_error_status"\s*:\s*429|request rejected \(429\)|rate limit/i; | ||
| const CLAUDE_OVERLOAD_PATTERN = /overloaded_error|"overloaded"/i; | ||
| /** Matches HTTP protocol/status lines such as "HTTP/1.1 503". */ | ||
| const CLAUDE_HTTP_5XX_PROTOCOL_PATTERN = /HTTP(?:\/\d\.\d)?\s+5\d{2}\b/; | ||
| /** Matches structured status fields such as "status: 502" or "status code=500". */ | ||
| const CLAUDE_HTTP_5XX_STATUS_FIELD_PATTERN = /status(?:\s+code)?\s*[:=]\s*5\d{2}\b/; | ||
| /** Matches request/fetch/http error prose that carries an explicit 5xx code. */ | ||
| const CLAUDE_HTTP_5XX_REQUEST_ERROR_PATTERN = /(?:http|fetch|request)\s+(?:failed|error)[^\n]*?\b5\d{2}\b/; | ||
| const CLAUDE_HTTP_5XX_STATUS_PATTERN = new RegExp([CLAUDE_HTTP_5XX_PROTOCOL_PATTERN.source, CLAUDE_HTTP_5XX_STATUS_FIELD_PATTERN.source, CLAUDE_HTTP_5XX_REQUEST_ERROR_PATTERN.source].join("|"), "i"); | ||
| const STARTUP_DIAGNOSTIC_LINE_PATTERN = /(?:ERR_|Error:|CAPIError|Authentication failed|rate[_ -]?limit|429|\b5\d{2}\b|overloaded|inference)/i; | ||
| const MAX_DIAGNOSTIC_TAIL_LINES = 8; | ||
|
|
||
| /** | ||
| * Build startup diagnostics for Claude failures with no structured entries. | ||
| * @param {string} rawContent | ||
| * @returns {{ | ||
| * exitCode: string, | ||
| * inferenceAccessError: boolean, | ||
| * aiCreditsRateLimitError: boolean, | ||
| * transientInferenceAvailabilityError: boolean, | ||
| * summaryLine: string, | ||
| * summaryMarkdown: string | ||
| * }} | ||
| */ | ||
| function buildClaudeStartupDiagnostics(rawContent) { | ||
| const content = typeof rawContent === "string" ? rawContent : ""; | ||
| const lines = content | ||
| .split(/\r?\n/) | ||
| .map(line => line.trim()) | ||
| .filter(Boolean); | ||
| const startupLines = lines.filter(line => line.includes("[claude-harness]") || STARTUP_DIAGNOSTIC_LINE_PATTERN.test(line)); | ||
| // Intentionally avoid falling back to arbitrary raw log lines here. For empty-structured-log | ||
| // failures, the unmatched tail can contain unrelated stdout/stderr, prompts, or secrets; when | ||
| // no startup/diagnostic lines are recognized, we emit no tail section rather than risk leaking it. | ||
| const tailLines = startupLines.slice(-MAX_DIAGNOSTIC_TAIL_LINES); | ||
| const tailText = tailLines.join("\n"); | ||
| const safeTailText = escapeHtml(tailText); | ||
|
|
||
| let exitCode = "unknown"; | ||
| const donePrefix = "done: 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] Exit code extraction searches for 💡 Suggested fixReverse the priority — scan for the last const prefixes = ["done: exitCode=", "failed: exitCode="];
for (const prefix of prefixes) {
const idx = content.lastIndexOf(prefix);
if (idx !== -1) {
const code = content.slice(idx + prefix.length).match(/^(\d+)/);
if (code && (exitCode === "unknown" || idx > bestIdx)) {
exitCode = code[1];
bestIdx = idx;
}
}
}Alternatively, add a test that verifies the exit code is extracted correctly when only @copilot please address this. |
||
| const doneIdx = content.lastIndexOf(donePrefix); | ||
| if (doneIdx !== -1) { | ||
| const doneTail = content.slice(doneIdx + donePrefix.length); | ||
| const doneCode = doneTail.match(/^(\d+)/); | ||
| if (doneCode) { | ||
| exitCode = doneCode[1]; | ||
| } | ||
| } else { | ||
| const failedPrefix = "failed: exitCode="; | ||
| const failedIdx = content.lastIndexOf(failedPrefix); | ||
| if (failedIdx !== -1) { | ||
| const failedTail = content.slice(failedIdx + failedPrefix.length); | ||
| const failedCode = failedTail.match(/^(\d+)/); | ||
| if (failedCode) { | ||
| exitCode = failedCode[1]; | ||
| } | ||
| } | ||
| } | ||
|
|
||
| const inferenceAccessError = INFERENCE_ACCESS_ERROR_PATTERN.test(content); | ||
| const aiCreditsRateLimitError = CLAUDE_RATE_LIMIT_PATTERN.test(content) || CLAUDE_OVERLOAD_PATTERN.test(content); | ||
| const transientInferenceAvailabilityError = aiCreditsRateLimitError || CLAUDE_HTTP_5XX_STATUS_PATTERN.test(content); | ||
|
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] 💡 Why this mattersWhen If inference access denial is deliberately kept separate, add a comment explaining the intentional asymmetry. Otherwise, consider also setting @copilot please address this. |
||
| const summaryLine = `Claude startup failed before structured logging (exitCode=${exitCode}).`; | ||
| const summaryMarkdown = safeTailText ? `<details><summary>Claude startup diagnostics</summary>\n\n<pre><code>${safeTailText}</code></pre>\n</details>` : ""; | ||
|
|
||
| return { | ||
| exitCode, | ||
| inferenceAccessError, | ||
| aiCreditsRateLimitError, | ||
| transientInferenceAvailabilityError, | ||
| summaryLine, | ||
| summaryMarkdown, | ||
| }; | ||
| } | ||
|
|
||
| /** | ||
| * @param {string} text | ||
| * @returns {string} | ||
| */ | ||
| function escapeHtml(text) { | ||
| const htmlEntities = { '"': """, "'": "'", "&": "&", "<": "<", ">": ">" }; | ||
| return text.replace(/["'&<>]/g, char => htmlEntities[char]); | ||
| } | ||
|
|
||
| /** | ||
| * Bootstrap helper for log parser entry points. | ||
|
|
@@ -344,7 +428,26 @@ async function runLogParser(options) { | |
| `Claude produced no structured log entries, but agent completed with ${safeOutputEntriesCount} safe output ${safeOutputEntriesCount === 1 ? "entry" : "entries"} — treating as non-fatal post-completion infrastructure failure` | ||
| ); | ||
| } else { | ||
| core.setFailed(`${ERR_CONFIG}: Claude execution failed: no structured log entries were produced. This usually indicates a startup or configuration error before tool execution.`); | ||
| const diagnostics = buildClaudeStartupDiagnostics(content); | ||
| if (diagnostics.summaryMarkdown) { | ||
| await core.summary.addRaw(diagnostics.summaryMarkdown).write(); | ||
| } | ||
|
|
||
| if (diagnostics.inferenceAccessError) { | ||
| core.setOutput("inference_access_error", "true"); | ||
| } | ||
| if (diagnostics.aiCreditsRateLimitError) { | ||
| core.setOutput("ai_credits_rate_limit_error", "true"); | ||
| } | ||
|
|
||
| const errorCode = diagnostics.inferenceAccessError || diagnostics.transientInferenceAvailabilityError ? ERR_API : ERR_CONFIG; | ||
| const failureKind = diagnostics.inferenceAccessError | ||
| ? "inference access denied by policy" | ||
| : diagnostics.transientInferenceAvailabilityError | ||
| ? "transient inference availability signal detected" | ||
| : "startup/configuration failure detected"; | ||
|
|
||
| core.setFailed(`${errorCode}: Claude execution failed: no structured log entries were produced. ${diagnostics.summaryLine} ${failureKind}.`); | ||
| } | ||
| } | ||
|
|
||
|
|
||
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.
[/diagnosing-bugs] The startup retry fires for ALL no-output exits — including authentication failures (
isAuthenticationFailed) and invalid model errors (isInvalidModel), which are non-retryable by design and checked explicitly above. Because theresult.hasOutputguard on line 525 exits early for those cases withbreak, they only reach the startup retry block when!result.hasOutputis also true.💡 Risk and suggestion
If an auth failure produces no stdout/stderr at all (silent binary crash), it will be retried once without benefit. The extra retry wastes time and, worse, the retry log says "no output produced — retrying startup as fresh run" which could mislead operators into thinking a transient condition occurred.
Consider threading the
isAuthenticationFailedandisInvalidModelsignals down into the no-output branch and short-circuiting the startup retry for them:Alternatively, add a test for the silent-auth-failure path to document the accepted behavior.
@copilot please address this.