diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index 5eef1adc..2bc1fbbd 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -551,3 +551,126 @@ divergences, so the deferred-work record is one place. Measurements in candidate — a real bug needing its own change, with a decision about whether legacy records can be distinguished from current ones at all. Caught in: timing-capture final review (gpt-5.6-sol). + +- [x] ~~No golden-corpus assertion of the four-bucket identity.~~ **DONE.** The + fixture clocks were unified (`_rebase_notifications` / `_rebase_lines` shift + codex's 2027 base and opencode's month-old base onto the replay's own clock, + keeping every derived duration exact) and `assert_timing_captured` now + asserts `Σ generation + ∪ tool + head + tail` against `duration_seconds`. + Mutation-verified: reintroducing the defect fails + `test_antigravity_golden[d_orphaned_tool]`, which previously passed. + 22 of 27 scenarios are checked. The remaining 5 are exempt via + `FICTIONAL_DURATIONS` for a reason rebasing cannot fix: they inject SDK + stamps in integer MILLISECONDS (17-900 ms of declared item time) while the + replay runs in well under one, so closing that last gap needs the agent's + own clock faked, not the fixtures' rebased. + +- [ ] **No TypeScript counterpart to CE058.** `evalboard/lib/runs.ts` and + `_sections.tsx` carry the same None-vs-0 contract as the Python side, and + `sumMeasured` implements it correctly, but nothing stops the next author + writing `?? 0` where an unmeasured value must stay null. Not a simple lint + rule: the residual arithmetic in `_sections.tsx` uses `?? 0` *correctly* + (subtract only what was measured), so a blanket ban fires on right code and + the rule needs a way to tell "publishing a value" from "consuming one". + Caught in: turn head/tail timing final review. + +- [ ] **`timing.py::decompose_turn` raises an uncaught `TypeError` on a + naive/aware datetime mix**, straight out of `EventCollector.build_turn_record`, + killing the turn. Unreachable today — every stamp in `agents/` and + `streaming/` is a naive `datetime.now()` (verified by grep: zero hits for + `timezone.utc` / `utcnow` / `astimezone`) — but nothing pins that invariant, + so the first agent to record an aware stamp discovers it at runtime. + Caught in: turn head/tail timing final review. + +- [x] ~~**`claude-code` does not subtract tool execution from its generation + windows.**~~ **FIXED** in `_ClaudeTurnState._subtract_tool_time_from_windows`, + which runs at finalization (it cannot run at flush time — a tool issued by an + earlier emission is still running when the next window closes). Re-measured + on the same task: 481 ms / 2.691% -> **1.4 ms / 0.006%** over four turns that + all carried overlapping tool calls. Original report kept below for the + reasoning. + + ORIGINAL: The other four + harnesses subtract the union (`timing.py::busy_ms`); claude-code is exempted + on the reasoning that it "marks the end of the previous SDK event and reads + again when the next message arrives, so a tool's execution falls between two + windows rather than inside one". But a tool's timer starts at the **emission** + carrying its `tool_use` block, and one assistant turn spans several emissions, + so a later emission's window runs concurrently with a tool already timing. + Measured live on a task with five parallel writes, five reads and two + concurrent `Bash` calls: the generation/tool overlap was **482 ms and 340 ms** + on two ~18-25 s turns, and the four-bucket residual came out at exactly + `-481 ms` / `-339 ms` — the overlap accounts for it to within 1.4 ms. The + other four harnesses overlapped by ~2.0-2.3 s on the same task and reconciled + to within 1.2 ms. Two claude-code turns with <1 ms of overlap reconciled to + within 0.1 ms, so the fault is precisely the missing subtraction. + Fix is to apply `busy_ms` in `on_assistant_message` as the other four do, but + it changes a PUBLISHED `generation_duration_ms` on the most-used harness, so + it needs its own golden regeneration and live pass. NOT introduced by the + head/tail work — generation-vs-tool timing predates it — but that work's + four-bucket identity is what made it visible. + Caught in: post-merge live verification of the head/tail buckets. + +### Deferred lint-rule widenings + +- [ ] **CE058 and CE059 still match `AssistantMessage` by a hardcoded constructor + NAME LIST** (`_MESSAGE_CONSTRUCTORS`), where CE060 derives the set from each + module's own `coder_eval.models` imports. The weakness is live, not + theoretical: `claude_code_agent.py` binds *only* + `AssistantMessage as AssistantMessageTelemetry` and never the bare name, so + the two shipped rules guard that file's two construction sites purely because + somebody wrote the current alias into a different file's frozenset — rename + the alias and both go silently blind there — and an arbitrary + `AssistantMessage as Msg` is missed outright by both. Adopting CE060's + alias-resolving `check()` pre-pass is about ten lines per rule, but it widens + two SHIPPED rules whose firing sets are load-bearing (CE058's constructor set + is a different, wider one: `CommandTelemetry`, `SlowestCommandInfo`, + `TurnRecord`), so it needs its own mutation check per rule and a re-measured + firing set over all of `src/`, not a drive-by edit. If a fourth same-scope + kwarg rule ever lands, extract `tests/lint/rules/_message_calls.py` at that + point rather than sooner. + Caught in: the CE060 / antigravity `message_id` run. + +- [ ] **Nothing pins that `message_id` is only ever a WITHIN-TURN identity.** Ids + repeat across retry attempts of one turn on every synthetic-id harness — + `Agent.discard_pending_turn` rolls the iteration counter back, so a crashed + partial and its retry both emit `-1-msg-0` (antigravity, codex, and + the out-of-tree delegate agent alike). Harmless today, and verified so: the + evalboard declares its grouping list INSIDE the per-turn loop + (`runs.ts:1822`, flushed at `:2217`) and only ever compares adjacent raws, and + no Python consumer reads the field at all. It stops being harmless the moment + anything joins on the id run-wide (a React key across turns, a cost join, a + dedup) — which is a natural thing to reach for once every harness populates + it. No cheap guard exists: the property to assert is "no consumer treats this + as run-unique", which is a negative over two languages, and asserting + within-turn uniqueness instead would pass today and catch nothing. Cheapest + real option is a comment on the model field; the durable one is a run-level + id if a consumer ever needs one. + Caught in: the CE060 / antigravity `message_id` final review. + +- [ ] **No evalboard test is fed by a Python golden snapshot.** The two halves of + a capture fix are pinned by two hand-written fixtures that never meet: the + golden (`tests/_fixtures/golden_streams/expected/antigravity_e_multi_generation.json`) + pins what the reducer emits, and `evalboard/lib/__tests__/parseMessages.test.ts` + pins what the consumer does with a fixture an author typed from the same + understanding. Nothing feeds a real recorded shape through `parseMessages`, so + a reducer change that makes the TS fixture unrepresentative breaks no test on + either side. Deferred as architectural: it needs a loader, a scrub-aware + timestamp story (the goldens mask exactly the stamps the grouping reads), and + a convention for which snapshots the JS suite owns — well over 30 min, and + wider than any one capture fix. + Caught in: the CE060 / antigravity `message_id` final review. + +- [ ] **`AssistantMessage.message_id`'s field description names one harness of + five** (`models/telemetry.py:283`: "Anthropic API message_id … when the Claude + Code CLI splits one API response"). Five backends now write the field and four + synthesize it, so `docs/agents/HARNESS_PARITY.md`'s new row is the real SSOT + while the model — which this project's DRY principle designates as + authoritative — describes claude-code only. Not fixed here because the plan + scoped out every model change (the field already existed, so touching it would + have put a schema file in a golden-regeneration diff for prose). No mechanical + guard is obvious either: "a field description must not name a single harness + when the union has five writers" needs a writer census per field, which is + CE054-shaped but over a `str` description rather than a key. The cheap version + is to fix the sentence in the next change that touches the model. + Caught in: the CE060 / antigravity `message_id` final review. diff --git a/CLAUDE.md b/CLAUDE.md index 616945b8..6bf3bc52 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -236,7 +236,7 @@ make plugin-reference # the plugin's bundled criteria reference from the models Editing `src/coder_eval/pricing.py` means editing `evalboard/lib/pricing.ts` too — it is a hand-copied mirror, and `evalboard/lib/__tests__/pricing-parity.test.ts` fails the build on drift in either direction. -Recent additions, each traceable to a shipped defect: **CE058** (in `src/coder_eval/`, an unknown timing value may not become a numeric literal — `duration_ms is None` means *never timed* and `0.0` means *timed and instant*, so writing the literal publishes the second while meaning the first. One invariant, one id, five syntactic forms — a zero constructor keyword, `x or 0`, `x if x is not None else 0.0`, `if x.duration_ms is None: x.duration_ms = 0.0`, and a `model_copy(update={...})` dict (the shape the Antigravity DONE path writes through, which a keyword-only rule cannot see). Antigravity constructed EVERY message with `generation_duration_ms=0.0`, so the task page's Generation cell read `0ms` and its breakdown rendered `0%` for months with nothing failing; Codex published the SDK's `0.0` as a measured command duration, so `avg_command_time_ms` divided real milliseconds by a command count of which 70 of 211 in one nightly had never been timed. The fourth form is the one no existing rule shape covered and is where a live instance was hiding — `claude_code_agent._finalize_commands` set `0.0` on every command force-closed without a tool result, in the one harness a timing audit had called healthy. BLIND SPOT, stated in the rule's docstring: form 1 keys on the callee's spelling, so renaming the `AssistantMessageTelemetry` import alias silently disarms it there), **CE059** (in `src/coder_eval/agents/`, an `AssistantMessage` may not receive the same `ast.Name` for both `started_at` and `completed_at` — the Antigravity reducer read `datetime.now()` once and passed it as both bounds, so `started_at == completed_at` on 368 of 368 sampled messages. A separate id from CE058 because it is a separate invariant, a zero-length window whatever the duration field says, and one invariant per id is what makes a `# noqa` mean one thing. It does NOT fire when the same call passes `generation_duration_ms=None`: a call that says, in the field built to say it, that no window was measurable is not claiming one — that exemption is what keeps the rule pointed at the misleading case instead of accumulating four permanent suppressions on the rollout-rebuild and sub-agent-synthesis sites), **CE056** (no bare `CODER_EVAL_IN_CONTAINER` literal outside `models/container_paths.py` — the CE053 shape again: a rename-safety constant that shipped beside the literal it replaced, and the straggler was the single WRITER, so a rename would have disarmed four security/correctness gates at once with nothing failing; CE052 cannot catch it because that rule inspects `if` guards and the writer is not one), **CE055** (a criterion `path:` in `tasks/` must be sandbox-relative — an absolute path is joined onto the sandbox root, which DISCARDS the root, so containment refuses it and the criterion can never match whatever the agent does; two in-tree tasks were broken this way and the pair is the argument for a static rule on top of the runtime `CheckerMisuseError`: `byod_smoke_test` IS in a CI bucket and produced only `Results: 7/8 succeeded` plus a gating 0.0 reading "file does not exist" for a file that existed, while `dockerfile_build_example` is in NO bucket, so nothing ran it and no runtime guard was ever reached — the fix is never to relax containment but to say what the criterion means, `run_command: test -f /opt/marker`, a claim about the container IMAGE rather than about the agent's workspace), **CE054** (an `environment_info` key that is READ must be WRITTEN somewhere in `src/` — the bag is `dict[str, Any]`, so nothing connects reader to writer, and the `reference_digest` anti-cheat guard shipped as a read with no writer anywhere: `.get()` returned `None`, the guard took its early return, and CLAUDE.md plus the user guide both described it as protection it never provided), **CE048** (never call a Typer command function in process — its parameter defaults are `OptionInfo` sentinels, not values, and the sentinel is TRUTHY, so `in_place=None` silently selected the wrong branch; the fix is the `run_pipeline` / `run_evaluation` / `run_plan` split, and this rule is the one that also scans `tests/`, since that is the only place the defect occurs), **CE049** (never coalesce a possibly-unmeasured score to a numeric literal — `score or 0.0` publishes "measured and scored zero" while meaning "never measured", which is how an ungraded night reached four unfiltered `avg(Score)` dashboards as a real zero), **CE050** (no untyped `getattr` probe for a discriminated-union field — pyright cannot see the string, so a rename degrades the guard to a permanent no-op; scoped to criterion-shaped receivers because `command`/`tool`/`prompt` are far too common to flag on their own), **CE051** (a sandbox driver may not be rewritten silently — the driver IS the isolation boundary, so a downgrade must be an explicit, stamped, operator-visible decision), **CE053** (no bare run-record or run-LOG filename literal outside `path_utils` — widened to `docker.log` / `grade.docker.log` / `task.log` / `grade.log` after the same shape recurred: `docker.log` was produced in `isolation/` and consumed in `orchestration/` as three unrelated literals, and because the consumer guards its copy with `is_file()`, a rename would have silently discarded the only record of why a grading container failed — `TASK_JSON_FILENAME` shipped with a rename-safety rationale while twelve exact literals stayed unmigrated, including all three `rglob("task.json")` sites the constant's own comment cites as its reason to exist, so it created the second source of truth it argues against), **CE052** (an `os._exit` must sit inside a branch testing `CODER_EVAL_IN_CONTAINER` — it is the right primitive only for reaping the container's own disposable main process, and `run_task_internal_command` armed its heartbeat watchdog, a daemon thread whose whole authority is `os._exit(137)`, unconditionally: a test that invoked the command in-process left the pytest worker holding that thread, which exited the worker 40s later inside an unrelated test file, naming a different test on each run and on each platform with no traceback — and the dead worker's lost coverage data then failed the gate as `65.13 < 80.00`, naming neither the test nor the cause), **CE037** (no unreferenced module-level private helper in `src/` — a helper whose docstring documents a bug the live code still has is worse than none), **CE038** (in an `@asynccontextmanager`, the acquire must sit INSIDE the `try` whose `finally` releases it — `asyncio.shield` protects the inner task, NOT the await, so a cancel on `__aenter__` skips the unwind while the work completes), **CE039** (a criterion checker must not return a gating `score=0.0` from an `except OSError` over a path the *task author* named — that books an eval-config error as an agent failure; raise `CheckerMisuseError` instead, and `# noqa: CE039` the cases that really are the agent's), **CE047** (every onboarding/marketing surface — README, `docs/index.md`, `docs/comparison.md`, `docs/llms.txt`, `mkdocs.yml`'s `site_description`, the Pages stub, and pyproject's `description`/`keywords` — must name every built-in `AgentKind`; OpenCode shipped while four of those seven still listed three harnesses, and nothing failed), **CE057** (a module copied into the recorder directory beside a generated sandbox shim — `models.sandbox.SIDECAR_MODULES`, currently `argv_match.py` — may import stdlib only. The failure is silent: the sidecar runs where `coder_eval` and its dependencies are not installed, so one package import makes every shadowed CLI die with an ImportError the agent reads as "the tool is broken", costing a whole run to diagnose. The rule derives its target set from that exported tuple and a test asserts it matches a file that exists — a lint rule guarding zero files must fail, not pass). +Recent additions, each traceable to a shipped defect: **CE060** (in `src/coder_eval/agents/`, every `AssistantMessage(...)` must pass `message_id` explicitly — an identity invariant, which is why it is its own id rather than a second arm of CE058/CE059, both of which are about timing. Antigravity omitted the kwarg, so the field defaulted to `None` on every message it ever recorded, and the evalboard — which groups assistant emissions by `message_id` and falls back to a `SAME_EMISSION_GAP_MS` wall-clock gap when either side lacks one — collapsed a whole turn's generations into ONE timeline row as soon as the harness's generation windows became contiguous (the gap is then exactly 0 ms, always). Nothing failed: the consumer SUMS the group, so the totals and the reconciliation invariant stayed right, and the golden snapshots had ratified the `null` on the day they were written — a snapshot is regenerated from whatever the code currently does, so it catches a later change and never an initial omission. The damage was not confined to the timeline, which is why "only granularity is lost" was the wrong way to describe it: a grouped emission is one API call to the evalboard's thinking-cost simulator, whose prompt-cache cascade is quadratic in that count, so a single-shot Antigravity run had every cascade coefficient pinned at zero; the `Messages` count and the 10 s slow-generation bar were per-turn too. Unlike its two siblings it **derives its constructor set from each module's own `coder_eval.models` imports** instead of hardcoding the spelling, which closes exactly the blind spot CE058's clause below concedes: `claude_code_agent.py` binds only `AssistantMessage as AssistantMessageTelemetry`, so a name list guards that file's two construction sites purely by coincidence, and an arbitrary `as Msg` is missed outright. Widening CE058/CE059 the same way is recorded in `.claude/harness-candidates.md`. BLIND SPOT, in the rule's docstring: the runtime `None` — the kwarg must be PRESENT, not statically non-`None`, because OpenCode's `messageID` and Pi's `responseId` legitimately evaluate to `None` when the CLI omits them, and passing a fallback expression *is* deciding), **CE058** (in `src/coder_eval/`, an unknown timing value may not become a numeric literal — `duration_ms is None` means *never timed* and `0.0` means *timed and instant*, so writing the literal publishes the second while meaning the first. One invariant, one id, five syntactic forms — a zero constructor keyword, `x or 0`, `x if x is not None else 0.0`, `if x.duration_ms is None: x.duration_ms = 0.0`, and a `model_copy(update={...})` dict (the shape the Antigravity DONE path writes through, which a keyword-only rule cannot see). Antigravity constructed EVERY message with `generation_duration_ms=0.0`, so the task page's Generation cell read `0ms` and its breakdown rendered `0%` for months with nothing failing; Codex published the SDK's `0.0` as a measured command duration, so `avg_command_time_ms` divided real milliseconds by a command count of which 70 of 211 in one nightly had never been timed. The fourth form is the one no existing rule shape covered and is where a live instance was hiding — `claude_code_agent._finalize_commands` set `0.0` on every command force-closed without a tool result, in the one harness a timing audit had called healthy. BLIND SPOT, stated in the rule's docstring: form 1 keys on the callee's spelling, so renaming the `AssistantMessageTelemetry` import alias silently disarms it there), **CE059** (in `src/coder_eval/agents/`, an `AssistantMessage` may not receive the same `ast.Name` for both `started_at` and `completed_at` — the Antigravity reducer read `datetime.now()` once and passed it as both bounds, so `started_at == completed_at` on 368 of 368 sampled messages. A separate id from CE058 because it is a separate invariant, a zero-length window whatever the duration field says, and one invariant per id is what makes a `# noqa` mean one thing. It does NOT fire when the same call passes `generation_duration_ms=None`: a call that says, in the field built to say it, that no window was measurable is not claiming one — that exemption is what keeps the rule pointed at the misleading case instead of accumulating four permanent suppressions on the rollout-rebuild and sub-agent-synthesis sites), **CE056** (no bare `CODER_EVAL_IN_CONTAINER` literal outside `models/container_paths.py` — the CE053 shape again: a rename-safety constant that shipped beside the literal it replaced, and the straggler was the single WRITER, so a rename would have disarmed four security/correctness gates at once with nothing failing; CE052 cannot catch it because that rule inspects `if` guards and the writer is not one), **CE055** (a criterion `path:` in `tasks/` must be sandbox-relative — an absolute path is joined onto the sandbox root, which DISCARDS the root, so containment refuses it and the criterion can never match whatever the agent does; two in-tree tasks were broken this way and the pair is the argument for a static rule on top of the runtime `CheckerMisuseError`: `byod_smoke_test` IS in a CI bucket and produced only `Results: 7/8 succeeded` plus a gating 0.0 reading "file does not exist" for a file that existed, while `dockerfile_build_example` is in NO bucket, so nothing ran it and no runtime guard was ever reached — the fix is never to relax containment but to say what the criterion means, `run_command: test -f /opt/marker`, a claim about the container IMAGE rather than about the agent's workspace), **CE054** (an `environment_info` key that is READ must be WRITTEN somewhere in `src/` — the bag is `dict[str, Any]`, so nothing connects reader to writer, and the `reference_digest` anti-cheat guard shipped as a read with no writer anywhere: `.get()` returned `None`, the guard took its early return, and CLAUDE.md plus the user guide both described it as protection it never provided), **CE048** (never call a Typer command function in process — its parameter defaults are `OptionInfo` sentinels, not values, and the sentinel is TRUTHY, so `in_place=None` silently selected the wrong branch; the fix is the `run_pipeline` / `run_evaluation` / `run_plan` split, and this rule is the one that also scans `tests/`, since that is the only place the defect occurs), **CE049** (never coalesce a possibly-unmeasured score to a numeric literal — `score or 0.0` publishes "measured and scored zero" while meaning "never measured", which is how an ungraded night reached four unfiltered `avg(Score)` dashboards as a real zero), **CE050** (no untyped `getattr` probe for a discriminated-union field — pyright cannot see the string, so a rename degrades the guard to a permanent no-op; scoped to criterion-shaped receivers because `command`/`tool`/`prompt` are far too common to flag on their own), **CE051** (a sandbox driver may not be rewritten silently — the driver IS the isolation boundary, so a downgrade must be an explicit, stamped, operator-visible decision), **CE053** (no bare run-record or run-LOG filename literal outside `path_utils` — widened to `docker.log` / `grade.docker.log` / `task.log` / `grade.log` after the same shape recurred: `docker.log` was produced in `isolation/` and consumed in `orchestration/` as three unrelated literals, and because the consumer guards its copy with `is_file()`, a rename would have silently discarded the only record of why a grading container failed — `TASK_JSON_FILENAME` shipped with a rename-safety rationale while twelve exact literals stayed unmigrated, including all three `rglob("task.json")` sites the constant's own comment cites as its reason to exist, so it created the second source of truth it argues against), **CE052** (an `os._exit` must sit inside a branch testing `CODER_EVAL_IN_CONTAINER` — it is the right primitive only for reaping the container's own disposable main process, and `run_task_internal_command` armed its heartbeat watchdog, a daemon thread whose whole authority is `os._exit(137)`, unconditionally: a test that invoked the command in-process left the pytest worker holding that thread, which exited the worker 40s later inside an unrelated test file, naming a different test on each run and on each platform with no traceback — and the dead worker's lost coverage data then failed the gate as `65.13 < 80.00`, naming neither the test nor the cause), **CE037** (no unreferenced module-level private helper in `src/` — a helper whose docstring documents a bug the live code still has is worse than none), **CE038** (in an `@asynccontextmanager`, the acquire must sit INSIDE the `try` whose `finally` releases it — `asyncio.shield` protects the inner task, NOT the await, so a cancel on `__aenter__` skips the unwind while the work completes), **CE039** (a criterion checker must not return a gating `score=0.0` from an `except OSError` over a path the *task author* named — that books an eval-config error as an agent failure; raise `CheckerMisuseError` instead, and `# noqa: CE039` the cases that really are the agent's), **CE047** (every onboarding/marketing surface — README, `docs/index.md`, `docs/comparison.md`, `docs/llms.txt`, `mkdocs.yml`'s `site_description`, the Pages stub, and pyproject's `description`/`keywords` — must name every built-in `AgentKind`; OpenCode shipped while four of those seven still listed three harnesses, and nothing failed), **CE057** (a module copied into the recorder directory beside a generated sandbox shim — `models.sandbox.SIDECAR_MODULES`, currently `argv_match.py` — may import stdlib only. The failure is silent: the sidecar runs where `coder_eval` and its dependencies are not installed, so one package import makes every shadowed CLI die with an ImportError the agent reads as "the tool is broken", costing a whole run to diagnose. The rule derives its target set from that exported tuple and a test asserts it matches a file that exists — a lint rule guarding zero files must fail, not pass). When fixing a bug, ask: *could a custom lint rule have prevented this?* If the root cause is a mechanically detectable pattern (e.g., "always import from `coder_eval.models`", "never call blocking IO in async"), add a rule to `tests/lint/rules/` following the CE001+ pattern and wire it up in `tests/lint/runner.py`. This turns a one-time fix into permanent enforcement. See `tests/test_custom_lint.py` for how rules are tested. (Doc-surface / whole-tree rules that reason over Markdown/YAML or the entire `src/` tree rather than one `.py` AST at a time — CE026–CE031, CE033–CE036 — are not `BaseRule`s in the runner; they are wired as dedicated `@pytest.mark.lint` test classes. CE036 enforces the `live_verdict` determinism + monotonicity contract (`criteria/base.py`) that `EarlyStopWatcher`'s latching, deferred fail-stop, and flip-attribution silently depend on: monotonicity over arbitrary Python is undecidable, so instead of a static check it REPLAYS each live criterion against every prefix of recorded trajectories (`tests/lint/live_verdict_contract.py::CASES`) — on the authored ordering AND under seeded shuffles (`permuted_violations`, which catch order-sensitive bugs the authored walk misses) — and asserts the property directly, plus registry-derived coverage — every `LiveSuccessCriterion` in the union must have cases, and every polarity its instances claim via `live_decidable_polarities()` must actually be reached by one (otherwise a single always-`undecided` fixture would "cover" a type while proving nothing). Adding a live criterion therefore means adding `ContractCase`s in the same change. CE035 resolves every `steps..outputs.` / `needs..outputs.` reference in `.github/workflows/**` to a writer that actually produces that key — GitHub expands an unwritten output to the empty string, so a typo degrades a gate silently and actionlint models `steps.*.outputs` as an open string map. CE034 scans `tasks/` and forces an armed, live-*passable* `command_executed` to set `require_success` — a crashed invocation would otherwise latch a live PASS, fire `on_pass: stop`, and let FIRED-ONLY armed gating report SUCCESS without ever consulting the unarmed criteria (negative assertions are fail-only and are exempt). CE033 keeps the plugin's bundled `reference/criteria.md` in parity with the `SuccessCriterion` union that generates it (`make plugin-reference` writes it; the rule re-renders and diffs — never hand-edit the file). CE031 guards against dead config: a behavior-driving field on `SimulationConfig`/`RunLimits`/`Dataset` that no code reads by name. CE026 keeps the GitHub Action's onboarding surfaces honest — `README.md`, `docs/CI_GATE.md`, `docs/tutorials/02-ci-pipeline.md`, and the plugin's `ci` skill, whose emitted workflow users copy into their own repos: a page's *first* Action snippet must show the agent-runtime prerequisite steps (pinned to the `action-dogfood` job that proves them in CI), a zero-install absolute next to such a snippet must name the channel it means, every `github.com/marketplace/actions/` link plus the shields badge label must match `action.yml`'s `name:`, and every `with:` key on a snippet's action step must be a real `action.yml` input (GitHub ignores unknown inputs, so a rename would silently degrade every copied workflow). Renaming an action input or changing its runtime prerequisites therefore means updating the skill too.) diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index 4b429032..121c6d17 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -25,21 +25,26 @@ wall clock its numbers account for. | Field | claude-code | codex | antigravity | opencode | pi | |---|---|---|---|---|---| | `generation_duration_ms` source | harness clock: previous SDK event → this message | SDK item stamps, minus tool execution inside the window | harness clock: previous flush → this flush, minus tool execution inside the window | harness clock per CLI step, minus tool execution inside the step | harness clock per CLI turn, minus tool execution inside the turn | +| what the **first** window covers | turn start → msg0, so dispatch + TTFT are INSIDE it | the first SDK item's own start, so CLI boot + TTFT are OUTSIDE it | turn start → first flush, so dispatch + TTFT are INSIDE it | the first `step_start`, so CLI boot + TTFT are OUTSIDE it | the first `turn_start`, so CLI boot + TTFT are OUTSIDE it | +| `harness_startup_ms` (turn head) | 0.0 — the window above already covers it | ~3.1 s — CLI boot fused with TTFT | 0.0 — the window above already covers it | ~2.5 s — CLI boot fused with TTFT | ~0.23 s — CLI boot fused with TTFT | +| `harness_teardown_ms` (turn tail) | ~1.3 s | ~13 ms | ~7 ms | ~26 ms | ~19 ms | | tool `duration_ms` source | measured around the tool result | SDK `completed_at_ms − started_at_ms`; the item's own `duration_ms` only as a fallback | measured ACTIVE → DONE | measured around the tool event | measured around the tool event | | `execution_started_at` / `execution_completed_at` | derived from the measured duration | SDK stamps (both, or neither) | measured at ACTIVE / DONE | measured | measured | | `generation_completed_at` | set | `None` — see below | `None` | `None` | `None` | -| `Σ generation + Σ tool ≈ turn duration` | yes | yes | yes | yes | yes | +| `message_id` source | SDK `message_id`; `None` when the stream carries none; `subagent-` for a synthesized sub-agent terminal | synthetic `turn_id-msg-N`, shared across the sub-messages of one generation; `turn_id-subagent-N` for recovered sub-agent generations | synthetic `turn_id-msg-N`, one per generation | CLI `messageID`; `None` when absent | CLI `responseId`; `None` when absent | +| `Σ generation + ∪ tool + head + tail ≈ turn duration` | yes | yes | yes | yes | yes | **`generation_duration_ms` is model-generation time, not `completed_at − started_at`.** -Four of the five harnesses interleave tool execution into a single generation -window. Antigravity reports a `Step` for the tool and only a later +All five harnesses can have tool execution inside a generation window, and all +five subtract it. Four interleave it structurally: Antigravity reports a `Step` +for the tool and only a later `usage_metadata` `Step` cuts the message; Codex's message window is seeded from the first item's start and extended to the last item's completion; OpenCode opens its window at `step_start` and closes it at `step_finish`, and Pi at -`turn_start` / `turn_end`, with every tool call running inside. In all four the +`turn_start` / `turn_end`, with every tool call running inside. In each the span between the recorded bounds legitimately CONTAINS tool time that the model -did not spend generating, so all four subtract it — the **union** of the closed tool intervals -clipped to the window (`agents/_timing.py::busy_ms`), never the sum, because +did not spend generating, so each subtracts it — the **union** of the closed tool intervals +clipped to the window (`coder_eval/timing.py::busy_ms`), never the sum, because tool calls overlap: Antigravity resolves several from one `Step` and backgrounds anything over ten seconds, and Codex spawns collab agents concurrently. Summing them over-subtracts by exactly the overlap and, with enough concurrency, drives @@ -48,10 +53,78 @@ the result to a clamped zero. The consequence worth knowing: on an emission that carries *only* a tool call, the whole measured window was that tool running, so the recorded generation time is legitimately `0.0`. That is a measurement, not a placeholder — `None` -is what "never measured" looks like. Only `claude-code` does not need the -subtraction: it marks the end of the previous SDK event and reads again when -the next message arrives, so a tool's execution falls between two windows -rather than inside one. +is what "never measured" looks like. + +**`claude-code` subtracts at finalization, not as it flushes.** It was once +exempt entirely, on the premise that because it marks the end of the previous +SDK event and reads again when the next message arrives, a tool's execution +falls *between* two windows rather than inside one. Measured, that premise does +not hold: a tool's timer starts at the **emission** carrying its `tool_use` +block, and one assistant turn spans several emissions, so a later emission's +window runs concurrently with a tool already timing. On a task issuing five +parallel writes, five reads and two concurrent `Bash` calls the overlap was +482 ms and 340 ms on two ~18-25 s turns, and the four-bucket residual came out +at exactly `-481 ms` and `-339 ms`; the other four overlapped by ~2.0-2.3 s on +the same task and still reconciled to within 1.2 ms, because they subtract it. + +It cannot subtract while flushing, because a tool issued by an earlier emission +is still running when the next window closes and its interval does not exist +yet. `_ClaudeTurnState._subtract_tool_time_from_windows` therefore runs once at +finalization, when every span is known. After it, the same task reconciles to +**1.4 ms (0.006% of wall)** over four turns that all carried overlapping tool +calls. + +**The head and tail are measured, not normalized.** Generation and tool are +only two of the four buckets. The turn's **head** (turn start → first +generation window) and **tail** (last window → turn end) are booked as +`TurnRecord.harness_startup_ms` / `harness_teardown_ms`, computed once at the +`EventCollector` seam by `coder_eval/timing.py::decompose_turn`. The tool term +is the **union** of the command intervals, for the same reason the subtraction +above is — Pi resolved a `Write` and a `Bash` overlapping by 18.4 ms in one +measured turn, and summing their durations books that overlap twice. The head +and tail exclude tool execution by that same rule and that same helper, which +is what keeps the four buckets disjoint: a tool is not confined to a +generation window (Antigravity force-closes an orphan at finalization, inside +the tail, and backgrounds anything over ten seconds), so a span that escapes +one would otherwise be counted both as tool and as head or tail. With all +four buckets and the union, six live turns per harness reconcile to within +1.7 ms of `duration_seconds` (worst case 0.014% of wall clock; the residual is +clock skew, since head and tail are measured between wall-clock event stamps +while `duration_seconds` is the agent's own monotonic span, and its sign flips +between harnesses). `scripts/timing/decompose_run.py` reproduces the table. The head and tail +figures in the table above are means of six live `tasks/hello_date` turns per +harness and move with CLI cache warmth, so read their ORDER OF MAGNITUDE, not +the digits. + +What the head CONTAINS differs per harness and is deliberately **not** +decomposed, because the divergence is real and unfixable in both directions: + +- On an **in-process SDK** (claude-code, antigravity) the first generation + window starts at turn entry, so dispatch and time-to-first-token are already + inside it. Excluding them is not possible — neither harness stamps a + per-message arrival to fall back to, and `started_at == completed_at` would + be the CE059 defect. **Read their `0.0` head as "nothing is left over", not + as a measured interval**: the window actually opens marginally BEFORE the + `AgentStartEvent` stamp (claude-code builds its turn state, then + `_build_claude_query`, and only then emits the event), so the raw figure is + negative and clamps. The setup between those two points is therefore booked + as generation — **measured at 0.03 ms, and 0.10 ms with four plugin roots**, + so it is the sub-millisecond skew the clamp exists for rather than hidden + overhead. Emitting the event earlier would make the `0.0` a measurement + instead of a clamp but would not change it, since the window's start stamp + also precedes the build; only re-seeding the window after the build would + surface that time, and that is the seeding change ruled out above. + `TestClaudeHeadIsStructurallyZero` pins the build cost so this stays true. +- On a **subprocess harness** (codex, opencode, pi) the first window cannot + start before the first event the CLI emits, so the head is one opaque + interval fusing CLI boot, provider resolution, dispatch and TTFT. Measured on + OpenCode: the process spawns in ~3 ms and its first `step_start` lands at + ~3.9 s, with no marker in between. + +So the fields are named for the **interval they measure**, never for what they +contain. Do not rename them `cli_boot_ms` or `ttft_ms` — that would claim a +split nobody performed. A measured `0.0` head is an answer; `None` is what +"never measured" looks like (a turn that produced no assistant message). **Why Codex leaves `generation_completed_at` as `None`.** It means "when the model finished emitting the `tool_use` block". Codex's stream does not carry @@ -69,6 +142,40 @@ generic tool items now carry a duration where they previously carried none, so `avg_command_time_ms` and `total_command_time_ms` for a Codex run describe every tool call rather than shell commands alone. +**`message_id` is what splits the timeline.** The evalboard groups assistant +emissions by `message_id`, and falls back to a wall-clock gap threshold +(`SAME_EMISSION_GAP_MS`, 100 ms, in `evalboard/lib/runs.ts`) when either side +lacks one. Antigravity's `Step` stream carries no message id, so the harness +synthesizes one — and it must, because this harness's generation windows are +*contiguous* by construction: each opens exactly where the previous one closed, +so the gap between two of them is always 0 ms and the fallback would fold a +whole turn's generations into a single row. CE060 makes the kwarg mandatory in +`src/coder_eval/agents/` for that reason. + +The collapse is a *display* defect, not an accounting one — the consumer SUMS a +group's token buckets and durations, so every total, percentage and cost is +identical either way, as is the reconciliation residual. But it is not +cosmetic, and three displayed figures do move when a turn stops collapsing: +the thinking-cost simulator's per-call cache cascade (`calls` in +`evalboard/lib/thinkingSim.ts` is the number of grouped emissions, and the +cascade is quadratic in it — on a single-shot run it was pinned at one call, +so every coefficient was zero), the `Messages` count and timeline heading, and +the "slow generation" count, whose 10 s bar was being applied to a whole turn's +summed generation time. All three move toward the figure they were always +meant to report, so the fix corrects them rather than breaking them — but a +trend compared across this change is not comparing like with like. + +The two synthetic schemes read differently on purpose: Codex deliberately REPEATS one +id across the sub-messages of a single generation — that is exactly the "the +CLI split one API response" signal the field exists to carry — while +Antigravity's are all distinct, because it emits one message per generation +with every block inside it. Runs recorded before a harness captured the field +still carry `null` and still depend on the gap fallback, which is why it stays +— and so does a current OpenCode or Pi message whose payload omitted the id, +which is the case CE060 cannot see (it requires the kwarg to be present, not +non-`None` at runtime). OpenCode tiles its windows contiguously too, so it is +the other harness where a missing id can still collapse a turn. + ### Known divergences - **Delegate (`delegate-sdk`, out of tree)** records `duration_ms` but no @@ -82,7 +189,19 @@ tool call rather than shell commands alone. records `execution_completed_at` while leaving `duration_ms` as `None` (audit P2-1). -Both are deliberately deferred; see `c/time-bugs-audit.md` for the measurements. +- **`TurnStartEvent` is emitted at inconsistent points.** Antigravity and Codex + fire it at turn entry, before the pump; claude-code, OpenCode and Pi fire it + when a generation begins. Nothing in the timing accounting reads it — the + head and tail are measured from the first and last `AssistantMessage` + instead, which is uniform across all five — so this is recorded rather than + fixed. It is NOT a `max_turns` hazard: `EventCollector.visible_turn_count` is + `len(self._commands)`, derived from `ToolEndEvent`, and `_turn_starts` feeds + only `assistant_turn_count` on the no-`AgentEndEvent` fallback path. The real + cost of normalizing it is that the event drives the live renderers, so moving + it changes the turn boundaries users watch during a run. + +All three are deliberately deferred; see `c/time-bugs-audit.md` for the +measurements. ## `max_turns` counts visible turns on Codex and Antigravity diff --git a/evalboard/app/runs/[id]/[...task]/__tests__/message-timeline.test.tsx b/evalboard/app/runs/[id]/[...task]/__tests__/message-timeline.test.tsx index bbeb5638..6f135086 100644 --- a/evalboard/app/runs/[id]/[...task]/__tests__/message-timeline.test.tsx +++ b/evalboard/app/runs/[id]/[...task]/__tests__/message-timeline.test.tsx @@ -621,6 +621,143 @@ describe("MessageTimelineSection — Unaccounted cell", () => { }); }); +describe("MessageTimelineSection — Startup and Teardown cells", () => { + function cell(label: string): HTMLElement { + const parent = screen.getByText(label).parentElement as HTMLElement; + return parent.children[1] as HTMLElement; + } + + // Same 4s generation + 1s tool exec fixture the Unaccounted block uses, so + // the two blocks' numbers are directly comparable. + function renderStrip(props: { + taskDurationSeconds?: number | null; + harnessStartupMs?: number | null; + harnessTeardownMs?: number | null; + }) { + const m = makeMessage({ + generationMs: 4000, + textMs: 4000, + toolUses: [ + { + toolName: "Bash", + toolUseId: "tu_1", + summary: "ls", + argText: "ls", + description: null, + genMs: null, + durationMs: 1000, + isError: false, + resultPreview: null, + outputTokens: null, + resultTokens: null, + }, + ], + }); + return render(); + } + + test("both buckets render their measured value", () => { + renderStrip({ + taskDurationSeconds: 10, + harnessStartupMs: 3000, + harnessTeardownMs: 1500, + }); + expect(cell("Startup").textContent).toBe("3.0s"); + expect(cell("Teardown").textContent).toBe("1.5s"); + }); + + test("a measured zero renders as 0ms, not as an em-dash", () => { + // claude-code and antigravity really do measure ~0 here — their first + // generation window already covers dispatch. "—" would report that + // honest measurement as a missing one. + renderStrip({ + taskDurationSeconds: 10, + harnessStartupMs: 0, + harnessTeardownMs: 834.7, + }); + expect(cell("Startup").textContent).toBe("0ms"); + expect(cell("Teardown").textContent).toBe("835ms"); + }); + + test("Unaccounted shrinks by exactly startup + teardown", () => { + // 10s − 4s gen − 1s tool = 5s before; minus 3s + 1.5s = 500ms after. + renderStrip({ + taskDurationSeconds: 10, + harnessStartupMs: 3000, + harnessTeardownMs: 1500, + }); + expect(cell("Unaccounted").textContent).toBe("500ms (5%)"); + }); + + test("a corrected residual still above 25% stays red", () => { + // The other direction: naming the buckets must not disable the tint, + // only move the number it reads. 20s − 4s gen − 1s tool − 3s − 1s + // = 11s, still 55% unexplained. + renderStrip({ + taskDurationSeconds: 20, + harnessStartupMs: 3000, + harnessTeardownMs: 1000, + }); + expect(cell("Unaccounted").textContent).toBe("11.0s (55%)"); + expect(cell("Unaccounted").className).toContain("text-red-700"); + }); + + test("a residual that was red goes grey once the buckets are named", () => { + // The 25% threshold applies to the CORRECTED residual: 50% before, + // 5% after, so the red tint must follow the correction. + renderStrip({ + taskDurationSeconds: 10, + harnessStartupMs: 3000, + harnessTeardownMs: 1500, + }); + expect(cell("Unaccounted").className).not.toContain("text-red-700"); + }); + + test("an older run with neither field renders — and today's residual", () => { + const { container } = renderStrip({ taskDurationSeconds: 10 }); + expect(cell("Startup").textContent).toBe("—"); + expect(cell("Teardown").textContent).toBe("—"); + // Byte-identical to the pre-existing Unaccounted expectation. + expect(cell("Unaccounted").textContent).toBe("5.0s (50%)"); + expect(cell("Unaccounted").className).toContain("text-red-700"); + expect(container.textContent).not.toContain("NaN"); + }); + + test("only the present bucket is subtracted", () => { + renderStrip({ taskDurationSeconds: 10, harnessStartupMs: 3000 }); + expect(cell("Startup").textContent).toBe("3.0s"); + expect(cell("Teardown").textContent).toBe("—"); + expect(cell("Unaccounted").textContent).toBe("2.0s (20%)"); + }); + + test("the residual still goes negative and stays amber", () => { + // Naming the buckets does not clamp the overlap signal. + renderStrip({ + taskDurationSeconds: 5, + harnessStartupMs: 1000, + harnessTeardownMs: 500, + }); + expect(cell("Unaccounted").textContent).toBe("-1.5s (-30%)"); + expect(cell("Unaccounted").className).toContain("text-amber-700"); + }); + + test("each bucket says what it measures and that it is not decomposed", () => { + renderStrip({ + taskDurationSeconds: 10, + harnessStartupMs: 3000, + harnessTeardownMs: 1500, + }); + expect(screen.getByText("Startup").parentElement).toHaveAttribute( + "title", + expect.stringContaining("time-to-first-token"), + ); + expect(screen.getByText("Teardown").parentElement).toHaveAttribute( + "title", + expect.stringContaining("teardown"), + ); + }); +}); + // A mixed-kind emission's per-kind split is apportioned by content size, so // the page must say so and must not let the unattributable part distort the // thinking share. diff --git a/evalboard/app/runs/[id]/[...task]/_sections.tsx b/evalboard/app/runs/[id]/[...task]/_sections.tsx index 77ed0aa4..9a3d2886 100644 --- a/evalboard/app/runs/[id]/[...task]/_sections.tsx +++ b/evalboard/app/runs/[id]/[...task]/_sections.tsx @@ -317,6 +317,8 @@ export function MessageTimelineSection({ subAgentUsageByToolId = {}, impactByIndex, taskDurationSeconds, + harnessStartupMs, + harnessTeardownMs, }: { messages: MessageEvent[]; // Per-Agent-call sub-agent token breakdown (input/output/cache-create/ @@ -331,6 +333,13 @@ export function MessageTimelineSection({ // tool execution do NOT account for. Null/absent on a run predating // duration capture — the cell then renders "—" rather than a fake residual. taskDurationSeconds?: number | null; + // The turn-level head and tail, summed over the task's turns: wall clock + // before the first generation window opened and after the last one closed. + // Turn-scoped, so they cannot be derived from the per-message stream the + // other stats come from. Null/absent on a run predating the capture, and + // the cells then read "—" while Unaccounted keeps exactly its old meaning. + harnessStartupMs?: number | null; + harnessTeardownMs?: number | null; }) { // Token columns can be shown as counts or as their estimated USD value. const [unit, setUnit] = useState("tokens"); @@ -396,11 +405,23 @@ export function MessageTimelineSection({ const attributableGenMs = totalGenMs - mixedMs; const thinkingShare = attributableGenMs > 0 ? thinkingMs / attributableGenMs : 0; - // Wall clock the agent stream does not explain. Negative means generation - // and tool execution overlapped, which is a real signal — never clamped. + // Wall clock the agent stream does not explain, AFTER every named bucket. + // Startup and teardown are subtracted because they are measured intervals, + // not residual — leaving them in reported a harness's CLI boot as + // unexplained time. `?? 0` subtracts only what was actually measured, so an + // older run with neither field keeps exactly its previous number. + // Negative means generation and tool execution overlapped, which is a real + // signal — never clamped. const taskMs = taskDurationSeconds != null ? taskDurationSeconds * 1000 : null; - const unaccountedMs = taskMs != null ? taskMs - totalGenMs - toolExecMs : null; + const unaccountedMs = + taskMs != null + ? taskMs - + totalGenMs - + toolExecMs - + (harnessStartupMs ?? 0) - + (harnessTeardownMs ?? 0) + : null; const unaccountedShare = taskMs != null && taskMs > 0 && unaccountedMs != null ? unaccountedMs / taskMs @@ -417,13 +438,23 @@ export function MessageTimelineSection({

MIXED = multiple block types · red = slow (gen ≥10s, tool ≥5s)

-
+
Messages
{messageCount}
+
+
+ Startup +
+
+ {fmtMs(harnessStartupMs ?? null)} +
+
@@ -512,7 +543,17 @@ export function MessageTimelineSection({
+
+ Teardown +
+
+ {fmtMs(harnessTeardownMs ?? null)} +
+
+
Unaccounted @@ -753,6 +794,8 @@ export function CostExplorerSection({ tokens, recordedCostUsd, taskDurationSeconds, + harnessStartupMs, + harnessTeardownMs, }: { messages: MessageEvent[]; subAgentUsageByToolId?: Record; @@ -760,6 +803,9 @@ export function CostExplorerSection({ recordedCostUsd: number | null; // Forwarded verbatim to the timeline's Unaccounted cell. taskDurationSeconds?: number | null; + // Forwarded verbatim to the timeline's Startup/Teardown cells. + harnessStartupMs?: number | null; + harnessTeardownMs?: number | null; }) { const [scale, setScale] = useState(1); const [toolScale, setToolScale] = useState(1); @@ -798,6 +844,8 @@ export function CostExplorerSection({ subAgentUsageByToolId={subAgentUsageByToolId} impactByIndex={impactByIndex} taskDurationSeconds={taskDurationSeconds} + harnessStartupMs={harnessStartupMs} + harnessTeardownMs={harnessTeardownMs} /> {model && tokens.total > 0 && (
diff --git a/evalboard/app/runs/[id]/[...task]/page.tsx b/evalboard/app/runs/[id]/[...task]/page.tsx index 12e8b334..84efa461 100644 --- a/evalboard/app/runs/[id]/[...task]/page.tsx +++ b/evalboard/app/runs/[id]/[...task]/page.tsx @@ -365,6 +365,8 @@ export default async function TaskPage({ tokens={task.tokens} recordedCostUsd={task.totalCostUsd} taskDurationSeconds={task.durationSeconds} + harnessStartupMs={task.harnessStartupMs} + harnessTeardownMs={task.harnessTeardownMs} /> )} diff --git a/evalboard/lib/__tests__/harnessOverhead.test.ts b/evalboard/lib/__tests__/harnessOverhead.test.ts new file mode 100644 index 00000000..a39fc6ac --- /dev/null +++ b/evalboard/lib/__tests__/harnessOverhead.test.ts @@ -0,0 +1,79 @@ +import { promises as fs } from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import { afterEach, beforeEach, describe, expect, test, vi } from "vitest"; + +// End-to-end: the two turn-level timing buckets survive the trip from +// task.json's `iterations` onto TaskDetail. `sumHarnessOverhead` is unit-tested +// in runs.test.ts; what only a read off disk can catch is a misspelled raw key, +// since every TurnEntry field is optional and a typo would just parse as +// absent. Mirrors providerCalls.test.ts's env-stub + fresh-import pattern. +const RUN = "2026-01-01_00-00-00"; +const TASK = "demo-task"; +let tmp: string; + +async function write(rel: string, body: string): Promise { + const abs = path.join(tmp, rel); + await fs.mkdir(path.dirname(abs), { recursive: true }); + await fs.writeFile(abs, body); +} + +async function loadRuns() { + vi.resetModules(); + vi.stubEnv("EVALBOARD_LOCAL_RUNS_DIR", tmp); + return import("../runs"); +} + +async function writeTask(iterations: unknown[]): Promise { + await write( + `${RUN}/run.json`, + JSON.stringify({ + run_id: RUN, + task_results: [{ task_id: TASK, status: "success" }], + }), + ); + await write( + `${RUN}/default/${TASK}/00/task.json`, + JSON.stringify({ final_status: "success", iterations }), + ); +} + +beforeEach(async () => { + tmp = await fs.mkdtemp(path.join(os.tmpdir(), "evalboard-overhead-")); +}); + +afterEach(async () => { + vi.unstubAllEnvs(); + await fs.rm(tmp, { recursive: true, force: true }); +}); + +describe("readTaskDetail: harness startup/teardown", () => { + test("sums both buckets across the task's turns", async () => { + await writeTask([ + { harness_startup_ms: 3047.9, harness_teardown_ms: 33.1 }, + { harness_startup_ms: 120.5, harness_teardown_ms: 4.2 }, + ]); + const { readTaskDetail } = await loadRuns(); + const detail = await readTaskDetail(RUN, TASK); + expect(detail?.harnessStartupMs).toBeCloseTo(3168.4, 3); + expect(detail?.harnessTeardownMs).toBeCloseTo(37.3, 3); + }); + + test("an older run without the fields reports null, not zero", async () => { + await writeTask([{ model_used: "claude-haiku-4-5" }]); + const { readTaskDetail } = await loadRuns(); + const detail = await readTaskDetail(RUN, TASK); + expect(detail?.harnessStartupMs).toBeNull(); + expect(detail?.harnessTeardownMs).toBeNull(); + }); + + test("a measured zero head is preserved as 0", async () => { + // An in-process SDK's first generation window already covers dispatch, + // so 0.0 is its honest answer and must not read as "never measured". + await writeTask([{ harness_startup_ms: 0.0, harness_teardown_ms: 834.7 }]); + const { readTaskDetail } = await loadRuns(); + const detail = await readTaskDetail(RUN, TASK); + expect(detail?.harnessStartupMs).toBe(0); + expect(detail?.harnessTeardownMs).toBeCloseTo(834.7, 3); + }); +}); diff --git a/evalboard/lib/__tests__/parseMessages.test.ts b/evalboard/lib/__tests__/parseMessages.test.ts index 15e73427..84f94c98 100644 --- a/evalboard/lib/__tests__/parseMessages.test.ts +++ b/evalboard/lib/__tests__/parseMessages.test.ts @@ -228,7 +228,7 @@ describe("parseMessages — message_id collapsing", () => { expect(e.generationMs).toBe(5500); }); - test("splits when message_ids differ even with tight gap", () => { + test("splits differing message_ids across contiguous windows (0ms gap — the Antigravity shape)", () => { const turns: TurnEntry[] = [ { messages: [ @@ -242,9 +242,11 @@ describe("parseMessages — message_id collapsing", () => { }, { role: "assistant", - started_at: "2026-01-01T00:00:01.010Z", // 10ms gap + // Opens exactly where the previous one closed, the + // way Antigravity tiles its generation windows. + started_at: "2026-01-01T00:00:01.000Z", completed_at: "2026-01-01T00:00:02.000Z", - generation_duration_ms: 990, + generation_duration_ms: 1000, message_id: "msg_b", content_blocks: [{ block_type: "text", text: "hi" }], }, diff --git a/evalboard/lib/__tests__/runs.test.ts b/evalboard/lib/__tests__/runs.test.ts index 0ac7b635..bef4fa8d 100644 --- a/evalboard/lib/__tests__/runs.test.ts +++ b/evalboard/lib/__tests__/runs.test.ts @@ -24,6 +24,7 @@ import { parseCriterionResults, type RawTaskResult, sortArtifacts, + sumHarnessOverhead, toTaskRow, visibleTurnsFromRaw, walkArtifacts, @@ -246,6 +247,60 @@ describe("aggregateSubAgentUsage", () => { }); }); +describe("sumHarnessOverhead", () => { + test("sums both buckets across iterations", () => { + expect( + sumHarnessOverhead([ + { harness_startup_ms: 3000, harness_teardown_ms: 800 }, + { harness_startup_ms: 120, harness_teardown_ms: 40 }, + ]), + ).toEqual({ startupMs: 3120, teardownMs: 840 }); + }); + + test("a measured zero is a measurement and still sums", () => { + // An in-process SDK whose first generation window already covers + // dispatch legitimately reports 0.0 — that is a number, not a gap. + expect( + sumHarnessOverhead([{ harness_startup_ms: 0, harness_teardown_ms: 3.5 }]), + ).toEqual({ startupMs: 0, teardownMs: 3.5 }); + }); + + test("is null when EVERY iteration is null — never 0", () => { + // 0 would claim the harness started instantly; null says nobody looked. + expect( + sumHarnessOverhead([ + { harness_startup_ms: null, harness_teardown_ms: null }, + {}, + ]), + ).toEqual({ startupMs: null, teardownMs: null }); + }); + + test("sums the measured iterations and ignores the unmeasured ones", () => { + expect( + sumHarnessOverhead([ + { harness_startup_ms: 500 }, + { harness_teardown_ms: 90 }, + ]), + ).toEqual({ startupMs: 500, teardownMs: 90 }); + }); + + test("is null on an empty turn list", () => { + expect(sumHarnessOverhead([])).toEqual({ + startupMs: null, + teardownMs: null, + }); + }); + + test("a non-finite value is dropped rather than poisoning the sum", () => { + expect( + sumHarnessOverhead([ + { harness_startup_ms: NaN, harness_teardown_ms: 10 }, + { harness_startup_ms: 25 }, + ]), + ).toEqual({ startupMs: 25, teardownMs: 10 }); + }); +}); + describe("isExcludedArtifact", () => { test("hides build artifacts, local state, and secrets", () => { for (const rel of [ diff --git a/evalboard/lib/runs.ts b/evalboard/lib/runs.ts index 36aea409..b3c0745f 100644 --- a/evalboard/lib/runs.ts +++ b/evalboard/lib/runs.ts @@ -355,6 +355,12 @@ export interface TaskDetail extends TaskResultSummary { // the Agent row). The cost simulator consumes the values via Object.values(). // Empty for runs/turns with no spawned sub-agents. subAgentUsageByToolId: Record; + // The task's harness head and tail, summed over its turns. `null` when no + // turn measured that end — never 0, which would claim the harness started + // or finished instantly. Subtracted from the timeline's Unaccounted cell so + // that residual is what is left after every named bucket. + harnessStartupMs: number | null; + harnessTeardownMs: number | null; // Per-call ACTUAL cost + cache audit rows, grouped by turn iteration. Only // turns whose `provider_call_costs` list is non-empty appear (LiteLLM/ // open-weight backend; empty on Claude/Bedrock). Rendered as a standalone @@ -385,6 +391,35 @@ export interface SubAgentTotals { cacheRead: number; } +// Sum one optional per-turn measurement across a task's turns. `null` — never +// 0 — when no turn carried the value, because 0 means "measured, and instant" +// while null means nobody measured (the `TurnRecord` fields' own contract, and +// what CE058 guards on the Python side). Non-finite values are dropped rather +// than poisoning the total with NaN. +function sumMeasured(values: (number | null | undefined)[]): number | null { + let total: number | null = null; + for (const v of values) { + if (typeof v !== "number" || !Number.isFinite(v)) continue; + total = (total ?? 0) + v; + } + return total; +} + +// The task's harness head and tail, summed over its turns. The per-turn values +// are measured by `coder_eval/timing.py::decompose_turn`; the summation is +// evalboard-only, and the arithmetic that consumes it — the Unaccounted +// residual in `_sections.tsx` — is the deliberate second implementation that +// helper's docstring names (as `pricing.ts` mirrors `pricing.py`). +export function sumHarnessOverhead(turns: TurnEntry[]): { + startupMs: number | null; + teardownMs: number | null; +} { + return { + startupMs: sumMeasured(turns.map((t) => t.harness_startup_ms)), + teardownMs: sumMeasured(turns.map((t) => t.harness_teardown_ms)), + }; +} + // Group the parsed assistant messages by `parentToolUseId` into a per-sub-agent // token breakdown. A sub-agent's generations all carry the spawning Agent call's // tool_use_id; main-thread messages (parentToolUseId null/undefined) are skipped. @@ -1517,6 +1552,12 @@ export interface TurnEntry { // reconciliation row, which carries no model of its own. model_used?: string | null; token_usage?: TokenUsageEntry | null; + // The turn's head and tail: wall ms before the first generation window + // opened and after the last one closed. Absent on runs predating the + // capture, and null on a turn that produced no assistant message — in both + // cases nobody measured, which is a different fact from a measured 0. + harness_startup_ms?: number | null; + harness_teardown_ms?: number | null; // Per-call actual cost + cache audit rows (LiteLLM/open-weight backend); // empty/absent on Claude/Bedrock. Surfaced as a standalone per-call table. provider_call_costs?: ProviderCallEntryRaw[]; @@ -2506,6 +2547,8 @@ export async function readTaskDetail( const tokens = selectTokenTotals(messages, task?.iterations ?? []); const subAgentUsageByToolId = aggregateSubAgentUsage(messages); + const { startupMs: harnessStartupMs, teardownMs: harnessTeardownMs } = + sumHarnessOverhead(task?.iterations ?? []); const taskDescription = task?.task_config?.resolved?.initial_prompt ?? @@ -2546,6 +2589,8 @@ export async function readTaskDetail( messages, tokens, subAgentUsageByToolId, + harnessStartupMs, + harnessTeardownMs, providerCalls, }; } diff --git a/pyproject.toml b/pyproject.toml index b1e08974..62f2ee82 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -277,6 +277,7 @@ external = [ "CE057", "CE058", "CE059", + "CE060", ] # custom architectural lint rules (tests/lint/) [tool.ruff.lint.pylint] diff --git a/scripts/timing/decompose_run.py b/scripts/timing/decompose_run.py new file mode 100644 index 00000000..ba6e3c41 --- /dev/null +++ b/scripts/timing/decompose_run.py @@ -0,0 +1,150 @@ +#!/usr/bin/env python3 +"""Decompose recorded turns into the four wall-clock buckets, per harness. + +Reads `task.json` files, groups their turns by `agent_type`, and prints the +mean generation / tool / startup / teardown against the mean turn duration, +plus the residual as a percentage of wall clock. A healthy harness reconciles +to well under 1%. The tool bucket is the UNION of the command intervals, never +their sum — tool calls overlap, and summing them books the overlap twice. + + uv run python scripts/timing/decompose_run.py runs//default/*/00/task.json + +Not wired into `make`: it needs live runs, not fixtures. NOTE `scripts/` is +outside the Makefile's LINT_PATHS, so this file is neither formatted nor +ruff-checked — keep it small and dependency-free. +""" + +from __future__ import annotations + +import argparse +import json +import sys +from collections import defaultdict +from datetime import datetime +from pathlib import Path + +from coder_eval.timing import busy_ms + + +def _parse(stamp: object) -> datetime | None: + if not isinstance(stamp, str): + return None + try: + return datetime.fromisoformat(stamp) + except ValueError: + return None + + +def _tool_ms(turn: dict) -> float: + """Wall ms this turn spent executing tools — the UNION, not the sum. + + The same rule `coder_eval.timing.busy_ms` applies when a harness subtracts + tool time out of a generation window, and it has to be the same rule here + or the identity does not close: Pi resolved a `Write` and a `Bash` that + overlapped by 18.4 ms in one measured turn, and summing their durations + booked that overlap twice, which is precisely the 18.3 ms residual that + found this. A command with no recorded bounds cannot be placed on the + timeline at all, so it contributes nothing rather than being summed in + blind — see docs/agents/HARNESS_PARITY.md's Delegate divergence. + """ + spans = [] + for command in turn.get("commands") or []: + start = _parse(command.get("execution_started_at")) + end = _parse(command.get("execution_completed_at")) + if start is not None and end is not None and end >= start: + spans.append((start, end)) + if not spans: + return 0.0 + return busy_ms(spans, min(s for s, _ in spans), max(e for _, e in spans)) + + +def _turn_buckets(turn: dict) -> tuple[float, float, float, float, float] | None: + """(wall_ms, generation_ms, tool_ms, startup_ms, teardown_ms) for one turn. + + None when the turn was never timed at all — a crash partial with no + generation. A bucket the harness could not measure counts as 0 toward the + sums while the turn still contributes its wall clock, so an unmeasured + bucket shows up as residual rather than silently vanishing. + """ + duration_seconds = turn.get("duration_seconds") + if not isinstance(duration_seconds, (int, float)): + return None + # MAIN THREAD ONLY. A sub-agent's generations bubble into the same stream + # tagged with the spawning Agent call's tool_use_id, and that call's own + # interval already spans the sub-agent's entire run. Counting both books the + # sub-agent twice — the evalboard's timeline strip filters on exactly this + # field for exactly this reason (a 120 s Agent call containing 90 s of + # sub-agent generation drove its residual to -57%). + messages = turn.get("messages") or [] + generation_ms = sum( + m.get("generation_duration_ms") or 0.0 + for m in messages + if m.get("role") == "assistant" + and m.get("parent_tool_use_id") is None + and isinstance(m.get("generation_duration_ms"), (int, float)) + ) + startup_ms = turn.get("harness_startup_ms") + teardown_ms = turn.get("harness_teardown_ms") + return ( + duration_seconds * 1000.0, + generation_ms, + _tool_ms(turn), + startup_ms if isinstance(startup_ms, (int, float)) else 0.0, + teardown_ms if isinstance(teardown_ms, (int, float)) else 0.0, + ) + + +def main(argv: list[str]) -> int: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("task_json", nargs="+", type=Path, help="task.json files to decompose") + args = parser.parse_args(argv) + + by_harness: dict[str, list[tuple[float, float, float, float, float]]] = defaultdict(list) + for path in args.task_json: + try: + record = json.loads(path.read_text(encoding="utf-8")) + except (OSError, json.JSONDecodeError) as exc: + print(f"skipping {path}: {exc}", file=sys.stderr) + continue + harness = record.get("agent_type") or "unknown" + for turn in record.get("iterations") or []: + buckets = _turn_buckets(turn) + if buckets is not None: + by_harness[harness].append(buckets) + + if not by_harness: + print("no timed turns found", file=sys.stderr) + return 1 + + header = ( + f"{'harness':<14} {'n':>3} {'wall':>10} {'generation':>11} {'tool':>9} " + f"{'startup':>9} {'teardown':>9} {'residual':>10} {'%':>7} {'worst turn':>11}" + ) + print(header) + print("-" * len(header)) + worst_share = 0.0 + worst_turn = 0.0 + for harness in sorted(by_harness): + turns = by_harness[harness] + n = len(turns) + wall, gen, tool, up, down = (sum(col) / n for col in zip(*turns, strict=True)) + residual = wall - gen - tool - up - down + share = (residual / wall * 100.0) if wall else 0.0 + # The MEAN residual can hide an outlier by cancellation — the sign + # flips between harnesses because head/tail are measured between event + # stamps while duration_seconds is the agent's own monotonic span. So + # report the worst single turn beside it; that is the real bound. + per_turn = max(abs(w - g - t - u - d) for w, g, t, u, d in turns) + worst_share = max(worst_share, abs(share)) + worst_turn = max(worst_turn, per_turn) + print( + f"{harness:<14} {n:>3} {wall:>9.1f}ms {gen:>10.1f}ms {tool:>8.1f}ms " + f"{up:>8.1f}ms {down:>8.1f}ms {residual:>9.3f}ms {share:>6.2f}% {per_turn:>9.3f}ms" + ) + print(f"\nworst mean |residual| = {worst_share:.2f}% of wall clock") + print(f"worst single-turn |residual| = {worst_turn:.3f}ms") + return 0 + + +if __name__ == "__main__": + raise SystemExit(main(sys.argv[1:])) diff --git a/src/coder_eval/agents/_timing.py b/src/coder_eval/agents/_timing.py deleted file mode 100644 index 6d568e56..00000000 --- a/src/coder_eval/agents/_timing.py +++ /dev/null @@ -1,42 +0,0 @@ -"""Shared timing helpers for agent implementations. - -Two harnesses interleave tool execution into a single generation window — -Antigravity (the Step for the tool arrives and only a later ``usage_metadata`` -Step cuts the message) and Codex (``_flush_message``'s window is extended to -the last item's ``completed_at_ms``). Both must therefore subtract the tool -time from the window before publishing ``generation_duration_ms``, and both -must subtract the same thing: the UNION of the closed intervals, clipped to -the window. -""" - -from datetime import datetime - - -def busy_ms(spans: list[tuple[datetime, datetime]], lo: datetime, hi: datetime) -> float: - """Wall milliseconds inside ``[lo, hi]`` where at least ONE span was running. - - The union, not the sum. Tool intervals overlap in practice — Antigravity - resolves several calls from one ``Step`` and backgrounds anything over ten - seconds; Codex spawns collab agents that run concurrently — so adding - their durations over-counts the busy time by exactly the overlap. - Subtracting such a sum from a generation window understates generation - and, with enough concurrency, drives it negative: four concurrent 400 ms - calls inside a 1000 ms window sum to 1600 ms, clamping the result to the - ``0.0`` that "unknown timing says unknown" exists to eliminate. - - Clipping to ``[lo, hi]`` is the other half: a tool that opened before this - window only spent part of its life inside it, and only that part is not - generation time here. - """ - clipped = sorted((max(s, lo), min(e, hi)) for s, e in spans if min(e, hi) > max(s, lo)) - if not clipped: - return 0.0 - total = 0.0 - open_start, open_end = clipped[0] - for start, end in clipped[1:]: - if start > open_end: # disjoint — bank the run and start a new one - total += (open_end - open_start).total_seconds() * 1000.0 - open_start, open_end = start, end - else: # overlapping or adjacent — extend the run - open_end = max(open_end, end) - return total + (open_end - open_start).total_seconds() * 1000.0 diff --git a/src/coder_eval/agents/antigravity_agent.py b/src/coder_eval/agents/antigravity_agent.py index 6c3269ec..51414eea 100644 --- a/src/coder_eval/agents/antigravity_agent.py +++ b/src/coder_eval/agents/antigravity_agent.py @@ -31,7 +31,6 @@ from coder_eval.agent import Agent, AgentState from coder_eval.agents._logging import PrefixedAdapter -from coder_eval.agents._timing import busy_ms from coder_eval.agents.registry import AgentRegistry from coder_eval.agents.watchdog import ThreadedWatchdog from coder_eval.config import settings @@ -68,6 +67,7 @@ TurnEndStatus, TurnStartEvent, ) +from coder_eval.timing import busy_ms from coder_eval.utils import expand_env_vars @@ -1087,6 +1087,10 @@ def _flush_generation(self, gen: TokenUsage, reasoning_tokens: int) -> None: cache_read_tokens=gen.cache_read_input_tokens, reasoning_tokens=reasoning_tokens, model=self.model, + # The Step stream carries no message id, and the evalboard's + # SAME_EMISSION_GAP_MS fallback cannot split this harness's + # contiguous windows — see docs/agents/HARNESS_PARITY.md. + message_id=f"{self.turn_id}-msg-{self._assistant_turns}", ) ) self._assistant_turns += 1 diff --git a/src/coder_eval/agents/claude_code_agent.py b/src/coder_eval/agents/claude_code_agent.py index 7175cb7f..b49305e0 100644 --- a/src/coder_eval/agents/claude_code_agent.py +++ b/src/coder_eval/agents/claude_code_agent.py @@ -76,6 +76,7 @@ TurnEndStatus, TurnStartEvent, ) +from coder_eval.timing import busy_ms from coder_eval.utils import dump_dataclass, process_plugins @@ -582,6 +583,49 @@ def _finalize_token_usage(self) -> TokenUsage: self._agent._reprice_for_litellm(usage, self.effective_model) return usage + def _subtract_tool_time_from_windows(self, commands: list[CommandTelemetry]) -> None: + """Take tool execution back out of the generation windows it overlapped. + + The other four harnesses do this as they flush, because their stream + interleaves tool calls into one window. claude-code was exempted on the + premise that a tool's execution falls BETWEEN two windows — but a tool's + timer starts at the emission carrying its ``tool_use`` block, and one + assistant turn spans several emissions, so a later emission's window + runs concurrently with a tool already timing. Measured on a task with + two concurrent ``Bash`` calls: 482 ms and 340 ms of a ~18-25 s turn + counted as both generation and tool, which is exactly the amount by + which the four-bucket identity missed. + + Deferred to finalization rather than done in ``on_assistant_message`` + because that is the first point where every span is known: a tool + issued by an earlier emission is still running when the next window + closes, so its interval does not exist yet. + + ``generation_duration_ms`` therefore means the same thing on all five + harnesses — wall time inside the window with no tool running. A window + entirely covered by tool execution legitimately reads ``0.0``; that is + a measurement, and ``None`` remains what "never measured" means. + """ + spans = [ + (c.execution_started_at, c.execution_completed_at) + for c in commands + if c.execution_started_at is not None and c.execution_completed_at is not None + ] + if not spans: + return + for emission in self.sdk_messages: + # A sub-agent's generation is not on this timeline: its own tools + # are not in `commands`, and the Agent call that spawned it already + # spans its whole run. A UserMessage / ReconciliationMessage has no + # window at all. + if not isinstance(emission, AssistantMessageTelemetry): + continue + if emission.generation_duration_ms is None or emission.parent_tool_use_id is not None: + continue + overlap = busy_ms(spans, emission.started_at, emission.completed_at) + if overlap > 0.0: + emission.generation_duration_ms = max(emission.generation_duration_ms - overlap, 0.0) + def finalize(self, status: AgentEndStatus, *, crashed: bool = False, crash_reason: str | None = None) -> None: """Close orphaned tools + the open turn, emit the terminal AgentEndEvent, and on a crash build the partial TurnRecord. Idempotent.""" @@ -590,6 +634,7 @@ def finalize(self, status: AgentEndStatus, *, crashed: bool = False, crash_reaso self.finalized = True commands = self._agent._finalize_commands(self.pending_commands, self.messages) + self._subtract_tool_time_from_windows(commands) for cmd in commands: if cmd.tool_id in self.emitted_tool_ends: continue diff --git a/src/coder_eval/agents/codex_agent.py b/src/coder_eval/agents/codex_agent.py index b8ffea86..0b5f39b3 100644 --- a/src/coder_eval/agents/codex_agent.py +++ b/src/coder_eval/agents/codex_agent.py @@ -17,7 +17,6 @@ from coder_eval.agent import Agent, AgentState from coder_eval.agents._logging import PrefixedAdapter, log_raw_sdk_event -from coder_eval.agents._timing import busy_ms from coder_eval.agents.registry import AgentRegistry from coder_eval.agents.watchdog import ThreadedWatchdog from coder_eval.config import settings @@ -54,6 +53,7 @@ TurnEndStatus, TurnStartEvent, ) +from coder_eval.timing import busy_ms from coder_eval.utils import expand_env_vars diff --git a/src/coder_eval/agents/opencode_agent.py b/src/coder_eval/agents/opencode_agent.py index 708f38ec..b9036eea 100644 --- a/src/coder_eval/agents/opencode_agent.py +++ b/src/coder_eval/agents/opencode_agent.py @@ -43,7 +43,6 @@ from typing import Any, ClassVar, Literal, NoReturn from coder_eval.agent import Agent -from coder_eval.agents._timing import busy_ms from coder_eval.errors import AgentCrashError, TurnTimeoutError from coder_eval.isolation.docker_runner import STDOUT_LINE_LIMIT_BYTES from coder_eval.models import ( @@ -77,6 +76,7 @@ TurnEndStatus, TurnStartEvent, ) +from coder_eval.timing import busy_ms from ._skills import _plugin_skill_dirs from .registry import AgentRegistry @@ -331,7 +331,7 @@ def __init__(self, *, task_id: str, iteration: int, user_input: str, model: str # milliseconds twice — once here and once as the tool's own # duration_ms. Intervals, not a running total: they overlap # whenever the harness runs tools concurrently, and only their - # union may be subtracted (agents/_timing.py::busy_ms). + # union may be subtracted (timing.py::busy_ms). self.step_tool_spans: list[tuple[datetime, datetime]] = [] # callID -> (telemetry, started_at) for tools awaiting a result. diff --git a/src/coder_eval/agents/pi_agent.py b/src/coder_eval/agents/pi_agent.py index 11fb8b73..02adbc89 100644 --- a/src/coder_eval/agents/pi_agent.py +++ b/src/coder_eval/agents/pi_agent.py @@ -77,7 +77,6 @@ from coder_eval.agent import Agent from coder_eval.agents._skills import _plugin_skill_dirs # shared plugin->skills resolver -from coder_eval.agents._timing import busy_ms from coder_eval.errors import AgentCrashError, TurnTimeoutError from coder_eval.isolation.docker_runner import STDOUT_LINE_LIMIT_BYTES from coder_eval.models import ( @@ -110,6 +109,7 @@ TurnEndStatus, TurnStartEvent, ) +from coder_eval.timing import busy_ms from .registry import AgentRegistry @@ -294,7 +294,7 @@ def __init__(self, *, task_id: str, iteration: int, user_input: str, model: str # milliseconds twice — once here and once as the tool's own # duration_ms. Intervals, not a running total: they overlap # whenever the harness runs tools concurrently, and only their - # union may be subtracted (agents/_timing.py::busy_ms). + # union may be subtracted (timing.py::busy_ms). self.turn_tool_spans: list[tuple[datetime, datetime]] = [] # toolCallId -> telemetry for tools awaiting a result. diff --git a/src/coder_eval/models/results.py b/src/coder_eval/models/results.py index a12bddd2..765fc281 100644 --- a/src/coder_eval/models/results.py +++ b/src/coder_eval/models/results.py @@ -325,6 +325,29 @@ class TurnRecord(BaseModel): ) timestamp: datetime = Field(default_factory=datetime.now, description="When this turn occurred") duration_seconds: float = Field(default=0.0, description="How long this turn took") + harness_startup_ms: float | None = Field( + default=None, + description=( + "Wall milliseconds between the agent turn starting and the first generation window " + "opening, measured between AGENT EVENT stamps — not from timestamp/duration_seconds " + "above, which are orchestrator-level and a slightly different clock, so a consumer " + "recomputing this from those will get a near-but-not-equal number. Its COMPOSITION " + "differs per harness and is deliberately not decomposed: on an in-process SDK the " + "first window already covers dispatch and time-to-first-token so this reads ~0, while " + "on a subprocess harness it fuses CLI boot, provider resolution, dispatch and TTFT, " + "which the event stream gives no marker to separate. See docs/agents/HARNESS_PARITY.md. " + "None when the turn produced no assistant message — never 0.0, which would mean " + "'measured, and instant'." + ), + ) + harness_teardown_ms: float | None = Field( + default=None, + description=( + "Wall milliseconds between the last generation window closing and the agent turn " + "ending: SDK/CLI finalization, result assembly and process teardown. Same clock " + "caveat as harness_startup_ms. None when the turn produced no assistant message." + ), + ) token_usage: TokenUsage | None = Field( default=None, description="Token usage for this turn (if available from agent SDK)" ) diff --git a/src/coder_eval/models/telemetry.py b/src/coder_eval/models/telemetry.py index 15a18430..65a8f5ac 100644 --- a/src/coder_eval/models/telemetry.py +++ b/src/coder_eval/models/telemetry.py @@ -228,10 +228,17 @@ class AssistantMessage(BaseModel): "Model-generation time for this emission, in milliseconds. None when the harness " "surfaced the message with no measurable window (a rollout rebuild, or a sub-agent " "generation delivered as a tool result). Equals completed_at - started_at only when " - "no tool execution closed inside the window; a harness whose stream interleaves tool " - "calls into one generation (Antigravity) subtracts those. The property this field exists " - "to make true — once every harness records a real window — is: " - "sum(generation_duration_ms) + sum(command duration_ms) ~= turn duration_seconds. " + "no tool execution closed inside the window; every harness subtracts tool time that " + "ran inside one (claude-code does it at finalization, the other four as they flush). " + "The property this field exists " + "to make true — once every harness records a real window — is the FOUR-bucket identity: " + "sum(generation_duration_ms) + UNION(command execution intervals) " + "+ TurnRecord.harness_startup_ms + TurnRecord.harness_teardown_ms ~= turn duration_seconds. " + "The tool term is the union and not the sum for the same reason the subtraction above " + "uses one (timing.py::busy_ms): concurrent tool calls otherwise book their overlap twice. " + "The last two are the turn's " + "head and tail, which no message can carry because they are the wall clock OUTSIDE every " + "generation window; without them the identity holds only on a harness with no CLI to boot. " "Per-harness status is in docs/agents/HARNESS_PARITY.md; do not assume it holds " "for a harness that table does not yet claim it for." ), diff --git a/src/coder_eval/streaming/collector.py b/src/coder_eval/streaming/collector.py index ebac3ee9..2a4e1e17 100644 --- a/src/coder_eval/streaming/collector.py +++ b/src/coder_eval/streaming/collector.py @@ -22,6 +22,8 @@ from __future__ import annotations +from datetime import datetime + from coder_eval.models import ( AssistantMessage, CommandTelemetry, @@ -37,6 +39,7 @@ ToolEndEvent, TurnStartEvent, ) +from coder_eval.timing import decompose_turn class EventCollector: @@ -54,6 +57,8 @@ def __init__(self) -> None: self._user_input: str = "" self._model: str | None = None self._turn_starts: int = 0 + # Stamped by AgentStartEvent; the head is measured from it. + self._agent_start_at: datetime | None = None # tool_id -> finalized telemetry (last ToolEnd wins, mirroring last-result-wins). self._commands: dict[str, CommandTelemetry] = {} self._agent_end: AgentEndEvent | None = None @@ -71,6 +76,13 @@ def on_event(self, event: StreamEvent) -> None: if isinstance(event, AgentStartEvent): self._iteration = event.iteration self._user_input = event.prompt + self._agent_start_at = event.timestamp + # A new turn has begun, so the previous turn's terminal event is no + # longer this turn's. Every agent builds a fresh collector per + # communicate(), but EarlyStopWatcher keeps ONE across retries: left + # stale, it would pair this attempt's start with the last attempt's + # end and publish the clamped inversion as a measured 0.0. + self._agent_end = None if event.model: self._model = event.model elif isinstance(event, TurnStartEvent): @@ -103,6 +115,48 @@ def visible_turn_count(self) -> int: def _ordered_commands(self) -> list[CommandTelemetry]: return sorted(self._commands.values(), key=lambda c: c.sequence_number) + def _overhead_ms(self, messages: list[TranscriptMessage]) -> tuple[float | None, float | None]: + """The turn's head and tail — the wall clock the generations do not cover. + + Measured against ``AssistantMessage`` entries only: a simulation turn + interleaves ``UserMessage`` entries, and a reconciled turn ends with a + ``ReconciliationMessage`` that carries no timestamps at all, so indexing + the raw list would measure the wrong thing or raise. + + Two further restrictions, both of which are the difference between a + measurement and an invention: + + A message whose ``generation_duration_ms`` is ``None`` is SKIPPED. That + field is the codebase's own marker for "no window was measurable here", + and every producer of one stamps ``started_at == completed_at == + datetime.now()`` at *append* time as an admitted placeholder — Codex's + rollout rebuild (``_messages_from_items``), both Codex sub-agent + recovery builders, and Claude's ``_synthesize_subagent_terminal_message``. + Reading those stamps as window bounds turns a placeholder into a + measurement: a Codex turn rebuilt from its rollout stamps every message + at turn END, which would book the entire turn as harness startup. It is + the same exemption CE059 makes for exactly the same reason. + + ``min`` / ``max`` rather than the first and last list entries, because + the list is not ordered by time — Codex appends recovered sub-agent + messages after the parent's last flush. Positional access made the + result depend on append order, which nothing enforces. + """ + generations = [m for m in messages if isinstance(m, AssistantMessage) and m.generation_duration_ms is not None] + if not generations: + return None, None + return decompose_turn( + min(m.started_at for m in generations), + max(m.completed_at for m in generations), + self._agent_start_at, + self._agent_end.timestamp if self._agent_end is not None else None, + [ + (c.execution_started_at, c.execution_completed_at) + for c in self._commands.values() + if c.execution_started_at is not None and c.execution_completed_at is not None + ], + ) + @staticmethod def _reconciled_messages(messages: list[TranscriptMessage], usage: TokenUsage) -> list[TranscriptMessage]: """Append a ``ReconciliationMessage`` so the transcript's token buckets @@ -193,6 +247,8 @@ def build_turn_record(self) -> TurnRecord: if token_usage is not None: messages = self._reconciled_messages(messages, token_usage) + startup_ms, teardown_ms = self._overhead_ms(messages) + return TurnRecord( iteration=end.iteration or self._iteration, user_input=end.user_input or self._user_input, @@ -208,4 +264,6 @@ def build_turn_record(self) -> TurnRecord: result_summary=end.result_summary, crashed=end.crashed, crash_reason=end.crash_reason, + harness_startup_ms=startup_ms, + harness_teardown_ms=teardown_ms, ) diff --git a/src/coder_eval/timing.py b/src/coder_eval/timing.py new file mode 100644 index 00000000..66f4a1a1 --- /dev/null +++ b/src/coder_eval/timing.py @@ -0,0 +1,114 @@ +"""Wall-clock arithmetic for a turn, defined once and shared. + +A cycle-free leaf (the ``models/cli_match.py`` rationale): it sits outside +``agents/`` because ``EventCollector`` consumes it, and importing anything +under ``agents/`` pulls in every agent, which imports ``streaming/``. + +Two harnesses interleave tool execution into a single generation window — +Antigravity (the Step for the tool arrives and only a later ``usage_metadata`` +Step cuts the message) and Codex (``_flush_message``'s window is extended to +the last item's ``completed_at_ms``). Both must therefore subtract the tool +time from the window before publishing ``generation_duration_ms``, and both +must subtract the same thing: the UNION of the closed intervals, clipped to +the window. +""" + +from datetime import datetime + + +def busy_ms(spans: list[tuple[datetime, datetime]], lo: datetime, hi: datetime) -> float: + """Wall milliseconds inside ``[lo, hi]`` where at least ONE span was running. + + The union, not the sum. Tool intervals overlap in practice — Antigravity + resolves several calls from one ``Step`` and backgrounds anything over ten + seconds; Codex spawns collab agents that run concurrently — so adding + their durations over-counts the busy time by exactly the overlap. + Subtracting such a sum from a generation window understates generation + and, with enough concurrency, drives it negative: four concurrent 400 ms + calls inside a 1000 ms window sum to 1600 ms, clamping the result to the + ``0.0`` that "unknown timing says unknown" exists to eliminate. + + Clipping to ``[lo, hi]`` is the other half: a tool that opened before this + window only spent part of its life inside it, and only that part is not + generation time here. + """ + clipped = sorted((max(s, lo), min(e, hi)) for s, e in spans if min(e, hi) > max(s, lo)) + if not clipped: + return 0.0 + total = 0.0 + open_start, open_end = clipped[0] + for start, end in clipped[1:]: + if start > open_end: # disjoint — bank the run and start a new one + total += (open_end - open_start).total_seconds() * 1000.0 + open_start, open_end = start, end + else: # overlapping or adjacent — extend the run + open_end = max(open_end, end) + return total + (open_end - open_start).total_seconds() * 1000.0 + + +def decompose_turn( + first_started_at: datetime | None, + last_completed_at: datetime | None, + agent_started_at: datetime | None, + agent_ended_at: datetime | None, + tool_spans: list[tuple[datetime, datetime]] | None = None, +) -> tuple[float | None, float | None]: + """Wall ms before the first generation window opens, and after the last closes. + + The turn's two unexplained ends. Between them the windows tile (each + harness's generation mark runs to the next) and tool execution is already + subtracted inside them, so head + generation + UNION(tool) + tail is the + whole turn — the union and not the sum, because concurrent tool calls + otherwise book their overlap twice (``busy_ms`` above, and measured: one + live Pi turn overlapped a ``Write`` and a ``Bash`` by 18.4 ms). + + ``tool_spans`` is what keeps those four buckets DISJOINT, and omitting it + is a double-count rather than a lost refinement. A tool is not confined to + a generation window: Antigravity force-closes an orphan at finalization + (``antigravity_agent.py``), which stamps its completion inside the tail, + and it backgrounds anything over ten seconds, which can straddle either + end. Such a span is subtracted out of the windows AND counted in the tool + bucket, so leaving it in the head or tail books it twice — measured on the + committed ``antigravity_d_orphaned_tool`` fixture as a residual of -86% of + wall clock. So the head and tail exclude tool time by the same rule and + the same helper the windows use. + + ``EventCollector`` is the SOLE caller, and deliberately so: this is the one + place the two values are computed, after which they are persisted on + ``TurnRecord`` and every later consumer READS them rather than recomputing. + The golden-stream sensor asserts on the dumped record, and + ``scripts/timing/decompose_run.py`` reads the stored fields — neither can + call this, because ``task.json`` carries no ``AgentStartEvent`` stamp to + recompute a head from. + + What the head CONTAINS differs per harness and is deliberately NOT split. + On an in-process SDK the first window already covers dispatch and + time-to-first-token, so this reads ~0; on a subprocess harness it fuses CLI + boot, provider resolution, dispatch and TTFT, and the stream carries no + marker between them — measured on OpenCode, the process spawns in 3 ms and + the first event lands at 3921 ms. Naming these for the interval they + MEASURE rather than for what they contain is the whole point; see + docs/agents/HARNESS_PARITY.md for the per-harness composition. + + ``None`` means never measured — a turn that produced no generation, or a + snapshot taken before the terminal event. Never 0.0, which would claim a + measurement was taken and came back instant (CE058). A measured inversion + (the two clocks disagreeing) IS a real zero and clamps, because both ends + were observed. + + NOTE the four-bucket identity has a second implementation in TypeScript — + the evalboard's Unaccounted cell (``_sections.tsx``) subtracts the same + buckets from the same wall clock, as ``pricing.ts`` mirrors ``pricing.py``. + It does not recompute a head or a tail (it reads the stored fields), so a + change HERE needs a TS change only when it alters what the buckets mean; + adding a fifth bucket means touching that cell and ``sumHarnessOverhead``. + """ + spans = tool_spans or [] + head = tail = None + if first_started_at is not None and agent_started_at is not None: + elapsed = (first_started_at - agent_started_at).total_seconds() * 1000.0 + head = max(elapsed - busy_ms(spans, agent_started_at, first_started_at), 0.0) + if last_completed_at is not None and agent_ended_at is not None: + elapsed = (agent_ended_at - last_completed_at).total_seconds() * 1000.0 + tail = max(elapsed - busy_ms(spans, last_completed_at, agent_ended_at), 0.0) + return head, tail diff --git a/tests/_fixtures/golden_streams/_scrub.py b/tests/_fixtures/golden_streams/_scrub.py index c84cc77d..9fb4705f 100644 --- a/tests/_fixtures/golden_streams/_scrub.py +++ b/tests/_fixtures/golden_streams/_scrub.py @@ -2,8 +2,11 @@ from __future__ import annotations +from datetime import datetime from typing import Any +from coder_eval.timing import busy_ms + SCRUB_PLACEHOLDER = "" @@ -24,6 +27,11 @@ "duration_ms", "duration_seconds", "generation_duration_ms", + # Measured wall intervals like the two above, so they vary run to run; + # masking keeps None-vs-set (the meaningful distinction) visible while + # the value itself stays out of the snapshot. + "harness_startup_ms", + "harness_teardown_ms", # Cost is a rate-card-dependent float (and is backfilled from the rate # card on timeout/kill), so it is masked too — keeping the snapshot # rate-card-independent. The integer TOKEN buckets stay EXACT; those are @@ -99,7 +107,41 @@ def assert_reconciliation(record: dict[str, Any]) -> None: assert cr_sum == usage["cache_read_input_tokens"], "cache_read bucket does not reconcile" -def assert_timing_captured(record: dict[str, Any], *, expect_generation_window: bool) -> None: +# The four buckets are disjoint by construction, so their sum cannot exceed the +# turn's own wall clock. Flag only an overshoot past BOTH bounds: the relative +# one is what catches the defect (an orphaned tool double-booked into the tail +# read +55% of wall on ``antigravity_d_orphaned_tool``), and the absolute floor +# keeps a replay whose whole turn is 40 microseconds from failing on scheduler +# jitter. Healthy fixtures overshoot by at most 0.003 ms / 2%. +_IDENTITY_FLOOR_MS = 0.1 +_IDENTITY_SHARE = 0.20 + + +def _tool_union_ms(record: dict[str, Any]) -> float: + """Wall ms this turn spent executing tools — the union, never the sum.""" + spans: list[tuple[datetime, datetime]] = [] + for command in record.get("commands") or []: + start = _parse_stamp(command.get("execution_started_at")) + end = _parse_stamp(command.get("execution_completed_at")) + if start is not None and end is not None and end >= start: + spans.append((start, end)) + if not spans: + return 0.0 + return busy_ms(spans, min(s for s, _ in spans), max(e for _, e in spans)) + + +def _parse_stamp(value: Any) -> datetime | None: + if not isinstance(value, str): + return None + try: + return datetime.fromisoformat(value) + except ValueError: + return None + + +def assert_timing_captured( + record: dict[str, Any], *, expect_generation_window: bool, check_identity: bool = True +) -> None: """Assert a TurnRecord dump actually recorded the timing it could measure. Run on the UNSCRUBBED dump. ``scrub()`` masks values but preserves ``None`` @@ -130,6 +172,42 @@ def assert_timing_captured(record: dict[str, Any], *, expect_generation_window: bounds are the same ``ast.Name``; when they are two different names holding the same value it cannot, and this is the check that does. + **Unconditional, and keyed on the messages rather than on the flag.** A + turn's head and tail (``harness_startup_ms`` / ``harness_teardown_ms``) are + set exactly when the turn produced an assistant message with a MEASURABLE + window, because that is what the collector measures them against — so both + are non-``None`` when one exists and both are ``None`` when none does. + + Both halves of that key are load-bearing. The flag is the wrong one: + ``codex_e_orphan_tool`` streams a generation whose window subtracts to + zero, so it clears the flag while still having a head and a tail to report. + And "any assistant message" is too weak: ``codex_g_items_rebuild`` rebuilds + its transcript from the rollout after the turn ended, with + ``generation_duration_ms=None`` and placeholder ``now()`` bounds, so there + is nothing there to measure an end against and the honest answer is + ``None`` for both. + + PRESENCE is all the fixtures can support, and it is the thing worth + asserting: the replays run in ~0.3 ms of synthetic wall clock, so their + head and tail are microseconds and any bound or ordering check would be + noise. A ``>= 0`` check would be worse than noise — ``decompose_turn`` + clamps with ``max(..., 0.0)``, so it would restate the implementation and + could never fail. + + **The four-bucket identity**, when ``check_identity``. Generation plus the + UNION of the tool intervals plus the head plus the tail cannot exceed the + turn's ``duration_seconds``, because the four are disjoint: the windows are + tool-subtracted and so are the head and tail. This is the one assertion + that catches a DOUBLE-COUNT rather than an absence — it is how an orphaned + tool force-closed inside the tail, booked both as tool and as teardown, was + found reconciling at -86% of wall clock while all 72 golden tests passed. + + ``check_identity`` is off for the scenarios that inject their own SDK + timestamps (see ``FICTIONAL_DURATIONS``): those declare integer-millisecond + item durations of 17-900 ms while the replay itself takes ~0.3 ms of real + wall clock, so no rebasing can make the two commensurable — the SDK's + stamps are milliseconds and the replay is faster than one. + Why a scenario-level floor rather than a per-entry rule: no per-entry form works against the real snapshots. ``claude_d_subagent_terminal`` holds two content-bearing assistant messages of which exactly one is legitimately @@ -149,9 +227,54 @@ def assert_timing_captured(record: dict[str, Any], *, expect_generation_window: "returned was timed, so the record must say when and for how long" ) + assistant = [m for m in record.get("messages") or [] if m.get("role") == "assistant"] + measurable = [m for m in assistant if m.get("generation_duration_ms") is not None] + for field in ("harness_startup_ms", "harness_teardown_ms"): + value = record.get(field) + if measurable: + assert value is not None, ( + f"{field} is None on a turn carrying {len(measurable)} measurable generation " + "window(s): the collector measures the head and tail against the earliest and " + "latest of those, so a turn that generated has both — None says never measured" + ) + else: + assert value is None, ( + f"{field} is {value!r} on a turn with no measurable generation window " + f"({len(assistant)} assistant message(s), none reporting a duration): there is " + "nothing to measure an end against, and a number here claims a measurement " + "nobody could have taken" + ) + + if check_identity: + wall_ms = (record.get("duration_seconds") or 0.0) * 1000.0 + # Main thread only: a sub-agent's generations bubble into the same + # stream, and the spawning Agent call's own interval already spans them. + generation_ms = sum( + m.get("generation_duration_ms") or 0.0 + for m in record.get("messages") or [] + if m.get("role") == "assistant" and m.get("parent_tool_use_id") is None + ) + tool_ms = _tool_union_ms(record) + bucket_sum = ( + generation_ms + + tool_ms + + (record.get("harness_startup_ms") or 0.0) + + (record.get("harness_teardown_ms") or 0.0) + ) + overshoot = bucket_sum - wall_ms + assert overshoot <= max(_IDENTITY_FLOOR_MS, _IDENTITY_SHARE * wall_ms), ( + f"the four buckets sum to {bucket_sum:.4f} ms against a {wall_ms:.4f} ms turn " + f"(over by {overshoot:.4f} ms): generation={generation_ms:.4f}, tool_union={tool_ms:.4f}, " + f"startup={record.get('harness_startup_ms')!r}, teardown={record.get('harness_teardown_ms')!r}. " + "They are meant to be DISJOINT, so a sum this far over the turn means something is " + "booked twice — most likely a tool that ran outside every generation window and was " + "left in the head or tail as well as in the tool union, or a generation window that " + "kept tool time it should have subtracted (see docs/agents/HARNESS_PARITY.md — all " + "five harnesses subtract, claude-code at finalization rather than as it flushes)" + ) + if not expect_generation_window: return - assistant = [m for m in record.get("messages") or [] if m.get("role") == "assistant"] windows = [(m.get("generation_duration_ms"), m.get("started_at"), m.get("completed_at")) for m in assistant] assert any( duration is not None and duration > 0 and started is not None and completed is not None and completed > started diff --git a/tests/_fixtures/golden_streams/codex_fixtures.py b/tests/_fixtures/golden_streams/codex_fixtures.py index 30008af7..a04def75 100644 --- a/tests/_fixtures/golden_streams/codex_fixtures.py +++ b/tests/_fixtures/golden_streams/codex_fixtures.py @@ -13,6 +13,7 @@ import os from dataclasses import dataclass +from datetime import datetime from pathlib import Path from types import SimpleNamespace from typing import Any @@ -26,12 +27,23 @@ CODEX_MODEL = "gpt-5-codex" +# How far after the replay's start the rebased timeline begins. Small, but +# non-zero so the first generation window opens AFTER the AgentStartEvent and +# the head is a measured interval instead of a clamped inversion. +_REPLAY_LEAD_MS = 2 + # --- Notification factories (mirror test_codex_agent) ----------------------- # Fixed epoch milliseconds, so every derived duration is deterministic and the -# golden snapshots pin a real value rather than a scrubbed clock read. +# golden snapshots pin a real value rather than a scrubbed clock read. It is a +# BASE, not a wall-clock claim: ``_rebase_notifications`` shifts the whole +# timeline onto the replay's own clock before the scenario runs, so the SDK +# stamps and the agent's own event stamps are commensurable. Left absolute, +# a codex replay recorded a ``harness_startup_ms`` of ~126 DAYS — the agent +# events are stamped ``now()`` while these sat in 2027 — which is a number no +# presence-only assertion can catch. _T0_MS = 1_800_000_000_000 @@ -314,6 +326,40 @@ def turn(self, _user_input: str) -> _FakeTurnHandle: return _FakeTurnHandle(self._notifications) +def _rebase_notifications(notifications: list[Any]) -> list[Any]: + """Shift every SDK item stamp from ``_T0_MS`` onto the replay's own clock. + + The scenario catalogue is built once at import with an absolute base, which + keeps every DERIVED duration deterministic (a 250 ms command stays 250 ms). + But the agent stamps its own lifecycle events with ``datetime.now()``, so + left absolute the two clocks are months apart and the recorded head and + tail are nonsense. Rebasing keeps the deltas and fixes the era. + + The offset puts the first item a beat AFTER the replay starts, so the head + is a small positive interval rather than an inversion clamped to 0.0. + """ + offset = int(datetime.now().timestamp() * 1000) - _T0_MS + _REPLAY_LEAD_MS + rebased: list[Any] = [] + for note in notifications: + payload = getattr(note, "payload", None) + started = getattr(payload, "started_at_ms", None) + completed = getattr(payload, "completed_at_ms", None) + if payload is None or (started is None and completed is None): + rebased.append(note) + continue + rebased.append( + SimpleNamespace( + method=note.method, + payload=SimpleNamespace( + item=payload.item, + started_at_ms=None if started is None else started + offset, + completed_at_ms=None if completed is None else completed + offset, + ), + ) + ) + return rebased + + async def run_codex_scenario(scenario: CodexScenario, working_dir: str) -> dict[str, Any]: """Run ``scenario`` with fakes and return the TurnRecord/pending_turn dump.""" import pytest @@ -322,7 +368,7 @@ async def run_codex_scenario(scenario: CodexScenario, working_dir: str) -> dict[ agent = CodexAgent(config) agent.working_directory = Path(working_dir) agent.codex_client = SimpleNamespace(close=lambda: None) - agent.thread = _FakeThread(scenario.notifications) + agent.thread = _FakeThread(_rebase_notifications(scenario.notifications)) # Point CODEX_HOME at a sessions-less dir so sub-agent rollout recovery # short-circuits instead of polling the real ~/.codex. diff --git a/tests/_fixtures/golden_streams/expected/antigravity_a_single_text_turn.json b/tests/_fixtures/golden_streams/expected/antigravity_a_single_text_turn.json index e388dae4..915390ff 100644 --- a/tests/_fixtures/golden_streams/expected/antigravity_a_single_text_turn.json +++ b/tests/_fixtures/golden_streams/expected/antigravity_a_single_text_turn.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ @@ -25,7 +27,7 @@ ], "generation_duration_ms": "", "input_tokens": 100, - "message_id": null, + "message_id": "antigravity-1-msg-0", "model": "gemini-3.5-flash", "output_tokens": 20, "parent_tool_use_id": null, diff --git a/tests/_fixtures/golden_streams/expected/antigravity_b_tool_call_resolved.json b/tests/_fixtures/golden_streams/expected/antigravity_b_tool_call_resolved.json index 062c9556..bda60126 100644 --- a/tests/_fixtures/golden_streams/expected/antigravity_b_tool_call_resolved.json +++ b/tests/_fixtures/golden_streams/expected/antigravity_b_tool_call_resolved.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ @@ -54,7 +56,7 @@ ], "generation_duration_ms": "", "input_tokens": 120, - "message_id": null, + "message_id": "antigravity-1-msg-0", "model": "gemini-3.5-flash", "output_tokens": 15, "parent_tool_use_id": null, diff --git a/tests/_fixtures/golden_streams/expected/antigravity_c_thinking_and_tool_same_generation.json b/tests/_fixtures/golden_streams/expected/antigravity_c_thinking_and_tool_same_generation.json index c767a652..56138f54 100644 --- a/tests/_fixtures/golden_streams/expected/antigravity_c_thinking_and_tool_same_generation.json +++ b/tests/_fixtures/golden_streams/expected/antigravity_c_thinking_and_tool_same_generation.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ @@ -63,7 +65,7 @@ ], "generation_duration_ms": "", "input_tokens": 200, - "message_id": null, + "message_id": "antigravity-1-msg-0", "model": "gemini-3.5-flash", "output_tokens": 50, "parent_tool_use_id": null, diff --git a/tests/_fixtures/golden_streams/expected/antigravity_d_orphaned_tool.json b/tests/_fixtures/golden_streams/expected/antigravity_d_orphaned_tool.json index 2cc1c723..02f13064 100644 --- a/tests/_fixtures/golden_streams/expected/antigravity_d_orphaned_tool.json +++ b/tests/_fixtures/golden_streams/expected/antigravity_d_orphaned_tool.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ @@ -45,7 +47,7 @@ ], "generation_duration_ms": "", "input_tokens": 90, - "message_id": null, + "message_id": "antigravity-1-msg-0", "model": "gemini-3.5-flash", "output_tokens": 10, "parent_tool_use_id": null, diff --git a/tests/_fixtures/golden_streams/expected/antigravity_e_multi_generation.json b/tests/_fixtures/golden_streams/expected/antigravity_e_multi_generation.json index ee0f36cb..1b69cc78 100644 --- a/tests/_fixtures/golden_streams/expected/antigravity_e_multi_generation.json +++ b/tests/_fixtures/golden_streams/expected/antigravity_e_multi_generation.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ @@ -25,7 +27,7 @@ ], "generation_duration_ms": "", "input_tokens": 100, - "message_id": null, + "message_id": "antigravity-1-msg-0", "model": "gemini-3.5-flash", "output_tokens": 15, "parent_tool_use_id": null, @@ -52,7 +54,7 @@ ], "generation_duration_ms": "", "input_tokens": 110, - "message_id": null, + "message_id": "antigravity-1-msg-1", "model": "gemini-3.5-flash", "output_tokens": 18, "parent_tool_use_id": null, @@ -79,7 +81,7 @@ ], "generation_duration_ms": "", "input_tokens": 120, - "message_id": null, + "message_id": "antigravity-1-msg-2", "model": "gemini-3.5-flash", "output_tokens": 14, "parent_tool_use_id": null, diff --git a/tests/_fixtures/golden_streams/expected/claude_a_single_text_turn.json b/tests/_fixtures/golden_streams/expected/claude_a_single_text_turn.json index febe95e0..7dd57bd4 100644 --- a/tests/_fixtures/golden_streams/expected/claude_a_single_text_turn.json +++ b/tests/_fixtures/golden_streams/expected/claude_a_single_text_turn.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/claude_b_tool_use_result.json b/tests/_fixtures/golden_streams/expected/claude_b_tool_use_result.json index 3ef5f669..d94df272 100644 --- a/tests/_fixtures/golden_streams/expected/claude_b_tool_use_result.json +++ b/tests/_fixtures/golden_streams/expected/claude_b_tool_use_result.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/claude_c_multi_emission_delta.json b/tests/_fixtures/golden_streams/expected/claude_c_multi_emission_delta.json index 00d6f778..0644c58c 100644 --- a/tests/_fixtures/golden_streams/expected/claude_c_multi_emission_delta.json +++ b/tests/_fixtures/golden_streams/expected/claude_c_multi_emission_delta.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/claude_d_subagent_terminal.json b/tests/_fixtures/golden_streams/expected/claude_d_subagent_terminal.json index 943e0ef7..37c18d97 100644 --- a/tests/_fixtures/golden_streams/expected/claude_d_subagent_terminal.json +++ b/tests/_fixtures/golden_streams/expected/claude_d_subagent_terminal.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/claude_e_model_usage_and_backfill.json b/tests/_fixtures/golden_streams/expected/claude_e_model_usage_and_backfill.json index 782fa203..88ee7a64 100644 --- a/tests/_fixtures/golden_streams/expected/claude_e_model_usage_and_backfill.json +++ b/tests/_fixtures/golden_streams/expected/claude_e_model_usage_and_backfill.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/claude_f_orphaned_tool.json b/tests/_fixtures/golden_streams/expected/claude_f_orphaned_tool.json index cae8354c..9195adde 100644 --- a/tests/_fixtures/golden_streams/expected/claude_f_orphaned_tool.json +++ b/tests/_fixtures/golden_streams/expected/claude_f_orphaned_tool.json @@ -26,6 +26,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/claude_g_crash_format_placeholder.json b/tests/_fixtures/golden_streams/expected/claude_g_crash_format_placeholder.json index d615eae2..4e60e81d 100644 --- a/tests/_fixtures/golden_streams/expected/claude_g_crash_format_placeholder.json +++ b/tests/_fixtures/golden_streams/expected/claude_g_crash_format_placeholder.json @@ -5,6 +5,8 @@ "crash_reason": "Communication with agent failed: crash after poison\nStderr output:\nNo stderr captured", "crashed": true, "duration_seconds": "", + "harness_startup_ms": null, + "harness_teardown_ms": null, "iteration": 1, "max_turns_exhausted": false, "messages": [], diff --git a/tests/_fixtures/golden_streams/expected/claude_h1_timeout_process_error.json b/tests/_fixtures/golden_streams/expected/claude_h1_timeout_process_error.json index 2e021896..c87fb5be 100644 --- a/tests/_fixtures/golden_streams/expected/claude_h1_timeout_process_error.json +++ b/tests/_fixtures/golden_streams/expected/claude_h1_timeout_process_error.json @@ -5,6 +5,8 @@ "crash_reason": "Agent turn timed out after 30s", "crashed": true, "duration_seconds": "", + "harness_startup_ms": null, + "harness_teardown_ms": null, "iteration": 1, "max_turns_exhausted": false, "messages": [], diff --git a/tests/_fixtures/golden_streams/expected/claude_h2_process_error_crash.json b/tests/_fixtures/golden_streams/expected/claude_h2_process_error_crash.json index dcdd6042..bf0c6715 100644 --- a/tests/_fixtures/golden_streams/expected/claude_h2_process_error_crash.json +++ b/tests/_fixtures/golden_streams/expected/claude_h2_process_error_crash.json @@ -5,6 +5,8 @@ "crash_reason": "CLI process failed (exit code 1): bad config", "crashed": true, "duration_seconds": "", + "harness_startup_ms": null, + "harness_teardown_ms": null, "iteration": 1, "max_turns_exhausted": false, "messages": [], diff --git a/tests/_fixtures/golden_streams/expected/claude_i_in_loop_deadline_break.json b/tests/_fixtures/golden_streams/expected/claude_i_in_loop_deadline_break.json index da8254bd..e0a00c6b 100644 --- a/tests/_fixtures/golden_streams/expected/claude_i_in_loop_deadline_break.json +++ b/tests/_fixtures/golden_streams/expected/claude_i_in_loop_deadline_break.json @@ -5,6 +5,8 @@ "crash_reason": "Agent turn timed out after 100s", "crashed": true, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_a_agent_message_only.json b/tests/_fixtures/golden_streams/expected/codex_a_agent_message_only.json index 1ef1685a..b3b0e23e 100644 --- a/tests/_fixtures/golden_streams/expected/codex_a_agent_message_only.json +++ b/tests/_fixtures/golden_streams/expected/codex_a_agent_message_only.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_b_command_execution.json b/tests/_fixtures/golden_streams/expected/codex_b_command_execution.json index 4f1ce309..df652657 100644 --- a/tests/_fixtures/golden_streams/expected/codex_b_command_execution.json +++ b/tests/_fixtures/golden_streams/expected/codex_b_command_execution.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_c_reasoning_placeholder.json b/tests/_fixtures/golden_streams/expected/codex_c_reasoning_placeholder.json index 4db03065..93b83762 100644 --- a/tests/_fixtures/golden_streams/expected/codex_c_reasoning_placeholder.json +++ b/tests/_fixtures/golden_streams/expected/codex_c_reasoning_placeholder.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_d_cross_flush_is_error.json b/tests/_fixtures/golden_streams/expected/codex_d_cross_flush_is_error.json index 55959efe..32092379 100644 --- a/tests/_fixtures/golden_streams/expected/codex_d_cross_flush_is_error.json +++ b/tests/_fixtures/golden_streams/expected/codex_d_cross_flush_is_error.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_e_orphan_tool.json b/tests/_fixtures/golden_streams/expected/codex_e_orphan_tool.json index 438c798e..81459ad0 100644 --- a/tests/_fixtures/golden_streams/expected/codex_e_orphan_tool.json +++ b/tests/_fixtures/golden_streams/expected/codex_e_orphan_tool.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_f_collab_fallback.json b/tests/_fixtures/golden_streams/expected/codex_f_collab_fallback.json index 74d457e3..b1f83b09 100644 --- a/tests/_fixtures/golden_streams/expected/codex_f_collab_fallback.json +++ b/tests/_fixtures/golden_streams/expected/codex_f_collab_fallback.json @@ -46,6 +46,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_g_items_rebuild.json b/tests/_fixtures/golden_streams/expected/codex_g_items_rebuild.json index aed8db92..75285012 100644 --- a/tests/_fixtures/golden_streams/expected/codex_g_items_rebuild.json +++ b/tests/_fixtures/golden_streams/expected/codex_g_items_rebuild.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": null, + "harness_teardown_ms": null, "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/codex_h_no_turn_completed_crash.json b/tests/_fixtures/golden_streams/expected/codex_h_no_turn_completed_crash.json index d58244c0..4828acb6 100644 --- a/tests/_fixtures/golden_streams/expected/codex_h_no_turn_completed_crash.json +++ b/tests/_fixtures/golden_streams/expected/codex_h_no_turn_completed_crash.json @@ -5,6 +5,8 @@ "crash_reason": "Codex turn failed: Turn did not complete (no turn/completed notification received)", "crashed": true, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/opencode_a_single_text_turn.json b/tests/_fixtures/golden_streams/expected/opencode_a_single_text_turn.json index 3d65a879..bc1b0dea 100644 --- a/tests/_fixtures/golden_streams/expected/opencode_a_single_text_turn.json +++ b/tests/_fixtures/golden_streams/expected/opencode_a_single_text_turn.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/opencode_b_tool_call_resolved.json b/tests/_fixtures/golden_streams/expected/opencode_b_tool_call_resolved.json index 571de997..8abfd499 100644 --- a/tests/_fixtures/golden_streams/expected/opencode_b_tool_call_resolved.json +++ b/tests/_fixtures/golden_streams/expected/opencode_b_tool_call_resolved.json @@ -25,6 +25,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/pi_a_single_text_turn.json b/tests/_fixtures/golden_streams/expected/pi_a_single_text_turn.json index 49083eac..025af6ce 100644 --- a/tests/_fixtures/golden_streams/expected/pi_a_single_text_turn.json +++ b/tests/_fixtures/golden_streams/expected/pi_a_single_text_turn.json @@ -5,6 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/expected/pi_b_tool_call_resolved.json b/tests/_fixtures/golden_streams/expected/pi_b_tool_call_resolved.json index a1c1aa85..f256747c 100644 --- a/tests/_fixtures/golden_streams/expected/pi_b_tool_call_resolved.json +++ b/tests/_fixtures/golden_streams/expected/pi_b_tool_call_resolved.json @@ -45,6 +45,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", + "harness_startup_ms": "", + "harness_teardown_ms": "", "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/_fixtures/golden_streams/opencode_fixtures.py b/tests/_fixtures/golden_streams/opencode_fixtures.py index f88c6a32..5a86908d 100644 --- a/tests/_fixtures/golden_streams/opencode_fixtures.py +++ b/tests/_fixtures/golden_streams/opencode_fixtures.py @@ -25,6 +25,7 @@ import json import os from dataclasses import dataclass +from datetime import datetime from typing import Any from unittest.mock import patch @@ -35,13 +36,49 @@ SESSION = "ses_test123" +# Base epoch milliseconds for the recorded stream. A BASE, not a wall-clock +# claim: `_rebase_lines` shifts the whole timeline onto the replay's own clock +# before the scenario runs, so these stamps and the agent's own `datetime.now()` +# event stamps are commensurable. Left absolute they sit a month away from the +# replay, which puts the recorded tool interval outside every measured window. +_T0_MS = 1_786_663_016_802 + +# How far after the replay's start the rebased timeline begins — small, but +# non-zero so the first window opens after the AgentStartEvent. +_REPLAY_LEAD_MS = 2 + + def _evt(event_type: str, part: dict[str, Any]) -> str: """One CLI event line: payload under ``part``, sessionID on the envelope.""" return json.dumps( - {"type": event_type, "timestamp": 1786663016802, "sessionID": SESSION, "part": {"sessionID": SESSION, **part}} + {"type": event_type, "timestamp": _T0_MS, "sessionID": SESSION, "part": {"sessionID": SESSION, **part}} ) +def _rebase_lines(lines: list[str]) -> list[str]: + """Shift every recorded stamp from ``_T0_MS`` onto the replay's own clock. + + Keeps every DERIVED duration exact (a 17 ms tool stays 17 ms) and fixes + only the era, so the head and tail the collector records against the + agent's `datetime.now()` stamps are meaningful rather than a month wide. + """ + offset = int(datetime.now().timestamp() * 1000) - _T0_MS + _REPLAY_LEAD_MS + + def shift(node: Any) -> Any: + if isinstance(node, dict): + return {k: (v + offset if k in _STAMP_KEYS and isinstance(v, int) else shift(v)) for k, v in node.items()} + if isinstance(node, list): + return [shift(v) for v in node] + return node + + return [json.dumps(shift(json.loads(line))) for line in lines] + + +# Millisecond-epoch keys anywhere in an event payload: the envelope's own +# stamp, and a tool's `state.time` bounds. +_STAMP_KEYS = frozenset({"timestamp", "start", "end"}) + + def _tokens(inp: int, out: int, *, write: int = 0, read: int = 0, reasoning: int = 0) -> dict[str, Any]: """Token payload in the NESTED convention (total = input+output+reasoning, cache counted inside `input`); see TestTokenShapeIsObservable for the flat one.""" @@ -175,7 +212,7 @@ class OpenCodeScenario: async def run_opencode_scenario(scenario: OpenCodeScenario, working_dir: str) -> dict[str, Any]: """Replay one scenario and return the resulting record as a plain dump.""" - proc = _FakeProcess(scenario.lines) + proc = _FakeProcess(_rebase_lines(scenario.lines)) async def fake_exec(*_argv: str, **_kwargs: Any) -> _FakeProcess: proc.stderr = proc # type: ignore[assignment] diff --git a/tests/lint/rules/ce058_no_timing_literal.py b/tests/lint/rules/ce058_no_timing_literal.py index 45bae047..9021fed8 100644 --- a/tests/lint/rules/ce058_no_timing_literal.py +++ b/tests/lint/rules/ce058_no_timing_literal.py @@ -15,6 +15,15 @@ milliseconds by a command count of which 70 of 211 in one nightly had never been timed at all. +A third field family joined the first two: ``TurnRecord.harness_startup_ms`` +and ``harness_teardown_ms``, the turn's head and tail buckets. They are the +same invariant one level up — a turn whose stream carried no assistant message +was never timed at either end, and a ``0.0`` there would claim the harness +started instantly, which is exactly the reading that sends a real gap into the +evalboard's ``Unaccounted`` cell while a named bucket says it was measured at +zero. ``0.0`` IS the right answer for an in-process SDK whose first generation +window already covers dispatch, so the two values must stay distinguishable. + Five syntactic forms, one invariant, one id — the shapes the codebase actually produced: @@ -47,16 +56,20 @@ # Trailing-segment match, so `cmd.duration_ms` and `generation_duration_ms` -# fire while `duration_ms_limit` does not. +# fire while `duration_ms_limit` does not. The `_startup_ms` / `_teardown_ms` +# arms need a leading segment for the same reason the `_duration_ms` arm does: +# the shipped fields are `harness_*`, and a bare `startup_ms` is more likely a +# budget than a measurement. _TIMING_NAME = re.compile( - r"^(duration_ms|generation_duration_ms|total_command_time_ms|avg_command_time_ms|[a-z_]*_duration_ms)$" + r"^(duration_ms|generation_duration_ms|total_command_time_ms|avg_command_time_ms" + r"|[a-z_]*_duration_ms|[a-z_]*_(?:startup|teardown)_ms)$" ) # The constructors that carry a timing field. Keying on the callee name is what # makes the alias hazard above real; it is also the only thing an AST rule can # see without type inference. _TIMING_CONSTRUCTORS = frozenset( - {"AssistantMessage", "AssistantMessageTelemetry", "CommandTelemetry", "SlowestCommandInfo"} + {"AssistantMessage", "AssistantMessageTelemetry", "CommandTelemetry", "SlowestCommandInfo", "TurnRecord"} ) _SRC_ROOT = re.compile(r"(?:^|[/\\])src[/\\]coder_eval[/\\]") diff --git a/tests/lint/rules/ce060_message_id_declared.py b/tests/lint/rules/ce060_message_id_declared.py new file mode 100644 index 00000000..aeb31fdd --- /dev/null +++ b/tests/lint/rules/ce060_message_id_declared.py @@ -0,0 +1,148 @@ +"""CE060: an assistant message must declare its identity. + +``AssistantMessage.message_id`` is what lets a consumer tell two generations +apart. Antigravity simply omitted the kwarg, so the field defaulted to ``None`` +on every message it ever recorded, and the evalboard — which groups assistant +emissions by ``message_id`` and falls back to a wall-clock ``SAME_EMISSION_GAP_MS`` +threshold when either side lacks one — folded a whole turn's generations into a +single timeline row once the harness's windows became contiguous. Nothing +failed: the consumer sums a group, so every total came out right, and the +golden snapshots had ratified the ``null`` the day they were written. It was +not confined to the timeline either — a grouped emission is one API call to the +thinking-cost simulator, so its whole cache cascade was computed from one call +per turn. The mechanism and the blast radius live in +``docs/agents/HARNESS_PARITY.md`` § Timing capture; neither is restated here. + +Separate id from CE058 and CE059 deliberately: those two are about *timing* +(an unknown duration published as a literal, a window built from one clock +read), this one is about *identity*. One invariant per id is what makes a +``# noqa`` mean one thing. + +WHY IT RESOLVES ALIASES where CE058 and CE059 hardcode constructor names: +CE058's own docstring already concedes that spelling-based matching dies on a +rename, and the weakness is live — ``claude_code_agent.py`` binds *only* +``AssistantMessage as AssistantMessageTelemetry`` and never the bare name, so a +name list guards that file's two construction sites purely because somebody +wrote the current alias into a different rule. CE060 instead derives its +constructor set from each module's own ``coder_eval.models`` imports, which +removes the gap rather than documenting it and catches an arbitrary +``AssistantMessage as Msg`` besides. Widening the other two rules the same way +is recorded in ``.claude/harness-candidates.md``; it is a change to two shipped +rules and needs its own mutation checks. + +What it removes is the *local binding* spelling, not every rename: the class's +own name still has to be known, so it is taken from the model itself +(``AssistantMessage.__name__``) rather than written here as a string, the way +CE056 imports ``IN_CONTAINER_ENV`` and CE057 derives its target set from +``SIDECAR_MODULES``. Renaming the model therefore moves this rule with it. + +BLIND SPOT 1: the runtime ``None``. The rule requires the kwarg to be +*present*, not non-``None`` when it runs. ``opencode_agent.py`` passes +``str(part.get("messageID") or "") or None`` and ``pi_agent.py`` the same shape +for ``responseId``, so either records ``None`` whenever the id is missing from +the payload (`pi_a_single_text_turn.json` is a snapshot of that shape, though +its null comes from a fixture that emits no ``responseId`` rather than from a +live CLI omission). No AST rule can see it, and demanding a statically +non-``None`` value would be wrong: passing a fallback expression *is* deciding +what the id is. The sensor for that case is the golden corpus, and only +partially — a snapshot is written from whatever the code currently does, so it +catches a later change, never an initial omission. + +BLIND SPOT 2: a binding this file cannot resolve. ``check()`` reads one +module's own imports, so it sees the direct forms — absolute or relative +``from ... import AssistantMessage``, under any alias — and the attribute +spelling ``.AssistantMessage(...)``, which is matched on the attribute +alone precisely because the module binding it comes through (``import +coder_eval.models as models``, ``from coder_eval import models``) is the part a +class-binding walk misses. What remains invisible is a re-export through an +intermediate module (``from .sibling import AssistantMessage``): resolving that +means following imports across files, which no rule in this package does. + +A ``**``-expanded call fires: such a call has not declared the field at the +site. There is no carve-out because no site in ``src/coder_eval/agents/`` uses +``**`` expansion for these constructors; if one is ever added, pass +``message_id=`` explicitly beside it. +""" + +import ast +import re + +from coder_eval.models import AssistantMessage +from tests.lint.rules.base import BaseRule +from tests.lint.violation import Violation + + +_AGENTS_ROOT = re.compile(r"(?:^|[/\\])src[/\\]coder_eval[/\\]agents[/\\]") + +_MODELS_MODULE = "coder_eval.models" +_MODELS_TAIL = _MODELS_MODULE.rpartition(".")[2] + +# Taken from the model, never spelled here: a rename then moves the rule too. +_CLASS = AssistantMessage.__name__ + + +def _binds_the_model(node: ast.ImportFrom) -> bool: + """True if this `from ... import` reaches `coder_eval.models`. + + A relative import inside `agents/` (`from ..models import ...`) carries only + the tail in `node.module`, so testing the absolute path alone would leave the + rule silently blind for a whole file — and `agents/` does use relative + imports. + """ + module = node.module or "" + if module.startswith(_MODELS_MODULE): + return True + return bool(node.level) and (module == _MODELS_TAIL or module.startswith(f"{_MODELS_TAIL}.")) + + +def _is_none(node: ast.expr | None) -> bool: + return isinstance(node, ast.Constant) and node.value is None + + +class MessageIdDeclared(BaseRule): + id = "CE060" + + def __init__(self, filepath: str) -> None: + super().__init__(filepath) + self._in_scope = bool(_AGENTS_ROOT.search(filepath)) + # Local bindings of coder_eval.models.AssistantMessage in THIS module. + # Built per file in check(): caching it across files would leak one + # module's alias into another's matching. + self._names: set[str] = set() + + def check(self, tree: ast.AST) -> list[Violation]: + for node in ast.walk(tree): + if isinstance(node, ast.ImportFrom) and _binds_the_model(node): + self._names.update(a.asname or a.name for a in node.names if a.name == _CLASS) + return super().check(tree) + + def visit_Call(self, node: ast.Call) -> None: + if self._in_scope: + func = node.func + # A bare name has to be bound in this module to be ours; the + # attribute spelling is matched on the attribute alone, since the + # module binding it arrives through is what an import walk over one + # file's class bindings cannot see (see BLIND SPOT 2). + name = ( + func.id + if isinstance(func, ast.Name) and func.id in self._names + else func.attr + if isinstance(func, ast.Attribute) and func.attr == _CLASS + else None + ) + if name is not None: + kwargs = {kw.arg: kw.value for kw in node.keywords if kw.arg is not None} + if "message_id" not in kwargs or _is_none(kwargs["message_id"]): + self.violation( + node, + f"{name}(...) leaves 'message_id' undeclared — absent, or an explicit None — " + "so every message it builds shares one empty identity. Pass the field " + "with a real value: the CLI's own " + "id where the stream carries one, else synthesize it the way Codex does " + "(f'{turn_id}-msg-{gen_index}'). Antigravity shipped without it: the " + "evalboard then falls back to its SAME_EMISSION_GAP_MS wall-clock gap to " + "group emissions, and a harness whose generation windows are contiguous " + "has every one of a turn's generations collapse into one row. See " + "docs/agents/HARNESS_PARITY.md.", + ) + self.generic_visit(node) diff --git a/tests/lint/runner.py b/tests/lint/runner.py index 8800c424..c14f9865 100644 --- a/tests/lint/runner.py +++ b/tests/lint/runner.py @@ -37,6 +37,7 @@ from tests.lint.rules.ce057_sidecar_shim_stdlib_only import SidecarShimStdlibOnly from tests.lint.rules.ce058_no_timing_literal import NoTimingLiteral from tests.lint.rules.ce059_generation_window_is_two_reads import GenerationWindowIsTwoReads +from tests.lint.rules.ce060_message_id_declared import MessageIdDeclared from tests.lint.rules.no_agent_timing_access import NoAgentTimingAccess from tests.lint.rules.no_blocking_io_in_async import NoBlockingIoInAsync from tests.lint.rules.no_cli_imports_in_core import NoCliImportsInCore @@ -97,6 +98,7 @@ SidecarShimStdlibOnly, NoTimingLiteral, GenerationWindowIsTwoReads, + MessageIdDeclared, ] # Anti-shadow invariant (mirrors AgentRegistry / register_pricing): every CE rule diff --git a/tests/test_agent_golden_master.py b/tests/test_agent_golden_master.py index 4c54d0a2..7655a5da 100644 --- a/tests/test_agent_golden_master.py +++ b/tests/test_agent_golden_master.py @@ -70,6 +70,29 @@ def _expect_window(harness: str, scenario_name: str) -> bool: return f"{harness}_{scenario_name}" not in NO_GENERATION_WINDOW +# Scenarios that inject their own SDK timestamps, so their recorded durations +# are FICTIONAL and cannot be reconciled against the replay's real wall clock. +# `_rebase_notifications` / `_rebase_lines` put those stamps on the replay's +# clock, which fixes the era — but the SDK's stamps are integer MILLISECONDS +# and these scenarios declare 17-900 ms of item time, while the replay itself +# runs in well under one. No rebasing closes that; the agent's own clock would +# have to be faked too. Everything else — every claude, antigravity and pi +# scenario, and the codex/opencode ones that inject nothing — is checked. +FICTIONAL_DURATIONS: frozenset[str] = frozenset( + { + "codex_b_command_execution", # 250 ms command + 150 ms generation + "codex_d_cross_flush_is_error", # 400 ms command + "codex_e_orphan_tool", # command started, never completed + "codex_f_collab_fallback", # 900 ms collab wait + "opencode_b_tool_call_resolved", # 17 ms tool interval + } +) + + +def _check_identity(harness: str, scenario_name: str) -> bool: + return f"{harness}_{scenario_name}" not in FICTIONAL_DURATIONS + + _EXPECTED_DIR = Path(__file__).parent / "_fixtures" / "golden_streams" / "expected" _REGEN = os.environ.get("GOLDEN_REGEN", "").strip().lower() in {"1", "true", "yes", "on"} @@ -101,7 +124,11 @@ async def test_claude_golden(scenario, tmp_path): # Reconciliation is asserted on the UNscrubbed dump (token buckets are never # scrubbed, but cost/timestamps are — assert before masking to be explicit). assert_reconciliation(raw) - assert_timing_captured(raw, expect_generation_window=_expect_window("claude", scenario.name)) + assert_timing_captured( + raw, + expect_generation_window=_expect_window("claude", scenario.name), + check_identity=_check_identity("claude", scenario.name), + ) _compare_or_regen(f"claude_{scenario.name}", scrub(raw)) @@ -111,7 +138,11 @@ async def test_claude_golden(scenario, tmp_path): async def test_codex_golden(scenario, tmp_path): raw = await run_codex_scenario(scenario, str(tmp_path)) assert_reconciliation(raw) - assert_timing_captured(raw, expect_generation_window=_expect_window("codex", scenario.name)) + assert_timing_captured( + raw, + expect_generation_window=_expect_window("codex", scenario.name), + check_identity=_check_identity("codex", scenario.name), + ) _compare_or_regen(f"codex_{scenario.name}", scrub(raw)) @@ -137,7 +168,11 @@ async def test_codex_reconciliation_invariant(scenario, tmp_path): async def test_antigravity_golden(scenario, tmp_path): raw = await run_antigravity_scenario(scenario, str(tmp_path)) assert_reconciliation(raw) - assert_timing_captured(raw, expect_generation_window=_expect_window("antigravity", scenario.name)) + assert_timing_captured( + raw, + expect_generation_window=_expect_window("antigravity", scenario.name), + check_identity=_check_identity("antigravity", scenario.name), + ) _compare_or_regen(f"antigravity_{scenario.name}", scrub(raw)) @@ -153,7 +188,11 @@ async def test_antigravity_reconciliation_invariant(scenario, tmp_path): async def test_opencode_golden(scenario, tmp_path): raw = await run_opencode_scenario(scenario, str(tmp_path)) assert_reconciliation(raw) - assert_timing_captured(raw, expect_generation_window=_expect_window("opencode", scenario.name)) + assert_timing_captured( + raw, + expect_generation_window=_expect_window("opencode", scenario.name), + check_identity=_check_identity("opencode", scenario.name), + ) _compare_or_regen(f"opencode_{scenario.name}", scrub(raw)) @@ -169,7 +208,11 @@ async def test_opencode_reconciliation_invariant(scenario, tmp_path): async def test_pi_golden(scenario, tmp_path): raw = await run_pi_scenario(scenario, str(tmp_path)) assert_reconciliation(raw) - assert_timing_captured(raw, expect_generation_window=_expect_window("pi", scenario.name)) + assert_timing_captured( + raw, + expect_generation_window=_expect_window("pi", scenario.name), + check_identity=_check_identity("pi", scenario.name), + ) _compare_or_regen(f"pi_{scenario.name}", scrub(raw)) @@ -265,9 +308,22 @@ def _record( windows: list[float | None] = (), commands: list[dict[str, Any]] = (), bounds_collapse: bool = False, + overhead: tuple[float | None, float | None] = (0.0, 3.5), + duration_seconds: float = 10.0, ) -> dict[str, Any]: - """A record whose bounds span each window, unless `bounds_collapse`.""" + """A record whose bounds span each window, unless `bounds_collapse`. + + `overhead` is the (head, tail) pair. It defaults to a MEASURED pair — + a 0.0 head is antigravity's real answer — because every record here + carries an assistant message unless a test says otherwise, and the + sensor requires both buckets on such a turn. + + `duration_seconds` defaults to a turn long enough that the four-bucket + identity is trivially satisfied, so these cases constrain only what + each is about; the identity has its own cases below. + """ return { + "duration_seconds": duration_seconds, "messages": [ { "role": "assistant", @@ -278,14 +334,18 @@ def _record( for w in windows ], "commands": list(commands), + "harness_startup_ms": overhead[0], + "harness_teardown_ms": overhead[1], } def test_a_positive_window_passes(self): assert_timing_captured(self._record(windows=[12.5]), expect_generation_window=True) def test_a_none_window_raises_when_one_is_expected(self): + # overhead=(None, None) because a turn with no measurable window has no + # head or tail either; this isolates the generation-window assertion. with pytest.raises(AssertionError, match="positive generation window"): - assert_timing_captured(self._record(windows=[None]), expect_generation_window=True) + assert_timing_captured(self._record(windows=[None], overhead=(None, None)), expect_generation_window=True) def test_exactly_zero_raises_too(self): # The Antigravity defect's exact signature: a value that is present, @@ -303,7 +363,7 @@ def test_collapsed_bounds_raise_even_with_a_healthy_duration(self): assert_timing_captured(self._record(windows=[500.0], bounds_collapse=True), expect_generation_window=True) def test_a_none_window_passes_when_none_is_expected(self): - assert_timing_captured(self._record(windows=[None]), expect_generation_window=False) + assert_timing_captured(self._record(windows=[None], overhead=(None, None)), expect_generation_window=False) def test_one_positive_among_several_passes(self): # The FLOOR, not a per-entry rule. claude_d_subagent_terminal holds two @@ -362,3 +422,75 @@ def test_an_unresolved_command_is_exempt(self): def test_a_scenario_with_no_commands_is_vacuously_fine(self): assert_timing_captured(self._record(windows=[5.0]), expect_generation_window=True) + + # The turn's head and tail. Presence only — the replays run in ~0.3 ms of + # synthetic wall clock, so any bound check here would be noise. + def test_a_generating_turn_must_report_a_head(self): + with pytest.raises(AssertionError, match="harness_startup_ms is None"): + assert_timing_captured(self._record(windows=[5.0], overhead=(None, 3.5)), expect_generation_window=True) + + def test_a_generating_turn_must_report_a_tail(self): + with pytest.raises(AssertionError, match="harness_teardown_ms is None"): + assert_timing_captured(self._record(windows=[5.0], overhead=(0.0, None)), expect_generation_window=True) + + def test_a_turn_with_no_generation_must_report_neither(self): + # A number here claims a measurement nobody could have taken: the + # collector measures both against the messages that report a window. + with pytest.raises(AssertionError, match=r"harness_startup_ms is 0\.0"): + assert_timing_captured(self._record(windows=[], overhead=(0.0, 3.5)), expect_generation_window=False) + assert_timing_captured(self._record(windows=[], overhead=(None, None)), expect_generation_window=False) + + def test_an_unmeasurable_window_is_not_something_to_measure_against(self): + # codex_g_items_rebuild's shape: an assistant message exists, but it was + # rebuilt after the turn ended with placeholder now() bounds and says so + # via generation_duration_ms=None. Those stamps are not window bounds, so + # the honest head and tail are None — keying on "any assistant message" + # would have demanded a number derived from a placeholder. + with pytest.raises(AssertionError, match=r"harness_startup_ms is 0\.0"): + assert_timing_captured(self._record(windows=[None], overhead=(0.0, 3.5)), expect_generation_window=False) + + # The four-bucket identity: generation + tool union + head + tail cannot + # exceed the turn, because the four are disjoint. + def test_buckets_summing_past_the_turn_raise(self): + # 4s generation + a 3.5ms tail on a 1s turn. + with pytest.raises(AssertionError, match="booked twice"): + assert_timing_captured(self._record(windows=[4000.0], duration_seconds=1.0), expect_generation_window=True) + + def test_a_tool_double_booked_into_the_tail_is_caught(self): + """The exact defect: an orphan force-closed inside the tail, counted + both in the tool union and in harness_teardown_ms.""" + record = self._record( + windows=[40.0], + duration_seconds=0.1, # 100 ms turn + overhead=(0.0, 50.0), + commands=[ + { + "tool_id": "orphan", + "result_status": "success", + "duration_ms": 50.0, + "execution_started_at": "2026-01-01T00:00:00.020000", + "execution_completed_at": "2026-01-01T00:00:00.070000", + } + ], + ) + with pytest.raises(AssertionError, match="booked twice"): + assert_timing_captured(record, expect_generation_window=True) + + def test_the_identity_can_be_waived_for_a_fictional_clock(self): + # codex/opencode scenarios declare integer-millisecond item durations + # that a sub-millisecond replay can never contain. + assert_timing_captured( + self._record(windows=[4000.0], duration_seconds=1.0), + expect_generation_window=True, + check_identity=False, + ) + + def test_buckets_well_inside_the_turn_pass(self): + assert_timing_captured(self._record(windows=[40.0], duration_seconds=1.0), expect_generation_window=True) + + def test_the_buckets_are_checked_even_when_no_window_is_expected(self): + # codex_e_orphan_tool clears the flag (its window subtracts to zero) + # while still having a head and a tail — so the flag is the wrong key + # for this half of the sensor, and the early return must not skip it. + with pytest.raises(AssertionError, match="harness_teardown_ms is None"): + assert_timing_captured(self._record(windows=[5.0], overhead=(0.0, None)), expect_generation_window=False) diff --git a/tests/test_agent_telemetry.py b/tests/test_agent_telemetry.py index 12c8c171..646c4c20 100644 --- a/tests/test_agent_telemetry.py +++ b/tests/test_agent_telemetry.py @@ -1278,3 +1278,76 @@ async def mock_query(prompt, options): assert second.cache_read_tokens == 50 finally: agent_module.query = original_query + + +class TestClaudeHeadIsStructurallyZero: + """Why claude-code's `harness_startup_ms` is 0.0, and why that is left alone. + + `_ClaudeTurnState.__init__` stamps `last_event_wall`, which becomes the + FIRST generation window's `started_at`. `_build_claude_query` runs next, + and only then is `AgentStartEvent` emitted. So the head — agent start to + first window — is a small NEGATIVE that `decompose_turn` clamps to 0.0. + + Two changes were considered and rejected, and this class pins the facts + each rejection rests on, because both are the kind of thing that rots + silently: + + 1. *Emit `AgentStartEvent` before `_build_claude_query`.* It would turn the + clamp into a genuine measurement, but the value stays ~0 either way — + `last_event_wall` is stamped before the build too, so the build sits + inside msg0's window regardless. The cost is real: the event carries + `model=effective_model`, which the build resolves, so moving it means + the live renderers show the configured model rather than the effective + one. Not worth it for a sub-millisecond gain. + + 2. *Re-seed the first window after the build.* That WOULD surface the build + cost, and it is the generation-window seeding change ruled out in + docs/agents/HARNESS_PARITY.md — for an in-process SDK the interval from + turn entry to the first message is msg0's generation. + + Both rejections assume the build is cheap. This test is what keeps that + assumption honest. + """ + + # Measured at 0.03 ms bare and 0.10 ms with four plugin roots. The bound is + # ~300x that: generous enough that a loaded CI box cannot trip it, tight + # enough to catch a regression that would make the reasoning above wrong. + BUDGET_MS = 50.0 + + @staticmethod + def _build_ms(**config_kwargs) -> float: + from pathlib import Path + + from coder_eval.agents.claude_code_agent import ClaudeCodeAgent + + config = parse_agent_config(type=AgentKind.CLAUDE_CODE, model="claude-haiku-4-5-20251001", **config_kwargs) + agent = ClaudeCodeAgent(config) + agent.working_directory = Path(".") + # Best of N: the claim is about the work the call does, not about the + # worst scheduling slice a shared runner happens to hand it. + samples = [] + for _ in range(5): + started = time.perf_counter() + agent._build_claude_query("hi", 60, 10, lambda _line: None) + samples.append((time.perf_counter() - started) * 1000.0) + return min(samples) + + def test_the_query_build_is_cheap_enough_to_leave_inside_msg0(self): + elapsed = self._build_ms() + assert elapsed < self.BUDGET_MS, ( + f"_build_claude_query took {elapsed:.2f} ms, over the {self.BUDGET_MS} ms budget. It runs " + "BETWEEN the first generation window's start stamp and the AgentStartEvent, so this time " + "is booked as model generation and the clamped 0.0 head hides it. At a few hundred " + "microseconds that is the right trade; at this size it is not — revisit the two options " + "in this class's docstring." + ) + + def test_plugin_resolution_does_not_change_that(self, tmp_path): + """The rejected proposal's motivating case was a plugin-heavy task.""" + (tmp_path / "skills").mkdir() + roots = [{"type": "local", "path": str(tmp_path)} for _ in range(4)] + elapsed = self._build_ms(plugins=roots) + assert elapsed < self.BUDGET_MS, ( + f"_build_claude_query with 4 plugin roots took {elapsed:.2f} ms, over the " + f"{self.BUDGET_MS} ms budget — see the sibling test for why that matters." + ) diff --git a/tests/test_antigravity_agent.py b/tests/test_antigravity_agent.py index c17986a9..a8c0d796 100644 --- a/tests/test_antigravity_agent.py +++ b/tests/test_antigravity_agent.py @@ -23,7 +23,7 @@ _to_token_usage, ) from coder_eval.agents.registry import AgentRegistry -from coder_eval.models import AgentKind, AntigravityAgentConfig, parse_agent_config +from coder_eval.models import AgentKind, AntigravityAgentConfig, AssistantMessage, parse_agent_config from coder_eval.plugins import ensure_plugins_loaded from coder_eval.pricing import calculate_cost from tests._fixtures.golden_streams._scrub import assert_reconciliation @@ -334,6 +334,13 @@ async def test_communicate_maps_steps_to_turn_record(): assert sum(m.output_tokens for m in bucketed) == tr.token_usage.output_tokens assert sum(m.cache_creation_tokens for m in bucketed) == tr.token_usage.cache_creation_input_tokens assert sum(m.cache_read_tokens for m in bucketed) == tr.token_usage.cache_read_input_tokens + # Every generation carries its own identity. Filter explicitly: `tr.messages` + # is list[TranscriptMessage] and ReconciliationMessage has no `message_id`, + # so a bare comprehension would raise the moment a residual is booked. + # The literal strings pin the 0-based Codex-parity scheme, which mere + # distinctness (a uuid would pass) does not. + ids = [m.message_id for m in tr.messages if isinstance(m, AssistantMessage)] + assert ids == ["antigravity-1-msg-0", "antigravity-1-msg-1", "antigravity-1-msg-2"] assert agent.pending_turn is None # success path leaves no partial @@ -1547,7 +1554,7 @@ def _at(ms: float) -> datetime: return _CLOCK_BASE + timedelta(milliseconds=ms) def _busy(self, spans, lo=0, hi=10_000) -> float: - from coder_eval.agents._timing import busy_ms + from coder_eval.timing import busy_ms return busy_ms([(self._at(s), self._at(e)) for s, e in spans], self._at(lo), self._at(hi)) diff --git a/tests/test_custom_lint.py b/tests/test_custom_lint.py index c2852353..05aff5d5 100644 --- a/tests/test_custom_lint.py +++ b/tests/test_custom_lint.py @@ -4355,6 +4355,28 @@ def test_ignores_a_dict_literal_that_is_not_an_update_kwarg(self): # Scoped to `update=` so an unrelated fixture dict cannot fire. assert not self._run('row = {"duration_ms": 0.0}') + # The head/tail family — the turn-level buckets on TurnRecord. + def test_flags_a_zero_harness_startup(self): + assert self._run("rec = TurnRecord(iteration=0, harness_startup_ms=0.0)") + + def test_flags_a_zero_harness_teardown(self): + assert self._run("rec = TurnRecord(iteration=0, harness_teardown_ms=0)") + + def test_allows_an_unmeasured_harness_startup(self): + assert not self._run("rec = TurnRecord(iteration=0, harness_startup_ms=None)") + + def test_allows_a_measured_harness_startup(self): + assert not self._run("rec = TurnRecord(iteration=0, harness_startup_ms=head_ms)") + + def test_flags_the_head_coalesce(self): + assert self._run("x = rec.harness_startup_ms or 0") + + def test_ignores_a_name_that_merely_starts_with_startup(self): + # Anchored at both ends, and the family needs a leading segment: a + # limit is not a measurement, and a bare `startup_ms` is not ours. + assert not self._run("cfg = TurnRecord(startup_ms_limit=0)") + assert not self._run("x = startup_ms_limit or 0") + # Scope + suppression. def test_is_out_of_scope_outside_src(self): assert not self._run( @@ -4424,3 +4446,99 @@ def test_noqa_suppresses(self): path = SRC / "coder_eval/agents/antigravity_agent.py" assert path.is_file(), "the noqa fixture file must exist or this test passes vacuously" assert not [v for v in check_file(path) if v.rule_id == "CE059"] + + +class TestCE060MessageIdDeclared: + """CE060 flags an assistant message built without an identity. + + Every source string carries its own import line: the rule derives its + constructor set from the module's own `coder_eval.models` imports, so a + bare `AssistantMessage(...)` with no import is correctly invisible to it. + """ + + _IMPORT = "from coder_eval.models import AssistantMessage\n" + + @staticmethod + def _run(src: str, filepath: str = "src/coder_eval/agents/antigravity_agent.py"): + import ast + + from tests.lint.rules.ce060_message_id_declared import MessageIdDeclared + + return MessageIdDeclared(filepath).check(ast.parse(src)) + + def test_flags_an_omitted_message_id(self): + assert self._run(self._IMPORT + "m = AssistantMessage(model=model, output_tokens=3)") + + def test_flags_an_explicit_none(self): + # Passing None is a claim that no id exists, which is never true for a + # harness that can synthesize one. + assert self._run(self._IMPORT + "m = AssistantMessage(model=model, message_id=None)") + + def test_flags_the_in_tree_alias_spelling(self): + assert self._run( + "from coder_eval.models import AssistantMessage as AssistantMessageTelemetry\n" + "m = AssistantMessageTelemetry(model=model)" + ) + + def test_flags_an_arbitrary_alias(self): + # The case a hardcoded name list misses entirely — the whole reason + # CE060 resolves aliases instead. + assert self._run("from coder_eval.models import AssistantMessage as Msg\nm = Msg(model=model)") + + def test_flags_the_module_alias_spelling(self): + # The realistic way to write `models.AssistantMessage(...)`: the class + # itself is never bound, so only the attribute is left to match on. + assert self._run("import coder_eval.models as models\nm = models.AssistantMessage(model=model)") + + def test_flags_the_attribute_spelling_beside_a_direct_import(self): + assert self._run(self._IMPORT + "m = models.AssistantMessage(model=model)") + + def test_flags_a_relative_import(self): + # `agents/` does use relative imports, and the absolute path test alone + # left the rule silently blind for a whole file. + assert self._run("from ..models import AssistantMessage\nm = AssistantMessage(model=model)") + + def test_keys_on_the_model_name_rather_than_a_literal(self): + from coder_eval.models import AssistantMessage as _Model + from tests.lint.rules import ce060_message_id_declared as rule_mod + + assert _Model.__name__ == rule_mod._CLASS + + def test_flags_a_star_expanded_call(self): + # `**fields` has not declared the field at the site. + assert self._run(self._IMPORT + "m = AssistantMessage(**fields)") + + def test_allows_a_literal_id(self): + assert not self._run(self._IMPORT + 'm = AssistantMessage(message_id="x")') + + def test_allows_an_fstring_id(self): + assert not self._run(self._IMPORT + 'm = AssistantMessage(message_id=f"{turn_id}-msg-{i}")') + + def test_allows_a_fallback_expression(self): + # The runtime-None blind spot, exempted deliberately: passing a + # fallback expression IS deciding what the id is. + assert not self._run(self._IMPORT + "m = AssistantMessage(message_id=str(x) or None)") + + def test_allows_a_star_expanded_call_that_also_passes_the_field(self): + assert not self._run(self._IMPORT + "m = AssistantMessage(**fields, message_id=mid)") + + def test_ignores_an_unrelated_constructor(self): + assert not self._run(self._IMPORT + "s = Span(model=model)") + + def test_ignores_a_module_with_no_matching_import(self): + # Nothing is bound, so the rule claims nothing here. A construction + # site has to import the class to reach it. + assert not self._run("m = AssistantMessage(model=model)") + + def test_is_out_of_scope_outside_agents(self): + assert not self._run( + self._IMPORT + "m = AssistantMessage(model=model)", + filepath="src/coder_eval/orchestrator.py", + ) + + def test_the_real_antigravity_flush_declares_its_id(self): + from tests.lint.runner import check_file + + path = SRC / "coder_eval/agents/antigravity_agent.py" + assert path.is_file(), "the fixture file must exist or this test passes vacuously" + assert not [v for v in check_file(path) if v.rule_id == "CE060"] diff --git a/tests/test_event_collector.py b/tests/test_event_collector.py index 76e49e49..8c1c0b79 100644 --- a/tests/test_event_collector.py +++ b/tests/test_event_collector.py @@ -8,6 +8,8 @@ from datetime import datetime from typing import ClassVar +import pytest + from coder_eval.models import ( AssistantMessage, CommandTelemetry, @@ -202,7 +204,17 @@ class TestFullFieldParity: # provider_call_costs -> joined in post-run by the orchestrator from the # LiteLLM proxy cost log (litellm_cost.apply_actual_cost), # not emitted by the agent/EventCollector. - _DERIVED: ClassVar[set[str]] = {"commands", "token_usage", "timestamp", "provider_call_costs"} + _DERIVED: ClassVar[set[str]] = { + "commands", + "token_usage", + "timestamp", + "provider_call_costs", + # Measured by the collector between the agent's own start/end event + # stamps and the first/last generation window — not carried on + # AgentEndEvent, because no agent computes them. + "harness_startup_ms", + "harness_teardown_ms", + } def _full_agent_end(self) -> AgentEndEvent: """An AgentEndEvent with every verbatim field set to a non-default sentinel.""" @@ -458,3 +470,211 @@ def test_minimal_record_without_agent_end(self): assert record.model_used == "gpt-x" assert record.assistant_turn_count == 1 assert [c.tool_id for c in record.commands] == ["a"] + + +class TestHarnessOverheadBuckets: + """The turn's two unexplained ends: before the first generation, after the last. + + Measured live across all five harnesses, these two plus generation plus tool + execution account for the turn to within 0.1 ms — so what the evalboard shows + as "Unaccounted" is fully explained rather than merely displayed. The head is + where the harnesses differ most (OpenCode ~3.0 s of CLI boot + TTFT fused, + claude-code a measured 0.0 because its first window already covers dispatch), + which is exactly why it is booked as its own bucket instead of being folded + into generation. + """ + + @staticmethod + def _msg(started: datetime, completed: datetime, *, measurable: bool = True) -> AssistantMessage: + """A generation window. ``measurable=False`` is the placeholder shape + every fabricated-bounds producer writes — a rollout rebuild or a + sub-agent recovery — which stamps one instant on both bounds and says + so with ``generation_duration_ms=None``.""" + return AssistantMessage( + started_at=started, + completed_at=completed, + generation_duration_ms=1.0 if measurable else None, + ) + + @staticmethod + def _tool(started: datetime, completed: datetime, tool_id: str = "t1") -> ToolEndEvent: + return ToolEndEvent( + task_id=TASK_ID, + tool=CommandTelemetry( + tool_id=tool_id, + tool_name="Bash", + timestamp=started, + sequence_number=0, + execution_started_at=started, + execution_completed_at=completed, + result_status="success", + ), + ) + + def _record(self, messages, *, start: datetime, end: datetime, tools=()) -> TurnRecord: + collector = EventCollector() + _feed( + collector, + [ + AgentStartEvent(task_id=TASK_ID, prompt="go", iteration=1, timestamp=start), + *tools, + AgentEndEvent( + task_id=TASK_ID, + usage=TokenUsage(output_tokens=1), + messages=messages, + timestamp=end, + ), + ], + ) + return collector.build_turn_record() + + def test_head_and_tail_are_measured_from_the_agent_event_stamps(self): + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [self._msg(t0.replace(second=2), t0.replace(second=5))], + start=t0, + end=t0.replace(second=9), + ) + assert rec.harness_startup_ms == pytest.approx(2000.0) + assert rec.harness_teardown_ms == pytest.approx(4000.0) + + def test_a_turn_with_no_generation_says_so_rather_than_claiming_zero(self): + """None means never measured; 0.0 would mean measured-and-instant (CE058).""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record([], start=t0, end=t0.replace(second=9)) + assert rec.harness_startup_ms is None + assert rec.harness_teardown_ms is None + + def test_a_measured_zero_head_is_zero_not_none(self): + """claude-code and Antigravity really do open their first window at turn + start, so their head is a genuine 0.0 — the distinction from None is the + whole point of the field.""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record([self._msg(t0, t0.replace(second=5))], start=t0, end=t0.replace(second=5)) + assert rec.harness_startup_ms == 0.0 + assert rec.harness_teardown_ms == 0.0 + + def test_the_tail_ignores_a_trailing_reconciliation_entry(self): + """It is always last when present and carries no timestamps at all, so + indexing messages[-1] would raise rather than measure.""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [ + self._msg(t0.replace(second=1), t0.replace(second=4)), + ReconciliationMessage(input_tokens=5, note="residual"), + ], + start=t0, + end=t0.replace(second=6), + ) + assert rec.harness_teardown_ms == pytest.approx(2000.0) + + def test_a_clock_inversion_clamps_rather_than_going_negative(self): + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [self._msg(t0.replace(minute=59, hour=11), t0.replace(second=5))], + start=t0, + end=t0.replace(second=1), + ) + assert rec.harness_startup_ms == 0.0 + + def test_a_snapshot_before_the_terminal_event_measures_nothing(self): + collector = EventCollector() + _feed(collector, [AgentStartEvent(task_id=TASK_ID, prompt="go", iteration=1)]) + rec = collector.build_turn_record() + assert rec.harness_startup_ms is None + assert rec.harness_teardown_ms is None + + def test_a_placeholder_message_does_not_supply_the_bounds(self): + """A Codex turn rebuilt from its rollout stamps every message at turn + END and marks them generation_duration_ms=None. Reading those stamps as + window bounds books the WHOLE TURN as harness startup.""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [ + self._msg(t0.replace(second=2), t0.replace(second=5)), + self._msg(t0.replace(second=9), t0.replace(second=9), measurable=False), + ], + start=t0, + end=t0.replace(second=9), + ) + assert rec.harness_startup_ms == pytest.approx(2000.0) + # 9s - 5s, measured off the real window, not off the placeholder's stamp. + assert rec.harness_teardown_ms == pytest.approx(4000.0) + + def test_a_turn_of_only_placeholders_measures_nothing(self): + """codex_g_items_rebuild's shape: an assistant message exists, but + nothing in it was timed, so there is no end to measure against.""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [self._msg(t0.replace(second=9), t0.replace(second=9), measurable=False)], + start=t0, + end=t0.replace(second=9), + ) + assert rec.harness_startup_ms is None + assert rec.harness_teardown_ms is None + + def test_the_bounds_do_not_depend_on_append_order(self): + """Codex appends recovered sub-agent messages after the parent's last + flush, so the list is not ordered by time.""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [ + self._msg(t0.replace(second=6), t0.replace(second=8)), + self._msg(t0.replace(second=2), t0.replace(second=4)), + ], + start=t0, + end=t0.replace(second=9), + ) + assert rec.harness_startup_ms == pytest.approx(2000.0) + assert rec.harness_teardown_ms == pytest.approx(1000.0) + + def test_a_tool_running_past_the_last_window_is_not_counted_twice(self): + """Antigravity force-closes an orphan at finalization, stamping its + completion inside the tail, and backgrounds anything over ten seconds. + Such a span is already in the tool bucket, so leaving it in the tail + books it twice and drives the residual sharply negative.""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [self._msg(t0.replace(second=1), t0.replace(second=4))], + start=t0, + end=t0.replace(second=9), + tools=[self._tool(t0.replace(second=3), t0.replace(second=7))], + ) + # Tail spans 4s->9s = 5s, of which 4s->7s = 3s was the tool still running. + assert rec.harness_teardown_ms == pytest.approx(2000.0) + + def test_a_tool_running_before_the_first_window_is_not_counted_twice(self): + t0 = datetime(2026, 1, 1, 12, 0, 0) + rec = self._record( + [self._msg(t0.replace(second=5), t0.replace(second=8))], + start=t0, + end=t0.replace(second=8), + tools=[self._tool(t0.replace(second=1), t0.replace(second=3))], + ) + # Head spans 0s->5s = 5s, of which 1s->3s = 2s was tool execution. + assert rec.harness_startup_ms == pytest.approx(3000.0) + + def test_a_new_turn_clears_the_previous_turn_terminal_event(self): + """EarlyStopWatcher keeps ONE collector across retries. Left stale, the + next attempt's start pairs with the last attempt's end and the clamped + inversion publishes as a measured 0.0.""" + t0 = datetime(2026, 1, 1, 12, 0, 0) + collector = EventCollector() + _feed( + collector, + [ + AgentStartEvent(task_id=TASK_ID, prompt="go", iteration=1, timestamp=t0), + AgentEndEvent( + task_id=TASK_ID, + usage=TokenUsage(output_tokens=1), + messages=[self._msg(t0.replace(second=1), t0.replace(second=2))], + timestamp=t0.replace(second=3), + crashed=True, + ), + # Retry, a minute later, with no terminal event of its own yet. + AgentStartEvent(task_id=TASK_ID, prompt="go", iteration=1, timestamp=t0.replace(minute=1)), + ], + ) + rec = collector.build_turn_record() + assert rec.harness_startup_ms is None + assert rec.harness_teardown_ms is None