From a3b83caf5905603f48b771b69166f9144268c728 Mon Sep 17 00:00:00 2001 From: Manu MA Date: Sun, 23 Aug 2026 12:44:06 +0200 Subject: [PATCH 1/6] fix: improve observability metrics to align with PostHog's schema and aggregation --- .agents/skills/observability/SKILL.md | 27 +- .changeset/posthog-ai-observability-fixes.md | 13 + packages/core/src/observability/posthog-ai.ts | 25 +- .../core/src/observability/traces.spec.ts | 347 ++++++++++++++++++ packages/core/src/observability/traces.ts | 113 ++++-- packages/core/src/tracking/registry.ts | 20 +- .../actions/query-agent-native-analytics.ts | 2 +- .../docs/schemas/first-party-analytics.md | 3 +- .../analytics/docs/schemas/tracked-events.md | 2 + 9 files changed, 520 insertions(+), 32 deletions(-) create mode 100644 .changeset/posthog-ai-observability-fixes.md diff --git a/.agents/skills/observability/SKILL.md b/.agents/skills/observability/SKILL.md index 11dd5bf35e..3fdad10dbd 100644 --- a/.agents/skills/observability/SKILL.md +++ b/.agents/skills/observability/SKILL.md @@ -32,7 +32,7 @@ await putSetting("observability-config", { enabled: true, capturePrompts: false, captureToolArgs: true, // capture action input args - captureToolResults: false, // include failed tool error text on tracked $ai_generation tool call entries + captureToolResults: false, // include tool results/error text on tool spans and $ai_generation entries evalSampleRate: 0.05, // 5% of runs get LLM-as-judge eval inferredSentimentEnabled: false, inferredSentimentSampleRate: 0, @@ -288,6 +288,9 @@ same best-effort fan-out as other tracking events. visit share a session. `setAnalyticsSessionId()` from `@agent-native/core/client/analytics` pins a custom id and opts it out of the 30-minute idle rotation. Emission lives in `posthog-ai.ts`. +- Each event is stamped with when it happened, not when the run flushed. The + whole tree is emitted in one burst at run end, so `track()` takes an + `occurredAt` and the trace tree keeps a real timeline. - Agent Native Analytics shape: the same event lands in `analytics_events` with mirrored query-friendly properties such as `run_id`, `thread_id`, `cost_cents_x100`, `duration_ms`, `tool_calls`, `successful_tools`, @@ -301,6 +304,28 @@ same best-effort fan-out as other tracking events. Constraints that are not visible from the emit site: +- **The trace event carries no latency, tokens, or cost under `$ai_*`.** PostHog + DERIVES those from a trace's children: its trace query sums `$ai_latency` over + every event whose `$ai_parent_id` is the trace or is absent, and sums + tokens/cost over `$ai_generation` / `$ai_embedding` only. An `$ai_latency` on + the `$ai_trace` event is therefore added to its own children's and reports + roughly twice the real duration. Run totals ride along as `duration_ms`, + `input_tokens`, `output_tokens`, and `cost_usd` for the backends that do no + such aggregation. +- **The generation's `$ai_latency` is model time, not run time.** Tool calls are + siblings under the same trace and PostHog adds their latency to the + generation's, so tool duration is subtracted out. `duration_ms` on the same + event is still the full run — the two differ on purpose. +- **PostHog's `$ai_*` latency fields are seconds; ours are milliseconds.** + `$ai_latency` and `$ai_time_to_first_token` are seconds; + `duration_ms` and `time_to_first_token_ms` are the millisecond siblings the + first-party dashboards read. Feeding a millisecond value to a seconds field is + invisible in the payload and inflates the metric 1000x. +- **Trace-level input/output state lives only on `$ai_trace`.** PostHog reads a + trace's input and output from that event and never from its children, so + `$ai_input_state` / `$ai_output_state` have to be set there or the trace + detail view is empty. + - **One generation per run, not per model round-trip.** The engine layer reports aggregate usage through `onUsage` and exposes no per-step hook, so a multi-step run collapses into a single generation carrying the whole message list. diff --git a/.changeset/posthog-ai-observability-fixes.md b/.changeset/posthog-ai-observability-fixes.md new file mode 100644 index 0000000000..c4b3102263 --- /dev/null +++ b/.changeset/posthog-ai-observability-fixes.md @@ -0,0 +1,13 @@ +--- +"@agent-native/core": patch +--- + +Fix PostHog LLM analytics events so trace, span, and generation metrics match PostHog's schema and aggregation. + +- `$ai_time_to_first_token` is now sent in seconds. It was being handed the millisecond value verbatim, inflating every time-to-first-token in LLM analytics 1000x. +- The `$ai_trace` event no longer carries `$ai_latency`, `$ai_input_tokens`, `$ai_output_tokens`, or `$ai_total_cost_usd`. PostHog derives all four from a trace's children, and summed the trace's own `$ai_latency` alongside them — reporting roughly twice the real run duration. The run totals now ride along as `duration_ms`, `input_tokens`, `output_tokens`, and `cost_usd` for backends that do no such aggregation. +- The generation's `$ai_latency` is now model time (run duration minus tool time) instead of the whole run, so tool duration is no longer counted both in the generation and in its sibling tool spans. +- `$ai_request_count` reports the run's real LLM round-trip count instead of a hardcoded `1`, which undercharged multi-step runs on request-priced models. +- `$ai_trace` now carries `$ai_input_state` / `$ai_output_state` when `capturePrompts` is on. PostHog reads a trace's input and output only from that event, so the trace detail view was empty. +- Successful tool calls now record their result on the span under `captureToolResults`, so a healthy tool span reports an output instead of looking like a tool that returned nothing. +- AI events are stamped with when they happened rather than when the run flushed. `track()` accepts an `occurredAt`, so a trace tree keeps a real timeline instead of collapsing into one instant. diff --git a/packages/core/src/observability/posthog-ai.ts b/packages/core/src/observability/posthog-ai.ts index c2aa836a3f..e159a3a820 100644 --- a/packages/core/src/observability/posthog-ai.ts +++ b/packages/core/src/observability/posthog-ai.ts @@ -12,6 +12,14 @@ * PostHog's `$session_id`: the latter is the browser session used for session * replay, and the two are different lifetimes. * + * PostHog DERIVES a trace's latency, tokens and cost from its children — its + * trace query sums `$ai_latency` over every event whose `$ai_parent_id` is the + * trace or absent, and sums tokens/cost over `$ai_generation` / `$ai_embedding` + * only. So the `$ai_trace` event carries none of those: an `$ai_latency` here + * was counted *in addition to* the generation's and reported roughly twice the + * real duration. Run totals ride along under plain names for the non-PostHog + * backends, which have no such aggregation. + * * Content (`$ai_input` / `$ai_output_choices` / `$ai_input_state` / * `$ai_output_state`) is gated on config and always OMITTED when disabled. * Sending `[]` instead would be indistinguishable from a run that genuinely had @@ -40,6 +48,7 @@ function trackAiEvent( name: string, properties: Record, userId: string | null, + occurredAt: number, ): void { for (const key of Object.keys(properties)) { if (properties[key] === undefined) delete properties[key]; @@ -47,7 +56,7 @@ function trackAiEvent( try { void import("../tracking/registry.js") .then(({ track }) => { - track(name, properties, { userId: userId ?? undefined }); + track(name, properties, { userId: userId ?? undefined, occurredAt }); }) .catch(() => {}); // coercion-ok: a throw here would break the run it is observing @@ -95,7 +104,9 @@ export interface AiTraceEventInput { spanName: string; model: string; provider: string; - latencySeconds: number; + /** Wall-clock duration of the whole run. Reported under `duration_ms`, not + * `$ai_latency` — see the aggregation note at the top of this file. */ + durationMs: number; isError: boolean; error?: AiErrorDetail; inputTokens?: number; @@ -130,12 +141,12 @@ export function emitAiTraceEvent(input: AiTraceEventInput): void { $ai_span_name: input.spanName, $ai_model: input.model, $ai_provider: input.provider, - $ai_latency: input.latencySeconds, $ai_is_error: input.isError, $ai_error: input.error, - $ai_input_tokens: input.inputTokens, - $ai_output_tokens: input.outputTokens, - $ai_total_cost_usd: input.costUsd, + duration_ms: Math.round(input.durationMs), + input_tokens: input.inputTokens, + output_tokens: input.outputTokens, + cost_usd: input.costUsd, $ai_input_state: inputContent?.value, $ai_output_state: outputContent?.value, $ai_input_truncated: inputContent?.truncated || undefined, @@ -144,6 +155,7 @@ export function emitAiTraceEvent(input: AiTraceEventInput): void { created_at: new Date(input.createdAt).toISOString(), }, input.userId, + input.createdAt, ); } @@ -196,6 +208,7 @@ export function emitAiSpanEvent(input: AiSpanEventInput): void { created_at: new Date(input.createdAt).toISOString(), }, input.userId, + input.createdAt, ); } diff --git a/packages/core/src/observability/traces.spec.ts b/packages/core/src/observability/traces.spec.ts index ef14819345..68056a2c79 100644 --- a/packages/core/src/observability/traces.spec.ts +++ b/packages/core/src/observability/traces.spec.ts @@ -1734,4 +1734,351 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { expect(runSpan?.status?.message).toBeUndefined(); expect(runSpan?.ended).toBe(true); }); + + // PostHog's trace query sums `$ai_latency` over the trace's direct children + // AND over any event with no `$ai_parent_id` — which the `$ai_trace` event + // itself is. Emitting it there reported roughly twice the real duration, and + // a generation claiming the whole run counted tool time a second time. + it("reports trace latency through children only, with tool time removed from the generation", async () => { + const byName = new Map(); + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (!event.name.startsWith("$ai_")) return; + const list = byName.get(event.name) ?? []; + list.push(event); + byName.set(event.name, list); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + await new Promise((resolve) => setTimeout(resolve, 20)); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + await new Promise((resolve) => setTimeout(resolve, 5)); + return { + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }; + }, + loopOpts, + runId: "run-latency", + threadId: "thread-latency", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const trace = byName.get("$ai_trace")?.[0]; + const generation = byName.get("$ai_generation")?.[0]; + const span = byName.get("$ai_span")?.[0]; + expect(trace).toBeDefined(); + expect(generation).toBeDefined(); + expect(span).toBeDefined(); + + // The trace contributes no latency of its own; PostHog derives it. + expect(trace?.properties).not.toHaveProperty("$ai_latency"); + // ...but the run duration is still recorded for the other backends. + expect(trace?.properties?.duration_ms).toEqual(expect.any(Number)); + + // What PostHog will sum: the generation plus its sibling tool spans. + const spanLatency = span?.properties?.["$ai_latency"] as number; + const generationLatency = generation?.properties?.["$ai_latency"] as number; + const summed = generationLatency + spanLatency; + const runSeconds = (trace?.properties?.duration_ms as number) / 1000; + expect(spanLatency).toBeGreaterThan(0); + expect(summed).toBeLessThanOrEqual(runSeconds + 0.01); + // The generation is model time only, so it cannot span the whole run once + // a tool has taken a measurable slice of it. + expect(generationLatency).toBeLessThan(runSeconds); + }); + + // `$ai_time_to_first_token` is a SECONDS field. It was being handed the + // millisecond value verbatim, inflating every TTFT in LLM analytics 1000x. + it("reports $ai_time_to_first_token in seconds while keeping the ms property", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name === "$ai_generation") events.push(event); + }, + }); + const loopOpts: any = { + engine: { name: "builder" }, + model: "gpt-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async () => ({ + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "gpt-test", + usageReported: true, + firstEngineEventAtMs: Date.now() + 2000, + }), + loopOpts, + runId: "run-ttft-seconds", + threadId: null, + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const props = events[0]?.properties ?? {}; + const ms = props.time_to_first_token_ms as number; + const seconds = props["$ai_time_to_first_token"] as number; + expect(ms).toBeGreaterThan(1000); + expect(seconds).toBeCloseTo(ms / 1000, 2); + }); + + // PostHog multiplies `$ai_request_count` by per-request pricing. A hardcoded + // 1 undercharged every multi-step run. + it("reports the run's real LLM round-trip count", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name === "$ai_generation") events.push(event); + }, + }); + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async () => ({ + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + llmCalls: 4, + }), + loopOpts, + runId: "run-request-count", + threadId: null, + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect(events[0]?.properties?.["$ai_request_count"]).toBe(4); + }); + + // PostHog reads a trace's input/output state ONLY from the `$ai_trace` + // event, so a trace that never carried them showed an empty detail view. + it("carries trace input/output state when capturePrompts is on, and omits it when off", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name === "$ai_trace") events.push(event); + }, + }); + + const run = (capturePrompts: boolean) => + instrumentAgentLoop({ + runAgentLoop: async ({ send }: any) => { + send({ type: "text", text: "the weather is fine" }); + return { + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }; + }, + loopOpts: { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [{ role: "user", content: "what is the weather?" }], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + } as any, + runId: `run-trace-state-${capturePrompts}`, + threadId: null, + userId: null, + config: { + ...DEFAULT_OBSERVABILITY_CONFIG, + enabled: true, + capturePrompts, + }, + }); + + await run(false); + await new Promise((resolve) => setTimeout(resolve, 0)); + // Absent, not empty — an empty array reads as "the run had no messages". + expect(events[0]?.properties).not.toHaveProperty("$ai_input_state"); + expect(events[0]?.properties).not.toHaveProperty("$ai_output_state"); + + events.length = 0; + await run(true); + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect(events[0]?.properties?.["$ai_input_state"]).toEqual([ + { role: "user", content: "what is the weather?" }, + ]); + expect(events[0]?.properties?.["$ai_output_state"]).toEqual([ + { role: "assistant", content: "the weather is fine" }, + ]); + }); + + // Only a FAILED tool's content had anywhere to go, so a healthy tool span + // shipped an input and no output — indistinguishable from a tool that + // returned nothing. + it("carries successful tool output on the span when captureToolResults is on", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name === "$ai_span") events.push(event); + }, + }); + + const run = (captureToolResults: boolean) => + instrumentAgentLoop({ + runAgentLoop: async ({ send }: any) => { + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + send({ + type: "tool_done", + id: "a", + tool: "read", + result: "three matching rows", + }); + return { + inputTokens: 1, + outputTokens: 1, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + }; + }, + loopOpts: { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + } as any, + runId: `run-tool-output-${captureToolResults}`, + threadId: null, + userId: null, + config: { + ...DEFAULT_OBSERVABILITY_CONFIG, + enabled: true, + captureToolResults, + }, + }); + + await run(false); + await new Promise((resolve) => setTimeout(resolve, 0)); + expect(events).toHaveLength(1); + expect(events[0]?.properties?.["$ai_is_error"]).toBe(false); + expect(events[0]?.properties).not.toHaveProperty("$ai_output_state"); + + events.length = 0; + await run(true); + await new Promise((resolve) => setTimeout(resolve, 0)); + expect(events).toHaveLength(1); + expect(events[0]?.properties?.["$ai_output_state"]).toBe( + "three matching rows", + ); + }); + + // Every event in a run is emitted in one burst at the end. Stamping them all + // with the flush time collapses the trace tree's timeline into an instant. + it("stamps each AI event with when it happened, not when the run flushed", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name.startsWith("$ai_")) events.push(event); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + const startedAt = Date.now(); + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + await new Promise((resolve) => setTimeout(resolve, 30)); + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + return { + inputTokens: 1, + outputTokens: 1, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + }; + }, + loopOpts, + runId: "run-timestamps", + threadId: null, + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const at = (name: string) => + new Date(events.find((e) => e.name === name)?.timestamp ?? 0).getTime(); + + // The trace and generation are anchored to run start; the tool span ran + // later. If every event were stamped at flush time these would be equal. + expect(at("$ai_trace")).toBeCloseTo(startedAt, -2); + expect(at("$ai_generation")).toBeCloseTo(startedAt, -2); + expect(at("$ai_span")).toBeGreaterThan(at("$ai_trace")); + }); }); diff --git a/packages/core/src/observability/traces.ts b/packages/core/src/observability/traces.ts index 3f607facde..a1f68c0a4e 100644 --- a/packages/core/src/observability/traces.ts +++ b/packages/core/src/observability/traces.ts @@ -141,6 +141,21 @@ function emitLlmGenerationTrackingEvent(args: { * them and is equally unmeasurable when they were never reported. */ costCentsX100: number | undefined; durationMs: number; + /** + * Wall-clock ms spent in the model: the run duration with tool-execution + * time removed. This is what `$ai_latency` reports, and it is deliberately + * NOT `durationMs`. + * + * PostHog sums `$ai_latency` across a trace's direct children, and every + * tool call is emitted as one of those children. Reporting the full run + * duration here counted tool time twice and made the trace waterfall wider + * than the run it describes. + */ + llmDurationMs: number; + /** LLM round-trips in the run. Feeds `$ai_request_count`, which PostHog + * multiplies by per-request pricing — a hardcoded 1 undercharged every + * multi-step run on a request-priced model. */ + llmCallCount: number; /** Elapsed ms from run start to the first non-heartbeat engine event. * Undefined when no such event ever arrived (the run never produced a * token before being aborted) — never coerced to 0. */ @@ -248,7 +263,7 @@ function emitLlmGenerationTrackingEvent(args: { $ai_provider: provider, $ai_input_tokens: args.inputTokens, $ai_output_tokens: args.outputTokens, - $ai_latency: Math.round((args.durationMs / 1000) * 1000) / 1000, + $ai_latency: Math.round(args.llmDurationMs) / 1000, $ai_is_error: args.status === "error", $ai_error: args.status === "error" @@ -260,14 +275,19 @@ function emitLlmGenerationTrackingEvent(args: { : undefined, $ai_cache_read_input_tokens: args.cacheReadTokens, $ai_cache_creation_input_tokens: args.cacheWriteTokens, - $ai_request_count: 1, + $ai_request_count: args.llmCallCount, $ai_total_cost_usd: costUsd, $ai_input: args.aiInput, $ai_output_choices: args.aiOutputChoices, $ai_tools: args.aiTools, $ai_input_truncated: args.aiInputTruncated || undefined, $ai_output_truncated: args.aiOutputTruncated || undefined, - $ai_time_to_first_token: args.firstTokenMs, + // Seconds, per PostHog's schema — `time_to_first_token_ms` above is the + // millisecond field this framework's own dashboards read. + $ai_time_to_first_token: + args.firstTokenMs === undefined + ? undefined + : Math.round(args.firstTokenMs) / 1000, $session_id: args.browserSessionId, }; if (args.experimentAssignments?.length) { @@ -293,6 +313,7 @@ function emitLlmGenerationTrackingEvent(args: { .then(({ track }) => { track("$ai_generation", properties, { userId: args.userId ?? undefined, + occurredAt: args.createdAt, }); }) .catch(() => {}); @@ -809,6 +830,30 @@ export async function instrumentAgentLoop(opts: { pending.endResult = otelEndResult; } + const spanMetadataFields: Record = {}; + if (config.captureToolArgs && pending) { + // Strip Authorization/api-key/token-shaped values before persisting + // (M14 in the MCP/A2A audit). Tool-runtime execution still sees the + // unredacted input — only the long-lived span row is sanitized. + spanMetadataFields.input = redactSensitiveFields(pending.input); + } + // A failed tool's content reaches the span through `errorMessage`; a + // successful one had nowhere to go, so every healthy tool span shipped + // an input and no output — indistinguishable from a tool that returned + // nothing. Same redaction and truncation as the error path. + if ( + !isError && + config.captureToolResults && + typeof event.result === "string" + ) { + spanMetadataFields.output = truncateToolErrorMessage( + redactToolErrorMessage(event.result), + ); + } + const spanMetadata = Object.keys(spanMetadataFields).length + ? spanMetadataFields + : null; + const span: TraceSpan = { id: pending?.spanId ?? spanId(), runId, @@ -825,19 +870,7 @@ export async function instrumentAgentLoop(opts: { durationMs: pending ? Math.max(0, finishedAt - pending.startMs) : 0, status: isError ? "error" : "success", errorMessage: isError ? event.result : null, - metadata: - config.captureToolArgs && pending - ? // Strip Authorization/api-key/token-shaped values before - // persisting (M14 in the MCP/A2A audit). Tool-runtime - // execution still sees the unredacted input — only the - // long-lived span row is sanitized. - { - input: redactSensitiveFields(pending.input) as Record< - string, - string - >, - } - : null, + metadata: spanMetadata, createdAt: Date.now(), }; spans.push(span); @@ -995,12 +1028,25 @@ export async function instrumentAgentLoop(opts: { ? Math.max(0, usage.firstEngineEventAtMs - runStart) : undefined; const llmSpanId = spanId(); + const generationToolSpans = spans.filter( + (s) => s.spanType === "tool_call", + ); + // Tool calls are emitted as sibling `$ai_span`s under the same trace, + // and PostHog adds their latency to this generation's. Subtracting + // their duration keeps the trace total equal to the run, not to the + // run plus its tools counted a second time. Clamped at 0 because tool + // spans are timed independently and can overlap. + const llmDurationMs = Math.max( + 0, + totalDurationMs - + generationToolSpans.reduce((sum, s) => sum + s.durationMs, 0), + ); const generationContent = buildGenerationContent({ config, messages: loopOpts.messages, tools: loopOpts.tools, assistantText: assistantTextParts.join(""), - toolSpans: spans.filter((s) => s.spanType === "tool_call"), + toolSpans: generationToolSpans, }); const llmSpan: TraceSpan = { id: llmSpanId, @@ -1045,6 +1091,8 @@ export async function instrumentAgentLoop(opts: { : undefined, costCentsX100: usageReported ? costCentsX100 : undefined, durationMs: totalDurationMs, + llmDurationMs, + llmCallCount, firstTokenMs, status: runStatus, errorMessage, @@ -1120,6 +1168,24 @@ export async function instrumentAgentLoop(opts: { const emittedToolSpans = toolSpans.slice(0, MAX_AI_SPANS_PER_RUN); const droppedToolSpans = toolSpans.length - emittedToolSpans.length; + // PostHog reads a trace's input/output state ONLY from the `$ai_trace` + // event — never from its children — so a trace whose detail view should + // show what the run was asked and what it answered has to carry them + // here. Gated on `capturePrompts` and omitted, not emptied, when off. + const traceInputState = config.capturePrompts + ? redactSensitiveFields(loopOpts.messages) + : undefined; + const traceAssistantText = assistantTextParts.join(""); + const traceOutputState = + config.capturePrompts && traceAssistantText + ? [ + { + role: "assistant", + content: redactToolErrorMessage(traceAssistantText), + }, + ] + : undefined; + emitAiTraceEvent({ runId, threadId, @@ -1127,7 +1193,7 @@ export async function instrumentAgentLoop(opts: { spanName, model: usage?.model ?? loopOpts.model, provider, - latencySeconds: Math.round(totalDurationMs) / 1000, + durationMs: totalDurationMs, isError: runStatus === "error", error: aiError, inputTokens: usage?.usageReported ? usage.inputTokens : undefined, @@ -1137,6 +1203,8 @@ export async function instrumentAgentLoop(opts: { : undefined, createdAt: runStart, browserSessionId, + inputState: traceInputState, + outputState: traceOutputState, extraProperties: { ...trackingIdentityProperties(), source: "agent_observability", @@ -1187,10 +1255,13 @@ export async function instrumentAgentLoop(opts: { : undefined, createdAt: span.createdAt, browserSessionId, - // `metadata.input` is already redacted and only present when - // `captureToolArgs` is on; absent stays absent. + // `metadata.input` / `metadata.output` are already redacted and + // only present when `captureToolArgs` / `captureToolResults` are + // on; absent stays absent. inputState: (span.metadata as { input?: unknown } | null)?.input, - outputState: toolErrorMessage, + outputState: + toolErrorMessage ?? + (span.metadata as { output?: unknown } | null)?.output, extraProperties: { ...trackingIdentityProperties(), source: "agent_observability", diff --git a/packages/core/src/tracking/registry.ts b/packages/core/src/tracking/registry.ts index 474e8c3586..d9a2d804d9 100644 --- a/packages/core/src/tracking/registry.ts +++ b/packages/core/src/tracking/registry.ts @@ -40,6 +40,17 @@ export interface TrackingMeta { anonymousId?: string; /** Overrides the ambient request's browser session. */ sessionId?: string; + /** + * When the event actually happened, in epoch ms. Defaults to now. + * + * Needed by callers that buffer and flush a batch of events at the end of a + * unit of work — an agent run emits its trace, generation, and tool spans in + * one burst, and stamping all of them with the flush time collapses a + * multi-second waterfall into a single instant. PostHog orders an LLM trace + * tree by event timestamp, so without this the tree renders with a synthetic + * timeline. + */ + occurredAt?: number; } /** @@ -62,6 +73,7 @@ function resolveTrackingSource(source: TrackingSource | undefined): { userId?: string; anonymousId?: string; sessionId?: string; + occurredAt?: number; } { // The browser session rides the request, not the caller's arguments, so it // resolves the same way whether the UI called the action or the agent did. @@ -74,6 +86,7 @@ function resolveTrackingSource(source: TrackingSource | undefined): { userId: source.userId, anonymousId: source.anonymousId, sessionId: source.sessionId ?? ambientSessionId, + occurredAt: source.occurredAt, }; } @@ -82,7 +95,8 @@ export function track( properties?: Record, source?: TrackingSource, ): void { - const { userId, anonymousId, sessionId } = resolveTrackingSource(source); + const { userId, anonymousId, sessionId, occurredAt } = + resolveTrackingSource(source); const clientPlatform = getRequestContext()?.clientPlatform; const trackedProperties = { ...(properties ?? {}), @@ -94,7 +108,9 @@ export function track( const event: TrackingEvent = { name, properties: trackedProperties, - timestamp: new Date().toISOString(), + // A caller-supplied `occurredAt` of 0 is not a real event time, so `||` + // rather than `??` is deliberate here. + timestamp: new Date(occurredAt || Date.now()).toISOString(), userId, anonymousId, sessionId, diff --git a/templates/analytics/actions/query-agent-native-analytics.ts b/templates/analytics/actions/query-agent-native-analytics.ts index 9b91d18dbe..b30feb742f 100644 --- a/templates/analytics/actions/query-agent-native-analytics.ts +++ b/templates/analytics/actions/query-agent-native-analytics.ts @@ -48,7 +48,7 @@ function toDataTableResult(result: { export default defineAction({ description: - "Query the built-in first-party Analytics source: events recorded through this app's analytics collector endpoint (/track), compact daily rollups updated transactionally with new ingest, identifiable user-day rollups, and session replay summaries recorded through /api/analytics/replay. This source does not require an external provider connection. Use it for questions about app/site traffic, product events, template/app usage, conversions, session recordings, LLM/agent observability, model cost, token volume, latency, and other first-party data collected by this analytics app. Use source-specific actions such as BigQuery, GA4, Mixpanel, PostHog, or Amplitude when the user asks for those sources or the relevant data lives there. SQL may read analytics_events, analytics_event_daily_rollups, analytics_user_days, and session_recordings; session_replay_chunks is intentionally unavailable, and reads are automatically scoped to the current user/org. Prefer analytics_event_daily_rollups for event counts and analytics_user_days for active-user or retention questions. On the Builder.io production organization after the explicit BigQuery cutover, event and rollup reads use partitioned BigQuery tables/views while session_recordings remains in the SQL store; cross-backend joins are not supported. Before a large or historical query, call get-first-party-analytics-health and use a configured external backend when it recommends one: BigQuery supports warehouse SQL and historical analysis, while Amplitude supports product analytics, funnels, and retention. Connecting a backend does not automatically reroute /track events or copy existing Neon events; the migration action performs that explicit prepare, backfill, and cutover sequence. Aggregate, project only needed columns, use bounded recent drill-downs, and add a LIMIT for raw or high-cardinality reads; do not issue an unbounded raw-event scan or paginate a large cohort. An explicit all-time or lifetime request remains all-time, so do not invent a default lower time bound. Safe scoped results are cached for up to five minutes for this agent action. analytics_events columns include event_name, timestamp, event_date, user_id, anonymous_id, user_key, session_id, app, template, signed_in, url, path, hostname, referrer, properties, and context. analytics_event_daily_rollups columns include tenant_key, owner_email, org_id, event_date, event_name, app, template, and event_count. analytics_user_days columns include tenant_key, owner_email, org_id, event_date, and user_key. LLM observability events use event_name = '$ai_generation'; useful properties include $ai_trace_id/run_id, $ai_session_id/thread_id, $ai_model/model, $ai_provider/provider, $ai_input_tokens/input_tokens, $ai_output_tokens/output_tokens, cache_read_tokens, cache_write_tokens, cost_cents_x100, $ai_total_cost_usd/cost_usd, duration_ms/$ai_latency, status, tool_calls, successful_tools, failed_tools, tools, tools_truncated, delegated, delegation_protocol, caller_app, delegation_task_id, a2a_task_id, parent_run_id, parent_turn_id, and error_message/$ai_error. Agent Teams child runs use delegation_protocol = 'agent-team' and retain their own run_id while linking to the launching run through parent_run_id. The bounded tools array contains names, relative start times, durations, statuses, and coarse error classes only, never args or results; failed runs and interrupted tools remain queryable. session_recordings columns include id, session_id, user_id, anonymous_id, user_key, started_at, ended_at, duration_ms, chunk_count, event_count, page_count, error_count, rage_click_count, app, template, status, first_url, last_url, path, hostname, referrer, and metadata.", + "Query the built-in first-party Analytics source: events recorded through this app's analytics collector endpoint (/track), compact daily rollups updated transactionally with new ingest, identifiable user-day rollups, and session replay summaries recorded through /api/analytics/replay. This source does not require an external provider connection. Use it for questions about app/site traffic, product events, template/app usage, conversions, session recordings, LLM/agent observability, model cost, token volume, latency, and other first-party data collected by this analytics app. Use source-specific actions such as BigQuery, GA4, Mixpanel, PostHog, or Amplitude when the user asks for those sources or the relevant data lives there. SQL may read analytics_events, analytics_event_daily_rollups, analytics_user_days, and session_recordings; session_replay_chunks is intentionally unavailable, and reads are automatically scoped to the current user/org. Prefer analytics_event_daily_rollups for event counts and analytics_user_days for active-user or retention questions. On the Builder.io production organization after the explicit BigQuery cutover, event and rollup reads use partitioned BigQuery tables/views while session_recordings remains in the SQL store; cross-backend joins are not supported. Before a large or historical query, call get-first-party-analytics-health and use a configured external backend when it recommends one: BigQuery supports warehouse SQL and historical analysis, while Amplitude supports product analytics, funnels, and retention. Connecting a backend does not automatically reroute /track events or copy existing Neon events; the migration action performs that explicit prepare, backfill, and cutover sequence. Aggregate, project only needed columns, use bounded recent drill-downs, and add a LIMIT for raw or high-cardinality reads; do not issue an unbounded raw-event scan or paginate a large cohort. An explicit all-time or lifetime request remains all-time, so do not invent a default lower time bound. Safe scoped results are cached for up to five minutes for this agent action. analytics_events columns include event_name, timestamp, event_date, user_id, anonymous_id, user_key, session_id, app, template, signed_in, url, path, hostname, referrer, properties, and context. analytics_event_daily_rollups columns include tenant_key, owner_email, org_id, event_date, event_name, app, template, and event_count. analytics_user_days columns include tenant_key, owner_email, org_id, event_date, and user_key. LLM observability events use event_name = '$ai_generation'; useful properties include $ai_trace_id/run_id, $ai_session_id/thread_id, $ai_model/model, $ai_provider/provider, $ai_input_tokens/input_tokens, $ai_output_tokens/output_tokens, cache_read_tokens, cache_write_tokens, cost_cents_x100, $ai_total_cost_usd/cost_usd, duration_ms (full run, milliseconds), $ai_latency (model time in seconds, run minus tool time), status, tool_calls, successful_tools, failed_tools, tools, tools_truncated, delegated, delegation_protocol, caller_app, delegation_task_id, a2a_task_id, parent_run_id, parent_turn_id, and error_message/$ai_error. Agent Teams child runs use delegation_protocol = 'agent-team' and retain their own run_id while linking to the launching run through parent_run_id. The bounded tools array contains names, relative start times, durations, statuses, and coarse error classes only, never args or results; failed runs and interrupted tools remain queryable. session_recordings columns include id, session_id, user_id, anonymous_id, user_key, started_at, ended_at, duration_ms, chunk_count, event_count, page_count, error_count, rage_click_count, app, template, status, first_url, last_url, path, hostname, referrer, and metadata.", schema: z.object({ sql: z .string() diff --git a/templates/analytics/docs/schemas/first-party-analytics.md b/templates/analytics/docs/schemas/first-party-analytics.md index 013bd3a234..d79e4deda2 100644 --- a/templates/analytics/docs/schemas/first-party-analytics.md +++ b/templates/analytics/docs/schemas/first-party-analytics.md @@ -128,7 +128,8 @@ Useful query fields live in `properties`: | `cache_read_tokens`, `cache_write_tokens` | Prompt-cache token counts | | `$ai_total_cost_usd`, `cost_usd` | Estimated run cost in USD | | `cost_cents_x100` | Estimated run cost in centicents | -| `$ai_latency`, `duration_ms` | Run duration in seconds / milliseconds | +| `duration_ms` | Run duration in milliseconds | +| `$ai_latency` | Model time in seconds (run duration minus tool time), on `$ai_generation` | | `tool_calls`, `successful_tools`, `failed_tools` | Complete tool-call counts | | `tools`, `tools_truncated` | First 50 tool names, offsets, durations, statuses, and error classes, including interrupted calls | | `delegated`, `delegation_protocol`, `caller_app` | Delegated-run attribution | diff --git a/templates/analytics/docs/schemas/tracked-events.md b/templates/analytics/docs/schemas/tracked-events.md index 710f45dcad..13088f3cc7 100644 --- a/templates/analytics/docs/schemas/tracked-events.md +++ b/templates/analytics/docs/schemas/tracked-events.md @@ -29,6 +29,8 @@ Events tracked by application instrumentation and stored in the configured appli `$ai_model`, `$ai_provider`, `$ai_input_tokens`, `$ai_output_tokens`, `$ai_latency`, `$ai_total_cost_usd`, `run_id`, `thread_id`, `cost_cents_x100`, `duration_ms`, `tool_calls`, `status`, and error fields. + `$ai_latency` is model time in seconds; `duration_ms` is the full run in + milliseconds, and the two differ by the time spent in tools. A bounded `tools` array records only tool names, relative start times, durations, statuses, and coarse error classes; interrupted tools and failed runs remain visible, and `tools_truncated` marks runs above the 50-entry cap. From d500dc93df0a711a72c35f8c753467a649278db2 Mon Sep 17 00:00:00 2001 From: Manu MA Date: Sun, 23 Aug 2026 13:02:21 +0200 Subject: [PATCH 2/6] =?UTF-8?q?=F0=9F=8C=9F?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .agents/skills/observability/SKILL.md | 6 +- .changeset/posthog-ai-observability-fixes.md | 2 + packages/core/src/observability/posthog-ai.ts | 12 +- .../core/src/observability/traces.spec.ts | 212 ++++++++++++++++++ packages/core/src/observability/traces.ts | 15 +- 5 files changed, 238 insertions(+), 9 deletions(-) diff --git a/.agents/skills/observability/SKILL.md b/.agents/skills/observability/SKILL.md index 3fdad10dbd..af85920022 100644 --- a/.agents/skills/observability/SKILL.md +++ b/.agents/skills/observability/SKILL.md @@ -321,6 +321,10 @@ Constraints that are not visible from the emit site: `duration_ms` and `time_to_first_token_ms` are the millisecond siblings the first-party dashboards read. Feeding a millisecond value to a seconds field is invisible in the payload and inflates the metric 1000x. +- **Custom properties never take an `$ai_` prefix.** That namespace belongs to + PostHog's schema; a name it does not define today it may define tomorrow with + a different meaning. Ours are plain (`duration_ms`, `input_truncated`, + `spans_dropped`), which also keeps them out of PostHog's `$ai_*` aggregation. - **Trace-level input/output state lives only on `$ai_trace`.** PostHog reads a trace's input and output from that event and never from its children, so `$ai_input_state` / `$ai_output_state` have to be set there or the trace @@ -335,7 +339,7 @@ Constraints that are not visible from the emit site: - **Disabled capture omits the field rather than sending an empty one.** An empty array is indistinguishable from a run that genuinely had no messages. Truncated content is marked, and a run over the span cap stamps - `$ai_spans_dropped` — a truncated run must not read as a complete one. + `spans_dropped` — a truncated run must not read as a complete one. - **The structural tool-call list ships even when content capture is off.** Backends derive their tool tags from tool-call blocks inside the output choices and from nothing else, so tool names (without arguments) are always diff --git a/.changeset/posthog-ai-observability-fixes.md b/.changeset/posthog-ai-observability-fixes.md index c4b3102263..7d1a82f8c9 100644 --- a/.changeset/posthog-ai-observability-fixes.md +++ b/.changeset/posthog-ai-observability-fixes.md @@ -11,3 +11,5 @@ Fix PostHog LLM analytics events so trace, span, and generation metrics match Po - `$ai_trace` now carries `$ai_input_state` / `$ai_output_state` when `capturePrompts` is on. PostHog reads a trace's input and output only from that event, so the trace detail view was empty. - Successful tool calls now record their result on the span under `captureToolResults`, so a healthy tool span reports an output instead of looking like a tool that returned nothing. - AI events are stamped with when they happened rather than when the run flushed. `track()` accepts an `occurredAt`, so a trace tree keeps a real timeline instead of collapsing into one instant. +- `$ai_stream` is set, which is what makes `$ai_time_to_first_token` meaningful. +- Custom properties no longer use an `$ai_` prefix (`$ai_input_truncated` → `input_truncated`, `$ai_spans_dropped` → `spans_dropped`). That namespace is PostHog's schema and a name it does not define today it may define tomorrow. diff --git a/packages/core/src/observability/posthog-ai.ts b/packages/core/src/observability/posthog-ai.ts index e159a3a820..1f8b767d8a 100644 --- a/packages/core/src/observability/posthog-ai.ts +++ b/packages/core/src/observability/posthog-ai.ts @@ -20,6 +20,10 @@ * real duration. Run totals ride along under plain names for the non-PostHog * backends, which have no such aggregation. * + * Custom properties do NOT take an `$ai_` prefix. That namespace is PostHog's + * schema, and a name it does not define today it may define tomorrow with + * different meaning — `input_truncated` / `spans_dropped` cannot collide. + * * Content (`$ai_input` / `$ai_output_choices` / `$ai_input_state` / * `$ai_output_state`) is gated on config and always OMITTED when disabled. * Sending `[]` instead would be indistinguishable from a run that genuinely had @@ -149,8 +153,8 @@ export function emitAiTraceEvent(input: AiTraceEventInput): void { cost_usd: input.costUsd, $ai_input_state: inputContent?.value, $ai_output_state: outputContent?.value, - $ai_input_truncated: inputContent?.truncated || undefined, - $ai_output_truncated: outputContent?.truncated || undefined, + input_truncated: inputContent?.truncated || undefined, + output_truncated: outputContent?.truncated || undefined, $session_id: input.browserSessionId, created_at: new Date(input.createdAt).toISOString(), }, @@ -202,8 +206,8 @@ export function emitAiSpanEvent(input: AiSpanEventInput): void { $ai_error: input.error, $ai_input_state: inputContent?.value, $ai_output_state: outputContent?.value, - $ai_input_truncated: inputContent?.truncated || undefined, - $ai_output_truncated: outputContent?.truncated || undefined, + input_truncated: inputContent?.truncated || undefined, + output_truncated: outputContent?.truncated || undefined, $session_id: input.browserSessionId, created_at: new Date(input.createdAt).toISOString(), }, diff --git a/packages/core/src/observability/traces.spec.ts b/packages/core/src/observability/traces.spec.ts index 68056a2c79..35bb84cc60 100644 --- a/packages/core/src/observability/traces.spec.ts +++ b/packages/core/src/observability/traces.spec.ts @@ -2081,4 +2081,216 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { expect(at("$ai_generation")).toBeCloseTo(startedAt, -2); expect(at("$ai_span")).toBeGreaterThan(at("$ai_trace")); }); + // Two different identifiers with two different lifetimes. `$ai_session_id` + // is the thread (backend-owned, groups traces into a conversation); + // `$session_id` is PostHog's frontend session, propagated from the + // `X-Agent-Native-Session-Id` header so a trace joins session replay. + // Collapsing them would break whichever one lost. + it("sends $ai_session_id (thread) and $session_id (browser) as distinct ids on every AI event", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name.startsWith("$ai_")) events.push(event); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + return { + inputTokens: 1, + outputTokens: 1, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + }; + }, + loopOpts, + runId: "run-sessions", + threadId: "thread-sessions", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + browserSessionId: "browser-session-xyz", + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const names = events.map((e) => e.name).sort(); + expect(names).toEqual(["$ai_generation", "$ai_span", "$ai_trace"]); + for (const event of events) { + expect(event.properties?.["$ai_session_id"]).toBe("thread-sessions"); + expect(event.properties?.["$session_id"]).toBe("browser-session-xyz"); + expect(event.properties?.["$ai_trace_id"]).toBe("run-sessions"); + } + }); + + // PostHog rejects ids outside this set, and a rejected id silently detaches + // the event from its trace. + it("emits trace and session ids within PostHog's allowed character set", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name.startsWith("$ai_")) events.push(event); + }, + }); + + await instrumentAgentLoop({ + runAgentLoop: async () => ({ + inputTokens: 1, + outputTokens: 1, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + }), + loopOpts: { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + } as any, + runId: "run-1770000000000-a1b2c3", + threadId: "thread-1770000000000-d4e5f6", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const allowed = /^[A-Za-z0-9\-_~.@()!':|]+$/; + for (const event of events) { + expect(String(event.properties?.["$ai_trace_id"])).toMatch(allowed); + expect(String(event.properties?.["$ai_session_id"])).toMatch(allowed); + } + }); + + // `$ai_trace` has exactly eight schema properties. Anything else that PostHog + // aggregates from elsewhere (tokens, cost, latency) must not appear under an + // `$ai_*` name here or it is counted twice. + it("keeps the $ai_trace event to PostHog's trace schema", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name === "$ai_trace") events.push(event); + }, + }); + + await instrumentAgentLoop({ + runAgentLoop: async () => ({ + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }), + loopOpts: { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + } as any, + runId: "run-trace-schema", + threadId: "thread-trace-schema", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const aiKeys = Object.keys(events[0]?.properties ?? {}) + .filter((k) => k.startsWith("$ai_")) + .sort(); + // No `$ai_error`: the run succeeded, and undefined properties are dropped + // rather than sent as null. + expect(aiKeys).toEqual([ + "$ai_is_error", + "$ai_model", + "$ai_provider", + "$ai_session_id", + "$ai_span_name", + "$ai_trace_id", + ]); + // Metrics PostHog derives from the trace's children never appear here. + for (const derived of [ + "$ai_latency", + "$ai_input_tokens", + "$ai_output_tokens", + "$ai_total_cost_usd", + ]) { + expect(events[0]?.properties).not.toHaveProperty(derived); + } + }); + + // PostHog accepts a `system` role in `$ai_input`, but the prompt is app + // configuration rather than conversation content and is near-identical on + // every run. Keeping it out is deliberate, not an oversight. + it("keeps the system prompt out of $ai_input even when capturePrompts is on", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (event.name === "$ai_generation") events.push(event); + }, + }); + + await instrumentAgentLoop({ + runAgentLoop: async () => ({ + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }), + loopOpts: { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "You are a careful assistant.", + tools: [], + messages: [{ role: "user", content: "hi" }], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + } as any, + runId: "run-system-prompt", + threadId: null, + userId: null, + config: { + ...DEFAULT_OBSERVABILITY_CONFIG, + enabled: true, + capturePrompts: true, + }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect(events[0]?.properties?.["$ai_input"]).toEqual([ + { role: "user", content: "hi" }, + ]); + expect(JSON.stringify(events[0])).not.toContain("careful assistant"); + expect(events[0]?.properties?.["$ai_stream"]).toBe(true); + }); }); diff --git a/packages/core/src/observability/traces.ts b/packages/core/src/observability/traces.ts index a1f68c0a4e..6e6c4957dd 100644 --- a/packages/core/src/observability/traces.ts +++ b/packages/core/src/observability/traces.ts @@ -273,6 +273,9 @@ function emitLlmGenerationTrackingEvent(args: { retryable: terminalRetryable, }) : undefined, + // Every engine here streams (`messages.stream`, `streamText`, gateway SSE), + // which is also what makes `$ai_time_to_first_token` meaningful. + $ai_stream: true, $ai_cache_read_input_tokens: args.cacheReadTokens, $ai_cache_creation_input_tokens: args.cacheWriteTokens, $ai_request_count: args.llmCallCount, @@ -280,8 +283,8 @@ function emitLlmGenerationTrackingEvent(args: { $ai_input: args.aiInput, $ai_output_choices: args.aiOutputChoices, $ai_tools: args.aiTools, - $ai_input_truncated: args.aiInputTruncated || undefined, - $ai_output_truncated: args.aiOutputTruncated || undefined, + input_truncated: args.aiInputTruncated || undefined, + output_truncated: args.aiOutputTruncated || undefined, // Seconds, per PostHog's schema — `time_to_first_token_ms` above is the // millisecond field this framework's own dashboards read. $ai_time_to_first_token: @@ -351,6 +354,10 @@ function buildGenerationContent(args: { } { const { config } = args; + // `$ai_input` is the conversation, not the system prompt. PostHog accepts a + // `system` role, but the prompt is app configuration rather than content and + // is near-identical on every run — shipping it would repeat kilobytes on each + // generation for no analytical gain. const input = config.capturePrompts ? boundAiContent(redactSensitiveFields(args.messages)) : undefined; @@ -1218,8 +1225,8 @@ export async function instrumentAgentLoop(opts: { // A truncated run must not read as a complete one. ...(droppedToolSpans > 0 ? { - $ai_spans_dropped: droppedToolSpans, - $ai_spans_emitted: emittedToolSpans.length, + spans_dropped: droppedToolSpans, + spans_emitted: emittedToolSpans.length, } : {}), }, From 829007bad6c898bc07a511c9406cf833ac7c234f Mon Sep 17 00:00:00 2001 From: Manu MA Date: Sun, 23 Aug 2026 19:47:39 +0200 Subject: [PATCH 3/6] fix: correct generation latency subtraction and tool span timestamps MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three defects in how the PostHog trace tree is assembled, all of which made a rendered number wrong rather than absent. Generation latency subtracted the sum of tool span durations from the run. Concurrent tools overlap, so the sum exceeds the time the run actually spent in tools — a parallel fan-out clamped the generation to zero while PostHog still summed every sibling span, putting the derived trace total over the wall clock. The subtraction now uses the union of the tool intervals. The subtraction also ran over every collected tool span, before the export path applied `captureLlmSpans` and `MAX_AI_SPANS_PER_RUN`. A tool that never reaches PostHog has no sibling span to hold its time, so subtracting it lost that time from the visible trace entirely. The emitted set is now resolved once, ahead of the generation event, and both use it. Tool spans were stamped `createdAt: Date.now()` at completion while their duration was measured from the pending start. PostHog draws a span forward from its event timestamp, so each tool rendered as beginning where it ended and running past the end of the trace containing it. Both the completed and the interrupted path now stamp the start. --- .changeset/posthog-ai-observability-fixes.md | 3 +- .../core/src/observability/traces.spec.ts | 202 ++++++++++++++++++ packages/core/src/observability/traces.ts | 72 +++++-- 3 files changed, 259 insertions(+), 18 deletions(-) diff --git a/.changeset/posthog-ai-observability-fixes.md b/.changeset/posthog-ai-observability-fixes.md index 7d1a82f8c9..551d571fbf 100644 --- a/.changeset/posthog-ai-observability-fixes.md +++ b/.changeset/posthog-ai-observability-fixes.md @@ -6,7 +6,8 @@ Fix PostHog LLM analytics events so trace, span, and generation metrics match Po - `$ai_time_to_first_token` is now sent in seconds. It was being handed the millisecond value verbatim, inflating every time-to-first-token in LLM analytics 1000x. - The `$ai_trace` event no longer carries `$ai_latency`, `$ai_input_tokens`, `$ai_output_tokens`, or `$ai_total_cost_usd`. PostHog derives all four from a trace's children, and summed the trace's own `$ai_latency` alongside them — reporting roughly twice the real run duration. The run totals now ride along as `duration_ms`, `input_tokens`, `output_tokens`, and `cost_usd` for backends that do no such aggregation. -- The generation's `$ai_latency` is now model time (run duration minus tool time) instead of the whole run, so tool duration is no longer counted both in the generation and in its sibling tool spans. +- The generation's `$ai_latency` is now model time (run duration minus tool time) instead of the whole run, so tool duration is no longer counted both in the generation and in its sibling tool spans. Concurrent tools count their overlapping window once, and tools that `captureLlmSpans` or the per-run span cap keeps out of PostHog are not subtracted at all — nothing else would carry their time. +- A tool `$ai_span` is timestamped at the tool's start rather than its completion. PostHog draws a span forward from its event timestamp by `$ai_latency`, so a completion-stamped span rendered the tool beginning where it ended and running past the end of its own trace. - `$ai_request_count` reports the run's real LLM round-trip count instead of a hardcoded `1`, which undercharged multi-step runs on request-priced models. - `$ai_trace` now carries `$ai_input_state` / `$ai_output_state` when `capturePrompts` is on. PostHog reads a trace's input and output only from that event, so the trace detail view was empty. - Successful tool calls now record their result on the span under `captureToolResults`, so a healthy tool span reports an output instead of looking like a tool that returned nothing. diff --git a/packages/core/src/observability/traces.spec.ts b/packages/core/src/observability/traces.spec.ts index 35bb84cc60..d52e7b9aa7 100644 --- a/packages/core/src/observability/traces.spec.ts +++ b/packages/core/src/observability/traces.spec.ts @@ -1810,6 +1810,208 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { expect(generationLatency).toBeLessThan(runSeconds); }); + // Tools run in parallel all the time. Summing sibling durations subtracts + // more than the run spent in tools, which drove the generation's remainder to + // zero and left the trace total short of the wall clock. + it("counts overlapping tool spans once when deriving generation latency", async () => { + const byName = new Map(); + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (!event.name.startsWith("$ai_")) return; + const list = byName.get(event.name) ?? []; + list.push(event); + byName.set(event.name, list); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + // Three tools covering the same ~40ms window: summed they are ~120ms, + // which is longer than the run itself. + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + send({ type: "tool_start", id: "b", tool: "search", input: {} }); + send({ type: "tool_start", id: "c", tool: "fetch", input: {} }); + await new Promise((resolve) => setTimeout(resolve, 40)); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + send({ type: "tool_done", id: "b", tool: "search", result: "ok" }); + send({ type: "tool_done", id: "c", tool: "fetch", result: "ok" }); + await new Promise((resolve) => setTimeout(resolve, 30)); + return { + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }; + }, + loopOpts, + runId: "run-overlap", + threadId: "thread-overlap", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const trace = byName.get("$ai_trace")?.[0]; + const generation = byName.get("$ai_generation")?.[0]; + const spans = byName.get("$ai_span") ?? []; + expect(spans).toHaveLength(3); + + const runSeconds = (trace?.properties?.duration_ms as number) / 1000; + const generationLatency = generation?.properties?.["$ai_latency"] as number; + const spanLatencies = spans.map( + (e) => e.properties?.["$ai_latency"] as number, + ); + const summedSpans = spanLatencies.reduce((a, b) => a + b, 0); + + // The premise: naive summing would have over-subtracted. + expect(summedSpans).toBeGreaterThan(runSeconds); + // Only the ~30ms tail was outside the tool window, and it survives. + expect(generationLatency).toBeGreaterThan(0.01); + expect(generationLatency).toBeLessThanOrEqual(runSeconds); + }); + + // Tool time is only subtracted from the generation because sibling `$ai_span` + // events carry it. When those events are not emitted, nothing else holds the + // run's tool time and the generation has to keep it. + it("keeps full generation latency when tool spans are not exported", async () => { + const byName = new Map(); + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (!event.name.startsWith("$ai_")) return; + const list = byName.get(event.name) ?? []; + list.push(event); + byName.set(event.name, list); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + await new Promise((resolve) => setTimeout(resolve, 30)); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + return { + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }; + }, + loopOpts, + runId: "run-no-span-latency", + threadId: "thread-no-span-latency", + userId: null, + config: { + ...DEFAULT_OBSERVABILITY_CONFIG, + enabled: true, + captureLlmSpans: false, + }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const trace = byName.get("$ai_trace")?.[0]; + const generation = byName.get("$ai_generation")?.[0]; + expect(byName.get("$ai_span") ?? []).toHaveLength(0); + + const runSeconds = (trace?.properties?.duration_ms as number) / 1000; + const generationLatency = generation?.properties?.["$ai_latency"] as number; + // The generation is the trace's only child, so it carries the whole run. + expect(generationLatency).toBeCloseTo(runSeconds, 3); + }); + + // PostHog plots a span from its event timestamp forward by `$ai_latency`. A + // span stamped at completion therefore drew the tool starting where it ended + // and running past the end of the run that contains it. + it("timestamps a tool span at its start, not its completion", async () => { + const byName = new Map(); + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (!event.name.startsWith("$ai_")) return; + const list = byName.get(event.name) ?? []; + list.push(event); + byName.set(event.name, list); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + await new Promise((resolve) => setTimeout(resolve, 40)); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + return { + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }; + }, + loopOpts, + runId: "run-span-timestamp", + threadId: "thread-span-timestamp", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const trace = byName.get("$ai_trace")?.[0]; + const span = byName.get("$ai_span")?.[0]; + expect(span).toBeDefined(); + + // The trace is stamped at run start; every child has to fit inside it. + const runStartMs = Date.parse(trace!.timestamp); + const runEndMs = runStartMs + (trace!.properties?.duration_ms as number); + const spanStartMs = Date.parse(span!.timestamp); + const spanEndMs = + spanStartMs + (span!.properties?.["$ai_latency"] as number) * 1000; + + expect(spanStartMs).toBeGreaterThanOrEqual(runStartMs); + expect(spanEndMs).toBeLessThanOrEqual(runEndMs); + }); + // `$ai_time_to_first_token` is a SECONDS field. It was being handed the // millisecond value verbatim, inflating every TTFT in LLM analytics 1000x. it("reports $ai_time_to_first_token in seconds while keeping the ms property", async () => { diff --git a/packages/core/src/observability/traces.ts b/packages/core/src/observability/traces.ts index 6e6c4957dd..9b16dee307 100644 --- a/packages/core/src/observability/traces.ts +++ b/packages/core/src/observability/traces.ts @@ -39,6 +39,35 @@ function costUsdFromCenticents(value: number): number { return Math.round((value / 10_000) * 1_000_000) / 1_000_000; } +/** + * Wall-clock time covered by these spans, counting overlap once. + * + * Tools run concurrently, so summing durations reports more time in tools than + * the run actually spent there — enough to drive the generation's remainder to + * zero on a parallel fan-out. + */ +function coveredDurationMs(spans: TraceSpan[]): number { + if (spans.length === 0) return 0; + const intervals = spans + .map((s) => { + const start = s.createdAt; + return { start, end: start + Math.max(0, s.durationMs) }; + }) + .sort((a, b) => a.start - b.start); + let covered = 0; + let { start: openStart, end: openEnd } = intervals[0]; + for (const { start, end } of intervals.slice(1)) { + if (start > openEnd) { + covered += openEnd - openStart; + openStart = start; + openEnd = end; + } else if (end > openEnd) { + openEnd = end; + } + } + return covered + (openEnd - openStart); +} + /** * Project run metadata onto flat PostHog trace properties. * @@ -878,7 +907,10 @@ export async function instrumentAgentLoop(opts: { status: isError ? "error" : "success", errorMessage: isError ? event.result : null, metadata: spanMetadata, - createdAt: Date.now(), + // The span's start, not its completion: `durationMs` is measured from + // here, so stamping the end instead places the tool after the run + // ended in any timeline that plots start + duration. + createdAt: pending?.startMs ?? finishedAt, }; spans.push(span); } @@ -970,7 +1002,7 @@ export async function instrumentAgentLoop(opts: { status: "error", errorMessage: interruptedMessage, metadata: null, - createdAt: runEnd, + createdAt: pending.startMs, }); } pendingTools.clear(); @@ -1010,6 +1042,21 @@ export async function instrumentAgentLoop(opts: { } : undefined); + const collectedToolSpans = spans.filter( + (s) => s.spanType === "tool_call", + ); + // Resolved before the generation event, not just before the span events: + // the generation's latency is the run minus the tool time PostHog will + // actually see, so it has to be computed against the same set. Tools + // dropped by `captureLlmSpans` or the per-run cap have no sibling span to + // hold their time, and subtracting them would lose it from the trace. + const emittedToolSpans = ( + config.captureLlmSpans ? collectedToolSpans : [] + ).slice(0, MAX_AI_SPANS_PER_RUN); + const droppedToolSpans = + (config.captureLlmSpans ? collectedToolSpans.length : 0) - + emittedToolSpans.length; + let llmCallCount = 0; if (usage || runStatus === "error") { llmCallCount = @@ -1035,18 +1082,15 @@ export async function instrumentAgentLoop(opts: { ? Math.max(0, usage.firstEngineEventAtMs - runStart) : undefined; const llmSpanId = spanId(); - const generationToolSpans = spans.filter( - (s) => s.spanType === "tool_call", - ); + const generationToolSpans = collectedToolSpans; // Tool calls are emitted as sibling `$ai_span`s under the same trace, - // and PostHog adds their latency to this generation's. Subtracting - // their duration keeps the trace total equal to the run, not to the - // run plus its tools counted a second time. Clamped at 0 because tool - // spans are timed independently and can overlap. + // and PostHog adds their latency to this generation's. Subtracting the + // time those siblings cover keeps the trace total equal to the run, not + // to the run plus its tools counted a second time. Clamped at 0 because + // tool spans are timed independently of the run window. const llmDurationMs = Math.max( 0, - totalDurationMs - - generationToolSpans.reduce((sum, s) => sum + s.durationMs, 0), + totalDurationMs - coveredDurationMs(emittedToolSpans), ); const generationContent = buildGenerationContent({ config, @@ -1169,12 +1213,6 @@ export async function instrumentAgentLoop(opts: { usage?.model ?? loopOpts.model, ); - const toolSpans = config.captureLlmSpans - ? spans.filter((s) => s.spanType === "tool_call") - : []; - const emittedToolSpans = toolSpans.slice(0, MAX_AI_SPANS_PER_RUN); - const droppedToolSpans = toolSpans.length - emittedToolSpans.length; - // PostHog reads a trace's input/output state ONLY from the `$ai_trace` // event — never from its children — so a trace whose detail view should // show what the run was asked and what it answered has to carry them From 789094f094b34b8d3d39cd37e9854c5a39b3cd2b Mon Sep 17 00:00:00 2001 From: Manu MA Date: Sun, 23 Aug 2026 19:59:19 +0200 Subject: [PATCH 4/6] fix: measure generation latency instead of inferring it from tool time The generation's `$ai_latency` was the run duration with tool time backed out of it. That subtraction is why the last three defects existed: it had to net out overlapping tools, skip tools the export path drops, and clamp at zero when the estimate went negative. Each of those is a special case on an inference, and the inference was never necessary. `production-agent.ts` already brackets every LLM round-trip with a `model_stream` start/end pair, and that bracket closes before any tool of the turn is started, so the two windows cannot overlap. `instrumentedSend` already received those events and dropped them. Recording them makes model time a measurement. The subtraction stays as a fallback for engines that never bracket their model calls, and `latency_source` marks which of the two a latency came from, so an estimate is never read as a measurement. Also drops the assumption that a trace's children must sum to its wall clock. Two tools sharing one 40ms window really are 80ms of work, and reporting each one honestly is worth more than a sum that flatters the total; elapsed time is what the trace's own `duration_ms` is for. --- .changeset/posthog-ai-observability-fixes.md | 2 +- .../core/src/observability/traces.spec.ts | 144 ++++++++++++++++++ packages/core/src/observability/traces.ts | 105 +++++++++---- 3 files changed, 224 insertions(+), 27 deletions(-) diff --git a/.changeset/posthog-ai-observability-fixes.md b/.changeset/posthog-ai-observability-fixes.md index 551d571fbf..7c819856e1 100644 --- a/.changeset/posthog-ai-observability-fixes.md +++ b/.changeset/posthog-ai-observability-fixes.md @@ -6,7 +6,7 @@ Fix PostHog LLM analytics events so trace, span, and generation metrics match Po - `$ai_time_to_first_token` is now sent in seconds. It was being handed the millisecond value verbatim, inflating every time-to-first-token in LLM analytics 1000x. - The `$ai_trace` event no longer carries `$ai_latency`, `$ai_input_tokens`, `$ai_output_tokens`, or `$ai_total_cost_usd`. PostHog derives all four from a trace's children, and summed the trace's own `$ai_latency` alongside them — reporting roughly twice the real run duration. The run totals now ride along as `duration_ms`, `input_tokens`, `output_tokens`, and `cost_usd` for backends that do no such aggregation. -- The generation's `$ai_latency` is now model time (run duration minus tool time) instead of the whole run, so tool duration is no longer counted both in the generation and in its sibling tool spans. Concurrent tools count their overlapping window once, and tools that `captureLlmSpans` or the per-run span cap keeps out of PostHog are not subtracted at all — nothing else would carry their time. +- The generation's `$ai_latency` is measured model time rather than the whole run, so tool duration is no longer counted both in the generation and in its sibling tool spans. It is read from the `model_stream` start/end brackets the agent loop already emits once per LLM round-trip, which close before any tool of that turn starts. Engines that do not bracket their model calls fall back to backing tool time out of the run duration — counting overlapping tools once, and leaving in the time of tools that `captureLlmSpans` or the per-run span cap keeps out of PostHog, since no sibling span would carry it. The new `latency_source` property records which of the two produced a given `$ai_latency`. - A tool `$ai_span` is timestamped at the tool's start rather than its completion. PostHog draws a span forward from its event timestamp by `$ai_latency`, so a completion-stamped span rendered the tool beginning where it ended and running past the end of its own trace. - `$ai_request_count` reports the run's real LLM round-trip count instead of a hardcoded `1`, which undercharged multi-step runs on request-priced models. - `$ai_trace` now carries `$ai_input_state` / `$ai_output_state` when `capturePrompts` is on. PostHog reads a trace's input and output only from that event, so the trace detail view was empty. diff --git a/packages/core/src/observability/traces.spec.ts b/packages/core/src/observability/traces.spec.ts index d52e7b9aa7..b0e70fd6d4 100644 --- a/packages/core/src/observability/traces.spec.ts +++ b/packages/core/src/observability/traces.spec.ts @@ -1810,6 +1810,150 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { expect(generationLatency).toBeLessThan(runSeconds); }); + // The engine already brackets each LLM round-trip with `model_stream` + // start/end, and that bracket closes before any tool of the turn starts. When + // it is present the generation's latency is measured, so none of the + // subtraction machinery below applies — overlapping tools cannot distort it. + it("measures generation latency from model_stream brackets when present", async () => { + const byName = new Map(); + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (!event.name.startsWith("$ai_")) return; + const list = byName.get(event.name) ?? []; + list.push(event); + byName.set(event.name, list); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + // Two round-trips of ~20ms each, with a ~40ms parallel tool fan-out in + // between. Model time is ~40ms; the run is ~80ms. + send({ type: "model_stream", status: "start" }); + await new Promise((resolve) => setTimeout(resolve, 20)); + send({ type: "model_stream", status: "end" }); + + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + send({ type: "tool_start", id: "b", tool: "search", input: {} }); + await new Promise((resolve) => setTimeout(resolve, 40)); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + send({ type: "tool_done", id: "b", tool: "search", result: "ok" }); + + send({ type: "model_stream", status: "start" }); + await new Promise((resolve) => setTimeout(resolve, 20)); + send({ type: "model_stream", status: "end" }); + return { + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + llmCalls: 2, + }; + }, + loopOpts, + runId: "run-measured", + threadId: "thread-measured", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + const trace = byName.get("$ai_trace")?.[0]; + const generation = byName.get("$ai_generation")?.[0]; + const spans = byName.get("$ai_span") ?? []; + expect(spans).toHaveLength(2); + + expect(generation?.properties?.latency_source).toBe("measured"); + const generationLatency = generation?.properties?.["$ai_latency"] as number; + const runSeconds = (trace?.properties?.duration_ms as number) / 1000; + + // The two brackets, and neither of the tool windows between them. + expect(generationLatency).toBeGreaterThan(0.03); + expect(generationLatency).toBeLessThan(0.06); + + // Each tool reports its own real duration, so two tools sharing one 40ms + // window contribute ~80ms of work to a ~80ms run. Summed children exceeding + // the wall clock is the honest result of concurrency, not an error: the + // trace's own `duration_ms` is what reports elapsed time, and the waterfall + // places each span by its timestamp. Shrinking the generation to force the + // sum down would only trade a true number for a flattering one. + const spanLatencies = spans.map( + (e) => e.properties?.["$ai_latency"] as number, + ); + for (const latency of spanLatencies) { + expect(latency).toBeGreaterThan(0.03); + } + expect(runSeconds).toBeGreaterThan(0.06); + }); + + // The fallback still has to exist for engines that never bracket their model + // calls, but a latency built on it must not be mistaken for a measured one. + it("labels a derived latency when the engine emits no model_stream", async () => { + const byName = new Map(); + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + if (!event.name.startsWith("$ai_")) return; + const list = byName.get(event.name) ?? []; + list.push(event); + byName.set(event.name, list); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + send({ type: "tool_start", id: "a", tool: "read", input: {} }); + await new Promise((resolve) => setTimeout(resolve, 20)); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + return { + inputTokens: 10, + outputTokens: 5, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + usageReported: true, + }; + }, + loopOpts, + runId: "run-derived", + threadId: "thread-derived", + userId: null, + config: { ...DEFAULT_OBSERVABILITY_CONFIG, enabled: true }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect(byName.get("$ai_generation")?.[0]?.properties?.latency_source).toBe( + "derived", + ); + }); + // Tools run in parallel all the time. Summing sibling durations subtracts // more than the run spent in tools, which drove the generation's remainder to // zero and left the trace total short of the wall clock. diff --git a/packages/core/src/observability/traces.ts b/packages/core/src/observability/traces.ts index 9b16dee307..9b0dfaaff4 100644 --- a/packages/core/src/observability/traces.ts +++ b/packages/core/src/observability/traces.ts @@ -39,24 +39,24 @@ function costUsdFromCenticents(value: number): number { return Math.round((value / 10_000) * 1_000_000) / 1_000_000; } +interface TimeInterval { + start: number; + end: number; +} + /** - * Wall-clock time covered by these spans, counting overlap once. + * Wall-clock time covered by these intervals, counting overlap once. * - * Tools run concurrently, so summing durations reports more time in tools than - * the run actually spent there — enough to drive the generation's remainder to - * zero on a parallel fan-out. + * Tools run concurrently, so summing durations reports more elapsed time than + * actually passed — enough to drive a derived remainder to zero on a parallel + * fan-out. */ -function coveredDurationMs(spans: TraceSpan[]): number { - if (spans.length === 0) return 0; - const intervals = spans - .map((s) => { - const start = s.createdAt; - return { start, end: start + Math.max(0, s.durationMs) }; - }) - .sort((a, b) => a.start - b.start); +function coveredDurationMs(intervals: TimeInterval[]): number { + if (intervals.length === 0) return 0; + const sorted = [...intervals].sort((a, b) => a.start - b.start); let covered = 0; - let { start: openStart, end: openEnd } = intervals[0]; - for (const { start, end } of intervals.slice(1)) { + let { start: openStart, end: openEnd } = sorted[0]; + for (const { start, end } of sorted.slice(1)) { if (start > openEnd) { covered += openEnd - openStart; openStart = start; @@ -68,6 +68,13 @@ function coveredDurationMs(spans: TraceSpan[]): number { return covered + (openEnd - openStart); } +function spanIntervals(spans: TraceSpan[]): TimeInterval[] { + return spans.map((s) => ({ + start: s.createdAt, + end: s.createdAt + Math.max(0, s.durationMs), + })); +} + /** * Project run metadata onto flat PostHog trace properties. * @@ -171,9 +178,8 @@ function emitLlmGenerationTrackingEvent(args: { costCentsX100: number | undefined; durationMs: number; /** - * Wall-clock ms spent in the model: the run duration with tool-execution - * time removed. This is what `$ai_latency` reports, and it is deliberately - * NOT `durationMs`. + * Wall-clock ms spent in the model. This is what `$ai_latency` reports, and + * it is deliberately NOT `durationMs`. * * PostHog sums `$ai_latency` across a trace's direct children, and every * tool call is emitted as one of those children. Reporting the full run @@ -181,6 +187,10 @@ function emitLlmGenerationTrackingEvent(args: { * than the run it describes. */ llmDurationMs: number; + /** False when `llmDurationMs` was derived by subtracting tool time from the + * run because the engine never bracketed its model calls. Emitted so a + * latency built on that estimate can be told apart from a measured one. */ + llmDurationMeasured: boolean; /** LLM round-trips in the run. Feeds `$ai_request_count`, which PostHog * multiplies by per-request pricing — a hardcoded 1 undercharged every * multi-step run on a request-priced model. */ @@ -314,6 +324,7 @@ function emitLlmGenerationTrackingEvent(args: { $ai_tools: args.aiTools, input_truncated: args.aiInputTruncated || undefined, output_truncated: args.aiOutputTruncated || undefined, + latency_source: args.llmDurationMeasured ? "measured" : "derived", // Seconds, per PostHog's schema — `time_to_first_token_ms` above is the // millisecond field this framework's own dashboards read. $ai_time_to_first_token: @@ -654,6 +665,14 @@ export async function instrumentAgentLoop(opts: { let successfulTools = 0; let failedTools = 0; + // One `model_stream` start/end bracket is emitted per LLM round-trip, and it + // closes before any tool of that turn is started — so these intervals ARE the + // model's wall clock, not an estimate of it. Recording them is what lets the + // generation report a measured `$ai_latency` instead of backing tool time out + // of the run duration. + const modelStreamIntervals: TimeInterval[] = []; + let modelStreamOpenedAt: number | null = null; + // Track in-flight OTel tool spans so they're all ended even if the loop // throws before a matching `tool_done` arrives. const openOtelToolSpans = new Set(); @@ -734,6 +753,20 @@ export async function instrumentAgentLoop(opts: { runStatus = "error"; errorMessage = "Missing API key"; } + if (event.type === "model_stream") { + // The emitter brackets these itself, so a repeated start or an + // unmatched end is a no-op here rather than a fabricated interval. + if (event.status === "start") { + modelStreamOpenedAt ??= Date.now(); + } else if (modelStreamOpenedAt !== null) { + modelStreamIntervals.push({ + start: modelStreamOpenedAt, + end: Date.now(), + }); + modelStreamOpenedAt = null; + } + } + if (event.type === "tool_start") { const counter = toolInvocationCounter++; const sid = spanId(); @@ -951,6 +984,20 @@ export async function instrumentAgentLoop(opts: { const runEnd = Date.now(); const totalDurationMs = runEnd - runStart; + // The loop threw or was killed mid-stream, so no `end` ever arrived. The + // model was still running when the run stopped, so the interval closes at + // the run's end rather than being dropped. + if (modelStreamOpenedAt !== null) { + modelStreamIntervals.push({ start: modelStreamOpenedAt, end: runEnd }); + modelStreamOpenedAt = null; + } + // Undefined means the engine never bracketed its model calls, NOT that + // the model took no time — the two must stay distinguishable, because + // only the first may fall back to backing tool time out of the run. + const measuredModelDurationMs = modelStreamIntervals.length + ? coveredDurationMs(modelStreamIntervals) + : undefined; + if (pendingTools.size > 0) { if (runStatus === "success") { runStatus = "error"; @@ -1083,15 +1130,20 @@ export async function instrumentAgentLoop(opts: { : undefined; const llmSpanId = spanId(); const generationToolSpans = collectedToolSpans; - // Tool calls are emitted as sibling `$ai_span`s under the same trace, - // and PostHog adds their latency to this generation's. Subtracting the - // time those siblings cover keeps the trace total equal to the run, not - // to the run plus its tools counted a second time. Clamped at 0 because - // tool spans are timed independently of the run window. - const llmDurationMs = Math.max( - 0, - totalDurationMs - coveredDurationMs(emittedToolSpans), - ); + // Measured model time when the engine bracketed its round-trips. + // + // The fallback backs tool time out of the run instead, which is an + // estimate and behaves like one: it has to net out overlapping tools, + // skip tools PostHog will not receive, and clamp at zero. Engines that + // report `model_stream` need none of that, so `latency_source` records + // which of the two a given `$ai_latency` came from. + const llmDurationMs = + measuredModelDurationMs ?? + Math.max( + 0, + totalDurationMs - + coveredDurationMs(spanIntervals(emittedToolSpans)), + ); const generationContent = buildGenerationContent({ config, messages: loopOpts.messages, @@ -1143,6 +1195,7 @@ export async function instrumentAgentLoop(opts: { costCentsX100: usageReported ? costCentsX100 : undefined, durationMs: totalDurationMs, llmDurationMs, + llmDurationMeasured: measuredModelDurationMs !== undefined, llmCallCount, firstTokenMs, status: runStatus, From cc758df092e8bd46a2d5d75d5c2752b672e58769 Mon Sep 17 00:00:00 2001 From: Manu MA Date: Sun, 23 Aug 2026 20:29:49 +0200 Subject: [PATCH 5/6] test: drive the latency assertions from a manual clock MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The trace timing tests slept for real and asserted on the elapsed result, so they were measuring the scheduler as much as the code. On a loaded CI runner a 20ms sleep stretched past 200ms and two of them failed: a measured latency came back 0.234s against a `< 0.06` bound, and the overlap test's premise (summed tool spans exceed the run) stopped holding once the run outgrew the tool window. Replaces every sleep in those tests with a hand-advanced `Date.now`. Nothing waits, so the arithmetic under test is the only variable left, and the assertions tighten from ranges to exact values — 40ms of model time in an 80ms run, three 40ms tools covering one 40ms window, a span starting exactly where its trace does. The clock is restored in `afterEach` so a failing assertion cannot leak it into the rest of the file. All five still fail against the pre-fix code, now with exact diffs. --- .../core/src/observability/traces.spec.ts | 122 ++++++++++++------ 1 file changed, 81 insertions(+), 41 deletions(-) diff --git a/packages/core/src/observability/traces.spec.ts b/packages/core/src/observability/traces.spec.ts index b0e70fd6d4..7e41807c19 100644 --- a/packages/core/src/observability/traces.spec.ts +++ b/packages/core/src/observability/traces.spec.ts @@ -183,8 +183,39 @@ function createRecordingTracer() { return { tracer, spans }; } +/** + * A hand-advanced `Date.now`. + * + * The latency tests below are about arithmetic on timestamps — which interval + * gets subtracted, which one is measured, where a span is stamped. Sleeping for + * real makes that arithmetic race the scheduler, and a loaded CI runner stretches + * a 20ms sleep into a 200ms one, so the assertions have to be either exact and + * deterministic or loose enough to stop testing anything. This buys the first. + */ +function manualClock(startMs = 1_700_000_000_000) { + const realNow = Date.now; + let now = startMs; + Date.now = () => now; + const clock = { + advance(ms: number) { + now += ms; + }, + restore() { + Date.now = realNow; + }, + }; + activeClock = clock; + return clock; +} + +let activeClock: { restore: () => void } | null = null; + describe("instrumentAgentLoop OpenTelemetry export", () => { afterEach(() => { + // Restored here rather than in each test so a failing assertion cannot + // leak the patched clock into the rest of the file. + activeClock?.restore(); + activeClock = null; __resetAgentTracerCache(); unregisterTrackingProvider("qa-ai-generation"); }); @@ -1740,6 +1771,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { // itself is. Emitting it there reported roughly twice the real duration, and // a generation claiming the whole run counted tool time a second time. it("reports trace latency through children only, with tool time removed from the generation", async () => { + const clock = manualClock(); const byName = new Map(); registerTrackingProvider({ name: "qa-ai-generation", @@ -1765,9 +1797,9 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { await instrumentAgentLoop({ runAgentLoop: async ({ send }) => { send({ type: "tool_start", id: "a", tool: "read", input: {} }); - await new Promise((resolve) => setTimeout(resolve, 20)); + clock.advance(20); send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); - await new Promise((resolve) => setTimeout(resolve, 5)); + clock.advance(5); return { inputTokens: 10, outputTokens: 5, @@ -1798,16 +1830,15 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { // ...but the run duration is still recorded for the other backends. expect(trace?.properties?.duration_ms).toEqual(expect.any(Number)); - // What PostHog will sum: the generation plus its sibling tool spans. + // What PostHog will sum: the generation plus its sibling tool spans. One + // 20ms tool inside a 25ms run, so the children account for the run exactly + // once. Before this the generation also claimed the full 25ms. const spanLatency = span?.properties?.["$ai_latency"] as number; const generationLatency = generation?.properties?.["$ai_latency"] as number; - const summed = generationLatency + spanLatency; const runSeconds = (trace?.properties?.duration_ms as number) / 1000; - expect(spanLatency).toBeGreaterThan(0); - expect(summed).toBeLessThanOrEqual(runSeconds + 0.01); - // The generation is model time only, so it cannot span the whole run once - // a tool has taken a measurable slice of it. - expect(generationLatency).toBeLessThan(runSeconds); + expect(runSeconds).toBe(0.025); + expect(spanLatency).toBe(0.02); + expect(generationLatency).toBe(0.005); }); // The engine already brackets each LLM round-trip with `model_stream` @@ -1815,6 +1846,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { // it is present the generation's latency is measured, so none of the // subtraction machinery below applies — overlapping tools cannot distort it. it("measures generation latency from model_stream brackets when present", async () => { + const clock = manualClock(); const byName = new Map(); registerTrackingProvider({ name: "qa-ai-generation", @@ -1842,17 +1874,17 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { // Two round-trips of ~20ms each, with a ~40ms parallel tool fan-out in // between. Model time is ~40ms; the run is ~80ms. send({ type: "model_stream", status: "start" }); - await new Promise((resolve) => setTimeout(resolve, 20)); + clock.advance(20); send({ type: "model_stream", status: "end" }); send({ type: "tool_start", id: "a", tool: "read", input: {} }); send({ type: "tool_start", id: "b", tool: "search", input: {} }); - await new Promise((resolve) => setTimeout(resolve, 40)); + clock.advance(40); send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); send({ type: "tool_done", id: "b", tool: "search", result: "ok" }); send({ type: "model_stream", status: "start" }); - await new Promise((resolve) => setTimeout(resolve, 20)); + clock.advance(20); send({ type: "model_stream", status: "end" }); return { inputTokens: 10, @@ -1882,9 +1914,10 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { const generationLatency = generation?.properties?.["$ai_latency"] as number; const runSeconds = (trace?.properties?.duration_ms as number) / 1000; - // The two brackets, and neither of the tool windows between them. - expect(generationLatency).toBeGreaterThan(0.03); - expect(generationLatency).toBeLessThan(0.06); + // Exactly the two 20ms brackets, and none of the 40ms tool window between + // them. Under the old subtraction this run reported 80 - 80 = 0. + expect(generationLatency).toBe(0.04); + expect(runSeconds).toBe(0.08); // Each tool reports its own real duration, so two tools sharing one 40ms // window contribute ~80ms of work to a ~80ms run. Summed children exceeding @@ -1892,18 +1925,15 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { // trace's own `duration_ms` is what reports elapsed time, and the waterfall // places each span by its timestamp. Shrinking the generation to force the // sum down would only trade a true number for a flattering one. - const spanLatencies = spans.map( - (e) => e.properties?.["$ai_latency"] as number, - ); - for (const latency of spanLatencies) { - expect(latency).toBeGreaterThan(0.03); - } - expect(runSeconds).toBeGreaterThan(0.06); + expect(spans.map((e) => e.properties?.["$ai_latency"] as number)).toEqual([ + 0.04, 0.04, + ]); }); // The fallback still has to exist for engines that never bracket their model // calls, but a latency built on it must not be mistaken for a measured one. it("labels a derived latency when the engine emits no model_stream", async () => { + const clock = manualClock(); const byName = new Map(); registerTrackingProvider({ name: "qa-ai-generation", @@ -1929,7 +1959,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { await instrumentAgentLoop({ runAgentLoop: async ({ send }) => { send({ type: "tool_start", id: "a", tool: "read", input: {} }); - await new Promise((resolve) => setTimeout(resolve, 20)); + clock.advance(20); send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); return { inputTokens: 10, @@ -1958,6 +1988,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { // more than the run spent in tools, which drove the generation's remainder to // zero and left the trace total short of the wall clock. it("counts overlapping tool spans once when deriving generation latency", async () => { + const clock = manualClock(); const byName = new Map(); registerTrackingProvider({ name: "qa-ai-generation", @@ -1987,11 +2018,11 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { send({ type: "tool_start", id: "a", tool: "read", input: {} }); send({ type: "tool_start", id: "b", tool: "search", input: {} }); send({ type: "tool_start", id: "c", tool: "fetch", input: {} }); - await new Promise((resolve) => setTimeout(resolve, 40)); + clock.advance(40); send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); send({ type: "tool_done", id: "b", tool: "search", result: "ok" }); send({ type: "tool_done", id: "c", tool: "fetch", result: "ok" }); - await new Promise((resolve) => setTimeout(resolve, 30)); + clock.advance(30); return { inputTokens: 10, outputTokens: 5, @@ -2017,22 +2048,25 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { const runSeconds = (trace?.properties?.duration_ms as number) / 1000; const generationLatency = generation?.properties?.["$ai_latency"] as number; - const spanLatencies = spans.map( - (e) => e.properties?.["$ai_latency"] as number, + const summedSpans = spans.reduce( + (sum, e) => sum + (e.properties?.["$ai_latency"] as number), + 0, ); - const summedSpans = spanLatencies.reduce((a, b) => a + b, 0); - // The premise: naive summing would have over-subtracted. - expect(summedSpans).toBeGreaterThan(runSeconds); - // Only the ~30ms tail was outside the tool window, and it survives. - expect(generationLatency).toBeGreaterThan(0.01); - expect(generationLatency).toBeLessThanOrEqual(runSeconds); + // Three tools share one 40ms window inside a 70ms run, so the premise + // holds: summing their durations claims 120ms of a 70ms run, and the old + // code subtracted all of it and clamped the generation to zero. + expect(runSeconds).toBe(0.07); + expect(summedSpans).toBe(0.12); + // Counting the shared window once leaves exactly the 30ms tail. + expect(generationLatency).toBe(0.03); }); // Tool time is only subtracted from the generation because sibling `$ai_span` // events carry it. When those events are not emitted, nothing else holds the // run's tool time and the generation has to keep it. it("keeps full generation latency when tool spans are not exported", async () => { + const clock = manualClock(); const byName = new Map(); registerTrackingProvider({ name: "qa-ai-generation", @@ -2058,7 +2092,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { await instrumentAgentLoop({ runAgentLoop: async ({ send }) => { send({ type: "tool_start", id: "a", tool: "read", input: {} }); - await new Promise((resolve) => setTimeout(resolve, 30)); + clock.advance(30); send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); return { inputTokens: 10, @@ -2088,14 +2122,17 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { const runSeconds = (trace?.properties?.duration_ms as number) / 1000; const generationLatency = generation?.properties?.["$ai_latency"] as number; - // The generation is the trace's only child, so it carries the whole run. - expect(generationLatency).toBeCloseTo(runSeconds, 3); + // The generation is the trace's only child, so it carries the whole run + // rather than losing the 30ms of tool time nothing else reports. + expect(runSeconds).toBe(0.03); + expect(generationLatency).toBe(0.03); }); // PostHog plots a span from its event timestamp forward by `$ai_latency`. A // span stamped at completion therefore drew the tool starting where it ended // and running past the end of the run that contains it. it("timestamps a tool span at its start, not its completion", async () => { + const clock = manualClock(); const byName = new Map(); registerTrackingProvider({ name: "qa-ai-generation", @@ -2121,7 +2158,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { await instrumentAgentLoop({ runAgentLoop: async ({ send }) => { send({ type: "tool_start", id: "a", tool: "read", input: {} }); - await new Promise((resolve) => setTimeout(resolve, 40)); + clock.advance(40); send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); return { inputTokens: 10, @@ -2145,15 +2182,17 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { const span = byName.get("$ai_span")?.[0]; expect(span).toBeDefined(); - // The trace is stamped at run start; every child has to fit inside it. + // The trace is stamped at run start; the tool ran for the whole 40ms of it, + // so the span starts exactly where the trace does. Stamped at completion it + // started at the run's end and ran 40ms past it. const runStartMs = Date.parse(trace!.timestamp); const runEndMs = runStartMs + (trace!.properties?.duration_ms as number); const spanStartMs = Date.parse(span!.timestamp); const spanEndMs = spanStartMs + (span!.properties?.["$ai_latency"] as number) * 1000; - expect(spanStartMs).toBeGreaterThanOrEqual(runStartMs); - expect(spanEndMs).toBeLessThanOrEqual(runEndMs); + expect(spanStartMs).toBe(runStartMs); + expect(spanEndMs).toBe(runEndMs); }); // `$ai_time_to_first_token` is a SECONDS field. It was being handed the @@ -2376,6 +2415,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { // Every event in a run is emitted in one burst at the end. Stamping them all // with the flush time collapses the trace tree's timeline into an instant. it("stamps each AI event with when it happened, not when the run flushed", async () => { + const clock = manualClock(); const events: TrackingEvent[] = []; registerTrackingProvider({ name: "qa-ai-generation", @@ -2398,7 +2438,7 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { const startedAt = Date.now(); await instrumentAgentLoop({ runAgentLoop: async ({ send }) => { - await new Promise((resolve) => setTimeout(resolve, 30)); + clock.advance(30); send({ type: "tool_start", id: "a", tool: "read", input: {} }); send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); return { From b6873aafb493401b8c4f95d338a3874be02eb5f1 Mon Sep 17 00:00:00 2001 From: Manu MA Date: Sun, 23 Aug 2026 21:11:20 +0200 Subject: [PATCH 6/6] test: pin what captureLlmSpans gates and what it does not MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `captureLlmSpans` decides whether each tool call gets its own `$ai_span` event. Whether a call may carry its arguments is `captureToolArgs`. Review read the first as if it were the second and asked for the generation's tool list to be emptied along with the span events, which would leave a trace showing a model that answered with no sign it called anything. Nothing here changes behavior — both tests pass unmodified against the code from before this branch's latency work. They exist because the contract was only legible by reading two config flags and a nested metadata guard, and that is not a durable way to keep the next reader from "fixing" it. --- .../core/src/observability/traces.spec.ts | 138 ++++++++++++++++++ 1 file changed, 138 insertions(+) diff --git a/packages/core/src/observability/traces.spec.ts b/packages/core/src/observability/traces.spec.ts index 7e41807c19..688a0c002b 100644 --- a/packages/core/src/observability/traces.spec.ts +++ b/packages/core/src/observability/traces.spec.ts @@ -889,6 +889,144 @@ describe("instrumentAgentLoop OpenTelemetry export", () => { expect(events.filter((e) => e.name === "$ai_trace")).toHaveLength(1); }); + // `captureLlmSpans` and `captureToolArgs` gate different things, and review + // has already read the first as if it were the second. `captureLlmSpans` + // decides whether each tool gets its own `$ai_span` event; what a tool call + // is allowed to SAY is `captureToolArgs`. Dropping the generation's tool list + // along with the span events would leave a trace showing a model that + // answered without any sign it called anything. + it("keeps tool calls in the generation when only span emission is off", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + events.push(event); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + send({ + type: "tool_start", + id: "a", + tool: "search", + input: { query: "pricing", apiKey: "sk-should-not-appear" }, + }); + send({ type: "tool_done", id: "a", tool: "search", result: "ok" }); + return { + inputTokens: 1, + outputTokens: 1, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + }; + }, + loopOpts, + runId: "run-spans-off-args-on", + threadId: null, + userId: null, + config: { + ...DEFAULT_OBSERVABILITY_CONFIG, + enabled: true, + captureLlmSpans: false, + captureToolArgs: true, + }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect(events.filter((e) => e.name === "$ai_span")).toHaveLength(0); + + const generation = events.find((e) => e.name === "$ai_generation"); + const choices = generation?.properties?.["$ai_output_choices"] as Array<{ + tool_calls?: Array<{ function: { name: string; arguments?: unknown } }>; + }>; + const call = choices?.[0]?.tool_calls?.[0]; + expect(call?.function.name).toBe("search"); + // Arguments ride on `captureToolArgs`, which is on here — and the span's + // own redaction still applies to them. + expect(call?.function.arguments).toEqual({ + query: "pricing", + apiKey: "[REDACTED]", + }); + }); + + // The other half of the same contract: turning span emission back ON must not + // start exporting arguments that `captureToolArgs` withheld. + it("omits tool arguments when captureToolArgs is off, spans or not", async () => { + const events: TrackingEvent[] = []; + registerTrackingProvider({ + name: "qa-ai-generation", + track(event) { + events.push(event); + }, + }); + + const loopOpts: any = { + engine: { name: "anthropic" }, + model: "claude-test", + systemPrompt: "", + tools: [], + messages: [], + actions: {}, + send: () => {}, + signal: new AbortController().signal, + }; + + await instrumentAgentLoop({ + runAgentLoop: async ({ send }) => { + send({ + type: "tool_start", + id: "a", + tool: "search", + input: { query: "pricing" }, + }); + send({ type: "tool_done", id: "a", tool: "search", result: "ok" }); + return { + inputTokens: 1, + outputTokens: 1, + cacheReadTokens: 0, + cacheWriteTokens: 0, + model: "claude-test", + }; + }, + loopOpts, + runId: "run-spans-on-args-off", + threadId: null, + userId: null, + config: { + ...DEFAULT_OBSERVABILITY_CONFIG, + enabled: true, + captureLlmSpans: true, + captureToolArgs: false, + }, + }); + + await new Promise((resolve) => setTimeout(resolve, 0)); + + expect(events.filter((e) => e.name === "$ai_span")).toHaveLength(1); + + const generation = events.find((e) => e.name === "$ai_generation"); + const choices = generation?.properties?.["$ai_output_choices"] as Array<{ + tool_calls?: Array<{ function: Record }>; + }>; + const call = choices?.[0]?.tool_calls?.[0]; + // The call is still visible — that it happened is not the secret. + expect(call?.function.name).toBe("search"); + expect(call?.function).not.toHaveProperty("arguments"); + }); + it("keeps tool detail in invocation order and pairs parallel calls by id", async () => { const events: TrackingEvent[] = []; registerTrackingProvider({