From 3709523bedacc0dee36e91331e5bd07a3b63ee46 Mon Sep 17 00:00:00 2001 From: joeysbase Date: Fri, 14 Aug 2026 23:08:08 +0000 Subject: [PATCH 1/3] fix(orchestrator): grade a forced-kill timeout instead of discarding it A TaskTimeoutError/TurnTimeoutError used to throw away whatever the agent had already produced, so a task that timed out but had in fact satisfied its success criteria was reported TIMEOUT. Both handlers now run _grade_after_forced_kill against the recorded trajectory and finalize SUCCESS (plain, error_message cleared) when the criteria pass, falling back to TIMEOUT otherwise. The grading pass is deliberately conservative: - It commits the fallback status synchronously before its first await and only ever upgrades to SUCCESS, so a BaseException (Ctrl-C, a batch-level cancel) mid-grade cannot leave the row at the constructor default. - It quiesces the agent first. On a TurnTimeoutError nothing has torn the harness down yet (Antigravity's kill_sync is intent-only and _cleanup runs later, in run()'s finally), so without this the criteria could read a sandbox a backgrounded build was still writing. - It is wall-clock bounded (60s), never raises, and honors the same FIRED-ONLY early-stop gate as a normal run via _gate_passed, back-filling result.early_stop from the watcher that a hard-killed run never reaches. - It re-grades rather than reusing results whose _graded_iteration_count predates the last recorded turn -- the simulation loop rewrites success_criteria_results every turn under check_criteria: every_turn, so a non-empty list alone does not mean the grade covers the trajectory. - It folds its judge slice into the dialog-wide accumulator, so a mid-dialog kill no longer drops every earlier turn's judge cost. Antigravity's background-work poll loop is rebounded. A cycle's cost is bimodal: against a backgrounded job the connection is idle and receive_steps() returns immediately (5s/cycle), while a wedged connection burns the full 30s per-step timeout. _MAX_BACKGROUND_POLLS stays at 120 (120 x 5s = 600s, ~2x the worst 60-300s job that motivated the poll loop) and a new _MAX_BACKGROUND_POLL_WALL_SECONDS bounds the wedged mode. The flat backstop is anchored at poll-loop ENTRY, not turn start: anchoring it at turn start meant a turn_timeout: null turn that had already run longer than the backstop got zero poll cycles. The configured-timeout deadline stays turn-anchored because it must win its race with the watchdog. CE022 is generalized from one hardcoded function to a (file, function, cap) table, since this change adds two # noqa: PLR0915 sites. Its registration contract is self-enforcing: an unregistered carrier is itself a violation. The rule reads source text plumbed through BaseRule.source_lines rather than re-opening its filepath, so a synthetic tree with a real-looking path can no longer scan an unrelated file. Co-Authored-By: Claude Opus 5 --- .claude/harness-candidates.md | 123 +++++ CLAUDE.md | 4 +- docs/agents/ANTIGRAVITY.md | 7 +- docs/agents/HARNESS_PARITY.md | 55 ++- src/coder_eval/agents/antigravity_agent.py | 187 ++++++- src/coder_eval/orchestrator.py | 226 ++++++++- tests/lint/rules/base.py | 11 + .../rules/ce022_dialog_loop_statement_cap.py | 157 ++++-- tests/lint/runner.py | 8 +- tests/test_antigravity_agent.py | 412 ++++++++++++++++ tests/test_custom_lint.py | 98 +++- tests/test_timeout_orchestrator.py | 462 ++++++++++++++++++ 12 files changed, 1653 insertions(+), 97 deletions(-) diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index 3957153f..14482709 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -391,3 +391,126 @@ with the two `action.yml` items above — one considered change to the action's violations on `main` before this bug, one on this PR). Worth a real look next time `agents/` is touched, since a second agent adding its own disconnected sleep-loop constant would reintroduce the exact same shape. + +## From the timeout-grading fix (2026-08-14) + +- [ ] **A forced-kill exception handler that sets a terminal `FinalStatus` must + attempt success-criteria grading before giving up.** Real nightly run data + (`runs/gemini-3-1-pro-full/default/energy-unit-commitment/01`) showed a + `TurnTimeoutError` land as `FinalStatus.ERROR` with zero criteria evaluated, + even though the agent's real, complete, correct output was already on disk — + `run()`'s `except TurnTimeoutError`/`except TaskTimeoutError` handlers never + called `check_all_async` at all. Fixed by adding `_grade_after_forced_kill()` + and calling it from both handlers. **Not promoted in this pass**: the + mechanical check would need a whole-tree rule asserting every `except` block + in `orchestrator.py` that sets `self.result.final_status` also reaches a + `check_all_async` call (directly or via a helper) or explicitly justifies not + doing so — a real design (which exception types are exempt, how to trace + "reaches a call" through a helper indirection), not a 30-minute rule. + +## From the final review of the timeout-grading fix (2026-08-14) + +- [ ] **`AgentCrashError` is not wired to `_grade_after_forced_kill`.** Only + `TurnTimeoutError`/`TaskTimeoutError` get the new forced-kill grading path; + `AgentCrashError` still falls through `run()`'s generic `except Exception:` + to `FinalStatus.ERROR` with grading unconditionally skipped, even though + `_on_attempt_failure` drains the same `pending_turn` slot for crashes as it + does for turn timeouts (`orchestrator.py`'s `_communicate_with_retry`). + Explicitly out of scope for this fix (the plan scoped it to the two timeout + exception types), but the asymmetry — timeouts get graded, crashes don't — + is a natural next candidate if a crashed-but-complete agent output turns out + to be common enough to matter. Flagged by an independent final-review agent. +- [ ] **Unverified assumption: a per-step `asyncio.wait_for` timeout's + cancellation unwinds the real SDK's two-layer delegating generator the same + way a cooperative-stop `break` does.** `AntigravityAgent._drain()`'s + docstring analyzes the re-entrancy retry needed after a `break` at a + suspended yield point (`should_stop`/`max_turns_reached`); the new + `except TimeoutError:` break results from `asyncio.wait_for` cancelling + `steps.__anext__()` while it is ACTIVELY awaiting, not suspended at a yield + — a different unwind mechanism the docstring doesn't cover. The existing + `_RECEIVE_STEPS_REENTRY_RETRIES` retry loop would likely absorb any extra + `RuntimeError` this causes on the next `receive_steps()` call, but this is + reasoned by analogy, not confirmed against the installed + `google-antigravity` SDK's actual re-entrancy guard under this exact path. + **Not promoted**: verifying it needs a live/integration test against the + real SDK (or a fake that faithfully reproduces the two-layer delegation AND + a genuinely-in-flight cancellation, harder to construct than the existing + `_TwoLayerReentrancyGuardedConversation` fixture), not a static rule. Revisit + if a live Antigravity run ever surfaces an unexpected `RuntimeError` spike + correlated with per-step timeouts. + +## From the /coder-eval-code-review pass on timeout-grading-and-blocking-drain (2026-08-14) + +Three independent reviewers (2 Opus fallback + 1 Opus specialized-lens) converged +on the per-step-timeout-too-aggressive High finding, fixed in this pass +(`_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS` decoupled from the poll interval and +raised to 30s). NOTE: that pass also recalibrated `_MAX_BACKGROUND_POLLS` to 17 from +a 35s-per-cycle assumption; a later review round found that arithmetic does not apply +to the idle backgrounded-job mode (a cycle there costs 5s, so the real budget was 85s, +not ~10 minutes) and reverted it to 120, adding a separate +`_MAX_BACKGROUND_POLL_WALL_SECONDS = 600.0` wall-clock backstop for the wedged mode. Also fixed: `_grade_after_forced_kill` skipping +re-grading when criteria are already populated, the FIRED-ONLY early-stop gate +(`_gate_passed`), a wall-clock bound on the salvage grading pass, the bogus +"after 0s" message, a missing `conversation.cancel()`, CE022's coverage of the two +new `# noqa: PLR0915` sites, and `docs/agents/HARNESS_PARITY.md`'s stale claims. + +Deferred (not fixed this pass): + +- [ ] **`_grade_after_forced_kill` still duplicates the load_reference → + check_all_async → store → calculate_weighted_score sequence** found in + `_evaluation_loop` and `_run_dialog_criteria_check`, rather than sharing one + helper. The FIRED-ONLY gate-selection *boolean* was extracted into + `_gate_passed` and is now shared, but the surrounding grading sequence and + `_evaluation_loop`'s own inline gate-selection block (which carries + additional per-branch logging — `armed_count`, disarmed-vs-never-fired + messages) were deliberately left untouched: refactoring that already-tested, + delicate correctness path purely for a DRY win risked a regression in + well-established normal-path code for no correctness benefit. Also, fully + sharing `_run_dialog_criteria_check` from `_grade_after_forced_kill` would + require hoisting `judge_usage_accum` (currently a `_simulation_dialog_loop` + local) onto `self` so both scopes can reach it — a real refactor, not a + drive-by fix. **Not promoted**: this is a structural improvement, not a + regression risk (the correctness gaps it exposed — double-grading, lost + judge-usage accumulation — are already closed by the "skip if already + graded" fix above), so it's lower priority than the items already fixed. +- [ ] **`except TimeoutError:` in `_drain()`'s per-step wait also catches a + genuine transport-level `TimeoutError`** (an `OSError` subclass) raised from + inside the SDK, indistinguishable from `asyncio.wait_for`'s own expiry — + a real connection failure would be reclassified as "still waiting" and + polled out to the budget instead of surfacing as a diagnosable crash. + **Not promoted**: distinguishing the two reliably needs an elapsed-time + check around the call (compare actual elapsed against the configured + timeout, with a safety margin for scheduling jitter) — cheap in isolation, + but the margin needs live-SDK validation to pick a value that doesn't + itself introduce false classifications, so it's not a pure ≲30-minute + mechanical change. Low severity: this only matters if the SDK ever raises a + real socket-level `TimeoutError`, which hasn't been observed. +- [x] **CLOSED (code review, 2026-08-14)** — `_grade_after_forced_kill`'s + `passed_count` log line ran `zip(criteria_results, + self.task.success_criteria, strict=True)` before the status decision was + committed, inside the same broad `try`, so a length mismatch would have + discarded the already-computed `all_passed` in favor of `fallback_status`. + Fixed directly rather than deferred: the tally moved into + `_log_graded_after_forced_kill`, which runs AFTER the status decision and + swallows its own `ValueError`. No lint rule — this was a one-off ordering + bug in a single function, not a mechanically detectable pattern. +- [ ] **CE022's self-guard cannot see a blanket `# noqa` or a file-level + `# ruff: noqa: PLR0915`.** It matches only the ordinary + `# noqa: PLR0915` form (the one in use). A bare `# noqa` on a `def` line + genuinely suppresses PLR0915 for ruff, but `runner._is_suppressed` would + also drop CE022's own violation reported on that same line (`_NOQA_ALL`), + so the marker is unreachable for this rule no matter how it matches. + **Not promoted**: closing it properly means teaching the runner that some + rules opt out of blanket-noqa suppression — a runner-wide semantic change + affecting all CE rules, well past a ≲30-minute mechanical fix. Low severity: + both forms are absent from `src/` today (verified by grep) and using one to + dodge CE022 would be deliberate. +- [x] **CLOSED (code review, 2026-08-14)** — CE022's "register every new + `# noqa: PLR0915` in `_TARGETS`" contract was documented but enforced by + nothing, so a fourth suppression would have been unbounded (ruff's check + off, the rule skipping it) while `test_no_violations` still reported the + tree clean. Promoted per the ≲30-minute rule: `NoqaPlr0915StatementCap` + now reads the `def` header from source and flags any carrier absent from + `_TARGETS` (`_carries_suppression`), covered by + `test_flags_an_unregistered_noqa_plr0915` and a negative test for a + registered target and a body-only PLR0915 mention. diff --git a/CLAUDE.md b/CLAUDE.md index 7ca54ef8..14471ac3 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -142,9 +142,9 @@ action.yml # Published composite GitHub Action (coder-ev - **Per-criterion aggregation**: Each `BaseCriterion` subclass exposes `aggregate(criterion, per_row_results) -> CriterionAggregate | None`. Default emits `count / mean / median / std / min / max` so every criterion is suite-thresholdable for free. Classification-style criteria return `ClassificationCriterionResult` (subclass of `CriterionResult`) and layer accuracy / P/R/F1 / confusion via the shared `overlay_classification_metrics` utility. `BaseSuccessCriterion.suite_thresholds` gates the suite on those metrics; CLI exits non-zero on any gate failure. - **Sub-agent token accounting**: There is NO separate per-sub-agent field. Every sub-agent generation is captured as a `parent_tool_use_id`-tagged `AssistantMessage` in the turn transcript, so per-sub-agent usage is derived by grouping those messages on that id (the evalboard's `aggregateSubAgentUsage` does exactly this). Claude bubbles its sub-agent's intermediate generations into the parent stream natively, and the **terminal** generation (delivered as the Agent tool result, never streamed) is synthesized into one via `_synthesize_subagent_terminal_message` from `tool_use_result.usage`. Codex reconstructs all child generations from the child rollout (`_recover_subagent_tool_calls`). The turn total already includes sub-agent cost — Claude via the SDK's cumulative `model_usage`; Codex via `_fold_subagent_tokens`, which folds the child messages (their real per-generation tokens) into the parent total. `CommandTelemetry.result_summary` is stored **untruncated** (no 200-char cap) so sub-agent returns are preserved whole. Set `CODER_EVAL_RAW_SDK_LOG=1` to dump every raw SDK event to the task log for inspection. - **Reconciliation message (stream self-reconciles to the turn total)**: The per-message stream consistently under-reports the authoritative turn total — a fixed prompt slice (~512 input tokens on Claude) is billed on no SDK-emitted message, and sub-agent input/cache only partially bubbles up. So `EventCollector.build_turn_record` appends one synthetic `ReconciliationMessage` (`role="reconciliation"`, in the `TranscriptMessage` union) per turn, carrying the per-bucket residual = `token_usage` − Σ(assistant message buckets). The invariant: **summing the four token buckets across `TurnRecord.messages` (assistant + reconciliation) equals `token_usage` exactly**, for both Claude and Codex (Codex's stream is already complete after `_recover_subagent_tool_calls`, so its residual is usually 0 and no entry is emitted). This is what lets the evalboard SUM the message stream as the source of truth instead of reading a separate aggregate ("agent tokens"): `selectTokenTotals` returns the stream sum whenever a reconciliation entry is present, and the timeline renders it as its own row. It is agent-agnostic (booked at the single `EventCollector` seam), carries no cost (cost stays on `token_usage`), and is excluded from generation/turn counts and the cost simulator. The LiteLLM open-weight actual-cost join (`litellm_cost.apply_actual_cost`) deliberately writes cost at the TURN level only (`token_usage.total_cost_usd` = the real OpenRouter bill) plus the per-call `TurnRecord.provider_call_costs` audit record; it does NOT touch the message token buckets, so `EventCollector` stays the single writer and this invariant holds on every backend. The Python `token_usage`/`total_token_usage` aggregate is unchanged and still authoritative for budget/judges/reports. -- **Harness run-limit parity**: a shared `BaseAgentConfig` field must mean the same thing on every backend, so a divergence is either fixed or documented — never silent. **`run_limits.max_turns` on Codex/Antigravity counts VISIBLE turns** (resolved tool calls, read live off the shared `EventCollector.visible_turn_count`, the same list `TurnRecord.commands` holds) because one `communicate()` is a single SDK turn on both, so a native counter would clamp at 1; claude-code keeps its native SDK cap, whose unit (an agent-loop turn) absorbs arbitrarily many parallel calls — the same number is NOT the same budget across harnesses. The cap is enforced on the same loop boundary as the cooperative early stop and finalizes cleanly as `max_turns_exhausted` (no crash, no retry); on Antigravity that boundary lives in `_drain()`, so the background-work poll loop honors it too. Known unfixed divergences: `permission_mode` on Codex and Antigravity (both run unconfined — the sandbox driver is the isolation boundary), `disallowed_tools` on Codex (forwarded, not SDK-enforced), `allowed_tools`/`disallowed_tools` on Antigravity (not read at all), and `turn_timeout` on Antigravity (bounded by an earlier internal poll deadline at 80% of it). Full table + rationale: docs/agents/HARNESS_PARITY.md. +- **Harness run-limit parity**: a shared `BaseAgentConfig` field must mean the same thing on every backend, so a divergence is either fixed or documented — never silent. **`run_limits.max_turns` on Codex/Antigravity counts VISIBLE turns** (resolved tool calls, read live off the shared `EventCollector.visible_turn_count`, the same list `TurnRecord.commands` holds) because one `communicate()` is a single SDK turn on both, so a native counter would clamp at 1; claude-code keeps its native SDK cap, whose unit (an agent-loop turn) absorbs arbitrarily many parallel calls — the same number is NOT the same budget across harnesses. The cap is enforced on the same loop boundary as the cooperative early stop and finalizes cleanly as `max_turns_exhausted` (no crash, no retry); on Antigravity that boundary lives in `_drain()`, so the background-work poll loop honors it too. Known unfixed divergences: `permission_mode` on Codex and Antigravity (both run unconfined — the sandbox driver is the isolation boundary), `disallowed_tools` on Codex (forwarded, not SDK-enforced), `allowed_tools`/`disallowed_tools` on Antigravity (not read at all), and `turn_timeout` on Antigravity (the background-work poll loop is bounded by an earlier internal deadline at 80% of it, or a flat 600s when the task sets no timeout — at that bound a still-ACTIVE tool call is force-closed and graded normally, while a connection that never produced a clean turn end raises a real `TurnTimeoutError`). Full table + rationale: docs/agents/HARNESS_PARITY.md. - **sandbox isolation**: Tasks that don't need MCP servers should set `setting_sources: []` in their `agent:` block to isolate the sandbox from the host project's CLAUDE.md and settings. Without this, the host project's CLAUDE.md (often 20 KB+) is injected into every API call, inflating cache-creation tokens and cost significantly. -- **Run-time caps (non-criterion enforcement)**: `TaskDefinition.run_limits` (`RunLimits` model) is the single namespace for all *task-level* run-time caps — `max_turns` / `task_timeout` / `turn_timeout` (structural) and `max_input_tokens` / `max_output_tokens` / `max_total_tokens` / `max_usd` (cumulative budget). Token/USD breaches abort with `FinalStatus.TOKEN_BUDGET_EXCEEDED` or `COST_BUDGET_EXCEEDED` (both `category == "failed"`). Structural caps are set from the CLI via `-D run_limits.max_turns=…` / `-D run_limits.task_timeout=…` / `-D run_limits.turn_timeout=…` (field-merged into `run_limits`); budget caps via `-D run_limits.max_usd=…` etc. or YAML. Layered config uses field-merge — a variant block overrides individual keys without replacing the task's block. The one *per-criterion* cap, `stop_early.decide_within`, deliberately lives on `LiveSuccessCriterion` instead (see below) — the watcher must attribute a decision-step timeout to a specific criterion, which `RunLimits` (task-scoped, criterion-agnostic) cannot express. +- **Run-time caps (non-criterion enforcement)**: `TaskDefinition.run_limits` (`RunLimits` model) is the single namespace for all *task-level* run-time caps — `max_turns` / `task_timeout` / `turn_timeout` (structural) and `max_input_tokens` / `max_output_tokens` / `max_total_tokens` / `max_usd` (cumulative budget). Token/USD breaches abort with `FinalStatus.TOKEN_BUDGET_EXCEEDED` or `COST_BUDGET_EXCEEDED` (both `category == "failed"`). A **structural timeout is graded, not discarded**: `TaskTimeoutError` and `TurnTimeoutError` both run `Orchestrator._grade_after_forced_kill` against whatever the agent produced before the kill, so a task that timed out but already satisfied its criteria finalizes `SUCCESS` (plain, error_message cleared) instead of `TIMEOUT` — downstream consumers must not read `TIMEOUT` as "every timed-out run". Grading is bounded (60s), never raises, honors the same FIRED-ONLY early-stop gate as a normal run, and falls back to `TIMEOUT` on any failure. Structural caps are set from the CLI via `-D run_limits.max_turns=…` / `-D run_limits.task_timeout=…` / `-D run_limits.turn_timeout=…` (field-merged into `run_limits`); budget caps via `-D run_limits.max_usd=…` etc. or YAML. Layered config uses field-merge — a variant block overrides individual keys without replacing the task's block. The one *per-criterion* cap, `stop_early.decide_within`, deliberately lives on `LiveSuccessCriterion` instead (see below) — the watcher must attribute a decision-step timeout to a specific criterion, which `RunLimits` (task-scoped, criterion-agnostic) cannot express. - **Early stop on criterion (opt-in, per-criterion arming)**: a `stop_early:` block (`StopEarlyPolicy`) on a criterion ends a single-shot run early once the run's **armed** criteria decide the outcome, so a raised `max_turns` isn't wasted on the smoke flavor. The block's PRESENCE is the arming and alone activates the watcher — there is **no run-level master switch**: `run_limits.stop_early: false` is the run-level KILL SWITCH that force-disarms every block (the one-line experiment-variant/`-D` override for an authoritative full run), and `run_limits.stop_early: true` (the removed master arm) is a hard `EarlyStopConfigError` at resolution. The block exists on `LiveSuccessCriterion` only (currently `skill_triggered`, `command_executed` — so arming an unobservable criterion is unrepresentable, a pydantic extra-forbid error). Arming carries one implicit trigger (a native live-fail may fail-stop the run); its keys refine it: `on_pass: stop` (pass-stop the moment the criterion live-passes; default `continue` just latches) and `decide_within: N` (still undecided after N tool-call steps latches an **effective fail**, fed through the same fail-stop rule, reported as `decision_budget_exceeded` — an ordinary weighted fail, NOT a gate-bypassing force-fail; cumulative across retry attempts of the same turn). A trigger whose polarity the instance can't decide (per the abstract, checker-independent `live_decidable_polarities()`, a pure function of the criterion's own fields, paired with the checker's `live_verdict` override by lint rule CE025, a registry-based whole-tree check) is **inert by design** — one dataset-fanned YAML line serves both positive rows (pass/timeout live) and distractor rows (fail live). Verdicts **latch**: once a criterion decides, its `live_verdict` is never polled again. Stop rule is weighted, not strict-boolean: `run_limits.stop_early_gate_threshold` (default `1.0`, reproducing strict-AND behavior exactly) is the minimum weighted score (`Σ weight·score / Σ weight` over the armed subset) required to pass; a fail-stop fires once the armed set's **ceiling** (best case for everything still undecided) can no longer reach the threshold — so a low-weight fail or timeout that can't doom the gate is absorbed and the run continues — and is **deferred while any pass-capable armed criterion is undecided** (a distractor misfire never truncates a positive row's recall signal); a pass-stop fires once the `on_pass: stop` subset's **floor** (worst case) already meets the threshold, and is symmetrically **deferred while any pass-capable armed criterion outside the `on_pass: stop` subset is undecided** (so an early pass never freezes a sibling `on_pass: continue` criterion's signal out of the trajectory). A fail-stop is therefore verdict-preserving; a pass-stop can miss a *later* distractor misfire, so authoritative P/R/F1 comes from a kill-switched (`stop_early: false`) run. Driven by `orchestration/early_stop.py::EarlyStopWatcher` (built when `early_stop_active(task)`: ≥1 armed criterion, kill switch not thrown) through the agent's cooperative `should_stop` seam (tool-call granularity, no SIGKILL); live verdicts only *trigger* the stop — the standard `check_all_async` on the frozen trajectory is authoritative. Gating is **FIRED-ONLY**: a run the watcher actually cut gates on the **armed subset** via the weighted `EvaluationResult.armed_criteria_passed`; a run that completes naturally — armed or not — gates strict-AND via `all_criteria_passed`, so adding a block never changes the verdict of a run it didn't cut. Note the gate keys on the watcher having FIRED (`result.early_stop is not None`), not on confirmed truncation — an agent that ignores `should_stop`, or a stop firing on the final message, still gates armed-only. Every resolution-time guardrail violation is a hard error at resolution (plan *and* run); the one load-time case — a `stop_early:` block on a non-live criterion — is a pydantic schema error at task load, which the run surface reports as a skipped task like any other malformed task. A runtime verdict bug **fails open** to a full run. Surfaces: `EarlyStopInfo` (incl. `gate_threshold` at stop time), report notes/badges, `stopped_early` run.json rows, `EarlyStopped`/`EarlyStopReason` telemetry dims. Worked rationale: docs/TASK_DEFINITION_GUIDE.md § `stop_early`. No blocks anywhere ⇒ behavior byte-for-byte unchanged. ## Success Criteria (15 types) diff --git a/docs/agents/ANTIGRAVITY.md b/docs/agents/ANTIGRAVITY.md index 51b80bd3..f63dccb7 100644 --- a/docs/agents/ANTIGRAVITY.md +++ b/docs/agents/ANTIGRAVITY.md @@ -197,8 +197,11 @@ as every other agent. 10-second maximum synchronous wait; past it the command becomes a background task and the model gets a task id, not a result. The turn polls for that result instead of finalizing on an idle step stream, so slow work does complete — but the wait is - bounded by 80% of `turn_timeout`, and a job that outlives it is force-closed as - `result_status: unknown` and graded as an ordinary low score rather than a timeout. + bounded by 80% of `turn_timeout` (600s when the task sets no timeout). What happens + at that bound depends on what is in flight: a job still ACTIVE is force-closed as + `result_status: unknown` and graded as an ordinary low score rather than a timeout; + a connection that never produced a clean turn end with nothing ACTIVE raises a real + `TurnTimeoutError` instead, so the orchestrator's grading path runs. Measured in [Run-Limit Parity](HARNESS_PARITY.md). ## Running in Docker diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index 296092f6..679150a6 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -69,9 +69,12 @@ The signals a capped run leaves behind, on every backend: On Claude Code and Codex a `turn_timeout` breach is a *failure*: the watchdog fires at the deadline, the partial turn is preserved on `pending_turn`, and the turn is -marked `crashed`. +marked `crashed`. The orchestrator then attempts success-criteria grading against +whatever was salvaged (`_grade_after_forced_kill`) before falling back to +`FinalStatus.TIMEOUT` if criteria don't pass. -Antigravity stops earlier and more gently, for the reason in the next section. +Antigravity's poll loop (next section) can exit two ways, and only one of them +stops earlier and more gently than the other two backends. ## Antigravity backgrounds anything over 10 seconds @@ -84,23 +87,43 @@ What coder_eval does about it: the turn polls for the backgrounded result rather than finalizing the moment the step stream goes idle, so slow work does finish and its real exit code reaches the model. Without that poll, a command over the 10s boundary left the tool call unresolved and the turn was graded on work that had not -happened yet. - -The wait is bounded by **80% of `turn_timeout`** (or 120 five-second cycles when the -task sets no timeout), not by `turn_timeout` itself. A job that outlives that bound -is force-closed as unresolved and the turn is graded on everything else, where -Claude Code and Codex instead raise a turn timeout and mark the turn crashed. - -So the residual divergence is the terminal signal, not whether slow work completes: -a long `npm install` or build runs to completion here the way it does on the other -two, but a command that never finishes reads as an ordinary low score rather than a -timeout. +happened yet. Each individual step-fetch inside a poll cycle is itself bounded (30s) +so a genuinely non-idle connection can't block the whole poll loop — see +`_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS` in `antigravity_agent.py`. + +The wait is bounded by **80% of `turn_timeout`**, not by `turn_timeout` itself; a +task that sets no timeout falls back to a flat **600s** wall-clock backstop. A +second bound, **120 poll cycles**, applies in parallel — whichever trips first +wins. Two bounds because a cycle's cost is bimodal: against a genuinely +backgrounded job the connection is idle and `receive_steps()` returns +immediately, so a cycle costs only the 5s poll interval (120 x 5s = 600s, ~2x +the worst 60-300s job observed in the tasks that motivated the poll loop); +against a wedged connection every re-drain burns the full 30s per-step timeout, +so a deadline rather than the cycle count is what bounds it (the flat 600s backstop +when the task set no `turn_timeout`; otherwise the tighter `0.8 x turn_timeout`). What happens when the bound is hit +depends on whether a tool call is still open: + +- **An orphaned tool call still ACTIVE**: force-closed as unresolved and the turn is + graded on everything else — the graceful path, and the residual divergence from + Claude Code/Codex: a long `npm install` or build runs to completion here the way + it does on the other two, but a command that never finishes reads as an ordinary + low score rather than a timeout. +- **Nothing ACTIVE at all** (the connection never produced a clean end and no tool + call is in flight to explain the silence): Antigravity now raises a turn timeout + and marks the turn crashed too, same as Claude Code and Codex, so the + orchestrator's forced-kill grading path gets a chance to run instead of the turn + silently finalizing as an ordinary, unmarked completion. ## Timeouts are not turn caps -A timeout is a *failure* (partial turn captured, error status); the turn cap is a -*clean stop*. Conflating them is the mistake this page exists to prevent: a task -whose cap fires should not look like a task whose harness hung. +Both now evaluate success criteria — a timeout runs +`Orchestrator._grade_after_forced_kill` against whatever the agent produced, so a +timed-out task that already satisfied its criteria finalizes `SUCCESS` rather than +being discarded. What still separates them is the DEFAULT status when criteria do +not pass (`TIMEOUT` vs `MAX_TURNS_EXHAUSTED`) and the `crashed` mark on the partial +turn: a cap is a clean stop mid-trajectory, a timeout means the harness was cut off. +Conflating them is the mistake this page exists to prevent: a task whose cap fires +should not look like a task whose harness hung. ## Reproducing diff --git a/src/coder_eval/agents/antigravity_agent.py b/src/coder_eval/agents/antigravity_agent.py index ee9901d8..1659e9b5 100644 --- a/src/coder_eval/agents/antigravity_agent.py +++ b/src/coder_eval/agents/antigravity_agent.py @@ -99,6 +99,29 @@ # separately-tuned budget. _RECEIVE_STEPS_REENTRY_RETRIES = 5 +# Bounds a single receive_steps() step-fetch so communicate()'s poll loop can +# re-check its own bounds (has_orphaned_tool_call, poll_deadline, +# _MAX_BACKGROUND_POLLS) even while the connection is genuinely non-idle and a +# fetch would otherwise block unboundedly (confirmed against the installed SDK: +# a single receive_steps() call has no internal timeout) -- see _drain(). +# +# Deliberately its OWN constant, NOT aliased to _BACKGROUND_POLL_INTERVAL_SECONDS +# (an earlier revision did this and it was wrong): the two measure different +# things. _BACKGROUND_POLL_INTERVAL_SECONDS is how often to re-check an IDLE +# connection for a backgrounded job's progress -- 5s is fine there, nothing is +# lost by waiting a little longer between checks. This constant is how long a +# GENUINELY IN-PROGRESS foreground step-fetch (an active tool call still +# running, a model still generating with no incremental signal) may go quiet +# before being treated as suspicious. Aliasing it to 5s meant an ordinary tool +# call or thinking burst lasting longer than 5s between SDK-visible steps +# routinely tripped this "looks orphaned" signal, feeding _POLL_DEADLINE and +# _MAX_BACKGROUND_POLLS with false cycles and materially shrinking the +# effective turn budget for completely normal work (round-4 review finding, +# confirmed against the installed SDK's queue-based receive_steps()). 30s is +# generous enough that ordinary latency should never trip it, while still +# bounding a truly stuck connection within a reasonable number of cycles. +_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS = 30.0 + # Fraction of the turn's configured `timeout` the poll loop is allowed to spend # waiting on a backgrounded tool call, before giving up and finalizing through # its OWN graceful path (force-close the orphan as unresolved, grade normally) @@ -124,12 +147,32 @@ # evaluated, a strict regression for that input class. _POLL_DEADLINE_TIMEOUT_FRACTION = 0.8 -# Cap on poll *cycles* per turn -- the SOLE bound when a task sets no -# run_limits.turn_timeout/task_timeout at all (timeout=None), since -# _POLL_DEADLINE_TIMEOUT_FRACTION has nothing to multiply in that case. Also a -# backstop against a very large configured timeout turning this loop into an -# effectively unbounded wait: 120 * 5s = 10 minutes, ~2x the worst real -# backgrounded-job duration observed in confirmed-broken tasks (60-300s). +# Cap on poll *cycles* per turn, and the wall-clock backstop that runs beside +# it. BOTH bound the loop; whichever trips first wins. They exist because a +# poll cycle's cost is bimodal, and a single bound cannot cover both modes: +# +# - Backgrounded job (the case this loop exists for): the connection is IDLE +# with an empty step queue, so the installed SDK's receive_steps() returns +# immediately (`if self.is_idle and self._processor.step_queue.empty(): +# return`, connections/local/local_connection.py) -- _drain() comes back +# instantly with step_fetch_timed_out=False and the cycle costs just +# _BACKGROUND_POLL_INTERVAL_SECONDS = 5s. _MAX_BACKGROUND_POLLS is what +# bounds this mode: 120 * 5s = 600s, ~2x the 60-300s worst backgrounded-job +# duration observed in the confirmed-broken tasks that motivated d3f1432. +# A code-review round derived this cap from a 35s worst-case cycle instead +# (17 * 35s) -- that arithmetic does not apply to THIS mode, and cut the +# real budget to 85s, re-opening the exact bug d3f1432 fixed (the turn +# graded on work that had not happened yet). tests/test_antigravity_agent.py +# ::test_background_poll_budget_still_covers_the_worst_observed_backgrounded_job +# pins the product in seconds so it cannot silently regress again. +# +# - Wedged connection: genuinely non-idle, every re-drain burns the full +# _RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS before giving up, so a cycle +# costs 30 + 5 = 35s and the cycle cap alone would allow 120 * 35s = 70 +# minutes. _MAX_BACKGROUND_POLL_WALL_SECONDS bounds this mode directly in +# wall-clock time, and applies only when the task set no turn_timeout (with +# one configured, _POLL_DEADLINE_TIMEOUT_FRACTION * timeout is tighter and +# wins). 600s keeps the same ~10-minute ceiling the cycle cap used to imply. # # Deliberately NOT "break after N consecutive empty polls" instead: the real # SDK's receive_steps() returns identically empty whether a backgrounded job is @@ -140,6 +183,7 @@ # empty polls before succeeding); one large enough to be safe barely improves # over this flat cap. A flat, data-grounded cap is the honest option. _MAX_BACKGROUND_POLLS = 120 +_MAX_BACKGROUND_POLL_WALL_SECONDS = 600.0 # Antigravity builtin tool name -> canonical Claude-ish tool name, so cross-agent # success criteria (command_executed / commands_efficiency / skill_triggered) and @@ -484,11 +528,35 @@ async def _drain( ``wait_for_idle()`` discards any steps already queued, which would silently drop real content instead of just retrying past a transient window. + + Each individual step-fetch is bounded by + ``_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS`` so a genuinely non-idle + connection can't block this call forever; ``state.step_fetch_timed_out`` + records whether THIS call's deciding exit was a per-step timeout (as + opposed to a clean ``StopAsyncIteration`` or a cooperative/cap break), + regardless of whether earlier steps in the same call landed first, so + ``communicate()``'s poll loop can tell "still waiting, nothing settled + yet" apart from a turn that genuinely finished. """ + state.step_fetch_timed_out = False for attempt in range(_RECEIVE_STEPS_REENTRY_RETRIES): try: async with contextlib.aclosing(conversation.receive_steps()) as steps: - async for step in steps: + while True: + try: + step = await asyncio.wait_for( + steps.__anext__(), timeout=_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS + ) + except StopAsyncIteration: + break + except TimeoutError: + # This one step-fetch took too long -- not an error. Return + # control to communicate()'s poll loop so ITS bounds + # (poll_deadline, _MAX_BACKGROUND_POLLS, state.timeout_hit) + # get a chance to run, instead of staying frozen inside + # this single call with no way to check elapsed time. + state.step_fetch_timed_out = True + break state.process_step(step) if should_stop is not None and should_stop(): state.stopped_early_hit = True @@ -515,7 +583,7 @@ async def _drain( ) await asyncio.sleep(0) - async def communicate( + async def communicate( # noqa: PLR0915 — the new step_fetch_timed_out post-loop branch pushed it over the cap; decomposing this poll-loop-plus-finalize method is out of scope for this fix. self, user_input: str, *, @@ -594,8 +662,27 @@ def _on_turn_timeout() -> None: # `timeout` itself, instead of the watchdog always firing first — # see _POLL_DEADLINE_TIMEOUT_FRACTION's comment for why a FRACTION # of `timeout` doesn't race it the way an identical value would. - # `timeout=None` has nothing to derive a fraction from, so the - # cycle-based _MAX_BACKGROUND_POLLS is the sole bound in that case. + # `timeout=None` has nothing to derive a fraction from, so it + # falls back to the flat _MAX_BACKGROUND_POLL_WALL_SECONDS + # backstop -- a deadline either way, so a wedged (non-idle) + # connection whose every re-drain burns the full per-step + # timeout is bounded in wall-clock time and not merely by the + # cycle count, whose per-cycle cost is bimodal. + # + # ANCHORING differs between the two, deliberately: + # - configured timeout: anchored at TURN START, because its + # whole job is to fire before the ThreadedWatchdog at + # `timeout` -- a poll-entry anchor would let 0.8*timeout of + # polling start after the turn already spent `timeout`, and + # the watchdog would win every time. + # - flat backstop: anchored at POLL-LOOP ENTRY, so the poll + # budget is what this constant says it is. Anchoring it at + # turn start meant a `turn_timeout: null` turn that had + # already worked longer than the backstop got ZERO poll + # cycles -- the loop head is checked before the first sleep + # -- silently re-opening the very bug the poll loop exists + # to fix (an ACTIVE tool call force-closed as unresolved and + # graded on work that had not happened yet). poll_deadline = turn_start_time + timeout * _POLL_DEADLINE_TIMEOUT_FRACTION if timeout else None try: await conversation.send(user_input) @@ -612,25 +699,32 @@ def _on_turn_timeout() -> None: # stub on this SDK's Local harness (always returns False, # regardless of pending state — confirmed against the installed # source and live-tested), so poll for progress ourselves - # instead, gated on that orphaned-tool signal so a normal turn - # (which always closes its tool calls before the stream - # exhausts) takes this branch zero times and finalizes exactly - # as fast as today. + # instead. Two entry signals: an orphaned tool call (the + # scenario above), or the last drain's per-step wait timing + # out with no clean end (state.step_fetch_timed_out) -- + # either way a normal turn that finished cleanly within + # _RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS takes this branch + # zero times. + # Anchored HERE, not at turn start -- see poll_deadline above. + if poll_deadline is None: + poll_deadline = time.monotonic() + _MAX_BACKGROUND_POLL_WALL_SECONDS while ( not state.stopped_early_hit and not state.max_turns_hit and not state.timeout_hit - and state.has_orphaned_tool_call() - and ( - poll_count < _MAX_BACKGROUND_POLLS - if poll_deadline is None - else time.monotonic() < poll_deadline - ) + and (state.has_orphaned_tool_call() or state.step_fetch_timed_out) + # Both bounds apply; whichever trips first wins. The + # cycle cap sizes the cheap idle-poll mode (5s/cycle), + # the deadline sizes the expensive wedged mode + # (35s/cycle) -- see _MAX_BACKGROUND_POLLS' comment. + and poll_count < _MAX_BACKGROUND_POLLS + and time.monotonic() < poll_deadline ): poll_count += 1 - self._log.debug("Polling for backgrounded work (orphaned tool call); attempt %d", poll_count) + reason = "orphaned tool call" if state.has_orphaned_tool_call() else "step fetch timed out" + self._log.debug("Polling for backgrounded work (%s); attempt %d", reason, poll_count) await asyncio.sleep(_BACKGROUND_POLL_INTERVAL_SECONDS) - if state.timeout_hit or (poll_deadline is not None and time.monotonic() >= poll_deadline): + if state.timeout_hit or time.monotonic() >= poll_deadline: # The watchdog decided to fire during the sleep above, or # this loop's own (earlier) deadline just passed: skip the # re-drain (which could itself await indefinitely on @@ -658,9 +752,11 @@ def _on_turn_timeout() -> None: # turn is still graded normally on everything else. bound = ( f"poll_deadline ({_POLL_DEADLINE_TIMEOUT_FRACTION:.0%} of {timeout:g}s turn timeout)" - if poll_deadline is not None - else f"_MAX_BACKGROUND_POLLS ({_MAX_BACKGROUND_POLLS})" + if timeout + else f"wall-clock backstop ({_MAX_BACKGROUND_POLL_WALL_SECONDS:g}s)" ) + if poll_count >= _MAX_BACKGROUND_POLLS: + bound = f"_MAX_BACKGROUND_POLLS ({_MAX_BACKGROUND_POLLS})" msg = "Poll budget exhausted (%s, poll_count=%d) with a tool call still ACTIVE." self._log.warning(msg, bound, poll_count) @@ -695,6 +791,37 @@ def _on_turn_timeout() -> None: # Watchdog fired but the pump finished before the cancel landed. assert timeout is not None self._finalize_and_raise_timeout(state.finalize, timeout) + elif ( + state.step_fetch_timed_out + and not state.has_orphaned_tool_call() + and not state.stopped_early_hit + and not state.max_turns_hit + ): + # Poll budget exhausted (poll_deadline or the cycle cap) with the + # connection never producing a clean end and nothing in flight to + # show for it (no orphaned tool call -- that case is graded + # normally above). Pre-fix, this scenario blocked inside _drain() + # until the ThreadedWatchdog genuinely fired; raise the same + # TurnTimeoutError here instead of silently finalizing as an + # ordinary COMPLETED turn with no timeout mark, so the + # orchestrator's forced-kill grading path gets a chance to run. + self._log.warning( + "Poll budget exhausted (poll_count=%d) with no clean turn end; treating as a timeout.", + poll_count, + ) + # Best-effort server-side cancel, mirrors the stopped_early/ + # max_turns exit above -- nothing legitimate is in flight here + # (no orphaned tool call), so there's no reason to leave the + # harness running while the orchestrator grades the sandbox. + with contextlib.suppress(Exception): + await conversation.cancel() + # This branch is reachable with `timeout` either set + # (exhausted via poll_deadline) or None (exhausted via + # _MAX_BACKGROUND_POLLS) -- report the configured timeout when + # there is one, else the real elapsed wall-clock time, instead + # of a nonsense "after 0s" for the timeout=None case. + elapsed = time.monotonic() - turn_start_time + self._finalize_and_raise_timeout(state.finalize, timeout if timeout is not None else elapsed) except (AgentCrashError, TurnTimeoutError): raise except asyncio.CancelledError: @@ -820,6 +947,18 @@ def __init__( self.stopped_early_hit = False self.max_turns_hit = False self.finalized = False + # Set False by _drain() at entry, True if that call's deciding exit + # was a per-step timeout (whether or not earlier steps in the same + # call landed first) -- distinct from has_orphaned_tool_call(), which + # needs a TOOL step specifically to have gone ACTIVE. OR'd into + # communicate()'s poll-loop entry condition so a merely-slow-but-real + # step (first or mid-stream) retries under the existing + # poll_deadline/_MAX_BACKGROUND_POLLS bound instead of being mistaken + # for a turn that produced nothing; also consulted after the poll + # loop exits to raise a timeout instead of silently finalizing as + # COMPLETED when nothing ever settled (see communicate()'s post-loop + # check). + self.step_fetch_timed_out = False self.total_usage = TokenUsage() self.messages: list[TranscriptMessage] = [] diff --git a/src/coder_eval/orchestrator.py b/src/coder_eval/orchestrator.py index 83f67da3..96d5fe70 100644 --- a/src/coder_eval/orchestrator.py +++ b/src/coder_eval/orchestrator.py @@ -75,6 +75,16 @@ # wins the race against the asyncio cancel path (which doesn't). _WAIT_FOR_GRACE_SECONDS = 2.0 +# Wall-clock cap on _grade_after_forced_kill's grading pass: this runs AFTER the +# ThreadedWatchdog/task_timeout has already fired (or a turn_timeout already +# elapsed), so it must not itself become an unbounded tail on an already-blown +# budget -- an agent_judge criterion spawns a fresh sub-agent and an llm_judge +# criterion makes a real API call, either of which could otherwise run for +# minutes past the configured limit. On expiry this falls back to the caller's +# fallback_status like any other grading failure -- best-effort, never worse +# than not grading at all. +_GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS = 60.0 + async def _pump_stream( stream: asyncio.StreamReader | None, @@ -394,6 +404,19 @@ def __init__( # stop_early: block and the kill switch is not thrown; None otherwise, # so the default path is entirely unaffected). self._early_stop_watcher: EarlyStopWatcher | None = None + # len(result.iterations) at the moment success_criteria_results was last + # written, so _grade_after_forced_kill can tell a grade that covers the + # whole recorded trajectory from a stale mid-dialog snapshot (the + # simulation path re-grades every turn under check_criteria: + # every_turn/both). None = never graded. + self._graded_iteration_count: int | None = None + # Dialog-wide per-judge token accumulator. Owned by the Orchestrator + # rather than being a local of _simulation_dialog_loop so the + # forced-kill grading path can fold ITS judge slice into the same + # running total -- otherwise a mid-dialog timeout re-grades and + # persists only that last call's judge cost, silently dropping every + # earlier turn's. Keyed by (position, criterion_type). + self._judge_usage_accum: dict[tuple[int, str], TokenUsage] = {} # One-shot flag: emit the "cost budget configured but no cost data" warning # exactly once per task even if _check_run_limits fires every turn. @@ -419,7 +442,7 @@ def _agent_name(self) -> str: return str(self.task.agent.type) return AgentKind.NONE.value - async def run(self) -> EvaluationResult: + async def run(self) -> EvaluationResult: # noqa: PLR0915 — pre-existing exception-handling ladder; the new TurnTimeoutError handler pushed it over the cap. Decomposing run()'s handler ladder is out of scope for this fix. """Run the complete evaluation. Returns: @@ -526,8 +549,6 @@ def _kill_agent_subprocess_sync() -> None: # Re-raise cancellation to allow proper task cancellation raise except TaskTimeoutError as e: - # Task-level timeout gets a dedicated status (not generic ERROR) - self.result.final_status = FinalStatus.TIMEOUT self.result.error_message = str(e) self.result.error_details = create_error_context( @@ -545,6 +566,30 @@ def _kill_agent_subprocess_sync() -> None: # BaseException, so it never reaches the retry executor's # per-attempt hook that drains the slot on a turn-level timeout. await self._drain_killed_turn() + + # The kill was correct; discarding a real, complete result isn't. + # Grade whatever the agent produced before falling back to the + # dedicated TIMEOUT status (not generic ERROR). + await self._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + except TurnTimeoutError as e: + self.result.error_message = str(e) + + self.result.error_details = create_error_context( + error=e, + task_id=self.task.task_id, + attempt=max(self.result.iteration_count, 1), + component="orchestrator.turn_timeout", + agent_name=self._agent_name, + ) + + logger.error(f"Turn timed out: {e}") + + # No _drain_killed_turn() here: the partial turn for a + # TurnTimeoutError is already salvaged by + # _on_attempt_failure's _drain_pending_turn() inside + # _communicate_with_retry, which runs before this exception + # reaches run(). + await self._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) except BudgetExceededError as e: # Map token-budget breaches and cost-budget breaches to distinct # statuses so per-task records preserve the failure mode. @@ -662,6 +707,176 @@ async def _drain_killed_turn(self) -> None: except Exception: logger.warning("[%s] Could not recover the hard-killed turn", self.task.task_id, exc_info=True) + async def _grade_after_forced_kill(self, *, fallback_status: FinalStatus) -> None: + """Attempt success-criteria grading against whatever the agent produced + before a forced-kill timeout, instead of unconditionally discarding it. + + Called from the ``TaskTimeoutError`` and ``TurnTimeoutError`` handlers + in ``run()``, after any turn salvage has already happened. By that + point ``self.success_checker``/``self.sandbox`` are set up in + ``_setup()`` (which ran before either exception could be raised) and + ``self.result.iterations`` holds whatever partial turn was recovered. + + If a completed grading pass already covers the WHOLE recorded + trajectory (``self._graded_iteration_count == len(result.iterations)`` + -- e.g. the belt-and-suspenders ``TaskTimeoutError`` at the end of + ``run()`` firing after ``_evaluation_loop`` already graded), this + re-derives the status from those existing results instead of re-running + ``check_all_async``: re-grading would double-spend any + ``llm_judge``/``agent_judge`` criterion for no new information. + The iteration-count guard is what makes that shortcut sound -- the + simulation dialog loop rewrites ``success_criteria_results`` on every + turn under ``check_criteria: every_turn``/``both``, so a non-empty + results list alone does NOT mean the grade covers the turns that + actually blew the budget. + + Best-effort, mirroring ``_drain_killed_turn``: never raises. It commits + ``fallback_status`` synchronously before its first ``await`` and only + ever UPGRADES that to ``SUCCESS``, so the status is correct even if a + ``BaseException`` (which ``except Exception`` does not catch) unwinds + the method mid-grade. + """ + if self.result is None: + return + # Commit the fallback FIRST, before any await. Everything below is + # best-effort and can only UPGRADE this to SUCCESS. Setting it eagerly + # is what keeps the status correct when a BaseException (Ctrl-C, a + # batch-level task cancel) arrives during one of the awaits below -- + # `except Exception` deliberately doesn't catch those, so without this + # the row would persist with the constructor default (FAILURE) while + # error_message says the task timed out. + self.result.final_status = fallback_status + # Quiesce the agent before reading the sandbox. On a TurnTimeoutError + # the agent raised at its own internal deadline and NOTHING has stopped + # the harness yet: the watchdog's kill_sync() is intent-only on + # Antigravity (async cancel/disconnect), _communicate_attempt's + # agent.kill() only runs on the outer wait_for backstop, and + # _cleanup()/stop() happens in run()'s finally -- i.e. AFTER this + # grading pass. A backgrounded `npm run build` would still be writing + # into the sandbox while check_all_async reads it, making the verdict + # nondeterministic in both directions. Best-effort and suppressed: + # failing to quiesce is never a reason to skip grading. + if self.agent is not None: + try: + await self.agent.kill() + except Exception: + # Warning, not debug: grading is about to read a sandbox that + # may still be under a live agent's control, so a failed + # quiesce is real context for an unexpected verdict. + logger.warning( + "[%s] Could not quiesce the agent before grading; criteria may race live writes", + self.task.task_id, + exc_info=True, + ) + # Everything below runs inside the try: the gate helpers raise + # ValueError on a results/criteria length mismatch, and this method's + # contract (like _drain_killed_turn's) is to never propagate out of + # run()'s timeout handler. + try: + # A hard-killed run never reaches _evaluation_loop's own + # self.result.early_stop assignment (only set after a successful + # _communicate_with_retry return), so record the watcher's decision + # here -- otherwise _gate_passed always takes the unarmed branch even + # when an armed criterion actually cut this run. + if self.result.early_stop is None and self._early_stop_watcher is not None: + self.result.early_stop = self._early_stop_watcher.info + if self.result.success_criteria_results and self._graded_iteration_count == len(self.result.iterations): + self.result.final_status = FinalStatus.SUCCESS if self._gate_passed() else fallback_status + if self.result.final_status == FinalStatus.SUCCESS: + self.result.error_message = None + self.result.error_details = None + return + if self.success_checker is None or self.sandbox is None: + self.result.final_status = fallback_status + return + reference_code, reference_dir, self._reference_code = load_reference( + task=self.task, + task_file=self.task_file, + cached_reference=self._reference_code, + ) + criteria_results = await asyncio.wait_for( + self.success_checker.check_all_async( + self.task.success_criteria, + reference_code=reference_code, + reference_dir=reference_dir, + turn_records=self.result.iterations, + ), + timeout=_GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS, + ) + # Fold this pass's judge slice into the dialog-wide total before + # storing, so a mid-dialog forced kill doesn't drop the judge cost + # of every earlier turn (no-op outside simulation: the accumulator + # is empty and each result keeps its own usage). + self._accumulate_judge_usage(criteria_results, self._judge_usage_accum) + self.result.success_criteria_results = criteria_results + self._graded_iteration_count = len(self.result.iterations) + all_passed = self._gate_passed() + self.result.calculate_weighted_score(self.task.success_criteria) + self._emit_criteria_event(criteria_results) + if all_passed: + # A genuinely successful, correctly-graded run must not carry + # the timeout exception's message/traceback forward -- the plan + # calls for "SUCCESS (plain, no special marker)", and a stale + # error_message/error_details would mislead report rendering. + self.result.final_status = FinalStatus.SUCCESS + self.result.error_message = None + self.result.error_details = None + else: + self.result.final_status = fallback_status + # Logged last, and suppressed on its own: a length mismatch in this + # human-readable tally must not discard the status decision above. + self._log_graded_after_forced_kill(criteria_results) + except Exception: + logger.warning( + "[%s] Could not grade after forced kill; falling back to %s", + self.task.task_id, + fallback_status, + exc_info=True, + ) + self.result.final_status = fallback_status + + def _log_graded_after_forced_kill(self, criteria_results: list[CriterionResult]) -> None: + """Human-readable pass tally for ``_grade_after_forced_kill``. + + Isolated (and failure-suppressed) so a ``zip(..., strict=True)`` length + mismatch in a log line can never undo the status its caller already + committed. + """ + try: + passed_count = sum( + 1 + for r, c in zip(criteria_results, self.task.success_criteria, strict=True) + if r.score >= c.pass_threshold + ) + except ValueError: + logger.warning("[%s] Graded after forced kill (tally unavailable)", self.task.task_id) + return + logger.info( + "[%s] Graded after forced kill: %d/%d criteria passed", + self.task.task_id, + passed_count, + len(criteria_results), + ) + + def _gate_passed(self) -> bool: + """FIRED-ONLY gate selection, mirroring ``_evaluation_loop``'s exact rule. + + The weighted armed gate applies iff the early-stop watcher actually cut + this run (``self.result.early_stop is not None``); otherwise every + gating criterion must pass (strict-AND), same as an unarmed run. Shared + by ``_grade_after_forced_kill``'s fresh-grade and already-graded paths + so both honor the same contract CLAUDE.md documents for `stop_early`. + """ + assert self.result is not None + if self.result.early_stop is not None: + gate_threshold = ( + self.task.run_limits.stop_early_gate_threshold + if self.task.run_limits is not None + else DEFAULT_STOP_EARLY_GATE_THRESHOLD + ) + return self.result.armed_criteria_passed(self.task.success_criteria, gate_threshold) + return self.result.all_criteria_passed(self.task.success_criteria) + def _finalize_result(self, start_time: float) -> None: """Finalize the evaluation result: scores, telemetry, and persistence.""" if not self.result: @@ -1505,6 +1720,7 @@ async def _evaluation_loop(self) -> bool: turn_records=self.result.iterations, ) self.result.success_criteria_results = criteria_results + self._graded_iteration_count = len(self.result.iterations) return self.result.all_criteria_passed(self.task.success_criteria) # Working directory context prepended to every prompt (including feedback). @@ -1563,6 +1779,7 @@ async def _evaluation_loop(self) -> bool: turn_records=self.result.iterations, ) self.result.success_criteria_results = criteria_results + self._graded_iteration_count = len(self.result.iterations) # Determine if all criteria passed their thresholds. all_passed is # single-sourced via the model gate; passed_count/total_count are kept @@ -1685,6 +1902,7 @@ async def _run_dialog_criteria_check( ) self._accumulate_judge_usage(criteria_results, judge_usage_accum) self.result.success_criteria_results = criteria_results + self._graded_iteration_count = len(self.result.iterations) self.result.calculate_weighted_score(self.task.success_criteria) return criteria_results @@ -1904,7 +2122,7 @@ async def _simulation_dialog_loop(self, initial_prompt: str | None, sandbox_dir: # each turn's judge slice into this accumulator (see # ``_accumulate_judge_usage``) to avoid dropping earlier judge calls. # Keyed by (position, criterion_type) — a stable criterion identity. - judge_usage_accum: dict[tuple[int, str], TokenUsage] = {} + judge_usage_accum = self._judge_usage_accum # turns_completed advances in lockstep with the agent's _iteration: # one _communicate_with_retry call per sim turn keeps partials diff --git a/tests/lint/rules/base.py b/tests/lint/rules/base.py index 802a1ba3..7da5b793 100644 --- a/tests/lint/rules/base.py +++ b/tests/lint/rules/base.py @@ -9,6 +9,17 @@ class BaseRule(ast.NodeVisitor, ABC): id: str = "" + #: Physical source lines of the tree being checked. ``runner.check_file`` + #: assigns this after construction (a CLASS attribute rather than an + #: ``__init__`` parameter so the many rules that override ``__init__`` + #: keep working unchanged). A rule needing raw text -- comments are absent + #: from the AST, so ``# noqa`` markers are only visible here -- must read + #: this instead of re-opening ``filepath``: a rule fed a synthetic tree + #: with a real-looking path would otherwise scan an unrelated file, a + #: silent false positive that also depends on the process's cwd. ``None`` + #: means the caller supplied only a path; degrade to doing nothing. + source_lines: list[str] | None = None + def __init__(self, filepath: str) -> None: self.filepath = filepath self.violations: list[Violation] = [] diff --git a/tests/lint/rules/ce022_dialog_loop_statement_cap.py b/tests/lint/rules/ce022_dialog_loop_statement_cap.py index f91a20d1..03bca68f 100644 --- a/tests/lint/rules/ce022_dialog_loop_statement_cap.py +++ b/tests/lint/rules/ce022_dialog_loop_statement_cap.py @@ -1,59 +1,138 @@ -"""CE022: ``Orchestrator._simulation_dialog_loop`` must stay under its statement cap. - -``_simulation_dialog_loop`` is the one function in the tree that keeps a -``# noqa: PLR0915``: it is a sequential dialog driver whose residual length is -irreducible without a state-object rewrite (see the 2026-06-23 -decompose-god-functions plan, Phase 5). But ``# noqa: PLR0915`` *disables ruff's -statement check entirely* — without a guard the function could silently regrow -back toward its pre-decomposition size and nothing would fail. - -This rule re-imposes a bound: it counts the statements in -``_simulation_dialog_loop`` (every statement node in the body, recursively — the -same notion ruff PLR0915 bounds) and fires if the count exceeds ``_CAP``. The cap -is the measured post-decomposition size plus a small headroom, so ordinary edits -don't trip it but a real regrowth does. Deliberately narrow: it targets the one -named function in ``orchestrator.py``, not a general size rule (ruff's 80/25 -ceiling already covers every other function). - -If a future decomposition legitimately brings the function under ruff's ceiling, -remove the ``# noqa: PLR0915`` AND this rule together. +"""CE022: functions carrying ``# noqa: PLR0915`` must stay under a measured cap. + +``# noqa: PLR0915`` *disables ruff's statement check entirely* for that +function — without a guard it could silently regrow past the size that earned +the suppression and nothing would fail. This rule re-imposes a bound on every +function in ``src/`` known to carry the suppression: it counts each target's +statements (every statement node in the body, recursively) and fires if the +count exceeds its registered cap. Each cap is the measured size at the time it +was registered, plus a small headroom, so ordinary edits don't trip it but a +real regrowth does. + +This count is CE022's OWN metric, deliberately not identical to ruff's PLR0915 +count (ruff's is higher — it counts some constructs this walk does not), so a +cap below ruff's 80 ceiling does NOT mean the function would now pass ruff and +could drop its suppression. The ruff-equivalent counts are recorded beside each +cap below; re-measure with `ruff check --select PLR0915 --ignore-noqa` before +concluding a suppression is removable. + +Registered targets (file, function, cap): + +- ``orchestrator.py::_simulation_dialog_loop`` (cap 128; 122 CE022-stmts ≙ 124 + ruff-stmts) — sequential dialog driver, irreducible without a state-object + rewrite (2026-06-23 decompose-god-functions plan, Phase 5). +- ``orchestrator.py::run`` (cap 76; 70 CE022-stmts ≙ 86 ruff-stmts) — the + exception-handling ladder around the evaluation loop; the + forced-kill-grading fix (2026-08-14) pushed it over ruff's ceiling. +- ``antigravity_agent.py::communicate`` (cap 81; 77 CE022-stmts ≙ 82 + ruff-stmts) — the poll-loop-plus-finalize driver; the + ``step_fetch_timed_out`` post-loop branch (2026-08-14) pushed it over + ruff's ceiling. + +Adding a new ``# noqa: PLR0915`` anywhere in ``src/`` means adding its +``(file, function, cap)`` to ``_TARGETS`` below too. That contract is +**self-enforcing**: an unregistered function carrying the suppression is itself +a CE022 violation (see ``_carries_suppression``), because otherwise its size +would be bounded by nothing — ruff's check suppressed, this rule skipping it — +and ``test_no_violations`` would still report the tree clean. + +If a future decomposition legitimately brings a target under ruff's ceiling, +remove its ``# noqa: PLR0915`` AND its entry in ``_TARGETS`` together. """ import ast +import re from pathlib import Path from tests.lint.rules.base import BaseRule +# Mirrors runner._NOQA_CODES so CE022 reads a suppression exactly the way the +# runner does; kept as its own copy to avoid a rules -> runner import cycle. +_NOQA_CODES = re.compile(r"#\s*noqa:\s*([A-Z]+\d+(?:\s*,\s*[A-Z]+\d+)*)") + + def _count_statements(func: ast.AsyncFunctionDef | ast.FunctionDef) -> int: """Statement nodes in the function body, counted recursively (nested - compound-statement bodies included) — the same notion ruff PLR0915 bounds.""" + compound-statement bodies included). Close to, but not identical with, + ruff's PLR0915 count — see the module docstring.""" return sum(1 for stmt in func.body for node in ast.walk(stmt) if isinstance(node, ast.stmt)) -class SimulationDialogLoopStatementCap(BaseRule): +class NoqaPlr0915StatementCap(BaseRule): id = "CE022" - _TARGET_FILE = "orchestrator.py" - _TARGET_FUNC = "_simulation_dialog_loop" - # Measured post-decomposition count (122) + 6 headroom. Re-measure and bump - # _CAP only alongside an intentional, reviewed change to the dialog driver. - _CAP = 128 + # (basename, function name, cap). Exact-basename match (not endswith) so a + # sibling like ``x_orchestrator.py`` can't accidentally match. + _TARGETS: tuple[tuple[str, str, int], ...] = ( + ("orchestrator.py", "_simulation_dialog_loop", 128), + ("orchestrator.py", "run", 76), + ("antigravity_agent.py", "communicate", 81), + ) + + def _carries_suppression(self, node: ast.AsyncFunctionDef | ast.FunctionDef) -> bool: + """True if this function's ``def`` header carries a PLR0915 suppression. + + Comments are absent from the AST, so this reads physical source lines — + but ONLY ``self.source_lines``, never the file at ``self.filepath``. + Re-reading the path would scan an unrelated file whenever the tree came + from somewhere else (the rule's own unit tests pass synthetic source + with a real-looking path), which is a silent false-positive source and + makes the result depend on the process's cwd. No source ⇒ no check. + + The scanned range is the ``def`` line through the line before the first + body statement, so a PLR0915 mention inside the body — a docstring, or + this rule's own message text — cannot register as a suppression. + + KNOWN GAP: a blanket ``# noqa`` (no codes) also suppresses PLR0915 for + ruff but is deliberately NOT matched here, because ``runner._is_suppressed`` + would drop this rule's own violation on that same line anyway — the + marker is unreachable for CE022 either way. A file-level + ``# ruff: noqa: PLR0915`` is likewise out of range. Both are recorded in + ``.claude/harness-candidates.md``; this guard closes the ordinary + per-function ``# noqa: PLR0915`` form, which is the one in use. + """ + if self.source_lines is None: + return False + start = node.lineno - 1 + end = max(node.lineno, node.body[0].lineno - 1) + for line in self.source_lines[start:end]: + m = _NOQA_CODES.search(line) + if m and "PLR0915" in {c.strip() for c in m.group(1).split(",")}: + return True + return False def _check(self, node: ast.AsyncFunctionDef | ast.FunctionDef) -> None: - # Exact-basename match (not endswith) so a sibling like ``x_orchestrator.py`` - # can't accidentally match; both sync and async defs are checked so a future - # ``async def`` → ``def`` conversion can't silently drop the guard. - if Path(self.filepath).name == self._TARGET_FILE and node.name == self._TARGET_FUNC: - count = _count_statements(node) - if count > self._CAP: - self.violation( - node, - f"{self._TARGET_FUNC} has {count} statements (cap {self._CAP}). It keeps a " - f"# noqa: PLR0915, which disables ruff's statement check entirely, so this CE rule " - f"bounds its regrowth. Decompose further, or — if the growth is intentional and " - f"reviewed — re-measure and bump _CAP in this rule.", - ) + # Both sync and async defs are checked so a future def-kind conversion + # can't silently drop the guard. + basename = Path(self.filepath).name + registered = False + for target_file, target_func, cap in self._TARGETS: + if basename == target_file and node.name == target_func: + registered = True + count = _count_statements(node) + if count > cap: + self.violation( + node, + f"{target_func} has {count} statements (cap {cap}). It keeps a " + f"# noqa: PLR0915, which disables ruff's statement check entirely, so this CE rule " + f"bounds its regrowth. Decompose further, or — if the growth is intentional and " + f"reviewed — re-measure and bump its cap in _TARGETS.", + ) + break + # Self-guard: a suppression this table doesn't know about is an + # UNBOUNDED function that test_no_violations would still call clean — + # the exact false sense of coverage this rule exists to prevent. Without + # it the "register your new noqa" contract in the module docstring is + # documentation only, enforced by nothing. + if not registered and self._carries_suppression(node): + self.violation( + node, + f"{node.name} carries a # noqa: PLR0915 but is not registered in CE022's _TARGETS, so its " + f"size is bounded by nothing (ruff's check is suppressed and this rule skips it). Add " + f"({basename!r}, {node.name!r}, ) to _TARGETS, or decompose the " + f"function and drop the suppression.", + ) self.generic_visit(node) def visit_AsyncFunctionDef(self, node: ast.AsyncFunctionDef) -> None: diff --git a/tests/lint/runner.py b/tests/lint/runner.py index c3b4b570..c5e0d3b2 100644 --- a/tests/lint/runner.py +++ b/tests/lint/runner.py @@ -17,7 +17,7 @@ from tests.lint.rules.ce019_telemetry_non_fatal import TelemetryNonFatal from tests.lint.rules.ce020_no_sdk_typed_base_agent_fields import NoSdkTypedBaseAgentFields from tests.lint.rules.ce021_guarded_evaluationresult_parse import GuardedEvaluationResultParse -from tests.lint.rules.ce022_dialog_loop_statement_cap import SimulationDialogLoopStatementCap +from tests.lint.rules.ce022_dialog_loop_statement_cap import NoqaPlr0915StatementCap from tests.lint.rules.ce023_no_proxy_shim_import import NoProxyShimImports from tests.lint.rules.ce024_discriminated_unions import DiscriminatedUnions from tests.lint.rules.ce032_criteria_path_seam import CriteriaPathSeam @@ -61,7 +61,7 @@ TelemetryNonFatal, NoSdkTypedBaseAgentFields, GuardedEvaluationResultParse, - SimulationDialogLoopStatementCap, + NoqaPlr0915StatementCap, NoProxyShimImports, DiscriminatedUnions, CriteriaPathSeam, @@ -117,7 +117,9 @@ def check_file(path: Path, rules: list[RuleClass] | None = None) -> list[Violati source_lines = source.splitlines() violations: list[Violation] = [] for rule_class in rules: - for v in rule_class(str(path)).check(tree): + rule = rule_class(str(path)) + rule.source_lines = source_lines + for v in rule.check(tree): if not _is_suppressed(source_lines, v): violations.append(v) return violations diff --git a/tests/test_antigravity_agent.py b/tests/test_antigravity_agent.py index cc780e59..4054f435 100644 --- a/tests/test_antigravity_agent.py +++ b/tests/test_antigravity_agent.py @@ -1563,3 +1563,415 @@ async def test_cap_reached_on_a_poll_redrain_stops_polling(monkeypatch): assert [c.tool_id for c in record.commands if c.result_status == "unknown"] == ["bg2"] assert conv.receive_steps_call_count == 2 # initial drain + one poll re-drain, then stop assert conv.cancel_call_count == 1 + + +def _make_turn_state(agent, *, max_turns=None): + """Build a bare _AntigravityTurnState the way communicate() does, for tests + that call _drain() directly rather than through the full poll loop.""" + from coder_eval.agents.antigravity_agent import _AntigravityTurnState + from coder_eval.streaming.callbacks import CompositeStreamCallback + from coder_eval.streaming.collector import EventCollector + + collector = EventCollector() + emit = CompositeStreamCallback([collector]) + return _AntigravityTurnState( + agent=agent, + emit=emit, + task_id="antigravity", + turn_id="antigravity-1", + collector=collector, + user_input="test", + iteration=1, + model="gemini-3.5-flash", + turn_start_time=0.0, + max_turns=max_turns, + ) + + +class _NeverYieldsConversation: + """A receive_steps() whose first step-fetch never resolves on its own -- + only a cancellation (from asyncio.wait_for's per-step timeout) can end it.""" + + last_response = "" + + def __init__(self): + self.receive_steps_call_count = 0 + + async def send(self, prompt, **kwargs): + return None + + async def receive_steps(self): + self.receive_steps_call_count += 1 + await asyncio.Event().wait() + yield # pragma: no cover - unreachable, keeps this an async generator + + async def cancel(self): + return None + + +async def test_drain_returns_control_when_a_single_step_fetch_blocks_too_long(monkeypatch): + """A receive_steps() call whose next step never arrives must not block + _drain() forever -- the per-step timeout returns control to the caller.""" + from coder_eval.agents import antigravity_agent + + monkeypatch.setattr(antigravity_agent, "_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS", 0.05) + + agent = _agent_with_steps([]) + state = _make_turn_state(agent) + conversation = _NeverYieldsConversation() + + await asyncio.wait_for(agent._drain(conversation, state, None), timeout=5.0) + + assert conversation.receive_steps_call_count == 1 + assert state.step_fetch_timed_out is True + + +class _SlowFirstStepThenNormalConversation: + """First receive_steps() call's only step-fetch never resolves (proving + _drain() really did return with zero steps on that call); the SECOND call + yields a complete, non-orphaned turn. Used to prove communicate()'s poll + loop re-enters via state.step_fetch_timed_out -- NOT via + has_orphaned_tool_call(), which is False here since no tool call was ever + ACTIVE.""" + + last_response = "" + + def __init__(self, second_batch): + self._second_batch = second_batch + self.receive_steps_call_count = 0 + + async def send(self, prompt, **kwargs): + return None + + async def receive_steps(self): + self.receive_steps_call_count += 1 + if self.receive_steps_call_count == 1: + await asyncio.Event().wait() + return + yield # pragma: no cover - unreachable, keeps this an async generator + for s in self._second_batch: + yield s + + async def cancel(self): + return None + + +async def test_communicate_finalizes_a_normal_turn_whose_first_step_is_slow(monkeypatch): + """Regression test for the step_fetch_timed_out mechanism: a normal turn's + first receive_steps() call timing out with zero steps must NOT be mistaken + for "the model produced nothing" -- the poll loop must re-drain and pick up + the turn's real, complete output on the next call.""" + from coder_eval.agents import antigravity_agent + + monkeypatch.setattr(antigravity_agent, "_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS", 0.05) + monkeypatch.setattr(antigravity_agent.asyncio, "sleep", _no_sleep) + + final_batch = [ + _step("TEXT_RESPONSE", "DONE", content="all done", complete=True, usage=_usage(10, 0, 1, 0)), + ] + conversation = _SlowFirstStepThenNormalConversation(final_batch) + agent = _agent_with_steps([]) + agent._sdk_agent.conversation = conversation + + tr = await agent.communicate("do it") + + assert not tr.crashed + assert tr.agent_output == "all done" + # Proves re-entry happened via step_fetch_timed_out, not + # has_orphaned_tool_call() (no tool call was ever ACTIVE in this scenario). + assert conversation.receive_steps_call_count == 2 + + +class _ReentrancyThenTimeoutConversation: + """First receive_steps() call raises RuntimeError (a stuck re-entrancy + guard from a prior drain, consuming one _RECEIVE_STEPS_REENTRY_RETRIES + attempt); the SECOND call's only step-fetch never resolves, tripping the + per-step timeout. Proves the two mechanisms don't interfere: the + TimeoutError must not be caught by the outer `except RuntimeError:` clause + and must not trigger a third call within this _drain() invocation.""" + + last_response = "" + + def __init__(self): + self.call_count = 0 + + async def send(self, prompt, **kwargs): + return None + + async def receive_steps(self): + self.call_count += 1 + if self.call_count == 1: + raise RuntimeError("Concurrent receive_steps() calls are not supported on this connection.") + yield # pragma: no cover - unreachable, keeps this an async generator + await asyncio.Event().wait() + yield # pragma: no cover - unreachable, keeps this an async generator + + async def cancel(self): + return None + + +async def test_drain_per_step_timeout_does_not_trigger_reentrancy_retry_path(monkeypatch): + """A TimeoutError from the per-step wait is a plain, unexceptional return -- + it must not be caught by the outer `except RuntimeError:` clause, and must + not consume a second _RECEIVE_STEPS_REENTRY_RETRIES attempt on its own.""" + from coder_eval.agents import antigravity_agent + + monkeypatch.setattr(antigravity_agent, "_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS", 0.05) + + agent = _agent_with_steps([]) + state = _make_turn_state(agent) + conversation = _ReentrancyThenTimeoutConversation() + + await asyncio.wait_for(agent._drain(conversation, state, None), timeout=5.0) + + # Exactly 2 calls: attempt 1 (RuntimeError, retried) + attempt 2 (times out, + # returns normally) -- no third call, proving the timeout didn't get routed + # through the RuntimeError retry path. + assert conversation.call_count == 2 + assert state.step_fetch_timed_out is True + + +class _OneStepThenStallConversation: + """A single receive_steps() call yields ONE real (non-terminal) step, then + its NEXT step-fetch never resolves -- proves state.step_fetch_timed_out + tracks the call's DECIDING exit reason, not merely "were zero steps ever + seen" (a mid-stream stall after real content already landed used to leave + the flag cleared, silently finalizing a still-generating turn as an + ordinary COMPLETED with no timeout mark).""" + + last_response = "" + + def __init__(self, first_step): + self._first_step = first_step + self.receive_steps_call_count = 0 + + async def send(self, prompt, **kwargs): + return None + + async def receive_steps(self): + self.receive_steps_call_count += 1 + yield self._first_step + await asyncio.Event().wait() + yield # pragma: no cover - unreachable, keeps this an async generator + + async def cancel(self): + return None + + +async def test_drain_marks_timed_out_even_after_processing_a_real_step_first(monkeypatch): + """A per-step timeout occurring AFTER at least one real step already landed + in the same _drain() call must still set state.step_fetch_timed_out.""" + from coder_eval.agents import antigravity_agent + + monkeypatch.setattr(antigravity_agent, "_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS", 0.05) + + thinking_step = _step("THINKING", "ACTIVE", thinking="planning") + agent = _agent_with_steps([]) + state = _make_turn_state(agent) + conversation = _OneStepThenStallConversation(thinking_step) + + await asyncio.wait_for(agent._drain(conversation, state, None), timeout=5.0) + + assert conversation.receive_steps_call_count == 1 + assert state.step_fetch_timed_out is True + + +class _AlwaysEmptyConversation: + """A receive_steps() that never emits a single step, for the whole turn -- + no tool call, no text, nothing. Every call's step-fetch blocks until its + per-step timeout fires.""" + + last_response = "" + + def __init__(self): + self.receive_steps_call_count = 0 + + async def send(self, prompt, **kwargs): + return None + + async def receive_steps(self): + self.receive_steps_call_count += 1 + await asyncio.Event().wait() + yield # pragma: no cover - unreachable, keeps this an async generator + + async def cancel(self): + return None + + +async def test_communicate_raises_timeout_when_connection_never_produces_a_single_step(monkeypatch): + """A connection that never emits ANY step for the whole turn must not + silently finalize as an ordinary COMPLETED turn once the poll budget is + exhausted -- that would defeat the whole point of grading forced-kill + timeouts (the orchestrator's _grade_after_forced_kill only runs on + TurnTimeoutError/TaskTimeoutError). It must raise TurnTimeoutError, + matching what happened pre-Phase-2 when this same scenario blocked inside + _drain() until the ThreadedWatchdog genuinely fired.""" + from coder_eval.agents import antigravity_agent + from coder_eval.errors import TurnTimeoutError + + monkeypatch.setattr(antigravity_agent, "_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS", 0.01) + monkeypatch.setattr(antigravity_agent, "_MAX_BACKGROUND_POLLS", 2) + monkeypatch.setattr(antigravity_agent.asyncio, "sleep", _no_sleep) + + conversation = _AlwaysEmptyConversation() + agent = _agent_with_steps([]) + agent._sdk_agent.conversation = conversation + + with pytest.raises(TurnTimeoutError): + await agent.communicate("do it") + + # Salvaged for the orchestrator's forced-kill grading path (Phase 1), not + # silently dropped. + assert agent.pending_turn is not None + assert agent.pending_turn.crashed is True + + +# Worst backgrounded-job duration observed in the confirmed-broken tasks that +# motivated d3f1432 ("poll for backgrounded work instead of grading it +# incomplete"). The poll budget must keep covering it. +_WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS = 300.0 + + +def test_per_step_timeout_is_not_aliased_to_the_poll_interval(): + """Regression test (final-review finding): the per-step timeout must NOT + be aliased to _BACKGROUND_POLL_INTERVAL_SECONDS. Aliasing them (an earlier + revision did this) meant any ordinary foreground tool call or thinking + burst lasting longer than the poll interval (5s) got misclassified as + "looks orphaned", feeding false step_fetch_timed_out cycles into + poll_deadline/_MAX_BACKGROUND_POLLS and materially shrinking the usable + turn budget for completely normal work. The two constants measure + different things (how often to re-check an idle connection vs. how long a + genuinely in-progress step-fetch may go quiet) and must be tuned + independently, with the per-step bound considerably more generous.""" + from coder_eval.agents import antigravity_agent + + assert ( + antigravity_agent._RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS != antigravity_agent._BACKGROUND_POLL_INTERVAL_SECONDS + ) + assert ( + antigravity_agent._RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS + >= 6 * antigravity_agent._BACKGROUND_POLL_INTERVAL_SECONDS + ) + + +def test_background_poll_budget_still_covers_the_worst_observed_backgrounded_job(): + """Regression test (code-review finding): the poll budget for a genuinely + backgrounded job is measured in EMPTY polls, not in 35s worst-case cycles. + + The installed SDK's ``LocalConnection.receive_steps()`` returns immediately + (``if self.is_idle and self._processor.step_queue.empty(): return``) in + exactly the state a backgrounded job leaves behind, so ``_drain()`` comes + back instantly with ``step_fetch_timed_out=False`` and such a cycle costs + only ``_BACKGROUND_POLL_INTERVAL_SECONDS`` -- the per-step timeout is never + reached. d3f1432 sized this budget against confirmed-broken tasks whose + backgrounded work ran 60-300s (~60 consecutive 5s-empty polls); a cap + derived from a 35s/cycle assumption silently cuts that budget to ~85s and + re-opens the bug (the turn gets graded on work that had not happened yet). + + Pin the budget in SECONDS so any future re-tuning has to keep covering the + measured worst case. + + SCOPE — this covers the ``turn_timeout: null`` path only, and deliberately + says so rather than overclaiming. With a turn_timeout CONFIGURED, the + binding bound is `_POLL_DEADLINE_TIMEOUT_FRACTION * turn_timeout` measured + from TURN START (it has to be turn-anchored to win its race with the + ThreadedWatchdog), so at the repo default `turn_timeout: 300` the poll + budget is at most 240s — already below this 300s worst case, and less by + however long the turn ran before backgrounding. That is a real, known + limitation of the configured-timeout path, asserted explicitly below so it + is visible rather than implied; raising it is a defaults change, not a + constants change. + """ + from coder_eval.agents import antigravity_agent + + # timeout=None path: the flat backstop is anchored at POLL-LOOP ENTRY, so + # this budget is actually achievable rather than being eaten by whatever + # the turn already spent. + assert antigravity_agent._MAX_BACKGROUND_POLL_WALL_SECONDS >= _WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS + # The cycle cap must not be the tighter of the two on that path, or it + # silently becomes the real budget (17 * 5s = 85s was exactly that bug). + empty_poll_budget_seconds = ( + antigravity_agent._MAX_BACKGROUND_POLLS * antigravity_agent._BACKGROUND_POLL_INTERVAL_SECONDS + ) + assert empty_poll_budget_seconds >= _WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS, ( + f"empty-poll budget is {empty_poll_budget_seconds:g}s, below the " + f"{_WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS:g}s worst observed backgrounded job" + ) + + # Configured-timeout path: document the achievable budget at the repo + # default. This asserts the CURRENT limitation, so raising the default (or + # the fraction) deliberately trips it and forces this comment to be revised. + default_turn_timeout = 300.0 + configured_budget = default_turn_timeout * antigravity_agent._POLL_DEADLINE_TIMEOUT_FRACTION + assert configured_budget == 240.0 + assert configured_budget < _WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS + + +class _ForegroundToolWithARealGapConversation: + """A single receive_steps() call: opens a tool call, waits a REAL delay + longer than the poll interval (but under the per-step timeout) before the + tool's DONE step arrives, then finishes with a text response -- all in ONE + call. Models an ordinary foreground tool call that simply takes a few + seconds between SDK-visible steps -- the exact case that must NOT be + misclassified as "looks orphaned".""" + + last_response = "" + + def __init__(self, active_step, done_step, final_step, gap_seconds: float): + self._steps = [active_step, done_step, final_step] + self._gap_seconds = gap_seconds + self.receive_steps_call_count = 0 + + async def send(self, prompt, **kwargs): + return None + + async def receive_steps(self): + self.receive_steps_call_count += 1 + yield self._steps[0] + await asyncio.sleep(self._gap_seconds) + for s in self._steps[1:]: + yield s + + async def cancel(self): + return None + + +async def test_communicate_does_not_misclassify_a_slow_but_real_foreground_gap_as_orphaned(monkeypatch): + """A foreground tool call whose DONE step legitimately takes longer than + the OLD (aliased-to-poll-interval) 5s threshold must still complete within + a single receive_steps() call and never enter the poll loop, as long as + the gap stays under the per-step timeout -- proving the fix in practice, + not just via the constants' relationship.""" + from coder_eval.agents import antigravity_agent + + monkeypatch.setattr(antigravity_agent, "_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS", 0.3) + + active = _step( + "TOOL_CALL", + "ACTIVE", + target="TARGET_ENVIRONMENT", + tool_calls=[_tc("run_command", "t1", {"command_line": "pytest"})], + ) + done = _step( + "TOOL_CALL", + "DONE", + target="TARGET_ENVIRONMENT", + tool_calls=[_tc("run_command", "t1", {"command_line": "pytest", "exit_code": 0, "combined_output": "ok"})], + ) + final = _step("TEXT_RESPONSE", "DONE", content="tests passed", complete=True, usage=_usage(10, 0, 1, 0)) + # 0.15s: longer than the OLD aliased-to-5s-poll-interval production value + # would have tolerated in spirit (proportionally), well under the 0.3s + # per-step timeout patched in for this test. + conversation = _ForegroundToolWithARealGapConversation(active, done, final, gap_seconds=0.15) + agent = _agent_with_steps([]) + agent._sdk_agent.conversation = conversation + + tr = await agent.communicate("run the tests") + + assert not tr.crashed + assert tr.agent_output == "tests passed" + bash = next(c for c in tr.commands if c.tool_name == "Bash") + assert bash.result_status == "success" + # The poll loop must never have entered -- everything completed within the + # single initial receive_steps() call. + assert conversation.receive_steps_call_count == 1 diff --git a/tests/test_custom_lint.py b/tests/test_custom_lint.py index 9f923a02..511609bc 100644 --- a/tests/test_custom_lint.py +++ b/tests/test_custom_lint.py @@ -380,22 +380,31 @@ def test_nested_try_propagates_guard(self): assert not self._run(src) +def _with_source(rule, src: str): + """Attach source lines the way ``runner.check_file`` does.""" + rule.source_lines = src.splitlines() + return rule + + @pytest.mark.lint class TestCE022SimulationDialogLoopStatementCap: - """CE022 bounds the regrowth of the noqa'd _simulation_dialog_loop. - - The whole-tree zero-violations guarantee (the live function is at/under the cap) - is asserted by the parametrized ``test_no_violations`` above; these pin that the - rule actually fires on regrowth and stays narrow. + """CE022 bounds the regrowth of every function that keeps a + ``# noqa: PLR0915`` (currently ``_simulation_dialog_loop``, ``run``, and + ``communicate``). + + The whole-tree zero-violations guarantee (each live target is at/under its + cap) is asserted by the parametrized ``test_no_violations`` above; these + pin that the rule actually fires on regrowth and stays scoped to its + registered targets. """ @staticmethod def _run(src: str, *, path: str = "src/coder_eval/orchestrator.py"): import ast - from tests.lint.rules.ce022_dialog_loop_statement_cap import SimulationDialogLoopStatementCap + from tests.lint.rules.ce022_dialog_loop_statement_cap import NoqaPlr0915StatementCap - return SimulationDialogLoopStatementCap(path).check(ast.parse(src)) + return NoqaPlr0915StatementCap(path).check(ast.parse(src)) @staticmethod def _padded_loop(name: str, n_statements: int) -> str: @@ -430,6 +439,81 @@ def test_flags_oversized_sync_dialog_loop(self): src = f"def _simulation_dialog_loop(self, initial_prompt, sandbox_dir):\n{body}" assert len(self._run(src)) == 1 + def test_flags_oversized_run(self): + """orchestrator.py::run is a registered target too (added by the + forced-kill-grading fix's # noqa: PLR0915).""" + violations = self._run(self._padded_loop("run", 200)) + assert len(violations) == 1 + assert violations[0].rule_id == "CE022" + + def test_flags_oversized_communicate_in_antigravity_agent(self): + """antigravity_agent.py::communicate is a registered target too (added + by the step_fetch_timed_out post-loop branch's # noqa: PLR0915).""" + violations = self._run(self._padded_loop("communicate", 200), path="src/coder_eval/agents/antigravity_agent.py") + assert len(violations) == 1 + assert violations[0].rule_id == "CE022" + + def test_ignores_run_outside_orchestrator(self): + """A same-named `run` in a different file is not a registered target.""" + assert not self._run(self._padded_loop("run", 200), path="src/coder_eval/other.py") + + def test_flags_an_unregistered_noqa_plr0915(self, tmp_path): + """The "register your new noqa in _TARGETS" contract is self-enforcing. + + An unregistered function carrying the suppression is bounded by + nothing — ruff's check is off and the cap table skips it — so CE022 + itself must flag it. Without this the contract is documentation only + and ``test_no_violations`` gives a false sense of coverage. + """ + import ast + + from tests.lint.rules.ce022_dialog_loop_statement_cap import NoqaPlr0915StatementCap + + src = "def brand_new_helper(self): # noqa: PLR0915 — new suppression\n x = 1\n" + f = tmp_path / "some_module.py" + f.write_text(src) + + # source_lines is what runner.check_file passes; the rule reads ONLY + # that, never the path, so tree and text can never disagree. + violations = _with_source(NoqaPlr0915StatementCap(str(f)), src).check(ast.parse(src)) + + assert len(violations) == 1 + assert violations[0].rule_id == "CE022" + assert "not registered in CE022's _TARGETS" in violations[0].message + + def test_does_not_flag_a_registered_noqa_or_an_unsuppressed_function(self, tmp_path): + """The self-guard must stay quiet for (a) a registered target and (b) an + ordinary function with no suppression — including one whose BODY merely + mentions PLR0915 (a docstring, or this rule's own message text).""" + import ast + + from tests.lint.rules.ce022_dialog_loop_statement_cap import NoqaPlr0915StatementCap + + registered = "def run(self): # noqa: PLR0915\n x = 1\n" + f = tmp_path / "orchestrator.py" + f.write_text(registered) + assert not _with_source(NoqaPlr0915StatementCap(str(f)), registered).check(ast.parse(registered)) + + body_mention = 'def helper(self):\n """Mentions PLR0915 and noqa in the body only."""\n x = 1\n' + g = tmp_path / "plain_module.py" + g.write_text(body_mention) + assert not _with_source(NoqaPlr0915StatementCap(str(g)), body_mention).check(ast.parse(body_mention)) + + def test_no_source_lines_disables_the_self_guard(self, tmp_path): + """Constructed with only a path (no source), the rule must NOT re-read + that path to hunt for suppressions -- a tree from one source and text + from another is how a synthetic-path unit test turns into a silent + false positive, and it makes the result cwd-dependent.""" + import ast + + from tests.lint.rules.ce022_dialog_loop_statement_cap import NoqaPlr0915StatementCap + + src = "def brand_new_helper(self): # noqa: PLR0915\n x = 1\n" + f = tmp_path / "some_module.py" + f.write_text(src) + + assert not NoqaPlr0915StatementCap(str(f)).check(ast.parse(src)) + @pytest.mark.lint class TestCE023NoProxyShimImports: diff --git a/tests/test_timeout_orchestrator.py b/tests/test_timeout_orchestrator.py index 2bca85b1..6baf80c9 100644 --- a/tests/test_timeout_orchestrator.py +++ b/tests/test_timeout_orchestrator.py @@ -14,6 +14,7 @@ CriterionResult, EvaluationResult, FileExistsCriterion, + FinalStatus, SandboxConfig, TaskDefinition, TokenUsage, @@ -66,6 +67,16 @@ def _make_turn_record(iteration: int = 1) -> TurnRecord: ) +def _make_success_checker(*, passing: bool) -> MagicMock: + """A success_checker mock whose check_all_async reports pass/fail for one criterion.""" + checker = MagicMock() + score = 1.0 if passing else 0.0 + checker.check_all_async = AsyncMock( + return_value=[CriterionResult(criterion_type="file_exists", description="test", score=score)] + ) + return checker + + def _make_initialized_orchestrator(task: TaskDefinition, tmp_path) -> Orchestrator: """Build an Orchestrator with a pre-initialized EvaluationResult and mock sandbox/checker.""" run_dir = tmp_path / "run" / "timeout_test" @@ -147,6 +158,11 @@ async def slow_loop(): result = await orchestrator.run() assert result.final_status == "TIMEOUT" assert f"Task timed out after {task_timeout}s" in (result.error_message or "") + # success_checker is None (never set — _setup was mocked), so + # _grade_after_forced_kill's precondition guard falls back to TIMEOUT + # without attempting grading. This exercises that fallback path + # specifically, not just a status that happens to match. + assert result.success_criteria_results == [] @pytest.mark.asyncio @@ -517,3 +533,449 @@ async def test_claude_agent_discard_pending_turn_rolls_back_iteration(): await agent.discard_pending_turn() assert agent.pending_turn is None assert agent._iteration == 2 + + +@pytest.mark.asyncio +async def test_turn_timeout_grades_success_when_agent_finished(tmp_path) -> None: + """A TurnTimeoutError whose salvaged partial turn satisfies success criteria + must result in SUCCESS, not ERROR -- the agent's real output must still be graded.""" + task = _make_task(turn_timeout=0.1) + run_dir = tmp_path / "run" / "timeout_test" + run_dir.mkdir(parents=True) + + orchestrator = Orchestrator(task=task, run_dir=run_dir, variant_id="test-variant") + + async def fake_setup() -> None: + mock_sandbox = MagicMock() + mock_sandbox.sandbox_dir = tmp_path / "sandbox" + mock_sandbox.sandbox_dir.mkdir() + orchestrator.sandbox = mock_sandbox + orchestrator.success_checker = _make_success_checker(passing=True) + + orchestrator._setup = fake_setup # type: ignore[method-assign] + orchestrator._cleanup = AsyncMock() # type: ignore[method-assign] + + partial = TurnRecord(iteration=1, user_input="p", agent_output="", crashed=True) + + mock_agent = MagicMock() + mock_agent.pending_turn = partial + mock_agent.discard_pending_turn = AsyncMock() + mock_agent.get_sdk_options = MagicMock(return_value=None) + + async def timeout_communicate(_prompt, **kwargs): + raise TurnTimeoutError(0.1, iteration=1) + + mock_agent.communicate = timeout_communicate + orchestrator.agent = mock_agent + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + result = await orchestrator.run() + + assert result.final_status == "SUCCESS" + assert result.success_criteria_results + # A genuinely successful, correctly-graded run must not carry the timeout + # exception's message/traceback forward -- "SUCCESS (plain, no special + # marker)" per the plan's decision. + assert result.error_message is None + assert result.error_details is None + + +@pytest.mark.asyncio +async def test_turn_timeout_grades_timeout_status_when_criteria_fail(tmp_path) -> None: + """A TurnTimeoutError whose salvaged partial turn does NOT satisfy criteria + must result in TIMEOUT (not ERROR, not FAILURE), with the timeout mark preserved.""" + task = _make_task(turn_timeout=0.1) + run_dir = tmp_path / "run" / "timeout_test" + run_dir.mkdir(parents=True) + + orchestrator = Orchestrator(task=task, run_dir=run_dir, variant_id="test-variant") + + async def fake_setup() -> None: + mock_sandbox = MagicMock() + mock_sandbox.sandbox_dir = tmp_path / "sandbox" + mock_sandbox.sandbox_dir.mkdir() + orchestrator.sandbox = mock_sandbox + orchestrator.success_checker = _make_success_checker(passing=False) + + orchestrator._setup = fake_setup # type: ignore[method-assign] + orchestrator._cleanup = AsyncMock() # type: ignore[method-assign] + + partial = TurnRecord(iteration=1, user_input="p", agent_output="", crashed=True) + + mock_agent = MagicMock() + mock_agent.pending_turn = partial + mock_agent.discard_pending_turn = AsyncMock() + mock_agent.get_sdk_options = MagicMock(return_value=None) + + async def timeout_communicate(_prompt, **kwargs): + raise TurnTimeoutError(0.1, iteration=1) + + mock_agent.communicate = timeout_communicate + orchestrator.agent = mock_agent + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + result = await orchestrator.run() + + assert result.final_status == "TIMEOUT" + assert "timed out" in (result.error_message or "").lower() + assert result.success_criteria_results + + +@pytest.mark.asyncio +async def test_task_timeout_grades_success_when_agent_finished(tmp_path) -> None: + """A TaskTimeoutError whose recovered turn satisfies criteria results in SUCCESS.""" + task = _make_task(task_timeout=0.1) + run_dir = tmp_path / "run" / "timeout_test" + run_dir.mkdir(parents=True) + + orchestrator = Orchestrator(task=task, run_dir=run_dir, variant_id="test-variant") + orchestrator._setup = AsyncMock() # type: ignore[method-assign] + orchestrator._cleanup = AsyncMock() # type: ignore[method-assign] + + mock_sandbox = MagicMock() + mock_sandbox.sandbox_dir = tmp_path / "sandbox" + mock_sandbox.sandbox_dir.mkdir() + orchestrator.sandbox = mock_sandbox + orchestrator.success_checker = _make_success_checker(passing=True) + + mock_agent = MagicMock() + mock_agent.pending_turn = None + mock_agent.get_sdk_options = MagicMock(return_value=None) + orchestrator.agent = mock_agent + + async def slow_loop(): + orchestrator.result.iterations.append(_make_turn_record()) + await asyncio.sleep(10) + return False + + orchestrator._evaluation_loop = slow_loop # type: ignore[method-assign] + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + result = await orchestrator.run() + + assert result.final_status == "SUCCESS" + assert result.success_criteria_results + assert result.error_message is None + assert result.error_details is None + + +@pytest.mark.asyncio +async def test_task_timeout_grades_timeout_status_when_criteria_fail(tmp_path) -> None: + """A TaskTimeoutError whose recovered turn does NOT satisfy criteria still results + in TIMEOUT (unchanged from today for the failing case).""" + task = _make_task(task_timeout=0.1) + run_dir = tmp_path / "run" / "timeout_test" + run_dir.mkdir(parents=True) + + orchestrator = Orchestrator(task=task, run_dir=run_dir, variant_id="test-variant") + orchestrator._setup = AsyncMock() # type: ignore[method-assign] + orchestrator._cleanup = AsyncMock() # type: ignore[method-assign] + + mock_sandbox = MagicMock() + mock_sandbox.sandbox_dir = tmp_path / "sandbox" + mock_sandbox.sandbox_dir.mkdir() + orchestrator.sandbox = mock_sandbox + orchestrator.success_checker = _make_success_checker(passing=False) + + mock_agent = MagicMock() + mock_agent.pending_turn = None + mock_agent.get_sdk_options = MagicMock(return_value=None) + orchestrator.agent = mock_agent + + async def slow_loop(): + orchestrator.result.iterations.append(_make_turn_record()) + await asyncio.sleep(10) + return False + + orchestrator._evaluation_loop = slow_loop # type: ignore[method-assign] + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + result = await orchestrator.run() + + assert result.final_status == "TIMEOUT" + assert result.success_criteria_results + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_falls_back_when_success_checker_missing(tmp_path) -> None: + """No success_checker (setup never completed) falls back without raising.""" + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + orchestrator.success_checker = None + + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + assert orchestrator.result is not None + assert orchestrator.result.final_status == FinalStatus.TIMEOUT + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_falls_back_when_check_all_async_raises(tmp_path) -> None: + """check_all_async raising falls back to fallback_status without propagating.""" + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + orchestrator.success_checker.check_all_async = AsyncMock(side_effect=RuntimeError("boom")) # type: ignore[union-attr] + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + assert orchestrator.result is not None + assert orchestrator.result.final_status == FinalStatus.TIMEOUT + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_skips_regrade_when_already_graded(tmp_path) -> None: + """The belt-and-suspenders TaskTimeoutError (run() fires it after + _evaluation_loop already completed a normal grading pass) must not + re-run check_all_async -- that would double-spend any llm_judge/agent_judge + criterion for no new information. Re-derive status from the existing + results instead. + + The shortcut requires the recorded grade to cover the whole recorded + trajectory (``_graded_iteration_count == len(result.iterations)``, stamped + by every grading path); see + ``test_grade_after_forced_kill_regrades_when_existing_results_predate_the_last_turn`` + for the stale-snapshot case that must NOT take it.""" + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + orchestrator.success_checker.check_all_async = AsyncMock( # type: ignore[union-attr] + return_value=[CriterionResult(criterion_type="file_exists", description="x", score=0.0)] + ) + orchestrator.result.iterations = [_make_turn_record(1)] + orchestrator.result.success_criteria_results = [ + CriterionResult(criterion_type="file_exists", description="x", score=1.0) + ] + orchestrator._graded_iteration_count = len(orchestrator.result.iterations) + + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + orchestrator.success_checker.check_all_async.assert_not_awaited() # type: ignore[union-attr] + assert orchestrator.result.final_status == FinalStatus.SUCCESS + assert orchestrator.result.error_message is None + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_keeps_the_fallback_status_when_grading_is_cancelled(tmp_path) -> None: + """Regression test (code-review finding): a BaseException during grading + must not leave the row at the constructor default. + + `except Exception` deliberately does not catch `CancelledError` (a + BaseException), so if the fallback were only committed inside the handler, + a Ctrl-C or batch-level cancel landing in `check_all_async` would persist + `final_status=FAILURE` while `error_message` says the task timed out. + """ + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + + async def cancelled_check_all_async(*args, **kwargs): + raise asyncio.CancelledError() + + orchestrator.success_checker.check_all_async = cancelled_check_all_async # type: ignore[union-attr] + + with ( + patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)), + contextlib.suppress(asyncio.CancelledError), + ): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + assert orchestrator.result.final_status == FinalStatus.TIMEOUT + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_quiesces_the_agent_before_reading_the_sandbox(tmp_path) -> None: + """Regression test (code-review finding): grading must not race a live agent. + + On a TurnTimeoutError the agent raised at its OWN internal deadline — + nothing has torn the harness down yet (Antigravity's `kill_sync` is + intent-only, and `_cleanup()` runs in run()'s finally, after this grading + pass). Without an explicit quiesce, a backgrounded build would still be + writing into the sandbox while the criteria read it. + """ + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + call_order: list[str] = [] + + async def recording_kill(): + call_order.append("kill") + + async def recording_check_all_async(*args, **kwargs): + call_order.append("grade") + return [CriterionResult(criterion_type="file_exists", description="x", score=1.0)] + + orchestrator.agent = MagicMock() + orchestrator.agent.kill = recording_kill + orchestrator.success_checker.check_all_async = recording_check_all_async # type: ignore[union-attr] + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + assert call_order == ["kill", "grade"] + assert orchestrator.result.final_status == FinalStatus.SUCCESS + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_grades_even_if_quiescing_the_agent_fails(tmp_path) -> None: + """The quiesce is best-effort: a failing kill() must not skip grading.""" + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + + async def failing_kill(): + raise RuntimeError("harness already gone") + + orchestrator.agent = MagicMock() + orchestrator.agent.kill = failing_kill + orchestrator.success_checker.check_all_async = AsyncMock( # type: ignore[union-attr] + return_value=[CriterionResult(criterion_type="file_exists", description="x", score=1.0)] + ) + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + orchestrator.success_checker.check_all_async.assert_awaited() # type: ignore[union-attr] + assert orchestrator.result.final_status == FinalStatus.SUCCESS + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_gates_armed_only_when_the_watcher_fired(tmp_path) -> None: + """The FIRED-ONLY gate contract must hold on the forced-kill path too. + + _grade_after_forced_kill back-fills ``result.early_stop`` from the watcher + (a hard-killed run never reaches _evaluation_loop's own assignment), which + is what makes the armed branch of ``_gate_passed`` reachable here at all. + Once it fires, gating is the WEIGHTED ARMED subset -- a failing UNARMED + criterion stays advisory and must not veto SUCCESS, exactly as on the + normal early-stop path CLAUDE.md documents. + """ + from coder_eval.models import EarlyStopInfo, EarlyStopReason + from coder_eval.orchestration.early_stop import EarlyStopWatcher + from coder_eval.orchestrator import DEFAULT_STOP_EARLY_GATE_THRESHOLD + + # file_exists is not a LiveSuccessCriterion, so it cannot carry a + # stop_early block at all -- it is unarmed by construction, and here it + # also fails, which is exactly the advisory-criterion case under test. + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + # spec'd so a typo'd attribute fails loudly, and .info is set EXPLICITLY: + # a bare MagicMock().info is a truthy Mock, which would make the armed + # branch look reachable even if the production back-fill were wrong. + orchestrator._early_stop_watcher = MagicMock(spec=EarlyStopWatcher) + orchestrator._early_stop_watcher.info = EarlyStopInfo( + reason=EarlyStopReason.CRITERION_PASSED, + deciding_criterion_type="file_exists", + deciding_criterion_description="test.py must exist", + armed_criteria=["file_exists"], + sdk_turn_index=1, + tool_call_index=0, + elapsed_seconds=0.5, + gate_threshold=1.0, + ) + orchestrator.result.iterations = [_make_turn_record(1)] + # The unarmed criterion fails; with strict-AND this would be TIMEOUT. + orchestrator.success_checker.check_all_async = AsyncMock( # type: ignore[union-attr] + return_value=[CriterionResult(criterion_type="file_exists", description="x", score=0.0)] + ) + # The gate methods are wrapped, not replaced, so the REAL weighted-armed + # verdict decides the outcome and the assertions below pin both the + # dispatch AND the threshold that gets forwarded. + with ( + patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)), + patch.object( + EvaluationResult, "armed_criteria_passed", autospec=True, side_effect=lambda self, c, t: True + ) as armed_gate, + patch.object(EvaluationResult, "all_criteria_passed", autospec=True) as strict_gate, + ): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + strict_gate.assert_not_called() + armed_gate.assert_called_once() + # the resolved gate threshold must be forwarded, not defaulted away + assert armed_gate.call_args.args[1] is task.success_criteria + assert armed_gate.call_args.args[2] == DEFAULT_STOP_EARLY_GATE_THRESHOLD + assert orchestrator.result.early_stop is not None + # ...and the failing UNARMED criterion did not veto SUCCESS + assert orchestrator.result.success_criteria_results[0].score == 0.0 + assert orchestrator.result.final_status == FinalStatus.SUCCESS + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_gates_strict_and_when_the_watcher_never_fired(tmp_path) -> None: + """Converse of the above: an armed run whose watcher never fired has a full + trajectory, so it gates strict-AND over every gating criterion -- arming a + criterion must never change the verdict of a run it did not cut.""" + from coder_eval.orchestration.early_stop import EarlyStopWatcher + + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + orchestrator._early_stop_watcher = MagicMock(spec=EarlyStopWatcher) + orchestrator._early_stop_watcher.info = None # armed, but never fired + orchestrator.result.iterations = [_make_turn_record(1)] + orchestrator.success_checker.check_all_async = AsyncMock( # type: ignore[union-attr] + return_value=[CriterionResult(criterion_type="file_exists", description="x", score=0.0)] + ) + # No patch on all_criteria_passed: the REAL strict-AND gate runs and must + # reject score=0.0 against pass_threshold=0.9 on its own. + with ( + patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)), + patch.object(EvaluationResult, "armed_criteria_passed", autospec=True) as armed_gate, + ): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + armed_gate.assert_not_called() + assert orchestrator.result.early_stop is None + assert orchestrator.result.final_status == FinalStatus.TIMEOUT + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_regrades_when_existing_results_predate_the_last_turn(tmp_path) -> None: + """Regression test (code-review finding): the skip-regrade shortcut must NOT + fire on stale results. + + With ``simulation.check_criteria: every_turn``/``both``, + ``_run_dialog_criteria_check`` replaces ``success_criteria_results`` on + EVERY dialog turn. A ``TurnTimeoutError`` several turns later would then hit + the already-graded branch and re-derive the final status from a snapshot + taken before the turns that actually blew the budget -- reporting SUCCESS + for a dialog whose later turns regressed the sandbox. The shortcut is only + sound when the recorded grade covers the whole recorded trajectory. + """ + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + fresh = [CriterionResult(criterion_type="file_exists", description="x", score=0.0)] + orchestrator.success_checker.check_all_async = AsyncMock(return_value=fresh) # type: ignore[union-attr] + + # A passing grade recorded when the trajectory was 1 turn long... + orchestrator.result.success_criteria_results = [ + CriterionResult(criterion_type="file_exists", description="x", score=1.0) + ] + orchestrator._graded_iteration_count = 1 + # ...but two more turns have since been recorded. + orchestrator.result.iterations = [_make_turn_record(i) for i in range(3)] + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + orchestrator.success_checker.check_all_async.assert_awaited() # type: ignore[union-attr] + assert orchestrator.result.final_status == FinalStatus.TIMEOUT + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_falls_back_when_grading_exceeds_its_grace_budget(tmp_path, monkeypatch) -> None: + """Grading after a forced kill must not itself become an unbounded tail on + an already-blown budget -- bound it and fall back like any other grading + failure.""" + from coder_eval import orchestrator as orchestrator_module + + monkeypatch.setattr(orchestrator_module, "_GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS", 0.05) + + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + + async def hanging_check_all_async(*args, **kwargs): + await asyncio.sleep(999) + + orchestrator.success_checker.check_all_async = hanging_check_all_async # type: ignore[union-attr] + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + await asyncio.wait_for(orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT), timeout=5.0) + + assert orchestrator.result.final_status == FinalStatus.TIMEOUT From fc5c0e9e42ada53b9c90b33f0bb6db46cb3242de Mon Sep 17 00:00:00 2001 From: joeysbase Date: Fri, 14 Aug 2026 23:39:13 +0000 Subject: [PATCH 2/3] fix: code review fixes (round 3) Round-3 review found two High issues, one of them a regression introduced by round 2's own fix, plus ripple that no earlier round had looked for. - Antigravity: remove the poll-loop cycle cap. Round 2 made it apply alongside the deadline instead of only when there was no deadline, so a task configuring turn_timeout: 1200 (960s of polling) was silently cut at 120 * 5s = 600s. On the timeout=None path the two bounds expired at the same instant anyway, so the cap bounded nothing the wall-clock deadline did not. One clock now covers both cost modes. - Orchestrator: shield and track the forced-kill grading pass. check_all_async offloads each criterion to asyncio.to_thread, which is not cancellable, so the 60s budget left a run_command criterion's subprocess running inside a sandbox that run()'s finally was about to move or rmtree. The budget still bounds how long we WAIT for a verdict; _await_pending_grade bounds when teardown may start. Mirrors SubAgentRunner, which documents this same hazard. - EvaluationResult.forced_kill records the kill durably, alongside final_status like max_turns_exhausted. Once grading can turn a TIMEOUT into SUCCESS the status stops being a usable proxy for "blew its budget": reports_experiment._cost_complete returned True for rows that lost in-flight spend, the error_log_tail allowlist dropped the only evidence of the kill, and telemetry could not count breaches. All three now key off the flag, and run.json carries it. - Bound the two new unbounded awaits (the pre-grading agent quiesce and the poll-budget cancel); both run on a connection already declared unresponsive, outside any watchdog. The quiesce also catches BaseException so a queued task.cancel landing there cannot skip the grading pass it protects. - DRY: _evaluation_loop now calls _gate_passed instead of keeping a second hand-maintained copy of the FIRED-ONLY rule, and the two timeout handlers collapse into _handle_forced_kill. That brings run() back under ruff's ceiling, so its # noqa: PLR0915 and its CE022 _TARGETS entry are both gone. - Docs: REPORT_SCHEMA.md gains the TIMEOUT-is-a-fallback gotcha and the ERROR -> TIMEOUT migration for turn timeouts; CLAUDE.md records forced_kill; smoke_task_timeout.yaml's comments no longer claim criteria are never evaluated on a timeout, which this change made false. Co-Authored-By: Claude Opus 5 --- CLAUDE.md | 2 +- docs/REPORT_SCHEMA.md | 12 +- src/coder_eval/agents/antigravity_agent.py | 93 ++++----- src/coder_eval/models/results.py | 9 + src/coder_eval/orchestrator.py | 186 ++++++++++++------ src/coder_eval/reports_experiment.py | 17 +- tasks/smoke_task_timeout.yaml | 12 +- .../rules/ce022_dialog_loop_statement_cap.py | 4 - tests/test_antigravity_agent.py | 40 ++-- tests/test_custom_lint.py | 15 +- tests/test_timeout_orchestrator.py | 70 +++++++ 11 files changed, 311 insertions(+), 149 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 50ee623d..9c065ed6 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -144,7 +144,7 @@ action.yml # Published composite GitHub Action (coder-ev - **Reconciliation message (stream self-reconciles to the turn total)**: The per-message stream consistently under-reports the authoritative turn total — a fixed prompt slice (~512 input tokens on Claude) is billed on no SDK-emitted message, and sub-agent input/cache only partially bubbles up. So `EventCollector.build_turn_record` appends one synthetic `ReconciliationMessage` (`role="reconciliation"`, in the `TranscriptMessage` union) per turn, carrying the per-bucket residual = `token_usage` − Σ(assistant message buckets). The invariant: **summing the four token buckets across `TurnRecord.messages` (assistant + reconciliation) equals `token_usage` exactly**, for both Claude and Codex (Codex's stream is already complete after `_recover_subagent_tool_calls`, so its residual is usually 0 and no entry is emitted). This is what lets the evalboard SUM the message stream as the source of truth instead of reading a separate aggregate ("agent tokens"): `selectTokenTotals` returns the stream sum whenever a reconciliation entry is present, and the timeline renders it as its own row. It is agent-agnostic (booked at the single `EventCollector` seam), carries no cost (cost stays on `token_usage`), and is excluded from generation/turn counts and the cost simulator. The LiteLLM open-weight actual-cost join (`litellm_cost.apply_actual_cost`) deliberately writes cost at the TURN level only (`token_usage.total_cost_usd` = the real OpenRouter bill) plus the per-call `TurnRecord.provider_call_costs` audit record; it does NOT touch the message token buckets, so `EventCollector` stays the single writer and this invariant holds on every backend. The Python `token_usage`/`total_token_usage` aggregate is unchanged and still authoritative for budget/judges/reports. - **Harness run-limit parity**: a shared `BaseAgentConfig` field must mean the same thing on every backend, so a divergence is either fixed or documented — never silent. **`run_limits.max_turns` on Codex/Antigravity counts VISIBLE turns** (resolved tool calls, read live off the shared `EventCollector.visible_turn_count`, the same list `TurnRecord.commands` holds) because one `communicate()` is a single SDK turn on both, so a native counter would clamp at 1; claude-code keeps its native SDK cap, whose unit (an agent-loop turn) absorbs arbitrarily many parallel calls — the same number is NOT the same budget across harnesses. The cap is enforced on the same loop boundary as the cooperative early stop and finalizes cleanly as `max_turns_exhausted` (no crash, no retry); on Antigravity that boundary lives in `_drain()`, so the background-work poll loop honors it too. Known unfixed divergences: `permission_mode` on Codex and Antigravity (both run unconfined — the sandbox driver is the isolation boundary), `disallowed_tools` on Codex (forwarded, not SDK-enforced), `allowed_tools`/`disallowed_tools` on Antigravity (not read at all), and `turn_timeout` on Antigravity (the background-work poll loop is bounded by an earlier internal deadline at 80% of it, or a flat 600s when the task sets no timeout — at that bound a still-ACTIVE tool call is force-closed and graded normally, while a connection that never produced a clean turn end raises a real `TurnTimeoutError`). Full table + rationale: docs/agents/HARNESS_PARITY.md. - **sandbox isolation**: Tasks that don't need MCP servers should set `setting_sources: []` in their `agent:` block to isolate the sandbox from the host project's CLAUDE.md and settings. Without this, the host project's CLAUDE.md (often 20 KB+) is injected into every API call, inflating cache-creation tokens and cost significantly. -- **Run-time caps (non-criterion enforcement)**: `TaskDefinition.run_limits` (`RunLimits` model) is the single namespace for all *task-level* run-time caps — `max_turns` / `task_timeout` / `turn_timeout` (structural) and `max_input_tokens` / `max_output_tokens` / `max_total_tokens` / `max_usd` (cumulative budget). Token/USD breaches abort with `FinalStatus.TOKEN_BUDGET_EXCEEDED` or `COST_BUDGET_EXCEEDED` (both `category == "failed"`). A **structural timeout is graded, not discarded**: `TaskTimeoutError` and `TurnTimeoutError` both run `Orchestrator._grade_after_forced_kill` against whatever the agent produced before the kill, so a task that timed out but already satisfied its criteria finalizes `SUCCESS` (plain, error_message cleared) instead of `TIMEOUT` — downstream consumers must not read `TIMEOUT` as "every timed-out run". Grading is bounded (60s), never raises, honors the same FIRED-ONLY early-stop gate as a normal run, and falls back to `TIMEOUT` on any failure. Structural caps are set from the CLI via `-D run_limits.max_turns=…` / `-D run_limits.task_timeout=…` / `-D run_limits.turn_timeout=…` (field-merged into `run_limits`); budget caps via `-D run_limits.max_usd=…` etc. or YAML. Layered config uses field-merge — a variant block overrides individual keys without replacing the task's block. The one *per-criterion* cap, `stop_early.decide_within`, deliberately lives on `LiveSuccessCriterion` instead (see below) — the watcher must attribute a decision-step timeout to a specific criterion, which `RunLimits` (task-scoped, criterion-agnostic) cannot express. +- **Run-time caps (non-criterion enforcement)**: `TaskDefinition.run_limits` (`RunLimits` model) is the single namespace for all *task-level* run-time caps — `max_turns` / `task_timeout` / `turn_timeout` (structural) and `max_input_tokens` / `max_output_tokens` / `max_total_tokens` / `max_usd` (cumulative budget). Token/USD breaches abort with `FinalStatus.TOKEN_BUDGET_EXCEEDED` or `COST_BUDGET_EXCEEDED` (both `category == "failed"`). A **structural timeout is graded, not discarded**: `TaskTimeoutError` and `TurnTimeoutError` both run `Orchestrator._grade_after_forced_kill` against whatever the agent produced before the kill, so a task that timed out but already satisfied its criteria finalizes `SUCCESS` (plain, error_message cleared) instead of `TIMEOUT` — downstream consumers must not read `TIMEOUT` as "every timed-out run". Grading is bounded (60s), never raises, honors the same FIRED-ONLY early-stop gate as a normal run, and falls back to `TIMEOUT` on any failure. `EvaluationResult.forced_kill` is the durable marker of the kill (like `max_turns_exhausted`) and is what consumers must read to ask "did this blow its budget?" — `reports_experiment._cost_complete`, the `error_log_tail` allowlist and the `ForcedKill` telemetry dim all key off it, not off the status. A turn-level timeout also moved from `FinalStatus.ERROR` (category `error`) to `TIMEOUT` (category `failed`) now that it has a dedicated handler, shifting rows between `tasks_error`/`tasks_failed` and between ``/`` in JUnit. Structural caps are set from the CLI via `-D run_limits.max_turns=…` / `-D run_limits.task_timeout=…` / `-D run_limits.turn_timeout=…` (field-merged into `run_limits`); budget caps via `-D run_limits.max_usd=…` etc. or YAML. Layered config uses field-merge — a variant block overrides individual keys without replacing the task's block. The one *per-criterion* cap, `stop_early.decide_within`, deliberately lives on `LiveSuccessCriterion` instead (see below) — the watcher must attribute a decision-step timeout to a specific criterion, which `RunLimits` (task-scoped, criterion-agnostic) cannot express. - **Early stop on criterion (opt-in, per-criterion arming)**: a `stop_early:` block (`StopEarlyPolicy`) on a criterion ends a single-shot run early once the run's **armed** criteria decide the outcome, so a raised `max_turns` isn't wasted on the smoke flavor. The block's PRESENCE is the arming and alone activates the watcher — there is **no run-level master switch**: `run_limits.stop_early: false` is the run-level KILL SWITCH that force-disarms every block (the one-line experiment-variant/`-D` override for an authoritative full run), and `run_limits.stop_early: true` (the removed master arm) is a hard `EarlyStopConfigError` at resolution. The block exists on `LiveSuccessCriterion` only (currently `skill_triggered`, `command_executed` — so arming an unobservable criterion is unrepresentable, a pydantic extra-forbid error). Arming carries one implicit trigger (a native live-fail may fail-stop the run); its keys refine it: `on_pass: stop` (pass-stop the moment the criterion live-passes; default `continue` just latches) and `decide_within: N` (still undecided after N tool-call steps latches an **effective fail**, fed through the same fail-stop rule, reported as `decision_budget_exceeded` — an ordinary weighted fail, NOT a gate-bypassing force-fail; cumulative across retry attempts of the same turn). A trigger whose polarity the instance can't decide (per the abstract, checker-independent `live_decidable_polarities()`, a pure function of the criterion's own fields, paired with the checker's `live_verdict` override by lint rule CE025, a registry-based whole-tree check) is **inert by design** — one dataset-fanned YAML line serves both positive rows (pass/timeout live) and distractor rows (fail live). Verdicts **latch**: once a criterion decides, its `live_verdict` is never polled again. Stop rule is weighted, not strict-boolean: `run_limits.stop_early_gate_threshold` (default `1.0`, reproducing strict-AND behavior exactly) is the minimum weighted score (`Σ weight·score / Σ weight` over the armed subset) required to pass; a fail-stop fires once the armed set's **ceiling** (best case for everything still undecided) can no longer reach the threshold — so a low-weight fail or timeout that can't doom the gate is absorbed and the run continues — and is **deferred while any pass-capable armed criterion is undecided** (a distractor misfire never truncates a positive row's recall signal); a pass-stop fires once the `on_pass: stop` subset's **floor** (worst case) already meets the threshold, and is symmetrically **deferred while any pass-capable armed criterion outside the `on_pass: stop` subset is undecided** (so an early pass never freezes a sibling `on_pass: continue` criterion's signal out of the trajectory). A fail-stop is therefore verdict-preserving; a pass-stop can miss a *later* distractor misfire, so authoritative P/R/F1 comes from a kill-switched (`stop_early: false`) run. Driven by `orchestration/early_stop.py::EarlyStopWatcher` (built when `early_stop_active(task)`: ≥1 armed criterion, kill switch not thrown) through the agent's cooperative `should_stop` seam (tool-call granularity, no SIGKILL); live verdicts only *trigger* the stop — the standard `check_all_async` on the frozen trajectory is authoritative. Gating is **FIRED-ONLY**: a run the watcher actually cut gates on the **armed subset** via the weighted `EvaluationResult.armed_criteria_passed`; a run that completes naturally — armed or not — gates strict-AND via `all_criteria_passed`, so adding a block never changes the verdict of a run it didn't cut. Note the gate keys on the watcher having FIRED (`result.early_stop is not None`), not on confirmed truncation — an agent that ignores `should_stop`, or a stop firing on the final message, still gates armed-only. Every resolution-time guardrail violation is a hard error at resolution (plan *and* run); the one load-time case — a `stop_early:` block on a non-live criterion — is a pydantic schema error at task load, which the run surface reports as a skipped task like any other malformed task. A runtime verdict bug **fails open** to a full run. Surfaces: `EarlyStopInfo` (incl. `gate_threshold` at stop time), report notes/badges, `stopped_early` run.json rows, `EarlyStopped`/`EarlyStopReason` telemetry dims. Worked rationale: docs/TASK_DEFINITION_GUIDE.md § `stop_early`. No blocks anywhere ⇒ behavior byte-for-byte unchanged. ## Success Criteria (15 types) diff --git a/docs/REPORT_SCHEMA.md b/docs/REPORT_SCHEMA.md index b656cae9..5f09fad6 100644 --- a/docs/REPORT_SCHEMA.md +++ b/docs/REPORT_SCHEMA.md @@ -87,7 +87,8 @@ crashed, crash_reason}`) — the full transcript is in `task.json`. ### Missing cost is never fatal Pricing degrades; the evaluation does not. A model absent from the rate card, a turn -the backend never priced, a hard-killed task that lost its in-flight spend: each one +the backend never priced, a hard-killed task that lost its in-flight spend (keyed on +`forced_kill`, since such a task may finalize `SUCCESS`): each one lowers a total and sets `cost_complete: false`. None of them raises, none of them books a zero, and none of them changes a run's exit code. @@ -290,6 +291,15 @@ String enum values and their reporting category: | `MAX_TURNS_EXHAUSTED` | failed | `M` | | `TOKEN_BUDGET_EXCEEDED` | failed | `#` | | `COST_BUDGET_EXCEEDED` | failed | `$` | + +`TIMEOUT` is the **fallback** status for a structural timeout, not a synonym for +"this run timed out". A hard-killed run is graded against whatever the agent +produced, so one that already satisfied its criteria serializes as `SUCCESS` +with `error_message` cleared. To ask "did this task blow its budget?", read the +durable `forced_kill` flag on the row, not the status. A turn-level timeout also +now lands as `TIMEOUT` (category `failed`) rather than the `ERROR` (category +`error`) it produced before it had a dedicated handler — it moves between +`tasks_error` and `tasks_failed`, and between `` and `` in JUnit. | `ERROR` | error | `!` | | `BUILD_FAILED` | error | `B` | diff --git a/src/coder_eval/agents/antigravity_agent.py b/src/coder_eval/agents/antigravity_agent.py index 1659e9b5..5da93580 100644 --- a/src/coder_eval/agents/antigravity_agent.py +++ b/src/coder_eval/agents/antigravity_agent.py @@ -100,8 +100,8 @@ _RECEIVE_STEPS_REENTRY_RETRIES = 5 # Bounds a single receive_steps() step-fetch so communicate()'s poll loop can -# re-check its own bounds (has_orphaned_tool_call, poll_deadline, -# _MAX_BACKGROUND_POLLS) even while the connection is genuinely non-idle and a +# re-check its own bounds (has_orphaned_tool_call, poll_deadline) +# even while the connection is genuinely non-idle and a # fetch would otherwise block unboundedly (confirmed against the installed SDK: # a single receive_steps() call has no internal timeout) -- see _drain(). # @@ -114,8 +114,8 @@ # running, a model still generating with no incremental signal) may go quiet # before being treated as suspicious. Aliasing it to 5s meant an ordinary tool # call or thinking burst lasting longer than 5s between SDK-visible steps -# routinely tripped this "looks orphaned" signal, feeding _POLL_DEADLINE and -# _MAX_BACKGROUND_POLLS with false cycles and materially shrinking the +# routinely tripped this "looks orphaned" signal, feeding poll_deadline +# with false cycles and materially shrinking the # effective turn budget for completely normal work (round-4 review finding, # confirmed against the installed SDK's queue-based receive_steps()). 30s is # generous enough that ordinary latency should never trip it, while still @@ -147,44 +147,45 @@ # evaluated, a strict regression for that input class. _POLL_DEADLINE_TIMEOUT_FRACTION = 0.8 -# Cap on poll *cycles* per turn, and the wall-clock backstop that runs beside -# it. BOTH bound the loop; whichever trips first wins. They exist because a -# poll cycle's cost is bimodal, and a single bound cannot cover both modes: +# Wall-clock backstop on the background-work poll loop for a task that sets no +# run_limits.turn_timeout/task_timeout at all (timeout=None), since +# _POLL_DEADLINE_TIMEOUT_FRACTION has nothing to multiply in that case. It is +# the SOLE bound on that path; with a timeout configured, 0.8 * timeout +# replaces it entirely. # -# - Backgrounded job (the case this loop exists for): the connection is IDLE -# with an empty step queue, so the installed SDK's receive_steps() returns +# 600s is ~2x the 60-300s worst backgrounded-job duration observed in the +# confirmed-broken tasks that motivated d3f1432, and it covers both cost modes +# a poll cycle has: +# - idle (the case this loop exists for): the connection is idle with an +# empty step queue, so the installed SDK's receive_steps() returns # immediately (`if self.is_idle and self._processor.step_queue.empty(): -# return`, connections/local/local_connection.py) -- _drain() comes back -# instantly with step_fetch_timed_out=False and the cycle costs just -# _BACKGROUND_POLL_INTERVAL_SECONDS = 5s. _MAX_BACKGROUND_POLLS is what -# bounds this mode: 120 * 5s = 600s, ~2x the 60-300s worst backgrounded-job -# duration observed in the confirmed-broken tasks that motivated d3f1432. -# A code-review round derived this cap from a 35s worst-case cycle instead -# (17 * 35s) -- that arithmetic does not apply to THIS mode, and cut the -# real budget to 85s, re-opening the exact bug d3f1432 fixed (the turn -# graded on work that had not happened yet). tests/test_antigravity_agent.py -# ::test_background_poll_budget_still_covers_the_worst_observed_backgrounded_job -# pins the product in seconds so it cannot silently regress again. +# return`, connections/local/local_connection.py) and the cycle costs just +# _BACKGROUND_POLL_INTERVAL_SECONDS = 5s -> 120 cycles inside the budget. +# - wedged: genuinely non-idle, every re-drain burns the full +# _RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS, so a cycle costs 30 + 5 = 35s +# -> ~17 cycles. Bounding this in wall-clock time rather than in cycles is +# the whole point: a cycle COUNT tuned for one mode is wrong for the other +# (a cap of 17 derived from the 35s cycle cut the idle budget to 85s and +# re-opened d3f1432's bug; a cap of 120 tuned for the idle mode overrode +# large configured timeouts). One clock, both modes. # -# - Wedged connection: genuinely non-idle, every re-drain burns the full -# _RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS before giving up, so a cycle -# costs 30 + 5 = 35s and the cycle cap alone would allow 120 * 35s = 70 -# minutes. _MAX_BACKGROUND_POLL_WALL_SECONDS bounds this mode directly in -# wall-clock time, and applies only when the task set no turn_timeout (with -# one configured, _POLL_DEADLINE_TIMEOUT_FRACTION * timeout is tighter and -# wins). 600s keeps the same ~10-minute ceiling the cycle cap used to imply. +# tests/test_antigravity_agent.py +# ::test_background_poll_budget_still_covers_the_worst_observed_backgrounded_job +# pins the budget in seconds so it cannot silently regress again. # # Deliberately NOT "break after N consecutive empty polls" instead: the real # SDK's receive_steps() returns identically empty whether a backgrounded job is # still genuinely running OR will never resolve at all (confirmed live against # the installed SDK) -- there is no signal that tells these two cases apart -# except waiting. A consecutive-empty-count small enough to matter would also -# abort real slow jobs (the confirmed cases needed up to ~60 consecutive 5s- -# empty polls before succeeding); one large enough to be safe barely improves -# over this flat cap. A flat, data-grounded cap is the honest option. -_MAX_BACKGROUND_POLLS = 120 +# except waiting. _MAX_BACKGROUND_POLL_WALL_SECONDS = 600.0 +# Wall-clock cap on the best-effort server-side cancel issued when the poll +# budget is exhausted. That exit means the connection never produced a clean +# turn end, so a cancel() -- itself a send on that connection -- is exactly the +# call most likely to hang, and it runs outside the ThreadedWatchdog block. +_CANCEL_TIMEOUT_SECONDS = 10.0 + # Antigravity builtin tool name -> canonical Claude-ish tool name, so cross-agent # success criteria (command_executed / commands_efficiency / skill_triggered) and # reports key on the SAME tool names the Claude / Codex backends emit. Unmapped @@ -552,7 +553,7 @@ async def _drain( except TimeoutError: # This one step-fetch took too long -- not an error. Return # control to communicate()'s poll loop so ITS bounds - # (poll_deadline, _MAX_BACKGROUND_POLLS, state.timeout_hit) + # (poll_deadline, state.timeout_hit) # get a chance to run, instead of staying frozen inside # this single call with no way to check elapsed time. state.step_fetch_timed_out = True @@ -713,11 +714,13 @@ def _on_turn_timeout() -> None: and not state.max_turns_hit and not state.timeout_hit and (state.has_orphaned_tool_call() or state.step_fetch_timed_out) - # Both bounds apply; whichever trips first wins. The - # cycle cap sizes the cheap idle-poll mode (5s/cycle), - # the deadline sizes the expensive wedged mode - # (35s/cycle) -- see _MAX_BACKGROUND_POLLS' comment. - and poll_count < _MAX_BACKGROUND_POLLS + # ONE bound: the deadline. A parallel cycle cap was + # tried and removed -- it silently overrode a large + # configured turn_timeout (a task asking for 960s of + # polling got 120*5s = 600s), and on the timeout=None + # path it expired at the same instant as the wall-clock + # backstop anyway, so it bounded nothing the deadline + # didn't already bound. and time.monotonic() < poll_deadline ): poll_count += 1 @@ -755,8 +758,6 @@ def _on_turn_timeout() -> None: if timeout else f"wall-clock backstop ({_MAX_BACKGROUND_POLL_WALL_SECONDS:g}s)" ) - if poll_count >= _MAX_BACKGROUND_POLLS: - bound = f"_MAX_BACKGROUND_POLLS ({_MAX_BACKGROUND_POLLS})" msg = "Poll budget exhausted (%s, poll_count=%d) with a tool call still ACTIVE." self._log.warning(msg, bound, poll_count) @@ -813,11 +814,15 @@ def _on_turn_timeout() -> None: # max_turns exit above -- nothing legitimate is in flight here # (no orphaned tool call), so there's no reason to leave the # harness running while the orchestrator grades the sandbox. + # Bounded: this branch has just declared the connection + # unresponsive, and cancel() bottoms out in a send on that same + # connection -- outside the ThreadedWatchdog block, so nothing + # else would stop it hanging. with contextlib.suppress(Exception): - await conversation.cancel() + await asyncio.wait_for(conversation.cancel(), timeout=_CANCEL_TIMEOUT_SECONDS) # This branch is reachable with `timeout` either set - # (exhausted via poll_deadline) or None (exhausted via - # _MAX_BACKGROUND_POLLS) -- report the configured timeout when + # (exhausted via poll_deadline) or None (exhausted via the + # wall-clock backstop) -- report the configured timeout when # there is one, else the real elapsed wall-clock time, instead # of a nonsense "after 0s" for the timeout=None case. elapsed = time.monotonic() - turn_start_time @@ -953,7 +958,7 @@ def __init__( # needs a TOOL step specifically to have gone ACTIVE. OR'd into # communicate()'s poll-loop entry condition so a merely-slow-but-real # step (first or mid-stream) retries under the existing - # poll_deadline/_MAX_BACKGROUND_POLLS bound instead of being mistaken + # poll_deadline bound instead of being mistaken # for a turn that produced nothing; also consulted after the poll # loop exits to raise a timeout instead of silently finalizing as # COMPLETED when nothing ever settled (see communicate()'s post-loop diff --git a/src/coder_eval/models/results.py b/src/coder_eval/models/results.py index 2f03222e..fe97d7d1 100644 --- a/src/coder_eval/models/results.py +++ b/src/coder_eval/models/results.py @@ -517,6 +517,15 @@ class EvaluationResult(BaseModel): default=False, description="Whether any iteration hit the agent max_turns limit without the agent voluntarily completing", ) + forced_kill: bool = Field( + default=False, + description=( + "Whether a structural timeout (task_timeout or turn_timeout) hard-killed this run. " + "Kept alongside final_status, like max_turns_exhausted, because the run is graded after " + "the kill and can therefore finalize SUCCESS -- without this flag a timed-out run that " + "passed its criteria is indistinguishable from one that finished inside its budget." + ), + ) weighted_score: float | None = Field( default=None, ge=0.0, le=1.0, description="Weighted average of criterion scores (0.0 to 1.0)" ) diff --git a/src/coder_eval/orchestrator.py b/src/coder_eval/orchestrator.py index 96d5fe70..736161bb 100644 --- a/src/coder_eval/orchestrator.py +++ b/src/coder_eval/orchestrator.py @@ -1,6 +1,7 @@ """Main orchestrator for coordinating task evaluation.""" import asyncio +import contextlib import logging import re import time @@ -85,6 +86,12 @@ # than not grading at all. _GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS = 60.0 +# Wall-clock cap on the pre-grading agent quiesce. kill() cancels and tears down +# the harness connection -- the same connection that may be wedged on the path +# that got us here -- and it runs after run()'s watchdog has exited, so without +# this it is an unbounded await on an already-blown budget. +_QUIESCE_TIMEOUT_SECONDS = 15.0 + async def _pump_stream( stream: asyncio.StreamReader | None, @@ -272,6 +279,10 @@ def build_task_event(result: EvaluationResult, *, driver: str, variant_id: str) "Driver": driver, "EarlyStopped": result.early_stop is not None, "EarlyStopReason": (result.early_stop.reason.value if result.early_stop is not None else ""), + # Independent of Status: a hard-killed run is graded after the kill and + # may report SUCCESS, so "how many tasks blew their structural budget?" + # is not answerable from Status/Category alone. + "ForcedKill": result.forced_kill, } return "CoderEval.Task.End", props @@ -417,6 +428,10 @@ def __init__( # persists only that last call's judge cost, silently dropping every # earlier turn's. Keyed by (position, criterion_type). self._judge_usage_accum: dict[tuple[int, str], TokenUsage] = {} + # In-flight forced-kill grading task, when its 60s budget expired while + # criteria were still running on worker threads. Awaited before sandbox + # teardown so cleanup can never race a live criterion. + self._pending_grade: asyncio.Task[list[CriterionResult]] | None = None # One-shot flag: emit the "cost budget configured but no cost data" warning # exactly once per task even if _check_run_limits fires every turn. @@ -442,7 +457,7 @@ def _agent_name(self) -> str: return str(self.task.agent.type) return AgentKind.NONE.value - async def run(self) -> EvaluationResult: # noqa: PLR0915 — pre-existing exception-handling ladder; the new TurnTimeoutError handler pushed it over the cap. Decomposing run()'s handler ladder is out of scope for this fix. + async def run(self) -> EvaluationResult: """Run the complete evaluation. Returns: @@ -549,47 +564,13 @@ def _kill_agent_subprocess_sync() -> None: # Re-raise cancellation to allow proper task cancellation raise except TaskTimeoutError as e: - self.result.error_message = str(e) - - self.result.error_details = create_error_context( - error=e, - task_id=self.task.task_id, - attempt=max(self.result.iteration_count, 1), - component="orchestrator.task_timeout", - agent_name=self._agent_name, - ) - - logger.error(f"Task timed out: {e}") - - # Recover the turn in flight when the watchdog killed the agent. - # Nothing else on this path does: the cancel arrives as a - # BaseException, so it never reaches the retry executor's - # per-attempt hook that drains the slot on a turn-level timeout. - await self._drain_killed_turn() - - # The kill was correct; discarding a real, complete result isn't. - # Grade whatever the agent produced before falling back to the - # dedicated TIMEOUT status (not generic ERROR). - await self._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + # drain: the task-level cancel arrives as a BaseException, so it + # never reaches the retry executor's per-attempt hook that + # salvages the in-flight turn. A TurnTimeoutError is already + # drained by _on_attempt_failure inside _communicate_with_retry. + await self._handle_forced_kill(e, component="orchestrator.task_timeout", drain=True) except TurnTimeoutError as e: - self.result.error_message = str(e) - - self.result.error_details = create_error_context( - error=e, - task_id=self.task.task_id, - attempt=max(self.result.iteration_count, 1), - component="orchestrator.turn_timeout", - agent_name=self._agent_name, - ) - - logger.error(f"Turn timed out: {e}") - - # No _drain_killed_turn() here: the partial turn for a - # TurnTimeoutError is already salvaged by - # _on_attempt_failure's _drain_pending_turn() inside - # _communicate_with_retry, which runs before this exception - # reaches run(). - await self._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + await self._handle_forced_kill(e, component="orchestrator.turn_timeout", drain=False) except BudgetExceededError as e: # Map token-budget breaches and cost-budget breaches to distinct # statuses so per-task records preserve the failure mode. @@ -653,13 +634,18 @@ def _kill_agent_subprocess_sync() -> None: type(e).__name__, e, ) + await self._await_pending_grade() await self._cleanup() # Capture the sanitised log tail AFTER teardown so any errors # logged during post-run / cleanup also land in the report, # but BEFORE _finalize_result so task.json includes the field. # Allowlist non-success terminal statuses; SUCCESS and # MAX_TURNS_EXHAUSTED skip the tail to keep task.json compact. - if self.result.final_status in { + # forced_kill is allowlisted independently of the status: such a + # run is graded after the kill and may finalize SUCCESS, and the + # tail is the only in-task.json evidence of the kill once + # error_message/error_details are cleared on that upgrade. + if self.result.forced_kill or self.result.final_status in { FinalStatus.ERROR, FinalStatus.TIMEOUT, FinalStatus.FAILURE, @@ -707,6 +693,32 @@ async def _drain_killed_turn(self) -> None: except Exception: logger.warning("[%s] Could not recover the hard-killed turn", self.task.task_id, exc_info=True) + async def _handle_forced_kill(self, e: TaskTimeoutError | TurnTimeoutError, *, component: str, drain: bool) -> None: + """Shared terminal handling for both structural-timeout exceptions. + + They differ only in the error-context ``component`` and whether the + in-flight turn still needs draining; everything else -- the message, the + log, and the salvage grading pass that finalizes SUCCESS or TIMEOUT -- + is identical, so it lives here once rather than as two near-copies in + ``run()``'s handler ladder. + """ + assert self.result is not None + self.result.error_message = str(e) + self.result.error_details = create_error_context( + error=e, + task_id=self.task.task_id, + attempt=max(self.result.iteration_count, 1), + component=component, + agent_name=self._agent_name, + ) + logger.error(f"{'Task' if drain else 'Turn'} timed out: {e}") + if drain: + await self._drain_killed_turn() + # The kill was correct; discarding a real, complete result isn't. Grade + # what the agent produced before falling back to the dedicated TIMEOUT + # status (not generic ERROR). + await self._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + async def _grade_after_forced_kill(self, *, fallback_status: FinalStatus) -> None: """Attempt success-criteria grading against whatever the agent produced before a forced-kill timeout, instead of unconditionally discarding it. @@ -746,6 +758,12 @@ async def _grade_after_forced_kill(self, *, fallback_status: FinalStatus) -> Non # the row would persist with the constructor default (FAILURE) while # error_message says the task timed out. self.result.final_status = fallback_status + # Durable, status-independent record that this run was hard-killed. + # final_status alone cannot carry it: the grading below may upgrade to + # SUCCESS, and consumers that key structural questions off the status + # (reports_experiment._cost_complete, telemetry, the error_log_tail + # allowlist) would then read a killed run as an ordinary clean one. + self.result.forced_kill = True # Quiesce the agent before reading the sandbox. On a TurnTimeoutError # the agent raised at its own internal deadline and NOTHING has stopped # the harness yet: the watchdog's kill_sync() is intent-only on @@ -756,10 +774,25 @@ async def _grade_after_forced_kill(self, *, fallback_status: FinalStatus) -> Non # into the sandbox while check_all_async reads it, making the verdict # nondeterministic in both directions. Best-effort and suppressed: # failing to quiesce is never a reason to skip grading. + # + # RESIDUAL (not closed by this): on Antigravity the harness backgrounds + # any command over ~10s -- that is why the poll loop exists -- and + # cancelling the conversation does not reap a detached shell job. So a + # criterion can still read a tree a backgrounded build is mutating. + # result.forced_kill marks such runs so a mid-write verdict is at least + # distinguishable from a settled one. if self.agent is not None: try: - await self.agent.kill() - except Exception: + # Bounded: kill() bottoms out in a cancel/teardown on the very + # connection that may be wedged, and run()'s watchdog has + # already exited by the time this runs, so nothing else would + # stop it hanging. Catch BaseException, not Exception: the + # task-timeout watchdog queues a task.cancel() and this is + # often the first real suspension point after the handler + # begins, so a CancelledError landing here must not skip the + # grading pass this quiesce exists to protect. + await asyncio.wait_for(self.agent.kill(), timeout=_QUIESCE_TIMEOUT_SECONDS) + except BaseException: # Warning, not debug: grading is about to read a sandbox that # may still be under a live agent's control, so a failed # quiesce is real context for an unexpected verdict. @@ -794,15 +827,28 @@ async def _grade_after_forced_kill(self, *, fallback_status: FinalStatus) -> Non task_file=self.task_file, cached_reference=self._reference_code, ) - criteria_results = await asyncio.wait_for( + # Shielded + tracked, NOT a bare wait_for. check_all_async offloads + # each criterion to asyncio.to_thread, which is NOT cancellable: on + # expiry the awaiting coroutine raises but the worker thread keeps + # running its criterion -- including a run_command criterion's + # subprocess inside the sandbox that run()'s finally is about to + # move or rmtree. SubAgentRunner documents and handles this exact + # hazard the same way. The shield lets the budget bound how long we + # WAIT for the verdict; _await_pending_grade (called before cleanup) + # bounds when the sandbox may be torn down. + grade = asyncio.ensure_future( self.success_checker.check_all_async( self.task.success_criteria, reference_code=reference_code, reference_dir=reference_dir, turn_records=self.result.iterations, - ), - timeout=_GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS, + ) + ) + self._pending_grade = grade + criteria_results = await asyncio.wait_for( + asyncio.shield(grade), timeout=_GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS ) + self._pending_grade = None # Fold this pass's judge slice into the dialog-wide total before # storing, so a mid-dialog forced kill doesn't drop the judge cost # of every earlier turn (no-op outside simulation: the accumulator @@ -835,6 +881,29 @@ async def _grade_after_forced_kill(self, *, fallback_status: FinalStatus) -> Non ) self.result.final_status = fallback_status + async def _await_pending_grade(self) -> None: + """Let an over-budget grading pass finish before the sandbox is torn down. + + ``_grade_after_forced_kill`` stops WAITING for the verdict at + ``_GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS``, but its criteria run on + ``asyncio.to_thread`` workers that a cancellation cannot stop. Deleting + or moving the sandbox out from under one is a real corruption risk (a + ``run_command`` criterion may still be writing), so wait here -- bounded + by the criteria's own timeouts -- before ``_cleanup()``. Best-effort: + never raises, and the late verdict is intentionally discarded, since the + status was already decided from the fallback. + """ + grade = self._pending_grade + if grade is None: + return + self._pending_grade = None + logger.warning( + "[%s] Waiting for an over-budget grading pass to finish before sandbox teardown", + self.task.task_id, + ) + with contextlib.suppress(Exception, asyncio.CancelledError): + await grade + def _log_graded_after_forced_kill(self, criteria_results: list[CriterionResult]) -> None: """Human-readable pass tally for ``_grade_after_forced_kill``. @@ -1795,6 +1864,11 @@ async def _evaluation_loop(self) -> bool: # gates strict-AND over every gating criterion, exactly like an unarmed # run — arming a criterion (e.g. adding a decide_within fail-fast # timeout) must never change the verdict of a run it didn't cut. + # Single source of the gate rule: _gate_passed. The per-branch logging + # stays here (it is about THIS loop's trajectory), but the decision + # itself must not be a second hand-maintained copy -- a FIRED-ONLY gate + # that drifted between the two call sites would be silently wrong. + all_passed = self._gate_passed() if self.result.early_stop is not None: # One gate for every early-stopped run, no per-reason branches: a # decision-budget stop is just a fail-stop whose deciding criterion @@ -1805,12 +1879,6 @@ async def _evaluation_loop(self) -> bool: # tool ends exactly like the agent's EventCollector does (see # EarlyStopWatcher._on_event_impl) — so the weighted armed gate is # correct whether the watcher fired on a pass, a fail, or a timeout. - gate_threshold = ( - self.task.run_limits.stop_early_gate_threshold - if self.task.run_limits is not None - else DEFAULT_STOP_EARLY_GATE_THRESHOLD - ) - all_passed = self.result.armed_criteria_passed(self.task.success_criteria, gate_threshold) armed_count = sum(1 for c in self.task.success_criteria if c.is_stop_armed) logger.info( "Early-stopped run (%s): gating on %d armed criteria (%d advisory, not gated).", @@ -1818,13 +1886,11 @@ async def _evaluation_loop(self) -> bool: armed_count, total_count - armed_count, ) - else: - if self._early_stop_watcher is not None: - if self._early_stop_watcher.disarmed: - logger.info("early-stop watcher disarmed fail-open (verdict error): gating on the full set.") - else: - logger.info("early-stop armed but never fired (run completed naturally): gating on the full set.") - all_passed = self.result.all_criteria_passed(self.task.success_criteria) + elif self._early_stop_watcher is not None: + if self._early_stop_watcher.disarmed: + logger.info("early-stop watcher disarmed fail-open (verdict error): gating on the full set.") + else: + logger.info("early-stop armed but never fired (run completed naturally): gating on the full set.") # Reuse the model method for weighted score (single source of truth) self.result.calculate_weighted_score(self.task.success_criteria) diff --git a/src/coder_eval/reports_experiment.py b/src/coder_eval/reports_experiment.py index e141174b..a66553c5 100644 --- a/src/coder_eval/reports_experiment.py +++ b/src/coder_eval/reports_experiment.py @@ -53,15 +53,18 @@ def _cost_complete(result: EvaluationResult) -> bool: 1. A turn burned tokens the rate card could not price. The card is the fallback for anything the backend did not price itself, so with no rate those tokens book no money. - 2. The task was hard-killed by the task-level timeout. Keyed on the status - rather than on emptiness: the watchdog fires while the evaluation loop is - running, so a TIMEOUT row always lost an in-flight turn, even one that - completed earlier turns that do carry costs. + 2. The task was hard-killed by a structural timeout. Keyed on the durable + ``forced_kill`` flag rather than on the status or on emptiness: the + watchdog fires while the evaluation loop is running, so a hard-killed row + always lost an in-flight turn, even one that completed earlier turns that + do carry costs. NOT keyed on ``final_status is TIMEOUT`` -- such a run is + graded after the kill and can finalize SUCCESS, which would silently flip + this flag to True for exactly the rows it is meant to catch. True for a row that burned nothing: an error before the agent ran genuinely cost zero, and a slow setup failure is as free as a fast one. """ - if result.final_status is FinalStatus.TIMEOUT: + if result.forced_kill or result.final_status is FinalStatus.TIMEOUT: return False return all( usage.total_cost_usd is not None @@ -194,6 +197,10 @@ def eval_result_to_task_dict( "sdk_options": result.sdk_options, "installed_tools": result.environment_info.get("installed_tools"), "max_turns_exhausted": result.max_turns_exhausted, + # Structural-breach marker kept beside the status: a hard-killed run is + # graded after the kill and may serialize as SUCCESS, so consumers need + # this to answer "did this task blow its timeout?" at all. + "forced_kill": result.forced_kill, "expected_turns_overage": list(overage) if overage is not None else None, "total_turns": total_turns, # Documented "visible turns" (tool calls + final reply) — the canonical diff --git a/tasks/smoke_task_timeout.yaml b/tasks/smoke_task_timeout.yaml index 0fb6a3e3..6c93fdc0 100644 --- a/tasks/smoke_task_timeout.yaml +++ b/tasks/smoke_task_timeout.yaml @@ -26,10 +26,12 @@ agent: allowed_tools: ["Bash"] success_criteria: - # If the orchestrator's task_timeout watchdog fires, this criterion never - # runs (sandbox never reaches the check phase). The bucket-level assertion - # in CI checks tasks_failed == EXPECTED_SMOKE_FAIL_FAILED to verify the - # task is counted as a failure (not a success or an error). + # The task_timeout watchdog fires, and the orchestrator then GRADES what the + # agent produced (see _grade_after_forced_kill) rather than discarding it -- + # so this criterion IS evaluated. It fails because the file never exists, + # which is what keeps the task in the failed bucket. The bucket-level + # assertion in CI checks tasks_failed == EXPECTED_SMOKE_FAIL_FAILED to verify + # the task is counted as a failure (not a success or an error). - type: "file_exists" path: "should_never_be_checked.txt" - description: "Placeholder; task_timeout fires before the criterion is evaluated." + description: "Never created, so grading after the forced kill fails and the task stays in the failed bucket." diff --git a/tests/lint/rules/ce022_dialog_loop_statement_cap.py b/tests/lint/rules/ce022_dialog_loop_statement_cap.py index 03bca68f..6d276c72 100644 --- a/tests/lint/rules/ce022_dialog_loop_statement_cap.py +++ b/tests/lint/rules/ce022_dialog_loop_statement_cap.py @@ -21,9 +21,6 @@ - ``orchestrator.py::_simulation_dialog_loop`` (cap 128; 122 CE022-stmts ≙ 124 ruff-stmts) — sequential dialog driver, irreducible without a state-object rewrite (2026-06-23 decompose-god-functions plan, Phase 5). -- ``orchestrator.py::run`` (cap 76; 70 CE022-stmts ≙ 86 ruff-stmts) — the - exception-handling ladder around the evaluation loop; the - forced-kill-grading fix (2026-08-14) pushed it over ruff's ceiling. - ``antigravity_agent.py::communicate`` (cap 81; 77 CE022-stmts ≙ 82 ruff-stmts) — the poll-loop-plus-finalize driver; the ``step_fetch_timed_out`` post-loop branch (2026-08-14) pushed it over @@ -66,7 +63,6 @@ class NoqaPlr0915StatementCap(BaseRule): # sibling like ``x_orchestrator.py`` can't accidentally match. _TARGETS: tuple[tuple[str, str, int], ...] = ( ("orchestrator.py", "_simulation_dialog_loop", 128), - ("orchestrator.py", "run", 76), ("antigravity_agent.py", "communicate", 81), ) diff --git a/tests/test_antigravity_agent.py b/tests/test_antigravity_agent.py index 4054f435..a522e09c 100644 --- a/tests/test_antigravity_agent.py +++ b/tests/test_antigravity_agent.py @@ -881,17 +881,26 @@ async def _record_sleep(seconds: float) -> None: async def test_communicate_stops_polling_at_max_poll_cap(monkeypatch): - """A pathological, never-closing background job must not poll forever -- - the hard _MAX_BACKGROUND_POLLS cap bounds it independent of the turn budget.""" + """A pathological, never-closing background job must not poll forever. + + With no configured turn_timeout the flat _MAX_BACKGROUND_POLL_WALL_SECONDS + backstop is the sole bound (a parallel cycle cap was removed: it overrode + large configured timeouts and bounded nothing the deadline didn't). Drive + it with a fake clock that only the poll sleeps advance, so the assertion is + on the real exit condition rather than on a cycle count. + """ from coder_eval.agents import antigravity_agent - monkeypatch.setattr(antigravity_agent, "_MAX_BACKGROUND_POLLS", 3) + monkeypatch.setattr(antigravity_agent, "_MAX_BACKGROUND_POLL_WALL_SECONDS", 15.0) sleep_calls: list[float] = [] + fake_now = [0.0] async def _record_sleep(seconds: float) -> None: sleep_calls.append(seconds) + fake_now[0] += seconds monkeypatch.setattr(antigravity_agent.asyncio, "sleep", _record_sleep) + monkeypatch.setattr(antigravity_agent.time, "monotonic", lambda: fake_now[0]) never_closing = [ _step( @@ -908,7 +917,8 @@ async def _record_sleep(seconds: float) -> None: agent = _agent_with_steps([never_closing]) tr = await agent.communicate("do it forever") - assert len(sleep_calls) == 3 # exactly _MAX_BACKGROUND_POLLS, not infinite + # 15s budget / 5s per cycle = 3 cycles, then the deadline stops it. + assert len(sleep_calls) == 3 bash = next(c for c in tr.commands if c.tool_name == "Bash") assert bash.result_status == "unknown" # force-closed as UNRESOLVED by finalize() @@ -919,7 +929,7 @@ async def test_communicate_finalizes_gracefully_under_a_realistic_turn_timeout(m the poll loop's own graceful path -- force-close the orphan, grade normally -- instead of the ThreadedWatchdog cutting the whole turn at `timeout` first. - Pre-fix, `_MAX_BACKGROUND_POLLS * _BACKGROUND_POLL_INTERVAL_SECONDS` (120 * + Pre-fix, the poll budget (120 * 5s = 600s) was DOUBLE the 300s default, so the watchdog always won that race and this exact scenario -- a tool call spuriously left ACTIVE with no real background job behind it, confirmed live in the final validation run -- burned @@ -984,12 +994,12 @@ def __exit__(self, *_exc): async def test_communicate_poll_loop_exits_promptly_once_watchdog_flag_lands(monkeypatch): """A watchdog timeout landing BETWEEN poll cycles (state.timeout_hit flips to True while the loop is sleeping) must stop the loop on its next condition - check, not burn through the rest of _MAX_BACKGROUND_POLLS waiting for a + check, not burn through the rest of the poll budget waiting for a cancellation that may not land on this coroutine right away (final-review finding: the loop condition must read the flag the watchdog already set).""" from coder_eval.agents import antigravity_agent - monkeypatch.setattr(antigravity_agent, "_MAX_BACKGROUND_POLLS", 50) + monkeypatch.setattr(antigravity_agent, "_MAX_BACKGROUND_POLL_WALL_SECONDS", 250.0) monkeypatch.setattr("coder_eval.agents.antigravity_agent.ThreadedWatchdog", _WatchdogFiresLater) sleep_calls: list[float] = [] @@ -1810,7 +1820,7 @@ async def test_communicate_raises_timeout_when_connection_never_produces_a_singl from coder_eval.errors import TurnTimeoutError monkeypatch.setattr(antigravity_agent, "_RECEIVE_STEPS_PER_STEP_TIMEOUT_SECONDS", 0.01) - monkeypatch.setattr(antigravity_agent, "_MAX_BACKGROUND_POLLS", 2) + monkeypatch.setattr(antigravity_agent, "_MAX_BACKGROUND_POLL_WALL_SECONDS", 0.05) monkeypatch.setattr(antigravity_agent.asyncio, "sleep", _no_sleep) conversation = _AlwaysEmptyConversation() @@ -1838,7 +1848,7 @@ def test_per_step_timeout_is_not_aliased_to_the_poll_interval(): revision did this) meant any ordinary foreground tool call or thinking burst lasting longer than the poll interval (5s) got misclassified as "looks orphaned", feeding false step_fetch_timed_out cycles into - poll_deadline/_MAX_BACKGROUND_POLLS and materially shrinking the usable + poll_deadline and materially shrinking the usable turn budget for completely normal work. The two constants measure different things (how often to re-check an idle connection vs. how long a genuinely in-progress step-fetch may go quiet) and must be tuned @@ -1888,15 +1898,9 @@ def test_background_poll_budget_still_covers_the_worst_observed_backgrounded_job # this budget is actually achievable rather than being eaten by whatever # the turn already spent. assert antigravity_agent._MAX_BACKGROUND_POLL_WALL_SECONDS >= _WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS - # The cycle cap must not be the tighter of the two on that path, or it - # silently becomes the real budget (17 * 5s = 85s was exactly that bug). - empty_poll_budget_seconds = ( - antigravity_agent._MAX_BACKGROUND_POLLS * antigravity_agent._BACKGROUND_POLL_INTERVAL_SECONDS - ) - assert empty_poll_budget_seconds >= _WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS, ( - f"empty-poll budget is {empty_poll_budget_seconds:g}s, below the " - f"{_WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS:g}s worst observed backgrounded job" - ) + # ...and that budget must buy enough 5s idle cycles to outlast the job. + cycles = antigravity_agent._MAX_BACKGROUND_POLL_WALL_SECONDS / antigravity_agent._BACKGROUND_POLL_INTERVAL_SECONDS + assert cycles >= _WORST_OBSERVED_BACKGROUNDED_JOB_SECONDS / antigravity_agent._BACKGROUND_POLL_INTERVAL_SECONDS # Configured-timeout path: document the achievable budget at the repo # default. This asserts the CURRENT limitation, so raising the default (or diff --git a/tests/test_custom_lint.py b/tests/test_custom_lint.py index 25c69aa6..a199edcc 100644 --- a/tests/test_custom_lint.py +++ b/tests/test_custom_lint.py @@ -439,13 +439,6 @@ def test_flags_oversized_sync_dialog_loop(self): src = f"def _simulation_dialog_loop(self, initial_prompt, sandbox_dir):\n{body}" assert len(self._run(src)) == 1 - def test_flags_oversized_run(self): - """orchestrator.py::run is a registered target too (added by the - forced-kill-grading fix's # noqa: PLR0915).""" - violations = self._run(self._padded_loop("run", 200)) - assert len(violations) == 1 - assert violations[0].rule_id == "CE022" - def test_flags_oversized_communicate_in_antigravity_agent(self): """antigravity_agent.py::communicate is a registered target too (added by the step_fetch_timed_out post-loop branch's # noqa: PLR0915).""" @@ -453,9 +446,9 @@ def test_flags_oversized_communicate_in_antigravity_agent(self): assert len(violations) == 1 assert violations[0].rule_id == "CE022" - def test_ignores_run_outside_orchestrator(self): - """A same-named `run` in a different file is not a registered target.""" - assert not self._run(self._padded_loop("run", 200), path="src/coder_eval/other.py") + def test_ignores_communicate_outside_its_registered_file(self): + """A same-named `communicate` in a different file is not a target.""" + assert not self._run(self._padded_loop("communicate", 200), path="src/coder_eval/other.py") def test_flags_an_unregistered_noqa_plr0915(self, tmp_path): """The "register your new noqa in _TARGETS" contract is self-enforcing. @@ -489,7 +482,7 @@ def test_does_not_flag_a_registered_noqa_or_an_unsuppressed_function(self, tmp_p from tests.lint.rules.ce022_dialog_loop_statement_cap import NoqaPlr0915StatementCap - registered = "def run(self): # noqa: PLR0915\n x = 1\n" + registered = "def _simulation_dialog_loop(self): # noqa: PLR0915\n x = 1\n" f = tmp_path / "orchestrator.py" f.write_text(registered) assert not _with_source(NoqaPlr0915StatementCap(str(f)), registered).check(ast.parse(registered)) diff --git a/tests/test_timeout_orchestrator.py b/tests/test_timeout_orchestrator.py index 6baf80c9..2e82f0eb 100644 --- a/tests/test_timeout_orchestrator.py +++ b/tests/test_timeout_orchestrator.py @@ -754,6 +754,76 @@ async def test_grade_after_forced_kill_skips_regrade_when_already_graded(tmp_pat assert orchestrator.result.error_message is None +@pytest.mark.asyncio +async def test_over_budget_grading_is_awaited_before_sandbox_teardown(tmp_path) -> None: + """Regression test (code-review finding): the 60s grading budget must not + let a live criterion race sandbox cleanup. + + check_all_async offloads each criterion to asyncio.to_thread, which is NOT + cancellable -- on expiry the awaiting coroutine raises but the worker keeps + running, and a run_command criterion's subprocess would still be writing + into the directory run()'s finally is about to move or rmtree. + """ + from coder_eval import orchestrator as orchestrator_module + + monkeypatch_budget = 0.05 + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + finished: list[str] = [] + + async def slow_check_all_async(*args, **kwargs): + await asyncio.sleep(0.3) + finished.append("criteria-done") + return [CriterionResult(criterion_type="file_exists", description="x", score=1.0)] + + orchestrator.success_checker.check_all_async = slow_check_all_async # type: ignore[union-attr] + + with ( + patch.object(orchestrator_module, "_GRADE_AFTER_FORCED_KILL_TIMEOUT_SECONDS", monkeypatch_budget), + patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)), + ): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + # Budget expired, so the verdict fell back... + assert orchestrator.result.final_status == FinalStatus.TIMEOUT + assert finished == [] + # ...but the criterion is still running and must be drained first. + assert orchestrator._pending_grade is not None + await orchestrator._await_pending_grade() + + assert finished == ["criteria-done"] + assert orchestrator._pending_grade is None + + +@pytest.mark.asyncio +async def test_grade_after_forced_kill_marks_the_run_even_when_it_upgrades_to_success(tmp_path) -> None: + """Regression test (code-review finding): a hard-killed run must stay + identifiable after the status upgrade. + + Once grading can turn a TIMEOUT into SUCCESS, `final_status` is no longer a + usable proxy for "this run blew its structural budget". Consumers key real + decisions off that question -- `reports_experiment._cost_complete` returns + False for a hard kill because the in-flight turn's spend was lost, the + error_log_tail allowlist keeps the only evidence of the kill, and telemetry + needs to count breaches. All of them read `forced_kill`, which must survive + the upgrade. + """ + from coder_eval.reports_experiment import _cost_complete + + task = _make_task() + orchestrator = _make_initialized_orchestrator(task, tmp_path) + orchestrator.success_checker.check_all_async = AsyncMock( # type: ignore[union-attr] + return_value=[CriterionResult(criterion_type="file_exists", description="x", score=1.0)] + ) + + with patch("coder_eval.orchestrator.load_reference", return_value=(None, None, None)): + await orchestrator._grade_after_forced_kill(fallback_status=FinalStatus.TIMEOUT) + + assert orchestrator.result.final_status == FinalStatus.SUCCESS + assert orchestrator.result.forced_kill is True + # ...and the cost-completeness contract still holds despite the SUCCESS. + assert _cost_complete(orchestrator.result) is False + + @pytest.mark.asyncio async def test_grade_after_forced_kill_keeps_the_fallback_status_when_grading_is_cancelled(tmp_path) -> None: """Regression test (code-review finding): a BaseException during grading From d720719addd6ee8a9d1545cb316bab53306c6340 Mon Sep 17 00:00:00 2001 From: joeysbase Date: Sat, 15 Aug 2026 00:06:14 +0000 Subject: [PATCH 3/3] fix(orchestrator): don't swallow CancelledError in the pre-grading quiesce CodeQL flagged the except BaseException added in the last round, and it was right: swallowing CancelledError there meant a batch shutdown or Ctrl-C arriving at the quiesce was ignored, and the run went on to spend up to 60s grading after being told to stop. Exception is the correct width. The earlier reasoning for BaseException -- that a queued task.cancel must not skip the grading pass -- had the trade backwards: fallback_status is committed before any await, so propagating leaves the row correct and skipping a best-effort grade is exactly what cancellation means. The sibling suppression in _await_pending_grade keeps CancelledError, and now says why: it runs inside run()'s teardown, which this file already establishes must be interrupt-proof, and aborting it would both leak the sandbox and abandon the worker thread it exists to wait for. Co-Authored-By: Claude Opus 5 --- src/coder_eval/orchestrator.py | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-) diff --git a/src/coder_eval/orchestrator.py b/src/coder_eval/orchestrator.py index 736161bb..28856025 100644 --- a/src/coder_eval/orchestrator.py +++ b/src/coder_eval/orchestrator.py @@ -786,13 +786,17 @@ async def _grade_after_forced_kill(self, *, fallback_status: FinalStatus) -> Non # Bounded: kill() bottoms out in a cancel/teardown on the very # connection that may be wedged, and run()'s watchdog has # already exited by the time this runs, so nothing else would - # stop it hanging. Catch BaseException, not Exception: the - # task-timeout watchdog queues a task.cancel() and this is - # often the first real suspension point after the handler - # begins, so a CancelledError landing here must not skip the - # grading pass this quiesce exists to protect. + # stop it hanging. + # + # Exception, NOT BaseException: a CancelledError here means the + # runtime asked this task to stop (batch shutdown, Ctrl-C), and + # swallowing it would run a 60s grading pass after being told to + # quit. Letting it propagate is safe precisely because + # fallback_status is already committed above, before any await -- + # bailing out leaves the row correct, and skipping a best-effort + # grade is what cancellation is supposed to mean. await asyncio.wait_for(self.agent.kill(), timeout=_QUIESCE_TIMEOUT_SECONDS) - except BaseException: + except Exception: # Warning, not debug: grading is about to read a sandbox that # may still be under a live agent's control, so a failed # quiesce is real context for an unexpected verdict. @@ -901,6 +905,13 @@ async def _await_pending_grade(self) -> None: "[%s] Waiting for an over-budget grading pass to finish before sandbox teardown", self.task.task_id, ) + # CancelledError IS suppressed here, unlike the quiesce above: this runs + # inside run()'s teardown, which the file already establishes must be + # interrupt-proof (see the teardown_interrupt handling in run()) -- + # aborting here would skip _cleanup() and leak the sandbox, and would + # also abandon the very thread we are waiting for. The awaited result is + # deliberately discarded: the status was decided from the fallback, and + # this await exists purely to order teardown after the worker thread. with contextlib.suppress(Exception, asyncio.CancelledError): await grade