diff --git a/agent/Dockerfile b/agent/Dockerfile index a2d8c17a..80d2cee1 100644 --- a/agent/Dockerfile +++ b/agent/Dockerfile @@ -61,10 +61,19 @@ RUN corepack enable && corepack prepare yarn@stable --activate || corepack enabl # returned creds are cached until 5 min before the JSON's `Expiration`, so an # 8 h task re-assumes the 1 h-capped SessionRole before expiry. Older builds # only refreshed hourly on a timer, racing the role-chaining cap. +# claude-code@2.1.x ships an error-shim at bin/claude.exe that its postinstall +# (install.cjs) replaces with the platform-native ELF binary. That postinstall +# can silently fall back (leaving the shim in place) — the shim then dies at +# runtime with "Exec format error: 'claude'" even though the native binary is +# present as an optional dep, just never wired up. Re-run install.cjs explicitly +# after the install so the native binary is placed at build time, and hard-verify +# it exec's (``claude --version`` fails the build if the shim is still on PATH). RUN npm install -g npm@latest && \ npm install -g @anthropic-ai/claude-code@2.1.191 && \ CLAUDE_NPM_ROOT="$(npm root -g)/@anthropic-ai/claude-code" && \ - npm --prefix "${CLAUDE_NPM_ROOT}" update tar minimatch glob cross-spawn picomatch + npm --prefix "${CLAUDE_NPM_ROOT}" update tar minimatch glob cross-spawn picomatch && \ + node "${CLAUDE_NPM_ROOT}/install.cjs" && \ + claude --version # Install uv (fast Python package manager) — pinned for reproducibility COPY --from=ghcr.io/astral-sh/uv:0.11.14 /uv /usr/local/bin/uv diff --git a/agent/src/shell.py b/agent/src/shell.py index a51c6594..79411ed2 100644 --- a/agent/src/shell.py +++ b/agent/src/shell.py @@ -160,6 +160,83 @@ def _clean_env() -> dict[str, str]: return env +# Substrings that mark a line as a real failure in build/test tool output — used +# to pull the FAILING line out of the MIDDLE of a large interleaved parallel-DAG +# log (a plain tail misses it). Lower-cased comparison; conservative so we don't +# flood on benign "warning"/"0 errors" lines. +_FAILURE_LINE_MARKERS = ( + "fail ", # jest "FAIL test/foo.test.ts", pytest "FAILED" + "failed", + "✕", + "✗", + "✖", + "●", # jest failed-assertion bullet + "error ts", # tsc "error TS2345:" + "error:", + "elifecycle", # yarn/npm lifecycle failure + "npm err!", + "does not meet", # jest coverage-threshold "global … does not meet threshold" + "coverage threshold", + 'jest: "global"', + "not trusted", # mise untrusted config + "no task ", # mise "no task named" + "missing script", # npm missing script + "assertionerror", + "traceback (most recent call last)", + "task failed", # mise "[//pkg:task] ERROR task failed" +) + +# Benign lines that CONTAIN a marker substring but are not failures — filtered so +# the surfaced set stays signal. e.g. "0 errors", "--no-error-on-unmatched". +_FAILURE_LINE_NOISE = ( + "0 errors", + "0 failed", + "no error", + "--no-error", + "0 problems", + "may fail", # advisory prose +) + +# Cap surfaced failure lines so a genuinely huge red run (hundreds of failing +# assertions) can't flood CloudWatch; the count + a tail still convey scale. +_MAX_SURFACED_FAILURE_LINES = 40 +_FAILURE_TAIL_LINES = 15 + + +def _surface_failure_lines(stdout: str) -> list[str]: + """From a failed command's stdout, return the lines most likely to name the + cause: every failure-signature line (scanning the WHOLE output, not just the + tail — a parallel task DAG interleaves output so the red line is often in the + middle) followed by a trailing-context tail. Deduped, order-preserving, + capped. This is the fix for build-gate failures that a plain tail couldn't + explain (ABCA-662: the tail was a passing package's coverage table).""" + lines = stdout.strip().splitlines() + matched: list[str] = [] + for ln in lines: + low = ln.lower() + if any(m in low for m in _FAILURE_LINE_MARKERS) and not any( + n in low for n in _FAILURE_LINE_NOISE + ): + matched.append(ln.rstrip()) + if len(matched) >= _MAX_SURFACED_FAILURE_LINES: + matched.append("… (more failure lines truncated)") + break + tail = [ln.rstrip() for ln in lines[-_FAILURE_TAIL_LINES:]] + # Order: failure-signature lines first (the WHY), then the tail (context), + # dropping tail lines already surfaced as matches. + seen = set(matched) + out = list(matched) + if matched and tail: + out.append("--- (trailing output) ---") + for ln in tail: + if ln not in seen: + out.append(ln) + seen.add(ln) + # Fallback: nothing matched a failure marker (unknown tool) → just the tail, + # so we never log NOTHING on a failure. + return out or tail + + def run_cmd( cmd: list[str], label: str, @@ -182,6 +259,24 @@ def run_cmd( if result.stderr: for line in result.stderr.strip().splitlines()[:20]: log("CMD", f" {line}") + # ALSO surface stdout on failure. Build/test tooling (jest, tsc, the mise + # task DAG) writes the ACTUAL failing-task error to STDOUT, not stderr — + # stderr often carries only the runner's plan echo. Logging stderr alone + # made build-gate failures undebuggable: a red ``mise run build`` showed + # every task STARTING but never WHICH one failed or why (ABCA-662). + # + # A plain tail is NOT enough for a PARALLEL task DAG: `mise run build` + # runs 4 packages concurrently and interleaves their output, so the + # failing task's error scrolls into the MIDDLE while the tail captures + # whatever finished LAST (e.g. a passing package's coverage table) — + # ABCA-662 follow-up: the tail showed a coverage table, not the red task. + # So FIRST scan the whole output for failure-signature lines and surface + # those (this is what names the failing sub-task), THEN a larger tail for + # trailing context. Redact — repo build output is untrusted. + if result.stdout: + surfaced = _surface_failure_lines(result.stdout) + for line in surfaced: + log("CMD", f" {redact_secrets(line)}") if check: stderr_snippet = redact_secrets(result.stderr.strip()[:500]) if result.stderr else "" raise RuntimeError(f"{label} failed (exit {result.returncode}): {stderr_snippet}") diff --git a/agent/tests/test_shell.py b/agent/tests/test_shell.py index eb59465f..51968735 100644 --- a/agent/tests/test_shell.py +++ b/agent/tests/test_shell.py @@ -6,6 +6,7 @@ from shell import ( is_transient_cmd_failure, redact_secrets, + run_cmd, run_cmd_with_backoff, slugify, truncate, @@ -185,3 +186,135 @@ def test_backoff_delays_are_exponential(self): with patch("shell.run_cmd", side_effect=lambda *a, **k: seq.pop(0)): run_cmd_with_backoff(["git", "clone"], "clone", base_delay_s=2.0, sleep=delays.append) assert delays == [2.0, 4.0] # 2 * 2**0, 2 * 2**1 + + +class TestRunCmdFailureLogging: + """A failing command must surface its ACTUAL error. Build/test tooling (jest, + tsc, the mise task DAG) writes the failing-task error to STDOUT, not stderr — + so logging stderr alone made build-gate failures undebuggable (ABCA-662: a red + ``mise run build`` showed every task starting but never WHICH one failed).""" + + def _completed(self, rc, stdout="", stderr=""): + return SimpleNamespace(returncode=rc, stdout=stdout, stderr=stderr) + + def _run_capturing_logs(self, proc): + logs = [] + with ( + patch("shell.subprocess.run", return_value=proc), + patch("shell.log", side_effect=lambda prefix, text: logs.append((prefix, text))), + ): + run_cmd(["mise", "run", "build"], "verify-build-post", check=False) + return logs + + def test_stdout_is_logged_on_failure(self): + # The failing task's error lives in stdout — it MUST reach the log. + proc = self._completed( + 1, + stdout="[//cdk:test] FAIL test/foo.test.ts\n expected 1 got 2\n[//cdk:test] exit 1", + stderr="", + ) + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + assert "FAIL test/foo.test.ts" in blob + assert "expected 1 got 2" in blob + + def test_no_markers_falls_back_to_tail(self): + # Unknown tool output with no failure signature → fall back to the tail. + proc = self._completed( + 1, + stdout="\n".join(f"line {i}" for i in range(50)), + stderr="", + ) + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + assert "line 49" in blob # last line present (tail) + assert "line 0" not in blob # earliest lines dropped + + def test_failure_line_in_the_MIDDLE_is_surfaced(self): + # ABCA-662 root cause of the tooling gap: a PARALLEL mise DAG interleaves + # output, so the failing task's line is in the MIDDLE while the tail is a + # passing package's coverage table. The failing line MUST be surfaced. + mid = "[//cdk:test] FAIL test/handlers/foo.test.ts — expected 1 got 2" + stdout = ( + "\n".join(f"[//cdk:test] passing line {i}" for i in range(30)) + + f"\n{mid}\n" + + "\n".join(f"[//agent:test] coverage {i} | 100 | 100" for i in range(30)) + ) + proc = self._completed(1, stdout=stdout, stderr="") + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + assert "FAIL test/handlers/foo.test.ts" in blob # the mid-DAG red is surfaced + assert "coverage 29" in blob # tail context still present + + def test_coverage_threshold_failure_is_surfaced(self): + # jest prints a coverage table then exits 1 with "does not meet threshold" + # — no ✕/FAIL line. That threshold line must be surfaced. + stdout = ( + "\n".join(f"file{i}.ts | 100 | 100 | 100 | 100" for i in range(40)) + + '\nJest: "global" coverage threshold for branches (82%) not met: 79%' + ) + proc = self._completed(1, stdout=stdout, stderr="") + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + assert "coverage threshold for branches" in blob + + def test_benign_zero_errors_line_not_surfaced_as_failure(self): + # "0 errors" / "no error" must NOT be pulled in as a failure marker. + stdout = "eslint: 0 errors, 0 warnings\n" + "\n".join(f"ok {i}" for i in range(20)) + proc = self._completed(1, stdout=stdout, stderr="") + logs = self._run_capturing_logs(proc) + # It falls back to tail (no real failure markers); the "0 errors" line is + # not falsely elevated as THE failure. + blob = "\n".join(text for _, text in logs) + assert "ok 19" in blob + + def test_marker_line_with_noise_term_is_filtered_by_allowlist(self): + # N3: the LOAD-BEARING allowlist case. A line that hits a real marker + # (`error:`) AND a noise term (`0 errors`) must be filtered OUT of the + # surfaced set. Placed in the MIDDLE (before the tail window) so it is + # only reachable via the marker scan — if _FAILURE_LINE_NOISE were + # deleted, this line WOULD be surfaced and the assertion would fail. + # A genuine failure line follows so the scan still produces a match set. + noisy = "error: eslint produced 0 errors after autofix retry" # marker + noise + real = "[//cdk:test] FAIL test/handlers/bar.test.ts — boom" + # 30 trailing passing lines push both lines above out of the tail window, + # so `noisy` is only reachable via the marker scan (where the allowlist runs). + stdout = f"{noisy}\n{real}\n" + "\n".join(f"[//agent:test] passing {i}" for i in range(30)) + proc = self._completed(1, stdout=stdout, stderr="") + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + assert "FAIL test/handlers/bar.test.ts" in blob # real failure surfaced + assert "0 errors after autofix retry" not in blob # noisy marker filtered by allowlist + + def test_surfaced_failure_lines_are_capped_and_truncation_marked(self): + # N4: a genuinely huge red run (more than _MAX_SURFACED_FAILURE_LINES + # marker lines) must be capped, with an explicit truncation breadcrumb — + # so it can't flood CloudWatch. Exercises the cap branch the other tests + # never reach. + from shell import _MAX_SURFACED_FAILURE_LINES + + n = _MAX_SURFACED_FAILURE_LINES + 10 + stdout = "\n".join(f"FAIL test/case_{i}.test.ts — assertion {i}" for i in range(n)) + proc = self._completed(1, stdout=stdout, stderr="") + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + # The marker-scan hit the cap and emitted the truncation breadcrumb. + assert "… (more failure lines truncated)" in blob + # The breadcrumb appears within the surfaced set BEFORE the tail divider — + # i.e. the matched-line scan was capped, not the whole output dumped. + head = blob.split("--- (trailing output) ---")[0] + head_cases = sum(1 for i in range(n) if f"case_{i}.test.ts" in head) + assert head_cases <= _MAX_SURFACED_FAILURE_LINES + + def test_stdout_is_redacted(self): + proc = self._completed(1, stdout="error: pushing with ghp_supersecrettoken123", stderr="") + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + assert "ghp_supersecrettoken123" not in blob + + def test_success_does_not_dump_stdout(self): + # On success we don't spam stdout — only the OK line. + proc = self._completed(0, stdout="lots of build output", stderr="") + logs = self._run_capturing_logs(proc) + blob = "\n".join(text for _, text in logs) + assert "lots of build output" not in blob diff --git a/cdk/src/constructs/ecs-agent-cluster.ts b/cdk/src/constructs/ecs-agent-cluster.ts index f74db31c..f21a3f16 100644 --- a/cdk/src/constructs/ecs-agent-cluster.ts +++ b/cdk/src/constructs/ecs-agent-cluster.ts @@ -184,10 +184,13 @@ export class EcsAgentCluster extends Construct { LOG_GROUP_NAME: logGroup.logGroupName, GITHUB_TOKEN_SECRET_ARN: props.githubTokenSecret.secretArn, // Heavy CI-parity builds on this big-box substrate legitimately run - // longer than the 1800s default (ABCA's own `mise run build` is - // ~50 min cold). Raise the post-agent build-verify cap so a slow-but- - // healthy build isn't mis-reported as a timeout (see post_hooks.py - // BUILD_VERIFY_TIMEOUT_S). ECS-only: AgentCore repos keep the default. + // long (ABCA's own `mise run build` is ~50 min cold), so set a generous + // post-agent build-verify cap here for the ECS-only path. NOTE: the + // consuming side (verify_build/verify_lint reading BUILD_VERIFY_TIMEOUT_S + // and passing it as the subprocess timeout) ships with the ECS-substrate + // work; on `main` today the verify subprocess still uses run_cmd's + // default cap, so this env is provisioned ahead of the wiring rather + // than currently effective. ECS-only: AgentCore repos don't set it. BUILD_VERIFY_TIMEOUT_S: '3600', ...(props.memoryId && { MEMORY_ID: props.memoryId }), // #502: the payload bucket name so the orchestrator-issued diff --git a/cdk/src/handlers/shared/error-classifier.ts b/cdk/src/handlers/shared/error-classifier.ts index 41d538e8..f68e15f4 100644 --- a/cdk/src/handlers/shared/error-classifier.ts +++ b/cdk/src/handlers/shared/error-classifier.ts @@ -433,6 +433,32 @@ const PATTERNS: readonly ErrorPattern[] = [ }, // --- Timeout --- + { + // An ``agent/`` subprocess (``run_cmd``) hit its wall-clock cap and Python + // raised an uncaught ``TimeoutExpired … timed out after N seconds``, which + // otherwise surfaces as a bare "Unexpected error". This is NOT a code + // failure — the command didn't fail, it ran too long — so name it precisely + // and point at "slow, retry", not the diff. NOTE: this matches only + // UNCAUGHT ``run_cmd`` timeouts (clone/setup/etc.); the post-agent build/lint + // VERIFY path catches ``TimeoutExpired`` itself and returns a plain build + // failure, so it does not reach here. The remedy is deliberately generic + // ("retry / it may be slow") rather than naming a specific env knob — on + // ``main`` the verify timeout is not operator-tunable, so promising a lever + // here would misdirect (the tunable ``BUILD_VERIFY_TIMEOUT_S`` + larger ECS + // build compute live on the ECS-substrate track, not this branch). + pattern: /TimeoutExpired.*timed out after \d+(?:\.\d+)? ?s(econds)?|Command .*build.* timed out/i, + classification: { + category: ErrorCategory.TIMEOUT, + title: 'Build/tests didn\'t finish in time (timed out)', + description: 'The configured build/verify command was still running when it hit the time limit and was stopped — it did not fail, it ran too long.', + remedy: 'This is usually a slow build, not broken code — retry, since a one-off may just have been slow. If a repo\'s build is legitimately long, its build environment likely needs more time or capacity; contact your ABCA admin.', + retryable: true, + // Intentionally USER (no auto-retry): re-running an unchanged slow build + // just times out again, so this must NOT be TRANSIENT — a human decides + // whether to retry or right-size the build. Do not "fix" this to TRANSIENT. + errorClass: ErrorClass.USER, + }, + }, { pattern: /poll timeout exceeded/i, classification: { diff --git a/cdk/test/handlers/shared/error-classifier.test.ts b/cdk/test/handlers/shared/error-classifier.test.ts index 8e6a8b48..43d0a315 100644 --- a/cdk/test/handlers/shared/error-classifier.test.ts +++ b/cdk/test/handlers/shared/error-classifier.test.ts @@ -407,6 +407,22 @@ describe('classifyError', () => { expect(result!.title).toBe('Task timed out'); expect(result!.retryable).toBe(false); }); + + test('classifies a build/verify command TIMEOUT distinctly from a crash (ABCA-667 live-caught)', () => { + // The fork's full `mise run build` exceeded the 600s cap → Python + // TimeoutExpired. Before this pattern it fell to "Unexpected error"; now it + // reads as a build-time-out (user-actionable: retry / raise the cap), not a + // mysterious crash. + const result = classifyError( + "TimeoutExpired: Command '['bash', '-lc', 'mise run install && MISE_EXPERIMENTAL=1 mise run build']' timed out after 600 seconds", + ); + expect(result!.category).toBe(ErrorCategory.TIMEOUT); + expect(result!.title).toMatch(/didn't finish in time|timed out/i); + // A timeout is user-actionable (retry / raise the cap), not a hard failure. + expect(result!.retryable).toBe(true); + // Must NOT fall through to the generic Unexpected error. + expect(result!.title).not.toMatch(/Unexpected error/i); + }); }); // --- Environmental blockers (#251) ---