fix(timing): claude-code's windows tile across a tool result

`on_user_message` reset the generation mark to `self.clock.now()`, so the
next window opened when the tool RESULT arrived instead of tiling from the
previous emission's close. Everything in between — SDK transport, CLI
processing, next-request dispatch — fell into no bucket at all, and the
four-bucket identity stopped closing.

The live stream delivers TWO user messages per tool call, and the mark was
reset on each, so the window opened at the LAST one. Traced on
`tasks/dataset_example.yaml`:

    msg2 (issues the Write) closes   27.773889 -> 28.067824
    user message #1                  28.080804   <- mark reset here
    user message #2                  30.009645   <- and again, 1.93s later
    msg3 window opened at            30.009645   (should be 28.067824)

1.94 s lost from an 11.7 s turn. CI's residual gate has been failing on
exactly these two rows (16.668% and 16.325% on the runner, 21-28% locally).
Same task after the fix: 0.02%, worst turn 4.5 ms — the known
`turn_start_time`-vs-`AgentStartEvent` baseline and nothing else.

The tool's own interval is not double-counted: it is a separate bucket and
`subtract_tool_time` clips the tool union out of every window it overlaps,
once, for all five harnesses. That central subtraction is precisely what
lets the reducer leave its mark alone — the same rule pi follows with
`gen_mark`, and the one pi was explicitly fixed for.

WHY THIS SURVIVED, which is worth more than the one-line fix. Three ways to
write a test for it cannot fail, and I wrote two of them before getting one
that does:

  1. A tool-heavy shape. Three concurrent `sleep 3` calls make the tool
     union absorb the interval; every live probe I ran read 0.05% and I
     concluded the harness was healthy. The defect needs a FAST tool.
  2. A single tool result. claude-code reconstructs `execution_started_at`
     by subtracting the measured duration from the resolve instant, so with
     one message the discarded interval and the tool's own span are the
     SAME milliseconds — `subtract_tool_time` removes them either way and
     the identity closes with or without the bug. This is why the existing
     `_claude_turn` case passed throughout.
  3. A duplicate tool RESULT as the second message. That re-resolves the
     call and stretches the tool span over the very interval being probed.

`test_a_slow_tool_result_round_trip_is_not_lost` scripts the shape that
discriminates: a 20 ms tool, then a second user message carrying no tool
result 2 s later. Mutation-checked — restoring the reset fails that case by
exactly -2000 ms and leaves the other seven green, which is the production
situation reproduced in the suite.

No golden regeneration: `_scrub.py::SCRUB_KEYS` masks every timing value, so
the corpus cannot see this class of change. That is a known property of the
goldens, not an oversight, and it is the reason the ms-exact identity
contract exists alongside them.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FpDo37ypvLjLiWXFsEkg6k

Author: uipreliga

docs/agents/HARNESS_PARITY.md

@@ -262,6 +262,29 @@ 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.
 
+**Windows tile ACROSS a tool result, on every harness.** claude-code used to
+reset its generation mark when the tool-result `UserMessage` arrived, so the
+next window opened at the result rather than tiling from the previous
+emission. Everything in between — SDK transport, CLI processing, next-request
+dispatch — fell into no bucket. The live stream delivers TWO user messages per
+tool call, ~2 s apart, and the mark was reset on each, so the window opened at
+the LAST one: measured on `tasks/dataset_example.yaml` at 1.94 s lost from an
+11.7 s turn, 16-28% of wall clock, and it is what failed CI's residual gate.
+The mark is now left where `on_assistant_message` put it and the tool's own
+interval is removed centrally by `subtract_tool_time`, exactly as pi does with
+`gen_mark`. Same task after the fix: 0.02%.
+
+Why it survived so long is the more useful half. A tool-heavy shape cannot see
+it — three concurrent `sleep 3` calls make the tool union absorb the interval
+and the residual reads 0.05%. Neither can a single-tool-result fixture:
+claude-code reconstructs `execution_started_at` by subtracting the measured
+duration from the resolve instant, so with one message the discarded interval
+and the tool's own span are the SAME milliseconds and the identity closes
+either way. It takes a FAST tool plus a SECOND user message carrying no tool
+result to separate them, which is what
+`test_a_slow_tool_result_round_trip_is_not_lost` scripts. Two earlier drafts of
+that test could not fail.
+
 **Four turn buckets, two task buckets — and they are different scopes.** The
 four above tile ONE TURN and their identity (`head + Σgeneration + UNION(tool)
 + tail == the turn's span`) is asserted to the millisecond by

src/coder_eval/agents/claude_code_agent.py

@@ -597,7 +597,28 @@ def on_user_message(self, message: Message) -> None:
         """Process tool results (and a sub-agent's terminal generation) from a
         tool-result UserMessage. The sub-agent message is appended BEFORE the
         tool-result loop — its position in ``sdk_messages`` is observable."""
-        self.last_event_wall = self.clock.now()
+        # The generation mark is DELIBERATELY NOT advanced here. It used to be
+        # reset to `self.clock.now()`, which opened the next window at the
+        # instant the tool RESULT arrived rather than tiling it from the
+        # previous window's close — so everything between the tool finishing
+        # and its result reaching this handler (SDK transport, CLI processing,
+        # next-request dispatch) fell into no bucket at all. Measured on
+        # `tasks/dataset_example.yaml`: a 21.5 ms `Write` followed by a 2511.7 ms
+        # round trip, which is 21% of an 11.7 s turn accounted to nothing and
+        # the reason CI's residual gate failed on that task while a
+        # `sleep`-heavy probe read 0.05%. A tool-heavy shape cannot see this:
+        # the tool union absorbs the interval. A fast tool leaves it exposed.
+        #
+        # Leaving the mark where `on_assistant_message` put it makes the next
+        # window run from the previous emission's arrival, so the windows tile
+        # the turn contiguously — the same rule pi follows with `gen_mark`, and
+        # the one pi was explicitly fixed for.
+        #
+        # The tool's OWN interval is not double-counted by this: it is a
+        # separate bucket, and `streaming/collector.py::subtract_tool_time`
+        # clips the tool union out of every window it overlaps, once, for all
+        # five harnesses. That is exactly why the mark can be left alone here —
+        # the reducer no longer has to carve the tool out of its own windows.
 
         sub_msg = self._agent._synthesize_subagent_terminal_message(message, self.sdk_model_used)
         if sub_msg is not None:

tests/test_timing_identity_contract.py

@@ -449,11 +449,17 @@ def _claude_turn(monkeypatch: pytest.MonkeyPatch) -> Turn:
     `tests/test_agent_telemetry.py`; here it shows up as the windows still
     tiling.
 
-    Note where its windows do NOT tile: the tool result resets both marks, so
-    the interval between the emission that ISSUED the call and the result is
-    left outside every window. That gap is the tool's own execution, which is
-    exactly what the tool bucket claims — which is why the identity still
-    closes to the millisecond.
+    Its windows TILE across the tool result, and this case only proved that by
+    accident until the reducer was fixed. The mark used to be reset when the
+    result arrived, so the interval between the emission that ISSUED the call
+    and the result landed in no bucket. Here that interval IS the tool's
+    execution exactly — the case scripts the result at the instant the tool
+    ends — so the tool bucket happened to claim the same milliseconds and the
+    identity closed anyway. On a real turn the two differ: a 21.5 ms `Write`
+    can be followed by a 2.5 s round trip, and 21% of the turn goes missing.
+    `test_a_slow_tool_result_round_trip_is_not_lost` is the case that
+    discriminates; this one deliberately keeps the coincident shape so the two
+    read as a pair.
     """
     from coder_eval.agents import claude_code_agent as claude_module
     from coder_eval.agents.claude_code_agent import ClaudeCodeAgent, _ClaudeTurnState
@@ -517,6 +523,98 @@ def _monotonic() -> float:
     return Turn(started_ms=0.0, ended_ms=3000.0, messages=list(state.sdk_messages), commands=commands)
 
 
+def _claude_slow_result_turn(monkeypatch: pytest.MonkeyPatch) -> Turn:
+    """A FAST tool followed by a SLOW result round trip — the shape that hid a defect.
+
+    ``_claude_turn`` above scripts the tool result at the instant the tool
+    finishes, so the un-tiled interval and the tool's own span were the same
+    milliseconds and the identity closed even while the mark was being reset.
+    Every live probe had the same blind spot from the other direction: three
+    concurrent ``sleep 3`` calls make the tool union so large that the round
+    trip rounds away (measured: 0.05% residual).
+
+    Here the tool runs for 20 ms and its result takes 2000 ms to come back,
+    which is `tasks/dataset_example.yaml` — the task CI actually runs, where a
+    21.5 ms ``Write`` met a 2511.7 ms round trip and 21% of the turn was
+    accounted to nothing. The identity closing here is the whole point: the
+    window after the result must tile from the previous emission, not open
+    when the result lands.
+    """
+    from coder_eval.agents import claude_code_agent as claude_module
+    from coder_eval.agents.claude_code_agent import ClaudeCodeAgent, _ClaudeTurnState
+    from coder_eval.streaming.events import AgentEndStatus as _AgentEndStatus
+    from tests._fixtures.golden_streams.claude_fixtures import AssistantMessage as SdkAssistantMessage
+    from tests._fixtures.golden_streams.claude_fixtures import ToolUseBlock, UserMessage, message_start
+
+    clock = _InjectedClock()
+
+    def _monotonic() -> float:
+        return clock.at_ms / 1000.0
+
+    monkeypatch.setattr(claude_module, "time", SimpleNamespace(monotonic=_monotonic))
+
+    agent = ClaudeCodeAgent(parse_agent_config(type=AgentKind.CLAUDE_CODE, permission_mode="acceptEdits"))
+    collector = EventCollector()
+    commands: list[CommandTelemetry] = []
+
+    clock.at_ms = 200
+    state = _ClaudeTurnState(
+        agent,
+        emit=CompositeStreamCallback(
+            [
+                collector,
+                SimpleNamespace(on_event=lambda e: commands.append(e.tool) if isinstance(e, ToolEndEvent) else None),
+            ]
+        ),
+        collector=collector,
+        task_id="t",
+        user_input="go",
+        iteration=1,
+        max_turns=None,
+        log=agent._log,
+        turn_start_time=_monotonic(),
+        deadline=None,
+        clock=clock,
+    )
+
+    clock.at_ms = 500
+    state.on_stream_event(message_start("m1"))
+    clock.at_ms = 980
+    state.on_assistant_message(
+        SdkAssistantMessage(
+            [ToolUseBlock("c1", "Write", {"file_path": "out.txt"})],
+            usage={"input_tokens": 10, "output_tokens": 5},
+            message_id="m1",
+        )
+    )
+    # The tool itself is 20 ms. What follows is the shape a live turn actually
+    # has, traced off `tasks/dataset_example.yaml`: the SDK delivers TWO user
+    # messages, the second ~2 s after the first. The old code reset the mark on
+    # each, so the next window opened at the LAST one and that 2 s vanished.
+    #
+    # One user message is not enough to catch it, and that is exactly why this
+    # shipped: claude-code reconstructs `execution_started_at` by subtracting
+    # the measured duration from the resolve instant, so with a single message
+    # the discarded interval and the tool's own span are the SAME milliseconds
+    # — `subtract_tool_time` removes them either way and the identity closes
+    # with or without the bug. The second message is what separates them.
+    clock.at_ms = 1000
+    state.on_user_message(UserMessage("c1", False, "written"))
+    clock.at_ms = 3000
+    # The second one carries NO tool-result block, which is what the live
+    # stream does — the traced turn kept its 21.5 ms Write span across it. A
+    # duplicate RESULT would instead re-resolve the call and stretch the tool
+    # span over the very interval this case exists to expose, which is a third
+    # way to write a test that cannot fail.
+    state.on_user_message(SimpleNamespace(content=[], tool_use_result=None))
+    state.on_stream_event(message_start("m2"))
+    clock.at_ms = 3400
+    state.on_assistant_message(SdkAssistantMessage([], usage={"input_tokens": 10, "output_tokens": 5}, message_id="m2"))
+    state.finalize(_AgentEndStatus.COMPLETED)
+
+    return Turn(started_ms=0.0, ended_ms=3800.0, messages=list(state.sdk_messages), commands=commands)
+
+
 # --------------------------------------------------------------------------
 # The contract
 # --------------------------------------------------------------------------
@@ -542,6 +640,16 @@ def test_claude_code_buckets_tile_the_turn(monkeypatch: pytest.MonkeyPatch):
     assert_identity_closes(_claude_turn(monkeypatch))
 
 
+def test_a_slow_tool_result_round_trip_is_not_lost(monkeypatch: pytest.MonkeyPatch):
+    """The discriminating case: a fast tool whose result takes 2 s to come back.
+
+    Reverting the fix (re-adding `last_event_wall = self.clock.now()` to
+    `on_user_message`) fails THIS and leaves every other case in the file
+    green, which is exactly what happened in production.
+    """
+    assert_identity_closes(_claude_slow_result_turn(monkeypatch))
+
+
 def test_every_built_in_harness_has_a_case():
     """A sensor that silently covers four of five is worse than one naming the gap.