From 4a8864a4cb2058ae416af253268639d1fd9b5c68 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Thu, 10 Sep 2026 22:28:20 -0700 Subject: [PATCH 01/16] feat(timing): book each turn's head and tail as their own buckets MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Measured live on all five harnesses, generation + tool left 0.1%-42% of the turn unexplained, and the whole remainder sat in two places: before the first generation window opened, and after the last one closed. EventCollector now measures both between the agent's own AgentStart/AgentEnd stamps and the first/last AssistantMessage, and publishes them on TurnRecord. One live turn per harness, residual after all four buckets: antigravity wall 14348 ms startup 0.0 teardown 3.5 -0.010 ms claude-code wall 13295 ms startup 0.0 teardown 834.7 +0.086 ms codex wall 11842 ms startup 5075.2 teardown 13.9 -0.019 ms opencode wall 8157 ms startup 3047.9 teardown 33.1 +0.022 ms pi wall 6906 ms startup 345.4 teardown 26.6 +0.621 ms The turn now reconciles to under a millisecond everywhere. The residual sign flips, so the invariant is |residual| < 1 ms rather than <= wall: head and tail are measured between event stamps while duration_seconds is the agent's own monotonic span, and the field descriptions say so. The head is NOT decomposed further, deliberately. Its composition differs per harness and the stream carries no marker to split it: OpenCode's process spawns in 3 ms and its first event lands at 3921 ms, so CLI boot, provider resolution, dispatch and TTFT are fused. claude-code and Antigravity read a measured 0.0 because their first window already covers dispatch — which is also why nothing folds that time OUT of their generation: for an in-process SDK it IS the generation. Hence names for the interval measured, not for what it contains. `agents/_timing.py` moves to `coder_eval/timing.py`. It is stdlib-only, but importing anything under `agents/` executes that package's __init__, which imports every agent, which imports streaming — so the collector could not reach it. A cycle-free leaf beside the other shared arithmetic, mirroring models/cli_match.py's rationale. Both fields join the golden-stream scrub list. They are measured wall values like duration_seconds and generation_duration_ms beside them; left unscrubbed they drifted 24 of 68 golden tests on an unchanged re-run. Co-Authored-By: Claude Opus 5 (1M context) --- src/coder_eval/agents/_timing.py | 42 ------- src/coder_eval/agents/antigravity_agent.py | 2 +- src/coder_eval/agents/codex_agent.py | 2 +- src/coder_eval/agents/opencode_agent.py | 4 +- src/coder_eval/agents/pi_agent.py | 4 +- src/coder_eval/models/results.py | 23 ++++ src/coder_eval/streaming/collector.py | 29 +++++ src/coder_eval/timing.py | 84 ++++++++++++++ tests/_fixtures/golden_streams/_scrub.py | 5 + .../antigravity_a_single_text_turn.json | 2 + .../antigravity_b_tool_call_resolved.json | 2 + ...y_c_thinking_and_tool_same_generation.json | 2 + .../expected/antigravity_d_orphaned_tool.json | 2 + .../antigravity_e_multi_generation.json | 2 + .../expected/claude_a_single_text_turn.json | 2 + .../expected/claude_b_tool_use_result.json | 2 + .../claude_c_multi_emission_delta.json | 2 + .../expected/claude_d_subagent_terminal.json | 2 + .../claude_e_model_usage_and_backfill.json | 2 + .../expected/claude_f_orphaned_tool.json | 2 + .../claude_g_crash_format_placeholder.json | 2 + .../claude_h1_timeout_process_error.json | 2 + .../claude_h2_process_error_crash.json | 2 + .../claude_i_in_loop_deadline_break.json | 2 + .../expected/codex_a_agent_message_only.json | 2 + .../expected/codex_b_command_execution.json | 2 + .../codex_c_reasoning_placeholder.json | 2 + .../codex_d_cross_flush_is_error.json | 2 + .../expected/codex_e_orphan_tool.json | 2 + .../expected/codex_f_collab_fallback.json | 2 + .../expected/codex_g_items_rebuild.json | 2 + .../codex_h_no_turn_completed_crash.json | 2 + .../expected/opencode_a_single_text_turn.json | 2 + .../opencode_b_tool_call_resolved.json | 2 + .../expected/pi_a_single_text_turn.json | 2 + .../expected/pi_b_tool_call_resolved.json | 2 + tests/test_antigravity_agent.py | 2 +- tests/test_event_collector.py | 103 +++++++++++++++++- 38 files changed, 304 insertions(+), 50 deletions(-) delete mode 100644 src/coder_eval/agents/_timing.py create mode 100644 src/coder_eval/timing.py 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..f1a33914 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 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/streaming/collector.py b/src/coder_eval/streaming/collector.py index ebac3ee9..03f79455 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,7 @@ 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 if event.model: self._model = event.model elif isinstance(event, TurnStartEvent): @@ -103,6 +109,25 @@ 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 the FIRST and LAST ``AssistantMessage``, not + ``messages[0]`` / ``messages[-1]``: 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. + """ + generations = [m for m in messages if isinstance(m, AssistantMessage)] + if not generations: + return None, None + return decompose_turn( + generations[0].started_at, + generations[-1].completed_at, + self._agent_start_at, + self._agent_end.timestamp if self._agent_end is not None else None, + ) + @staticmethod def _reconciled_messages(messages: list[TranscriptMessage], usage: TokenUsage) -> list[TranscriptMessage]: """Append a ``ReconciliationMessage`` so the transcript's token buckets @@ -193,6 +218,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 +235,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..b2950896 --- /dev/null +++ b/src/coder_eval/timing.py @@ -0,0 +1,84 @@ +"""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 + + +def decompose_turn( + first_started_at: datetime | None, + last_completed_at: datetime | None, + agent_started_at: datetime | None, + agent_ended_at: datetime | 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 + tool + tail is the whole + turn. Defined once here rather than in five agents, and consumed by + ``EventCollector``, the golden-stream sensor, and + ``scripts/timing/decompose_run.py``. + + 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 a second implementation of this arithmetic lives in the evalboard's + Unaccounted cell (``_sections.tsx``), as ``pricing.ts`` mirrors + ``pricing.py``. Change one, change the other. + """ + head = tail = None + if first_started_at is not None and agent_started_at is not None: + head = max((first_started_at - agent_started_at).total_seconds() * 1000.0, 0.0) + if last_completed_at is not None and agent_ended_at is not None: + tail = max((agent_ended_at - last_completed_at).total_seconds() * 1000.0, 0.0) + return head, tail diff --git a/tests/_fixtures/golden_streams/_scrub.py b/tests/_fixtures/golden_streams/_scrub.py index c84cc77d..9450bc8e 100644 --- a/tests/_fixtures/golden_streams/_scrub.py +++ b/tests/_fixtures/golden_streams/_scrub.py @@ -24,6 +24,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 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..fe601ee4 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": [ 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..3729ef53 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": [ 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..f75f40fb 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": [ 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..ee177ff6 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": [ 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..1a47c81f 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": [ 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..1c88ea85 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": "", + "harness_teardown_ms": "", "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/test_antigravity_agent.py b/tests/test_antigravity_agent.py index c17986a9..25fd80b1 100644 --- a/tests/test_antigravity_agent.py +++ b/tests/test_antigravity_agent.py @@ -1547,7 +1547,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_event_collector.py b/tests/test_event_collector.py index 76e49e49..324f10fa 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,92 @@ 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) -> AssistantMessage: + return AssistantMessage(started_at=started, completed_at=completed, generation_duration_ms=1.0) + + def _record(self, messages, *, start: datetime, end: datetime) -> TurnRecord: + collector = EventCollector() + _feed( + collector, + [ + AgentStartEvent(task_id=TASK_ID, prompt="go", iteration=1, timestamp=start), + 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 From a3d116f9929d5301d52b7e2cacbaae97fd64fea1 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Thu, 10 Sep 2026 22:46:32 -0700 Subject: [PATCH 02/16] =?UTF-8?q?test(lint):=202/4=20=E2=80=94=20widen=20C?= =?UTF-8?q?E058=20to=20the=20turn=20head/tail=20buckets?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `harness_startup_ms` / `harness_teardown_ms` were cited as CE058-guarded but matched neither `_TIMING_NAME` nor `_TIMING_CONSTRUCTORS`, so the guard the head/tail work leans on did not exist for the two fields it was named for. Add one alternation arm (`[a-z_]*_(?:startup|teardown)_ms`, leading segment required like the `_duration_ms` arm) and `TurnRecord` to the constructor set, which is what arms form 1. Mutating the real collector call site from `harness_startup_ms=startup_ms` to `0.0` now fires the rule. Co-Authored-By: Claude Opus 5 (1M context) --- tests/lint/rules/ce058_no_timing_literal.py | 19 +++++++++++++++--- tests/test_custom_lint.py | 22 +++++++++++++++++++++ 2 files changed, 38 insertions(+), 3 deletions(-) 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/test_custom_lint.py b/tests/test_custom_lint.py index c2852353..84a95d53 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( From d42f8b377c0a329c50499e03673eda5caa79441f Mon Sep 17 00:00:00 2001 From: uipreliga Date: Thu, 10 Sep 2026 22:54:33 -0700 Subject: [PATCH 03/16] =?UTF-8?q?feat(evalboard):=203/4=20=E2=80=94=20name?= =?UTF-8?q?=20the=20harness=20head=20and=20tail=20in=20the=20timeline=20st?= =?UTF-8?q?rip?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Unaccounted cell was reporting a harness's CLI boot as unexplained time: opencode's ~3.4s head and claude-code's ~1.0s tail are measured intervals, not residual. Parse `harness_startup_ms` / `harness_teardown_ms` off each turn, sum them across the task's iterations, render them as their own Startup and Teardown cells, and subtract both so Unaccounted is a true residual. Aggregation is `null` — never 0 — when no turn measured that end, mirroring the TurnRecord fields' own contract; a measured 0 (an in-process SDK whose first generation window already covers dispatch) is preserved and renders as `0ms`. An older run without either field renders exactly as before, including the 25% red threshold, which now reads the corrected number in both directions. Co-Authored-By: Claude Opus 5 (1M context) --- .../__tests__/message-timeline.test.tsx | 137 ++++++++++++++++++ .../app/runs/[id]/[...task]/_sections.tsx | 58 +++++++- evalboard/app/runs/[id]/[...task]/page.tsx | 2 + .../lib/__tests__/harnessOverhead.test.ts | 79 ++++++++++ evalboard/lib/__tests__/runs.test.ts | 55 +++++++ evalboard/lib/runs.ts | 45 ++++++ 6 files changed, 371 insertions(+), 5 deletions(-) create mode 100644 evalboard/lib/__tests__/harnessOverhead.test.ts 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__/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, }; } From bf6d2c1287c42a3e96bac577920e5d64008fb3ea Mon Sep 17 00:00:00 2001 From: uipreliga Date: Thu, 10 Sep 2026 23:18:53 -0700 Subject: [PATCH 04/16] =?UTF-8?q?feat(timing):=204/4=20=E2=80=94=20assert?= =?UTF-8?q?=20the=20buckets=20in=20replay,=20and=20record=20what=20they=20?= =?UTF-8?q?contain?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Extend `assert_timing_captured` with the one thing the golden replays can support: a turn that produced an assistant message reports both buckets, and a turn that produced none reports neither. Keyed on that message rather than on `expect_generation_window` — `codex_e_orphan_tool` and `claude_i_in_loop_deadline_break` clear the flag while still having a head and a tail, so the flag would have left them unchecked. No golden regeneration: all 27 dumps already carried both fields and still match. `HARNESS_PARITY.md` gains the rows this change exists to publish — what the FIRST generation window covers per harness, and the measured head and tail — plus the reason the head is deliberately not split into CLI boot vs TTFT, and a Known-divergences note for `TurnStartEvent`'s inconsistent emission point. Live verification (15 runs, 3 turns × 5 harnesses) corrected the identity itself: `Σ tool` books overlapping tool calls twice, and one Pi turn overlapped a Write and a Bash by 18.4 ms, producing exactly an 18.3 ms residual. The tool term is the UNION (`timing.py::busy_ms`), as it already is where a harness subtracts tool time out of a generation window. With all four buckets and the union, every harness reconciles to under 0.012% of wall clock. Co-Authored-By: Claude Opus 5 (1M context) --- docs/agents/HARNESS_PARITY.md | 57 ++++++++- scripts/timing/decompose_run.py | 142 +++++++++++++++++++++++ src/coder_eval/models/telemetry.py | 10 +- src/coder_eval/timing.py | 16 ++- tests/_fixtures/golden_streams/_scrub.py | 33 +++++- tests/test_agent_golden_master.py | 35 +++++- 6 files changed, 282 insertions(+), 11 deletions(-) create mode 100644 scripts/timing/decompose_run.py diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index 4b429032..d0ad4a97 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -25,10 +25,13 @@ 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.2 s — CLI boot fused with TTFT | 0.0 — the window above already covers it | ~2.5 s — CLI boot fused with TTFT | ~0.24 s — CLI boot fused with TTFT | +| `harness_teardown_ms` (turn tail) | ~1.4 s | ~12 ms | ~5 ms | ~28 ms | ~13 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 | +| `Σ 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 @@ -39,7 +42,7 @@ 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 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 +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 @@ -53,6 +56,42 @@ 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. +**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. With all +four buckets and the union, three live turns per harness reconcile to within +1.3 ms of `duration_seconds` (worst case 0.012% 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 three 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 and the head reads a measured ~0. 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. +- 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 that per tool; deriving it from the flush time would be a guess. Note also that @@ -82,7 +121,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/scripts/timing/decompose_run.py b/scripts/timing/decompose_run.py new file mode 100644 index 00000000..df60ad4b --- /dev/null +++ b/scripts/timing/decompose_run.py @@ -0,0 +1,142 @@ +#!/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 + 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 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("environment_info") or {}).get("agent_type") or 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/models/telemetry.py b/src/coder_eval/models/telemetry.py index 15a18430..0bef609f 100644 --- a/src/coder_eval/models/telemetry.py +++ b/src/coder_eval/models/telemetry.py @@ -230,8 +230,14 @@ class AssistantMessage(BaseModel): "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. " + "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/timing.py b/src/coder_eval/timing.py index b2950896..c64bece1 100644 --- a/src/coder_eval/timing.py +++ b/src/coder_eval/timing.py @@ -52,10 +52,18 @@ def decompose_turn( 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 + tool + tail is the whole - turn. Defined once here rather than in five agents, and consumed by - ``EventCollector``, the golden-stream sensor, and - ``scripts/timing/decompose_run.py``. + 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). + + ``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 diff --git a/tests/_fixtures/golden_streams/_scrub.py b/tests/_fixtures/golden_streams/_scrub.py index 9450bc8e..27263a4d 100644 --- a/tests/_fixtures/golden_streams/_scrub.py +++ b/tests/_fixtures/golden_streams/_scrub.py @@ -135,6 +135,22 @@ 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, because that is + what the collector measures them against — so both are non-``None`` when + one exists and both are ``None`` when none does. The flag is the wrong key + for this 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. + + 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. + 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 @@ -154,9 +170,24 @@ 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"] + for field in ("harness_startup_ms", "harness_teardown_ms"): + value = record.get(field) + if assistant: + assert value is not None, ( + f"{field} is None on a turn that produced {len(assistant)} assistant message(s): " + "the collector measures the head and tail against the first and last generation, " + "so a turn that generated has both — None here says the bucket was never measured" + ) + else: + assert value is None, ( + f"{field} is {value!r} on a turn that produced NO assistant message: there is no " + "generation window to measure against, and a number here claims a measurement " + "nobody could have taken" + ) + 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/test_agent_golden_master.py b/tests/test_agent_golden_master.py index 4c54d0a2..54d7e98d 100644 --- a/tests/test_agent_golden_master.py +++ b/tests/test_agent_golden_master.py @@ -265,8 +265,15 @@ 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), ) -> 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. + """ return { "messages": [ { @@ -278,6 +285,8 @@ 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): @@ -362,3 +371,27 @@ 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 first and last generation. + 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_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=[None], overhead=(0.0, None)), expect_generation_window=False) From 6111bf6b89aa95ce0652efd5b7f9e9fc849a189b Mon Sep 17 00:00:00 2001 From: uipreliga Date: Thu, 10 Sep 2026 23:39:56 -0700 Subject: [PATCH 05/16] fix: code review fixes for turn head/tail timing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three defects the final review found, each breaking the invariant the change exists to establish. **A placeholder stamp was read as a window bound.** Codex's rollout rebuild, both its sub-agent recovery builders and Claude's synthesized terminal message all stamp `started_at == completed_at == now()` at APPEND time and declare `generation_duration_ms=None` to say no window was measurable. `_overhead_ms` read those stamps anyway, so a Codex turn rebuilt from its rollout — stamped at turn end — booked the ENTIRE TURN as harness startup. Skip them, the same exemption CE059 already makes for the same reason. **The bounds depended on append order.** Codex appends recovered sub-agent messages after the parent's last flush, so `generations[-1]` is not the last generation. Use min/max instead of the first and last list entries. **The four buckets were not disjoint.** Generation windows are tool-subtracted; the head and tail were not. A tool that escapes every window — Antigravity force-closes an orphan at finalization, inside the tail, and backgrounds anything over ten seconds — was counted both as tool and as head or tail. On the committed `antigravity_d_orphaned_tool` fixture that is a residual of -86% of wall clock. `decompose_turn` now subtracts tool time from both ends via the same `busy_ms` the windows use. Also: reset the terminal event when a new turn starts, so the one collector that outlives a turn (EarlyStopWatcher, across retries) cannot pair this attempt's start with the last attempt's end and publish the clamped inversion as a measured 0.0; stop `decompose_run.py` double-counting a sub-agent's generation against its parent Agent call's interval; and say plainly in HARNESS_PARITY.md that claude-code's and antigravity's `0.0` head is a clamped value rather than a measured interval. One golden dump changes, by two lines: `codex_g_items_rebuild` now honestly reports `null` for both buckets instead of a number derived from a placeholder. Co-Authored-By: Claude Opus 5 (1M context) --- docs/agents/HARNESS_PARITY.md | 19 ++- scripts/timing/decompose_run.py | 12 +- src/coder_eval/streaming/collector.py | 41 +++++- src/coder_eval/timing.py | 34 ++++- tests/_fixtures/golden_streams/_scrub.py | 32 +++-- .../expected/codex_g_items_rebuild.json | 4 +- tests/test_agent_golden_master.py | 19 ++- tests/test_event_collector.py | 125 +++++++++++++++++- 8 files changed, 247 insertions(+), 39 deletions(-) diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index d0ad4a97..d34b9921 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -63,7 +63,12 @@ generation window) and **tail** (last window → turn end) are booked as `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. With all +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, three live turns per harness reconcile to within 1.3 ms of `duration_seconds` (worst case 0.012% of wall clock; the residual is clock skew, since head and tail are measured between wall-clock event stamps @@ -78,9 +83,15 @@ 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 and the head reads a measured ~0. 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. + 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 practical consequence is that harness setup on + these two is booked as generation, and a regression in it would not show up + in the Startup cell. - 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 diff --git a/scripts/timing/decompose_run.py b/scripts/timing/decompose_run.py index df60ad4b..ba6e3c41 100644 --- a/scripts/timing/decompose_run.py +++ b/scripts/timing/decompose_run.py @@ -69,11 +69,19 @@ def _turn_buckets(turn: dict) -> tuple[float, float, float, float, float] | None 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 isinstance(m.get("generation_duration_ms"), (int, float)) + 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") @@ -98,7 +106,7 @@ def main(argv: list[str]) -> int: except (OSError, json.JSONDecodeError) as exc: print(f"skipping {path}: {exc}", file=sys.stderr) continue - harness = (record.get("environment_info") or {}).get("agent_type") or record.get("agent_type") or "unknown" + harness = record.get("agent_type") or "unknown" for turn in record.get("iterations") or []: buckets = _turn_buckets(turn) if buckets is not None: diff --git a/src/coder_eval/streaming/collector.py b/src/coder_eval/streaming/collector.py index 03f79455..2a4e1e17 100644 --- a/src/coder_eval/streaming/collector.py +++ b/src/coder_eval/streaming/collector.py @@ -77,6 +77,12 @@ def on_event(self, event: StreamEvent) -> None: 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): @@ -112,20 +118,43 @@ def _ordered_commands(self) -> list[CommandTelemetry]: 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 the FIRST and LAST ``AssistantMessage``, not - ``messages[0]`` / ``messages[-1]``: a simulation turn interleaves - ``UserMessage`` entries, and a reconciled turn ends with a + 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)] + 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( - generations[0].started_at, - generations[-1].completed_at, + 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 diff --git a/src/coder_eval/timing.py b/src/coder_eval/timing.py index c64bece1..66f4a1a1 100644 --- a/src/coder_eval/timing.py +++ b/src/coder_eval/timing.py @@ -1,4 +1,8 @@ -"""Shared timing helpers for agent implementations. +"""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`` @@ -47,6 +51,7 @@ def decompose_turn( 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. @@ -57,6 +62,17 @@ def decompose_turn( 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. @@ -80,13 +96,19 @@ def decompose_turn( (the two clocks disagreeing) IS a real zero and clamps, because both ends were observed. - NOTE a second implementation of this arithmetic lives in the evalboard's - Unaccounted cell (``_sections.tsx``), as ``pricing.ts`` mirrors - ``pricing.py``. Change one, change the other. + 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: - head = max((first_started_at - agent_started_at).total_seconds() * 1000.0, 0.0) + 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: - tail = max((agent_ended_at - last_completed_at).total_seconds() * 1000.0, 0.0) + 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 27263a4d..fb8c324e 100644 --- a/tests/_fixtures/golden_streams/_scrub.py +++ b/tests/_fixtures/golden_streams/_scrub.py @@ -137,12 +137,18 @@ def assert_timing_captured(record: dict[str, Any], *, expect_generation_window: **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, because that is - what the collector measures them against — so both are non-``None`` when - one exists and both are ``None`` when none does. The flag is the wrong key - for this 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. + 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 @@ -171,18 +177,20 @@ def assert_timing_captured(record: dict[str, Any], *, expect_generation_window: ) 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 assistant: + if measurable: assert value is not None, ( - f"{field} is None on a turn that produced {len(assistant)} assistant message(s): " - "the collector measures the head and tail against the first and last generation, " - "so a turn that generated has both — None here says the bucket was never measured" + 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 that produced NO assistant message: there is no " - "generation window to measure against, and a number here claims a measurement " + 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" ) 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 1c88ea85..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,8 +5,8 @@ "crash_reason": null, "crashed": false, "duration_seconds": "", - "harness_startup_ms": "", - "harness_teardown_ms": "", + "harness_startup_ms": null, + "harness_teardown_ms": null, "iteration": 1, "max_turns_exhausted": false, "messages": [ diff --git a/tests/test_agent_golden_master.py b/tests/test_agent_golden_master.py index 54d7e98d..df1df412 100644 --- a/tests/test_agent_golden_master.py +++ b/tests/test_agent_golden_master.py @@ -293,8 +293,10 @@ 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, @@ -312,7 +314,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 @@ -384,14 +386,23 @@ def test_a_generating_turn_must_report_a_tail(self): 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 first and last generation. + # 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) + 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=[None], overhead=(0.0, None)), expect_generation_window=False) + assert_timing_captured(self._record(windows=[5.0], overhead=(0.0, None)), expect_generation_window=False) diff --git a/tests/test_event_collector.py b/tests/test_event_collector.py index 324f10fa..8c1c0b79 100644 --- a/tests/test_event_collector.py +++ b/tests/test_event_collector.py @@ -485,15 +485,39 @@ class TestHarnessOverheadBuckets: """ @staticmethod - def _msg(started: datetime, completed: datetime) -> AssistantMessage: - return AssistantMessage(started_at=started, completed_at=completed, generation_duration_ms=1.0) + 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) -> TurnRecord: + 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), @@ -559,3 +583,98 @@ def test_a_snapshot_before_the_terminal_event_measures_nothing(self): 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 From 356551c7e0ba81ceb91acb429e121eacd1ddab23 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Thu, 10 Sep 2026 23:40:58 -0700 Subject: [PATCH 06/16] docs(harness): record three guards the head/tail review could not close The first is the valuable one: a golden-corpus assertion of the four-bucket identity would have caught this work's worst defect, and it is blocked only because 5 of 27 fixtures stamp generations on a clock that is not commensurable with their agent events. Co-Authored-By: Claude Opus 5 (1M context) --- .claude/harness-candidates.md | 32 ++++++++++++++++++++++++++++++++ 1 file changed, 32 insertions(+) diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index 5eef1adc..de431a08 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -551,3 +551,35 @@ 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). + +- [ ] **No golden-corpus assertion of the four-bucket identity**, which is what + would have caught the worst defect of the head/tail work (head and tail were + not tool-subtracted, so an orphaned or window-straddling tool was booked + twice — `antigravity_d_orphaned_tool` reconciled at **-86% of wall clock** + and every one of the 72 golden tests passed). The check itself is three + lines in `assert_timing_captured`: `Σ generation + ∪ tool + head + tail` must + not exceed `duration_seconds`. It is blocked because **5 of 27 fixtures stamp + their generations on a clock that is not commensurable with their agent + events** — the codex scenarios hardcode `2027-01-15` while the agent events + are stamped `now()`, giving a head of ~126 days, and `opencode_b` and + `claude_i` are similar. Adding the assertion today means a 5-entry + suppression list, i.e. a guard that is off for the harnesses most likely to + break it. The real fix is to make the fixtures use one clock; then the + invariant costs three lines. Caught in: turn head/tail timing final review. + +- [ ] **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. From e33d8ccd24b0dbc4c70bba2ce26bc0e6244774f4 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Thu, 10 Sep 2026 23:44:32 -0700 Subject: [PATCH 07/16] docs(harness): widen the measured head/tail figures to six turns per harness The post-fix re-verification doubled the sample. Figures move by 5-30% with CLI cache warmth, which is why the table already says to read their order of magnitude. Co-Authored-By: Claude Opus 5 (1M context) --- docs/agents/HARNESS_PARITY.md | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index d34b9921..0a82f37c 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -26,8 +26,8 @@ wall clock its numbers account for. |---|---|---|---|---|---| | `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.2 s — CLI boot fused with TTFT | 0.0 — the window above already covers it | ~2.5 s — CLI boot fused with TTFT | ~0.24 s — CLI boot fused with TTFT | -| `harness_teardown_ms` (turn tail) | ~1.4 s | ~12 ms | ~5 ms | ~28 ms | ~13 ms | +| `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` | @@ -69,14 +69,14 @@ 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, three live turns per harness reconcile to within -1.3 ms of `duration_seconds` (worst case 0.012% of wall clock; the residual is +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 three live `tasks/hello_date` turns -per harness and move with CLI cache warmth, so read their ORDER OF -MAGNITUDE, not the digits. +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: From eec776130c38863ec57b286681e20a27577950a7 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 06:46:28 -0700 Subject: [PATCH 08/16] test(timing): unify the fixture clocks and assert the four-bucket identity MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The golden corpus could not catch a DOUBLE-COUNT, only an absence. That is how the head/tail work shipped a defect where an orphaned tool was booked both in the tool union and in the tail: `antigravity_d_orphaned_tool` reconciled at -86% of its own wall clock while all 72 golden tests passed. Unify the clocks first, because the assertion is meaningless without it. Codex stamped its SDK items at a fixed 2027 epoch and OpenCode a month in the past, while both agents stamp their own lifecycle events with `now()` — so a codex replay recorded a `harness_startup_ms` of ~126 days and no presence-only check could see it. Both catalogues stay declarative with an absolute base; the runners now shift that base onto the replay's own clock, which keeps every derived duration exact (a 250 ms command stays 250 ms) and fixes only the era. No golden dump changes — these stamps are scrubbed. Then assert it: generation + UNION(tool) + head + tail cannot exceed `duration_seconds`, because the four are disjoint. The threshold is relative with an absolute floor, which is what makes it work at fixture scale — the defect reads +55% of wall but only +0.175 ms, so an absolute-only bound generous enough to survive scheduler jitter would have missed it. Mutation-verified: reintroducing the defect fails the antigravity fixture. 22 of 27 scenarios are checked. The other 5 inject SDK stamps in integer MILLISECONDS — 17 to 900 ms of declared item time against a replay that runs in well under one — so no rebasing makes them commensurable and they are exempt via `FICTIONAL_DURATIONS`, named individually with the reason. Closing that last gap needs the agent's own clock faked, not the fixtures' rebased. Co-Authored-By: Claude Opus 5 (1M context) --- .claude/harness-candidates.md | 26 +++-- tests/_fixtures/golden_streams/_scrub.py | 79 ++++++++++++++- .../golden_streams/codex_fixtures.py | 50 +++++++++- .../golden_streams/opencode_fixtures.py | 41 +++++++- tests/test_agent_golden_master.py | 98 ++++++++++++++++++- 5 files changed, 270 insertions(+), 24 deletions(-) diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index de431a08..7c4e31a9 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -552,20 +552,18 @@ divergences, so the deferred-work record is one place. Measurements in whether legacy records can be distinguished from current ones at all. Caught in: timing-capture final review (gpt-5.6-sol). -- [ ] **No golden-corpus assertion of the four-bucket identity**, which is what - would have caught the worst defect of the head/tail work (head and tail were - not tool-subtracted, so an orphaned or window-straddling tool was booked - twice — `antigravity_d_orphaned_tool` reconciled at **-86% of wall clock** - and every one of the 72 golden tests passed). The check itself is three - lines in `assert_timing_captured`: `Σ generation + ∪ tool + head + tail` must - not exceed `duration_seconds`. It is blocked because **5 of 27 fixtures stamp - their generations on a clock that is not commensurable with their agent - events** — the codex scenarios hardcode `2027-01-15` while the agent events - are stamped `now()`, giving a head of ~126 days, and `opencode_b` and - `claude_i` are similar. Adding the assertion today means a 5-entry - suppression list, i.e. a guard that is off for the harnesses most likely to - break it. The real fix is to make the fixtures use one clock; then the - invariant costs three lines. Caught in: turn head/tail timing final review. +- [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 diff --git a/tests/_fixtures/golden_streams/_scrub.py b/tests/_fixtures/golden_streams/_scrub.py index fb8c324e..d397b548 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 = "" @@ -104,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`` @@ -157,6 +194,20 @@ def assert_timing_captured(record: dict[str, Any], *, expect_generation_window: 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 @@ -194,6 +245,32 @@ def assert_timing_captured(record: dict[str, Any], *, expect_generation_window: "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" + ) + if not expect_generation_window: return windows = [(m.get("generation_duration_ms"), m.get("started_at"), m.get("completed_at")) for m in assistant] 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/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/test_agent_golden_master.py b/tests/test_agent_golden_master.py index df1df412..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)) @@ -266,6 +309,7 @@ def _record( 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`. @@ -273,8 +317,13 @@ def _record( 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", @@ -400,6 +449,45 @@ def test_an_unmeasurable_window_is_not_something_to_measure_against(self): 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 From 0020a99da396b046048f733784afad48cb9ec8d6 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 06:49:53 -0700 Subject: [PATCH 09/16] test(harness): pin why claude-code's zero head is left as a clamp MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The question was whether to emit `AgentStartEvent` before `_build_claude_query`, so the head became a measurement rather than a clamped negative. Measured first: the build is 0.03 ms, and 0.10 ms with four plugin roots — not the hundreds of milliseconds the review hypothesised, because the transport is constructed lazily and plugin resolution is path work. So: no. Moving the emit would not change the number anyway — `last_event_wall`, which becomes the first window's start, is stamped before the build too, so the build sits inside msg0's generation window either way. It would only convert a -0.03 ms clamp into a +0.03 ms measurement, and it would cost the event its `model=effective_model`, which the build resolves and the live renderers display. Surfacing the build cost would need the window re-seeded after it, which is the generation-window seeding change HARNESS_PARITY.md already rules out for an in-process SDK. Both rejections rest on the build being cheap, so guard that rather than leaving it as a claim in a commit message: `TestClaudeHeadIsStructurallyZero` holds it under 50 ms (~300x headroom, best-of-5 so a loaded runner cannot trip it) and its docstring carries the reasoning. The parity doc now states the measured figures instead of implying an unquantified gap. Co-Authored-By: Claude Opus 5 (1M context) --- docs/agents/HARNESS_PARITY.md | 11 ++++-- tests/test_agent_telemetry.py | 73 +++++++++++++++++++++++++++++++++++ 2 files changed, 81 insertions(+), 3 deletions(-) diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index 0a82f37c..dfbc977c 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -89,9 +89,14 @@ decomposed, because the divergence is real and unfixable in both directions: 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 practical consequence is that harness setup on - these two is booked as generation, and a regression in it would not show up - in the Startup cell. + 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 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." + ) From 5a4c9c3e46bc1103e79f03814988376b878161bf Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 07:21:59 -0700 Subject: [PATCH 10/16] docs(harness): claude-code's generation windows are not tool-subtracted MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Live verification on a task with concurrent tool calls — the earlier runs all used `hello_date`, which has none — found the four-bucket identity failing on claude-code alone, by 482 ms and 340 ms on two ~18-25 s turns. The residual equals the generation/tool overlap to within 1.4 ms on every claude-code turn measured, including the two whose overlap was under a millisecond and which reconciled to within 0.1 ms. Cause is a documented exemption whose premise does not hold: claude-code is the one harness that does not subtract tool time from its generation windows, on the reasoning that a tool's execution falls between two windows. 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. The other four harnesses overlapped by ~2.0-2.3 s on the same task and reconciled to within 1.2 ms, because they subtract it. This predates the head/tail work — generation-vs-tool timing is older — but that work's identity is what made it visible, and the parity table was claiming "yes" for all five. Correct the table and the paragraph, state the measurement, and track the fix as a candidate: applying `busy_ms` here changes a published `generation_duration_ms` on the most-used harness, so it needs its own golden regeneration and live pass rather than a quiet amendment here. Also warn in the new golden identity assertion's failure text, so a future claude-code fixture that trips it is not misdiagnosed as a fresh double-count. Co-Authored-By: Claude Opus 5 (1M context) --- .claude/harness-candidates.md | 22 ++++++++++++++++++++++ docs/agents/HARNESS_PARITY.md | 23 ++++++++++++++++++----- tests/_fixtures/golden_streams/_scrub.py | 6 +++++- 3 files changed, 45 insertions(+), 6 deletions(-) diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index 7c4e31a9..3a508d77 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -581,3 +581,25 @@ divergences, so the deferred-work record is one place. Measurements in `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. + +- [ ] **`claude-code` does not subtract tool execution from its generation + windows, and the premise for that is measurably wrong.** 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. diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index dfbc977c..c4a13f53 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -31,7 +31,7 @@ wall clock its numbers account for. | 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 + head + tail ≈ turn duration` | yes | yes | yes | yes | yes | +| `Σ generation + ∪ tool + head + tail ≈ turn duration` | within 0.1 ms when nothing overlaps; off by the generation/tool overlap when it does — see below | 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 @@ -51,10 +51,23 @@ 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` is the one harness that does **not** apply the subtraction: it +marks the end of the previous SDK event and reads again when the next message +arrives, on the premise that a tool's execution then falls between two windows +rather than inside one. **Measured, that premise does not always hold.** A tool's +timer starts at the emission carrying its `tool_use` block, and one assistant +turn can span 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`. +On the same task the other four harnesses overlapped by ~2.0-2.3 s and still +reconciled to within 1.2 ms, because they subtract it. Two claude-code turns in +the same batch that happened to overlap by <1 ms reconciled to within 0.1 ms. +Applying `busy_ms` here as the other four do is the obvious fix and is tracked +in `.claude/harness-candidates.md`; it is a change to a published +`generation_duration_ms`, so it needs its own verification pass. **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 diff --git a/tests/_fixtures/golden_streams/_scrub.py b/tests/_fixtures/golden_streams/_scrub.py index d397b548..e1574053 100644 --- a/tests/_fixtures/golden_streams/_scrub.py +++ b/tests/_fixtures/golden_streams/_scrub.py @@ -268,7 +268,11 @@ def assert_timing_captured( 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" + "left in the head or tail as well as in the tool union. The one KNOWN exception is " + "claude-code, which does not subtract tool time from its generation windows, so a " + "trajectory where a tool runs concurrently with a later emission of the same turn " + "overlaps legitimately; see docs/agents/HARNESS_PARITY.md before concluding this is " + "a new bug" ) if not expect_generation_window: From 0fcaf89f6fa405bddcd4b3f9ff96bce1e211de65 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 07:48:02 -0700 Subject: [PATCH 11/16] fix(claude-code): subtract tool execution from the generation windows MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit claude-code was the one harness that did not, and the reason it was exempt is measurably wrong. The premise was 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. 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 five parallel writes, five reads and two concurrent `Bash` calls: 482 ms and 340 ms of overlap on two ~18-25 s turns, and the four-bucket residual came out at exactly -481 ms and -339 ms. The other four harnesses overlapped by ~2.0-2.3 s on the same task and still reconciled to within 1.2 ms, because they subtract it. Two claude-code turns in the same batch whose overlap happened to be under a millisecond reconciled to 0.1 ms, which is what isolated the cause to the missing subtraction rather than to anything about the head and tail. The subtraction cannot happen while flushing: a tool issued by an earlier emission is still running when the next window closes, so its interval does not exist yet. `_subtract_tool_time_from_windows` therefore runs once at finalization, when every span is known, and uses the same `busy_ms` union the other four use — the union and not the sum, because these tools overlap each other too. Sub-agent emissions are skipped: their own tools are not in this command list, and the Agent call that spawned them already spans their run. Re-verified live, same task: claude-code 481 ms / 2.691% -> 1.4 ms / 0.006% over four turns that all carried overlapping tool calls, and all five harnesses reconcile (worst 1.7 ms, 0.012%). `generation_duration_ms` now means the same thing on every harness, so the parity table's identity row is "yes" for all five without a caveat. Co-Authored-By: Claude Opus 5 (1M context) --- .claude/harness-candidates.md | 11 +++++- docs/agents/HARNESS_PARITY.md | 44 +++++++++++---------- src/coder_eval/agents/claude_code_agent.py | 45 ++++++++++++++++++++++ src/coder_eval/models/telemetry.py | 5 ++- tests/_fixtures/golden_streams/_scrub.py | 8 ++-- 5 files changed, 84 insertions(+), 29 deletions(-) diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index 3a508d77..88356270 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -582,8 +582,15 @@ divergences, so the deferred-work record is one place. Measurements in so the first agent to record an aware stamp discovers it at runtime. Caught in: turn head/tail timing final review. -- [ ] **`claude-code` does not subtract tool execution from its generation - windows, and the premise for that is measurably wrong.** The other four +- [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 diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index c4a13f53..ea99835a 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -31,17 +31,18 @@ wall clock its numbers account for. | 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 + head + tail ≈ turn duration` | within 0.1 ms when nothing overlaps; off by the generation/tool overlap when it does — see below | yes | yes | yes | yes | +| `Σ 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 +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 @@ -53,21 +54,24 @@ 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. -`claude-code` is the one harness that does **not** apply the subtraction: it -marks the end of the previous SDK event and reads again when the next message -arrives, on the premise that a tool's execution then falls between two windows -rather than inside one. **Measured, that premise does not always hold.** A tool's -timer starts at the emission carrying its `tool_use` block, and one assistant -turn can span 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`. -On the same task the other four harnesses overlapped by ~2.0-2.3 s and still -reconciled to within 1.2 ms, because they subtract it. Two claude-code turns in -the same batch that happened to overlap by <1 ms reconciled to within 0.1 ms. -Applying `busy_ms` here as the other four do is the obvious fix and is tracked -in `.claude/harness-candidates.md`; it is a change to a published -`generation_duration_ms`, so it needs its own verification pass. +**`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 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/models/telemetry.py b/src/coder_eval/models/telemetry.py index 0bef609f..65a8f5ac 100644 --- a/src/coder_eval/models/telemetry.py +++ b/src/coder_eval/models/telemetry.py @@ -228,8 +228,9 @@ 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 " + "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. " diff --git a/tests/_fixtures/golden_streams/_scrub.py b/tests/_fixtures/golden_streams/_scrub.py index e1574053..9fb4705f 100644 --- a/tests/_fixtures/golden_streams/_scrub.py +++ b/tests/_fixtures/golden_streams/_scrub.py @@ -268,11 +268,9 @@ def assert_timing_captured( 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. The one KNOWN exception is " - "claude-code, which does not subtract tool time from its generation windows, so a " - "trajectory where a tool runs concurrently with a later emission of the same turn " - "overlaps legitimately; see docs/agents/HARNESS_PARITY.md before concluding this is " - "a new bug" + "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: From b867eb3154b0aadefb5567ccd2ba603873fb4694 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 11:04:49 -0700 Subject: [PATCH 12/16] =?UTF-8?q?fix(antigravity):=201/3=20=E2=80=94=20giv?= =?UTF-8?q?e=20every=20generation=20a=20message=5Fid?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Step stream carries no message id, so every Antigravity `AssistantMessage` was recorded with `message_id: None`. The evalboard groups assistant emissions by that field and falls back to a wall-clock gap threshold when either side lacks one — and PR #164 made this harness's generation windows contiguous, so the gap is now exactly 0 ms and the fallback folds a whole turn's generations into one timeline row. Synthesize the id the way Codex does (`{turn_id}-msg-{gen_index}`), reusing the `_assistant_turns` counter that already counts appended generations, read before its increment so the first id is `-msg-0`. Totals are unaffected: the evalboard sums token buckets across a group, and the turn/generation counts come from `_assistant_turns` Python-side. Only display granularity was lost. The five regenerated goldens are the regression sensor (`message_id` is not scrubbed); the new unit assertion pins the exact id strings, so moving the increment above the append fails loudly instead of silently making the ids 1-based. Co-Authored-By: Claude Opus 5 (1M context) --- src/coder_eval/agents/antigravity_agent.py | 4 ++++ .../expected/antigravity_a_single_text_turn.json | 2 +- .../expected/antigravity_b_tool_call_resolved.json | 2 +- .../antigravity_c_thinking_and_tool_same_generation.json | 2 +- .../expected/antigravity_d_orphaned_tool.json | 2 +- .../expected/antigravity_e_multi_generation.json | 6 +++--- tests/test_antigravity_agent.py | 9 ++++++++- 7 files changed, 19 insertions(+), 8 deletions(-) diff --git a/src/coder_eval/agents/antigravity_agent.py b/src/coder_eval/agents/antigravity_agent.py index f1a33914..51414eea 100644 --- a/src/coder_eval/agents/antigravity_agent.py +++ b/src/coder_eval/agents/antigravity_agent.py @@ -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/tests/_fixtures/golden_streams/expected/antigravity_a_single_text_turn.json b/tests/_fixtures/golden_streams/expected/antigravity_a_single_text_turn.json index fe601ee4..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 @@ -27,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 3729ef53..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 @@ -56,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 f75f40fb..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 @@ -65,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 ee177ff6..02f13064 100644 --- a/tests/_fixtures/golden_streams/expected/antigravity_d_orphaned_tool.json +++ b/tests/_fixtures/golden_streams/expected/antigravity_d_orphaned_tool.json @@ -47,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 1a47c81f..1b69cc78 100644 --- a/tests/_fixtures/golden_streams/expected/antigravity_e_multi_generation.json +++ b/tests/_fixtures/golden_streams/expected/antigravity_e_multi_generation.json @@ -27,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, @@ -54,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, @@ -81,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/test_antigravity_agent.py b/tests/test_antigravity_agent.py index 25fd80b1..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 From 68a64c2d79ce120d3bc413443b7d9260c7734ff0 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 11:10:09 -0700 Subject: [PATCH 13/16] =?UTF-8?q?test(lint):=202/3=20=E2=80=94=20CE060,=20?= =?UTF-8?q?an=20AssistantMessage=20must=20declare=20its=20message=5Fid?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Antigravity omitted the kwarg and nothing failed: the field defaulted to None on every message, the evalboard summed the collapsed group so the totals stayed right, and the golden snapshots had ratified the null 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 — which is why the author-time rule is worth its cost and is the only one of the three sensors that would have failed on the day this shipped. Unlike CE058/CE059 it derives its constructor set from each module's own `coder_eval.models` imports rather than hardcoding the spelling. That closes the blind spot CE058's own docstring concedes: claude_code_agent 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 the other two the same way is recorded in .claude/harness-candidates.md — it changes two shipped rules and needs its own per-rule mutation check. Verified non-vacuous: stripping the Phase 1 kwarg yields exactly one violation, at the site it came from; the clean tree yields zero, with no suppression anywhere. Co-Authored-By: Claude Opus 5 (1M context) --- .claude/harness-candidates.md | 20 ++++ CLAUDE.md | 2 +- pyproject.toml | 1 + tests/lint/rules/ce060_message_id_declared.py | 99 +++++++++++++++++++ tests/lint/runner.py | 2 + tests/test_custom_lint.py | 80 +++++++++++++++ 6 files changed, 203 insertions(+), 1 deletion(-) create mode 100644 tests/lint/rules/ce060_message_id_declared.py diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index 88356270..45a0fd77 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -610,3 +610,23 @@ divergences, so the deferred-work record is one place. Measurements in 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. diff --git a/CLAUDE.md b/CLAUDE.md index 616945b8..d5a23e92 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 only granularity was lost, 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. 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/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/tests/lint/rules/ce060_message_id_declared.py b/tests/lint/rules/ce060_message_id_declared.py new file mode 100644 index 00000000..c28d1374 --- /dev/null +++ b/tests/lint/rules/ce060_message_id_declared.py @@ -0,0 +1,99 @@ +"""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 totals are summed across the group, so only granularity was lost, +and the golden snapshots had ratified the ``null`` the day they were written. +The mechanism lives in ``docs/agents/HARNESS_PARITY.md`` § Timing capture; +it is not 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. + +BLIND SPOT: 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``, and both evaluate to ``None`` whenever the CLI omits the id +— ``pi_a_single_text_turn.json`` records exactly that. 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. + +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 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" + + +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 (node.module or "").startswith(_MODELS_MODULE): + self._names.update(a.asname or a.name for a in node.names if a.name == "AssistantMessage") + return super().check(tree) + + def visit_Call(self, node: ast.Call) -> None: + if self._in_scope: + func = node.func + name = func.id if isinstance(func, ast.Name) else func.attr if isinstance(func, ast.Attribute) else None + if name in self._names: + 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_custom_lint.py b/tests/test_custom_lint.py index 84a95d53..16f8b6e8 100644 --- a/tests/test_custom_lint.py +++ b/tests/test_custom_lint.py @@ -4446,3 +4446,83 @@ 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_attribute_spelling(self): + assert self._run(self._IMPORT + "m = models.AssistantMessage(model=model)") + + 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"] From 06d8dacd542b6873db2782dfbe500c9157f24727 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 11:13:22 -0700 Subject: [PATCH 14/16] =?UTF-8?q?docs(harness):=203/3=20=E2=80=94=20messag?= =?UTF-8?q?e=5Fid=20is=20what=20splits=20the=20timeline?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Record the per-harness `message_id` source in the Timing-capture table and give the rationale one home: the evalboard groups assistant emissions by the field and falls back to a wall-clock gap when either side lacks one, which cannot split windows that are contiguous by construction. The source comment and the CE060 docstring point here rather than restating it, and this is the only place the 100 ms numeral is written outside runs.ts. The table row names both synthetic sub-agent forms, since a row titled "message_id source" that omits them reads as wrong the first time somebody greps it. Nothing goes in Known divergences — this is a fix. On the consumer side, tighten the existing message_id-splitting case from a 10 ms to a 0 ms gap so the fixture matches the shape this harness really emits. No second case: runs.ts short-circuits on the two ids before the gap is computed, so 10 ms and 0 ms take the identical branch and a parallel case would test nothing new. Co-Authored-By: Claude Opus 5 (1M context) --- docs/agents/HARNESS_PARITY.md | 19 +++++++++++++++++++ evalboard/lib/__tests__/parseMessages.test.ts | 8 +++++--- 2 files changed, 24 insertions(+), 3 deletions(-) diff --git a/docs/agents/HARNESS_PARITY.md b/docs/agents/HARNESS_PARITY.md index ea99835a..5a60ca0a 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -31,6 +31,7 @@ wall clock its numbers account for. | 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` | +| `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` | 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`.** @@ -141,6 +142,24 @@ 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. Nothing about the numbers would +look wrong, because the consumer SUMS a group's token buckets and durations; +what is lost is per-generation thinking / text / tool attribution. CE060 makes +the kwarg mandatory in `src/coder_eval/agents/` for that reason. Note 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. + ### Known divergences - **Delegate (`delegate-sdk`, out of tree)** records `duration_ms` but no 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" }], }, From 1a853b7f56fc984d6d3224f2f8171f14b9ab8eae Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 11:37:56 -0700 Subject: [PATCH 15/16] fix: code review fixes for antigravity-message-id MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two findings, each raised independently by both final reviewers. CE060's rename-safety was half delivered. Deriving the constructor set from the module's imports removes the local-BINDING spelling, but the class's own name was still a string literal here, so renaming the model — the likelier rename, since the alias exists only because two AssistantMessage types collide — would have disarmed the rule exactly as it disarms the name lists CE060 argues against. It now reads `AssistantMessage.__name__`, the way CE056 imports IN_CONTAINER_ENV. The import walk also traded the alias gap for an import-FORM gap that the docstring's "one remaining blind spot" did not mention: only an absolute `from coder_eval.models import ...` bound anything, so a relative import went silently blind for a whole file (and agents/ does use relative imports), as did every module-alias spelling. Both now fire, verified case by case; the attribute spelling is matched on the attribute alone, deliberately, because the module binding it arrives through is the part a class-binding walk cannot see. What remains — a re-export through an intermediate module — is now stated as such. The attribute test was retargeted at the module-alias form, since with a direct import beside it it had been passing for the wrong reason. The prose in all three surfaces claimed "only granularity was lost", which is measurably false: a grouped emission is one API call to the evalboard's thinking-cost simulator, whose cache cascade is quadratic in that count, so a single-shot Antigravity run had every coefficient pinned at zero; the Messages count and the 10 s slow-generation bar were per-turn too. All three move toward the figure they were always meant to report, so this fix corrects them — but a trend compared across it is not comparing like with like, and the docs now say so. Also: the table gave OpenCode's `None` case where the CE060 docstring asserted it, so the two surfaces in one diff disagreed, and the remaining nulls are not legacy-only. Co-Authored-By: Claude Opus 5 (1M context) --- CLAUDE.md | 2 +- docs/agents/HARNESS_PARITY.md | 30 +++++-- tests/lint/rules/ce060_message_id_declared.py | 81 +++++++++++++++---- tests/test_custom_lint.py | 18 ++++- 4 files changed, 106 insertions(+), 25 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index d5a23e92..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: **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 only granularity was lost, 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. 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). +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 5a60ca0a..121c6d17 100644 --- a/docs/agents/HARNESS_PARITY.md +++ b/docs/agents/HARNESS_PARITY.md @@ -31,7 +31,7 @@ wall clock its numbers account for. | 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` | -| `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` | CLI `responseId`; `None` when absent | +| `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`.** @@ -149,16 +149,32 @@ 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. Nothing about the numbers would -look wrong, because the consumer SUMS a group's token buckets and durations; -what is lost is per-generation thinking / text / tool attribution. CE060 makes -the kwarg mandatory in `src/coder_eval/agents/` for that reason. Note the two -synthetic schemes read differently on purpose: Codex deliberately REPEATS one +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. +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 diff --git a/tests/lint/rules/ce060_message_id_declared.py b/tests/lint/rules/ce060_message_id_declared.py index c28d1374..aeb31fdd 100644 --- a/tests/lint/rules/ce060_message_id_declared.py +++ b/tests/lint/rules/ce060_message_id_declared.py @@ -6,10 +6,12 @@ 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 totals are summed across the group, so only granularity was lost, -and the golden snapshots had ratified the ``null`` the day they were written. -The mechanism lives in ``docs/agents/HARNESS_PARITY.md`` § Timing capture; -it is not restated here. +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 @@ -28,15 +30,33 @@ is recorded in ``.claude/harness-candidates.md``; it is a change to two shipped rules and needs its own mutation checks. -BLIND SPOT: the runtime ``None``. The rule requires the kwarg to be *present*, -not non-``None`` when it runs. ``opencode_agent.py`` passes +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``, and both evaluate to ``None`` whenever the CLI omits the id -— ``pi_a_single_text_turn.json`` records exactly that. 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. +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 @@ -47,6 +67,7 @@ import ast import re +from coder_eval.models import AssistantMessage from tests.lint.rules.base import BaseRule from tests.lint.violation import Violation @@ -54,6 +75,24 @@ _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: @@ -73,15 +112,25 @@ def __init__(self, filepath: str) -> None: def check(self, tree: ast.AST) -> list[Violation]: for node in ast.walk(tree): - if isinstance(node, ast.ImportFrom) and (node.module or "").startswith(_MODELS_MODULE): - self._names.update(a.asname or a.name for a in node.names if a.name == "AssistantMessage") + 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 - name = func.id if isinstance(func, ast.Name) else func.attr if isinstance(func, ast.Attribute) else None - if name in self._names: + # 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( diff --git a/tests/test_custom_lint.py b/tests/test_custom_lint.py index 16f8b6e8..05aff5d5 100644 --- a/tests/test_custom_lint.py +++ b/tests/test_custom_lint.py @@ -4485,9 +4485,25 @@ def test_flags_an_arbitrary_alias(self): # CE060 resolves aliases instead. assert self._run("from coder_eval.models import AssistantMessage as Msg\nm = Msg(model=model)") - def test_flags_the_attribute_spelling(self): + 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)") From ac4e88f418db1343b897d30123b248e2a9f5cf04 Mon Sep 17 00:00:00 2001 From: uipreliga Date: Fri, 11 Sep 2026 11:39:23 -0700 Subject: [PATCH 16/16] docs(harness): register the message_id gaps the final review surfaced MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three candidates, all deferred with the reason stated rather than the work done: the within-turn-only nature of a synthetic message_id (a negative property over two languages, and the obvious assertion would pass today while catching nothing), the absence of any evalboard test fed by a Python golden (needs a loader and a scrub-aware timestamp story), and the model field's claude-only description (the plan scoped out model changes; no mechanical guard is obvious). A fourth was attempted and dropped: a vitest case asserting that two null-id messages at a 0 ms gap collapse. Its mutation check showed it takes the identical `gap <= SAME_EMISSION_GAP_MS` branch as the existing 50 ms legacy case, so it could not fail for the reason it claimed — which is what the plan's own argument against a parallel case said. Co-Authored-By: Claude Opus 5 (1M context) --- .claude/harness-candidates.md | 44 +++++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/.claude/harness-candidates.md b/.claude/harness-candidates.md index 45a0fd77..2bc1fbbd 100644 --- a/.claude/harness-candidates.md +++ b/.claude/harness-candidates.md @@ -630,3 +630,47 @@ divergences, so the deferred-work record is one place. Measurements in 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.