fix(daemon): anchor ACP tool-first turns at the tool's start

Three findings from the fifth review round.

ACP accumulates `tool_call` frames and emits the canonical `tool_use` only once
the call reaches terminal status, carrying `startedAt` set to the first frame's
arrival. The universal `send()` path stamped the anchor with `Date.now()` when
that delayed event arrived, so a tool-only ACP turn put its anchor at tool
COMPLETION -- measuring the whole tool loop as runtime init. That is precisely
the case this PR exists to fix, still fully present for the ACP family. The
stream-event markers now carry the producer's `startedAt` (daemon clock, same
domain as our own marks) and the tracer stamps that instead of arrival time.

Tool ids are reused across a retry: sequential ids like `call_0` restart in the
retry's fresh session, and `openTools` is keyed by id alone. A killed
attempt's still-open `call_0` therefore merged with the retry's genuinely new
`call_0`, pairing attempt one's opening with attempt two's close and reporting
a 19s tool that never ran -- inflating `tool_duration_ms` as well as phase
occupancy. A still-open entry observed before the current attempt began is now
replaced rather than merged.

The Langfuse `model-active` diagnostic used different boundaries from the
metric it exists to be compared against: it preferred `firstModelEventAt` over
the earliest mark, and ended at `finalizeStartAt` rather than run end. On a
text-first stream those differ, so the same run reported two windows. It now
mirrors the canonical rules; the shared "earliest finite mark" logic is a named
helper.

Author: lefarcen

apps/daemon/src/langfuse-trace.ts

@@ -998,6 +998,19 @@ function buildArtifactWriteDiagnostics(
   };
 }
 
+// Earliest of the supplied marks, ignoring absent and non-finite values. Mirrors
+// how `summarizeRunTimingAnalytics` picks its phase anchor: the model cannot
+// have started responding after it emitted its first token, so a later mark is
+// always a producer bug rather than a later start.
+function earliestFiniteTimestamp(
+  ...values: Array<number | undefined>
+): number | undefined {
+  const finite = values.filter(
+    (value): value is number => typeof value === 'number' && Number.isFinite(value),
+  );
+  return finite.length > 0 ? Math.min(...finite) : undefined;
+}
+
 function buildSemanticPhaseDiagnostics(ctx: ReportContext): Record<string, unknown> {
   const marks = ctx.run.timingMarks ?? {};
   const measured: Record<string, unknown> = {};
@@ -1026,7 +1039,16 @@ function buildSemanticPhaseDiagnostics(ctx: ReportContext): Record<string, unkno
   // on the first model event of any kind. Kept as a diagnostics entry rather
   // than a second span: this map rides along in existing metadata, while a new
   // span would add an observation row per run.
-  addMeasured('model-active', marks.firstModelEventAt ?? marks.firstTokenAt, marks.finalizeStartAt ?? ctx.run.endedAt);
+  //
+  // Boundaries mirror `model_active_duration_ms` in run-analytics-observability
+  // exactly -- earliest of the two marks, through run end -- because the whole
+  // point of this entry is to be compared against that number. Deliberately
+  // unlike its neighbours above, which end at `finalizeStartAt`.
+  addMeasured(
+    'model-active',
+    earliestFiniteTimestamp(marks.firstModelEventAt, marks.firstTokenAt),
+    ctx.run.endedAt,
+  );
   addMeasured('artifact-write', marks.firstArtifactWriteAt, marks.finalizeStartAt ?? ctx.run.endedAt);
   addMeasured('finalize', marks.finalizeStartAt, ctx.run.endedAt);
   return {

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

@@ -970,6 +970,11 @@ export function summarizeRunTimingAnalytics(args: {
 }): RunTimingAnalytics {
   const telemetry = args.telemetry ?? {};
   const runEndAt = args.runUpdatedAt;
+  const scanStartAt = telemetry.startChatRunStartedAt ?? telemetry.startRequestedAt;
+  // When the current attempt began. Needed inside the scan so a tool id reused
+  // by a retry is not merged with the corpse of the same id from a dead
+  // attempt.
+  const attemptStartAt = telemetry.attemptStartedAt ?? scanStartAt;
   let toolCallCount = 0;
   let toolDurationMs = 0;
   const toolIntervals: Array<{ start: number; end: number }> = [];
@@ -1032,7 +1037,19 @@ export function summarizeRunTimingAnalytics(args: {
           : undefined;
       const toolStartedAt = payloadStartedAt ?? ts;
       // First tool_use timestamp wins for duration pairing.
-      if (!openTools.has(data.id)) {
+      const priorObservedAt = openToolObservedAt.get(data.id);
+      // Sequential tool ids (`call_0`, `call_1`, ...) restart in a retry's
+      // fresh session, so a still-open entry from a killed attempt can collide
+      // with a genuinely new call. Keeping the old start would pair attempt
+      // one's opening with attempt two's close and report a tool that never
+      // ran. Replace, rather than merge, when the open entry predates this
+      // attempt and the new one does not.
+      const reusesDeadAttemptId =
+        priorObservedAt !== undefined &&
+        attemptStartAt !== undefined &&
+        priorObservedAt < attemptStartAt &&
+        ts >= attemptStartAt;
+      if (!openTools.has(data.id) || reusesDeadAttemptId) {
         openTools.set(data.id, toolStartedAt);
         openToolObservedAt.set(data.id, ts);
       } else if (payloadStartedAt !== undefined) {
@@ -1100,10 +1117,6 @@ export function summarizeRunTimingAnalytics(args: {
   ].filter((value): value is number => value !== undefined && Number.isFinite(value));
   const phaseAnchorAt =
     phaseAnchorCandidates.length > 0 ? Math.min(...phaseAnchorCandidates) : undefined;
-  // When the current attempt began. Distinct from `phaseAnchorAt`: the anchor
-  // is when the model started responding, this is when the attempt started
-  // running, and on a tool-first run the tools come between them.
-  const attemptStartAt = telemetry.attemptStartedAt ?? startAt;
   // A run can end while a tool is still outstanding (crash, cancel, timeout),
   // leaving a tool_use with no tool_result. That span still occupied the clock,
   // so close it at run end for phase purposes.

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

@@ -44,6 +44,13 @@ export interface RunWithLifecycleTelemetry {
 
 export interface RunLifecycleStreamEventMarkers {
   firstModelEventType?: TrackingFirstModelEventType;
+  // When the producer says this event's work actually began, on the daemon's
+  // clock. Present when a payload carries `startedAt`, which ACP does: it
+  // accumulates tool_call frames and emits the canonical `tool_use` only once
+  // the call is terminal, so the arrival time of that event is the tool's END.
+  // Stamping the anchor from arrival would measure a tool-only ACP turn as
+  // runtime init, which is the case this whole boundary change exists for.
+  firstModelEventAt?: number;
   firstVisibleOutput: boolean;
   firstArtifactWrite: boolean;
 }
@@ -68,8 +75,19 @@ export function runLifecycleMarkersForStreamEvent(
       type === 'text_delta' || type === 'thinking_delta' || type === 'tool_use'
         ? type
         : undefined;
+    const startedAt =
+      data && typeof data === 'object' && 'startedAt' in data
+        ? (data as { startedAt?: unknown }).startedAt
+        : undefined;
+    const firstModelEventAt =
+      typeof startedAt === 'number' && Number.isFinite(startedAt)
+        ? startedAt
+        : undefined;
     return {
       ...(firstModelEventType ? { firstModelEventType } : {}),
+      ...(firstModelEventType && firstModelEventAt !== undefined
+        ? { firstModelEventAt }
+        : {}),
       firstVisibleOutput:
         type === 'text_delta' ||
         type === 'thinking_delta' ||

apps/daemon/src/server.ts

@@ -10688,7 +10688,13 @@ export async function startServer({
     const send = (event, data) => {
       const lifecycleMarkers = runLifecycleMarkersForStreamEvent(event, data);
       if (lifecycleMarkers.firstModelEventType) {
-        lifecycle.markFirstModelEvent(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.
+        lifecycle.markFirstModelEvent(
+          lifecycleMarkers.firstModelEventType,
+          lifecycleMarkers.firstModelEventAt,
+        );
       }
       if (lifecycleMarkers.firstVisibleOutput) {
         lifecycle.mark('first_visible_output');

apps/daemon/tests/langfuse-trace.test.ts

@@ -1358,6 +1358,43 @@ describe('buildTracePayload', () => {
     expect(metadata.total_duration_ms).toBe(100);
   });
 
+  it('measures model-active on the same boundaries as the analytics metric', () => {
+    const batch = buildTracePayload(
+      makeCtx({
+        run: {
+          runId: 'run-model-active',
+          status: 'succeeded',
+          startedAt: 1_700_000_000_000,
+          endedAt: 1_700_000_010_000,
+          timingMarks: {
+            startChatRunStartedAt: 1_700_000_000_100,
+            processSpawnedAt: 1_700_000_000_300,
+            stdinWriteEndAt: 1_700_000_000_500,
+            // Text-first: the server stamps first-token before the send() path
+            // records the model-event mark, so the two are not equal and the
+            // earlier one is the true start of the response.
+            firstTokenAt: 1_700_000_001_000,
+            firstModelEventAt: 1_700_000_001_200,
+            finalizeStartAt: 1_700_000_009_000,
+          },
+        },
+      }),
+    );
+
+    const generation = bodyOf(batch, 'generation-create', 'llm');
+    const measured =
+      generation.metadata.performance_diagnostics.semantic_phases.measured;
+
+    // `model_active_duration_ms` takes the earliest of the two marks and runs
+    // to run end. This entry exists to be compared against that number, so a
+    // different window here makes PostHog and Langfuse disagree on the same
+    // run.
+    expect(measured['model-active']).toMatchObject({
+      duration_ms: 9_000,
+      status: 'measured',
+    });
+  });
+
   it('adds duration spans for run timing marks', () => {
     const promptTelemetry = buildPromptStackTelemetry({
       composedPrompt:

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

@@ -1946,3 +1946,36 @@ describe('summarizeRunTimingAnalytics outstanding tools without a model-event ma
     expect(result.bottleneck_phase).toBe('tool_execution');
   });
 });
+
+describe('summarizeRunTimingAnalytics tool id reuse across a retry', () => {
+  it('does not pair a dead attempt\'s open tool with a same-id retry tool', () => {
+    const result = summarizeRunTimingAnalytics({
+      runCreatedAt: 1_000,
+      runUpdatedAt: 25_000,
+      analyticsCapturedAt: 25_050,
+      telemetry: {
+        startRequestedAt: 1_100,
+        attemptStartedAt: 20_000,
+        attemptIndex: 2,
+        stdinWriteEndAt: 20_200,
+        firstModelEventAt: 20_500,
+        firstModelEventType: 'text_delta' as const,
+        firstTokenAt: 20_500,
+      },
+      events: [
+        // Attempt 1's child was killed mid-tool, leaving `call_0` open.
+        { id: 1, event: 'agent', timestamp: 3_000, data: { type: 'tool_use', id: 'call_0', name: 'Bash' } },
+        // Sequential ids restart at `call_0` in the retry's fresh session, so
+        // the id collides with the corpse above.
+        { id: 2, event: 'agent', timestamp: 21_500, data: { type: 'tool_use', id: 'call_0', name: 'Read' } },
+        { id: 3, event: 'agent', timestamp: 22_000, data: { type: 'tool_result', toolUseId: 'call_0' } },
+      ],
+    });
+
+    // The retry tool ran 21.5s -> 22.0s. Keeping the stale start pairs
+    // attempt 1's 3s opening with attempt 2's 22s close and reports a 19s
+    // tool that never existed.
+    expect(result.tool_duration_ms).toBe(500);
+    expect(result.model_active_duration_ms).toBe(4_500);
+  });
+});

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

@@ -78,3 +78,43 @@ describe('runLifecycleMarkersForStreamEvent artifact events', () => {
     ).toBe('thinking_delta');
   });
 });
+
+describe('runLifecycleMarkersForStreamEvent producer-supplied start', () => {
+  it('carries a tool_use startedAt so the anchor is not stamped at completion', () => {
+    // ACP accumulates tool_call frames and emits the canonical tool_use only
+    // once the call reaches a terminal status, with `startedAt` set to the
+    // first frame's arrival (daemon clock). Stamping the anchor when that
+    // delayed event arrives puts it at tool COMPLETION, so a tool-only ACP
+    // turn measures its whole tool loop as runtime init.
+    const markers = runLifecycleMarkersForStreamEvent('agent', {
+      type: 'tool_use',
+      id: 't1',
+      name: 'Bash',
+      startedAt: 1_700_000_000_000,
+    });
+
+    expect(markers.firstModelEventType).toBe('tool_use');
+    expect(markers.firstModelEventAt).toBe(1_700_000_000_000);
+  });
+
+  it('leaves the timestamp to the caller when the payload carries no start', () => {
+    const markers = runLifecycleMarkersForStreamEvent('agent', {
+      type: 'text_delta',
+      text: 'hi',
+    });
+
+    expect(markers.firstModelEventType).toBe('text_delta');
+    expect(markers.firstModelEventAt).toBeUndefined();
+  });
+
+  it('ignores a start that is not a finite number', () => {
+    for (const startedAt of [Number.NaN, Number.POSITIVE_INFINITY, '123', null]) {
+      const markers = runLifecycleMarkersForStreamEvent('agent', {
+        type: 'tool_use',
+        id: 't1',
+        startedAt,
+      });
+      expect(markers.firstModelEventAt).toBeUndefined();
+    }
+  });
+});