fix(daemon): stop moving a published metric, and abstain when tools are unattributable

Two findings from the seventh review round.

Passing the producer's start into `markFirstModelEvent` moved
`time_to_first_model_event_ms`, which this PR promised not to touch. That field
means "when we first saw a model event"; for an ACP tool starting at 4s and
emitted at terminal 20s it began reporting 4s instead of 20s. My own invariance
fixture did not catch it because it only pins the four first-token metrics.

The mark is now split. `firstModelEventAt` goes back to first-write-wins on
arrival and keeps feeding the published metric unchanged. A new
`firstModelResponseAt` holds the earliest producer start (clamped to arrival, so
a fast producer clock cannot claim the model responded in the future) and is
what phase boundaries anchor on. The new phase field is renamed to
`runtime_init_to_first_model_response_ms` to match what it measures; it is
introduced by this PR and has never shipped.

Second, a tool id shared by two attempts cannot be attributed. When a retry
reuses an id whose previous opener is still outstanding, a later `tool_result`
could belong to either, and the two readings differ by seconds of occupancy.
Earlier rounds tried to pick a winner; nothing in the event log supports one.
The summarizer now records that an opener was displaced, marks the ledger
ambiguous when a result arrives for such an id, and withholds
`bottleneck_phase` and a `complete` phase status -- the same treatment
truncation already gets, and for the same reason. Timings derived from
lifecycle marks keep reporting.

Fixing this properly rather than abstaining needs an attempt or generation id
carried on the tool events themselves, which is a producer and event-schema
change; noted in the review thread rather than smuggled in here.

Author: lefarcen

apps/daemon/src/run-analytics-observability.ts

@@ -104,6 +104,10 @@ export interface RunTelemetryTimestamps {
   stdinWriteStartAt?: number;
   stdinWriteEndAt?: number;
   firstModelEventAt?: number;
+  // When the model began responding, as opposed to when we first saw evidence
+  // of it. Phase boundaries anchor here; `firstModelEventAt` keeps feeding the
+  // published `time_to_first_model_event_ms`.
+  firstModelResponseAt?: number;
   firstModelEventType?: TrackingFirstModelEventType;
   firstTokenAt?: number;
   firstVisibleOutputAt?: number;
@@ -172,7 +176,7 @@ export interface RunTimingAnalytics {
   // thinking, text, artifact) rather than to the first text token. On a
   // tool-first run `runtime_init_to_first_token_ms` swallows the entire tool
   // loop; this one stops the moment the model starts responding.
-  runtime_init_to_first_model_event_ms?: number;
+  runtime_init_to_first_model_response_ms?: number;
   spawn_to_first_token_ms?: number;
   time_to_first_artifact_ms?: number;
   // `spawn_to_first_token_ms` split into auditable subsegments. By construction
@@ -1009,6 +1013,12 @@ export function summarizeRunTimingAnalytics(args: {
   // separate from its start, which may be a producer-supplied `startedAt` from
   // a different clock and so cannot be compared against our own marks.
   const openToolObservedAt = new Map<string, number>();
+  // Tool ids whose opener was replaced by a same-id call from a later attempt.
+  const displacedToolUseIds = new Set<string>();
+  // Set when a `tool_result` arrives for such an id: the two candidate openers
+  // differ by seconds of occupancy and the log cannot say which one closed, so
+  // phase attribution for this run is not a measurement.
+  let toolLedgerAmbiguous = false;
   const openToolNames = new Map<string, string>();
   // Count unique tool_use ids so historical double-emits (or retries) do not
   // inflate tool_call_count.
@@ -1068,6 +1078,10 @@ export function summarizeRunTimingAnalytics(args: {
         attemptStartAt !== undefined &&
         priorObservedAt < attemptStartAt &&
         ts >= attemptStartAt;
+      // Remember that a previous attempt's opener was pushed aside. Its result
+      // may still be in flight, and once two calls have shared an id nothing in
+      // the event log says which of them a later `tool_result` closes.
+      if (reusesDeadAttemptId) displacedToolUseIds.add(data.id);
       if (!openTools.has(data.id) || reusesDeadAttemptId) {
         openTools.set(data.id, toolStartedAt);
         openToolObservedAt.set(data.id, ts);
@@ -1095,6 +1109,7 @@ export function summarizeRunTimingAnalytics(args: {
       const startedAt = openTools.get(data.toolUseId);
       if (startedAt !== undefined && ts >= startedAt) {
         toolDurationMs += ts - startedAt;
+        if (displacedToolUseIds.has(data.toolUseId)) toolLedgerAmbiguous = true;
         if (openedInCurrentAttempt(openToolObservedAt.get(data.toolUseId))) {
           toolIntervals.push({ start: startedAt, end: ts });
         }
@@ -1133,6 +1148,7 @@ export function summarizeRunTimingAnalytics(args: {
   // daemon-generated finalizer event, a producer clock offset), and this keeps
   // one from dragging every boundary to the end of the run.
   const phaseAnchorCandidates = [
+    telemetry.firstModelResponseAt,
     telemetry.firstModelEventAt,
     telemetry.firstTokenAt,
   ].filter((value): value is number => value !== undefined && Number.isFinite(value));
@@ -1196,7 +1212,7 @@ export function summarizeRunTimingAnalytics(args: {
   if (runtimeInitToFirstToken !== undefined) {
     result.runtime_init_to_first_token_ms = runtimeInitToFirstToken;
   }
-  setMeasuredDuration(result, 'runtime_init_to_first_model_event_ms', phaseDurations, 'runtime_init', runtimeInitStartAt, phaseAnchorAt);
+  setMeasuredDuration(result, 'runtime_init_to_first_model_response_ms', phaseDurations, 'runtime_init', runtimeInitStartAt, phaseAnchorAt);
   const spawnToFirstToken = durationBetween(telemetry.processSpawnedAt, telemetry.firstTokenAt);
   if (spawnToFirstToken !== undefined) result.spawn_to_first_token_ms = spawnToFirstToken;
   const timeToFirstArtifact = durationBetween(startAt, firstArtifactWriteAt);
@@ -1281,7 +1297,12 @@ export function summarizeRunTimingAnalytics(args: {
   // built from lifecycle marks are still sound, but we cannot know whether an
   // evicted tool would have outweighed them, so naming a winner would report
   // an artefact of what the buffer happened to keep.
-  if (bottleneckPhase !== undefined && eventStreamComplete) {
+  // The ledger phases are reconstructed from tool frames. Truncation removes
+  // frames; an id shared by two attempts makes the surviving ones
+  // unattributable. Either way the winner would describe the log rather than
+  // the run.
+  const phaseLedgerReliable = eventStreamComplete && !toolLedgerAmbiguous;
+  if (bottleneckPhase !== undefined && phaseLedgerReliable) {
     result.bottleneck_phase = bottleneckPhase;
   }
   result.phase_schema_version = RUN_PHASE_SCHEMA_VERSION;
@@ -1302,7 +1323,7 @@ export function summarizeRunTimingAnalytics(args: {
   // Truncation can only downgrade a `complete` claim; it never upgrades a
   // bundle whose boundaries were genuinely missing.
   result.phase_timing_status =
-    !eventStreamComplete && phaseTimingStatus === 'complete'
+    !phaseLedgerReliable && phaseTimingStatus === 'complete'
       ? 'partial'
       : phaseTimingStatus;
 

apps/daemon/src/run-lifecycle-tracer.ts

@@ -103,7 +103,10 @@ export function runLifecycleMarkersForStreamEvent(
 
 export function createRunLifecycleTracer(run: RunWithLifecycleTelemetry): {
   mark(mark: RunLifecycleMark, timestamp?: number): void;
-  markFirstModelEvent(type: TrackingFirstModelEventType, timestamp?: number): void;
+  markFirstModelEvent(
+    type: TrackingFirstModelEventType,
+    producerStartedAt?: number,
+  ): void;
   resetForAttempt(attemptIndex: number, timestamp?: number): void;
 } {
   const mark = (lifecycleMark: RunLifecycleMark, timestamp = Date.now()) => {
@@ -118,22 +121,45 @@ export function createRunLifecycleTracer(run: RunWithLifecycleTelemetry): {
 
   return {
     mark,
-    markFirstModelEvent(type: TrackingFirstModelEventType, timestamp = Date.now()) {
-      if (!Number.isFinite(timestamp)) return;
+    markFirstModelEvent(
+      type: TrackingFirstModelEventType,
+      producerStartedAt?: number,
+    ) {
+      const arrivedAt = Date.now();
       const current = run.analyticsTelemetry ?? {};
-      const existing = current.firstModelEventAt;
-      // Earliest wins, not first observed. ACP holds each toolCallId until it
-      // is terminal, so two parallel calls can complete in the opposite order
-      // they started: the call that began later can be the first one we hear
-      // about. First-write-wins would anchor on it and lose the real head
-      // start. Marks without a producer timestamp default to arrival, which is
-      // monotonic, so this only ever moves the anchor earlier.
-      if (existing !== undefined && timestamp >= existing) return;
-      run.analyticsTelemetry = {
-        ...current,
-        firstModelEventAt: timestamp,
-        firstModelEventType: type,
-      };
+      const next = { ...current };
+      let changed = false;
+
+      // `firstModelEventAt` is when we SAW the first model event. It is already
+      // published as `time_to_first_model_event_ms`, so it stays first-write-
+      // wins on arrival -- a producer-supplied start must not silently move it.
+      if (current.firstModelEventAt === undefined) {
+        next.firstModelEventAt = arrivedAt;
+        next.firstModelEventType = type;
+        changed = true;
+      }
+
+      // `firstModelResponseAt` is when the model actually began responding, and
+      // is what phase boundaries anchor on. Two reasons it differs from
+      // arrival: ACP holds each toolCallId until terminal status, so the
+      // canonical `tool_use` arrives when the tool ENDS while its payload
+      // carries the real start; and parallel calls can terminate in the
+      // opposite order they began, so earliest-wins rather than first-wins.
+      // Clamped to arrival so a producer clock running ahead cannot claim the
+      // model responded in the future.
+      const responseAt =
+        typeof producerStartedAt === 'number' && Number.isFinite(producerStartedAt)
+          ? Math.min(producerStartedAt, arrivedAt)
+          : arrivedAt;
+      if (
+        current.firstModelResponseAt === undefined ||
+        responseAt < current.firstModelResponseAt
+      ) {
+        next.firstModelResponseAt = responseAt;
+        changed = true;
+      }
+
+      if (changed) run.analyticsTelemetry = next;
     },
     resetForAttempt(attemptIndex: number, timestamp = Date.now()) {
       run.analyticsTelemetry = {

apps/daemon/src/server.ts

@@ -10688,9 +10688,10 @@ export async function startServer({
     const send = (event, data) => {
       const lifecycleMarkers = runLifecycleMarkersForStreamEvent(event, data);
       if (lifecycleMarkers.firstModelEventType) {
-        // `firstModelEventAt` is present when the producer told us when the
-        // work began. ACP emits `tool_use` at terminal status, so without this
-        // the anchor lands at tool completion.
+        // Second argument is the PRODUCER's start, used only for the phase
+        // anchor. ACP emits `tool_use` at terminal status, so without it the
+        // anchor lands at tool completion. `time_to_first_model_event_ms`
+        // still measures to arrival and is unaffected.
         lifecycle.markFirstModelEvent(
           lifecycleMarkers.firstModelEventType,
           lifecycleMarkers.firstModelEventAt,

apps/daemon/tests/run-analytics-observability.test.ts

@@ -1148,7 +1148,7 @@ describe('summarizeRunTimingAnalytics', () => {
       time_to_first_token_ms: 1300,
       time_to_first_visible_output_ms: 1300,
       runtime_init_to_first_token_ms: 650,
-      runtime_init_to_first_model_event_ms: 150,
+      runtime_init_to_first_model_response_ms: 150,
       spawn_to_first_token_ms: 740,
       time_to_first_artifact_ms: 3050,
       // No subsegment markers were observed, so the whole spawn->first-token
@@ -1550,7 +1550,7 @@ describe('summarizeRunTimingAnalytics phase anchoring', () => {
     const result = summarizeRunTimingAnalytics(toolFirstRun);
 
     // stdin closed at 3.2s and the model responded at 4s.
-    expect(result.runtime_init_to_first_model_event_ms).toBe(800);
+    expect(result.runtime_init_to_first_model_response_ms).toBe(800);
   });
 
   it('counts the whole tool loop as model-active time', () => {
@@ -1614,7 +1614,7 @@ describe('summarizeRunTimingAnalytics phase anchoring', () => {
 
     // Text-first runs already had a truthful anchor, so the new fields must
     // land on exactly the old numbers -- no drift for Claude Code-shaped runs.
-    expect(result.runtime_init_to_first_model_event_ms).toBe(result.runtime_init_to_first_token_ms);
+    expect(result.runtime_init_to_first_model_response_ms).toBe(result.runtime_init_to_first_token_ms);
     expect(result.model_active_duration_ms).toBe(result.generation_duration_ms);
   });
 
@@ -1644,7 +1644,7 @@ describe('summarizeRunTimingAnalytics phase anchoring', () => {
     // are not reset per retry attempt. `time_to_first_model_event_ms` keeps
     // its existing scan-based fallback and is unaffected.
     expect(result.time_to_first_model_event_ms).toBe(2_000);
-    expect(result.runtime_init_to_first_model_event_ms).toBe(20_800);
+    expect(result.runtime_init_to_first_model_response_ms).toBe(20_800);
     expect(result.model_active_duration_ms).toBe(1_000);
   });
 });
@@ -1788,7 +1788,7 @@ describe('summarizeRunTimingAnalytics anchor and completeness edges', () => {
     // reports a 1s active window and a 16s runtime init for a run that was
     // streaming the whole time.
     expect(result.model_active_duration_ms).toBe(15_000);
-    expect(result.runtime_init_to_first_model_event_ms).toBe(2_000);
+    expect(result.runtime_init_to_first_model_response_ms).toBe(2_000);
     expect(result.bottleneck_phase).toBe('stream_output');
   });
 
@@ -2068,3 +2068,77 @@ describe('summarizeRunTimingAnalytics late tool results from a dead attempt', ()
     expect(result.tool_duration_ms).toBe(26_900);
   });
 });
+
+describe('summarizeRunTimingAnalytics separates the response anchor from the event mark', () => {
+  it('anchors phases on the response while the published metric keeps arrival', () => {
+    const result = summarizeRunTimingAnalytics({
+      runCreatedAt: 1_000,
+      runUpdatedAt: 30_000,
+      analyticsCapturedAt: 30_050,
+      telemetry: {
+        startRequestedAt: 1_100,
+        startChatRunStartedAt: 2_000,
+        stdinWriteEndAt: 3_000,
+        // ACP: the canonical tool_use arrived at 20s, but the tool began at 4s.
+        firstModelEventAt: 20_000,
+        firstModelResponseAt: 4_000,
+        firstModelEventType: 'tool_use' as const,
+        attemptStartedAt: 2_000,
+        attemptIndex: 1,
+      },
+      events: [],
+    });
+
+    // Already published, and this PR promised not to move it.
+    expect(result.time_to_first_model_event_ms).toBe(18_000);
+    // New, and measured from when the model actually started working.
+    expect(result.runtime_init_to_first_model_response_ms).toBe(1_000);
+    expect(result.model_active_duration_ms).toBe(26_000);
+  });
+});
+
+describe('summarizeRunTimingAnalytics with an unattributable tool ledger', () => {
+  const ambiguousRun = {
+    runCreatedAt: 1_000,
+    runUpdatedAt: 30_000,
+    analyticsCapturedAt: 30_050,
+    telemetry: {
+      startRequestedAt: 1_100,
+      attemptStartedAt: 20_000,
+      attemptIndex: 2,
+      stdinWriteEndAt: 20_500,
+      firstModelEventAt: 21_000,
+      firstModelResponseAt: 21_000,
+      firstModelEventType: 'text_delta' as const,
+      firstTokenAt: 21_000,
+    },
+    events: [
+      // Attempt 1 opened `call_0` and was killed before it returned.
+      { id: 1, event: 'agent', timestamp: 3_000, data: { type: 'tool_use', id: 'call_0', name: 'Bash' } },
+      // Attempt 2's fresh session restarts sequential ids and opens the same
+      // one for a different call.
+      { id: 2, event: 'agent', timestamp: 21_500, data: { type: 'tool_use', id: 'call_0', name: 'Read' } },
+      // A result arrives. Nothing in the event log says which of the two it
+      // belongs to, and the two readings differ by 8s of occupancy.
+      { id: 3, event: 'agent', timestamp: 22_000, data: { type: 'tool_result', toolUseId: 'call_0' } },
+    ],
+  };
+
+  it('withholds the bottleneck when a result cannot be attributed to an attempt', () => {
+    const result = summarizeRunTimingAnalytics(ambiguousRun);
+
+    expect(result.bottleneck_phase).toBeUndefined();
+  });
+
+  it('marks phase timing partial rather than complete', () => {
+    const result = summarizeRunTimingAnalytics(ambiguousRun);
+
+    expect(result.phase_timing_status).toBe('partial');
+  });
+
+  it('still reports mark-derived timings', () => {
+    const result = summarizeRunTimingAnalytics(ambiguousRun);
+
+    expect(result.model_active_duration_ms).toBe(9_000);
+  });
+});

apps/daemon/tests/run-lifecycle-tracer.test.ts

@@ -1,4 +1,4 @@
-import { describe, expect, it } from 'vitest';
+import { afterEach, describe, expect, it, vi } from 'vitest';
 import {
   createRunLifecycleTracer,
   runLifecycleMarkersForStreamEvent,
@@ -27,21 +27,30 @@ describe('runLifecycleMarkersForStreamEvent', () => {
 
 describe('createRunLifecycleTracer', () => {
   it('only records first timestamps for repeated lifecycle marks', () => {
+    vi.useFakeTimers();
+    vi.setSystemTime(new Date('2026-08-20T00:00:10.000Z'));
+    const arrivedAt = Date.now();
     const run = {};
     const lifecycle = createRunLifecycleTracer(run);
 
     lifecycle.mark('first_artifact_write', 1_000);
     lifecycle.mark('first_artifact_write', 2_000);
+    // Second argument is the producer's start, not the mark's timestamp.
     lifecycle.markFirstModelEvent('tool_use', 3_000);
     lifecycle.markFirstModelEvent('text_delta', 4_000);
 
     expect(run).toEqual({
       analyticsTelemetry: {
         firstArtifactWriteAt: 1_000,
-        firstModelEventAt: 3_000,
+        // Arrival, first-write-wins -- the repeat does not overwrite it.
+        firstModelEventAt: arrivedAt,
         firstModelEventType: 'tool_use',
+        // Earliest producer start wins, so the 4_000 repeat does not win here
+        // either.
+        firstModelResponseAt: 3_000,
       },
     });
+    vi.useRealTimers();
   });
 });
 
@@ -132,7 +141,7 @@ describe('createRunLifecycleTracer first model event ordering', () => {
 
     // First-write-wins would anchor at 200 and lose the 100ms head start,
     // pushing every phase boundary later.
-    expect(run.analyticsTelemetry?.firstModelEventAt).toBe(100);
+    expect(run.analyticsTelemetry?.firstModelResponseAt).toBe(100);
     expect(run.analyticsTelemetry?.firstModelEventType).toBe('tool_use');
   });
 
@@ -143,7 +152,34 @@ describe('createRunLifecycleTracer first model event ordering', () => {
     tracer.markFirstModelEvent('tool_use', 100);
     tracer.markFirstModelEvent('text_delta', 300);
 
-    expect(run.analyticsTelemetry?.firstModelEventAt).toBe(100);
+    expect(run.analyticsTelemetry?.firstModelResponseAt).toBe(100);
     expect(run.analyticsTelemetry?.firstModelEventType).toBe('tool_use');
   });
 })
+
+describe('createRunLifecycleTracer keeps the legacy model-event mark intact', () => {
+  afterEach(() => {
+    vi.useRealTimers();
+  });
+
+  it('records arrival for firstModelEventAt and the producer start separately', () => {
+    vi.useFakeTimers();
+    vi.setSystemTime(new Date('2026-08-20T00:00:20.000Z'));
+    const arrivedAt = Date.now();
+    const producerStartedAt = arrivedAt - 16_000;
+    const run: { analyticsTelemetry?: Record<string, unknown> | null } = {};
+    const tracer = createRunLifecycleTracer(run as never);
+
+    // ACP emits the canonical tool_use at terminal status, so this arrives at
+    // 20s carrying a first-frame time of 4s.
+    tracer.markFirstModelEvent('tool_use', producerStartedAt);
+
+    // `time_to_first_model_event_ms` is built from this field and is already
+    // published. It must keep meaning "when we saw the first model event",
+    // or every dashboard reading it silently shifts.
+    expect(run.analyticsTelemetry?.firstModelEventAt).toBe(arrivedAt);
+    expect(run.analyticsTelemetry?.firstModelEventType).toBe('tool_use');
+    // The phase anchor is a separate mark: when the model actually began.
+    expect(run.analyticsTelemetry?.firstModelResponseAt).toBe(producerStartedAt);
+  });
+});

packages/contracts/src/analytics/events/result-events.ts

@@ -517,7 +517,7 @@ export interface RunFinishedProps extends Omit<RunCreatedProps, 'area'> {
   // Runtime init measured to the first model event of any kind rather than to
   // the first text token. On a tool-first run the first-token variant absorbs
   // the whole tool loop and reads as slow startup.
-  runtime_init_to_first_model_event_ms?: number;
+  runtime_init_to_first_model_response_ms?: number;
   spawn_to_first_token_ms?: number;
   time_to_first_artifact_ms?: number;
   // `spawn_to_first_token_ms` split into auditable subsegments so dashboards