diff --git a/.agents/skills/observability/SKILL.md b/.agents/skills/observability/SKILL.md index 11dd5bf35e..af85920022 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,32 @@ 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. +- **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 + 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. @@ -310,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 new file mode 100644 index 0000000000..7c819856e1 --- /dev/null +++ b/.changeset/posthog-ai-observability-fixes.md @@ -0,0 +1,16 @@ +--- +"@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 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. +- 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 c2aa836a3f..1f8b767d8a 100644 --- a/packages/core/src/observability/posthog-ai.ts +++ b/packages/core/src/observability/posthog-ai.ts @@ -12,6 +12,18 @@ * 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. + * + * 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 @@ -40,6 +52,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 +60,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 +108,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,20 +145,21 @@ 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, - $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(), }, input.userId, + input.createdAt, ); } @@ -190,12 +206,13 @@ 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(), }, input.userId, + input.createdAt, ); } diff --git a/packages/core/src/observability/traces.spec.ts b/packages/core/src/observability/traces.spec.ts index ef14819345..688a0c002b 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"); }); @@ -858,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({ @@ -1734,4 +1903,918 @@ 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 clock = manualClock(); + 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: {} }); + clock.advance(20); + send({ type: "tool_done", id: "a", tool: "read", result: "ok" }); + clock.advance(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. 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 runSeconds = (trace?.properties?.duration_ms as number) / 1000; + 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` + // 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 clock = manualClock(); + 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" }); + 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: {} }); + 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" }); + clock.advance(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; + + // 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 + // 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. + 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", + 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: {} }); + clock.advance(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. + it("counts overlapping tool spans once when deriving generation latency", async () => { + const clock = manualClock(); + 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: {} }); + 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" }); + clock.advance(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 summedSpans = spans.reduce( + (sum, e) => sum + (e.properties?.["$ai_latency"] as number), + 0, + ); + + // 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", + 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: {} }); + clock.advance(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 + // 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", + 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: {} }); + clock.advance(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; 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).toBe(runStartMs); + expect(spanEndMs).toBe(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 () => { + 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 clock = manualClock(); + 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 }) => { + clock.advance(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")); + }); + // 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 3f607facde..9b0dfaaff4 100644 --- a/packages/core/src/observability/traces.ts +++ b/packages/core/src/observability/traces.ts @@ -39,6 +39,42 @@ 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 intervals, counting overlap once. + * + * 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(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 } = sorted[0]; + for (const { start, end } of sorted.slice(1)) { + if (start > openEnd) { + covered += openEnd - openStart; + openStart = start; + openEnd = end; + } else if (end > openEnd) { + openEnd = end; + } + } + 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. * @@ -141,6 +177,24 @@ 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. 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; + /** 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. */ + 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 +302,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" @@ -258,16 +312,25 @@ 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: 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, + 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: + args.firstTokenMs === undefined + ? undefined + : Math.round(args.firstTokenMs) / 1000, $session_id: args.browserSessionId, }; if (args.experimentAssignments?.length) { @@ -293,6 +356,7 @@ function emitLlmGenerationTrackingEvent(args: { .then(({ track }) => { track("$ai_generation", properties, { userId: args.userId ?? undefined, + occurredAt: args.createdAt, }); }) .catch(() => {}); @@ -330,6 +394,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; @@ -597,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(); @@ -677,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(); @@ -809,6 +899,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,20 +939,11 @@ 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, - createdAt: Date.now(), + metadata: spanMetadata, + // 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); } @@ -879,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"; @@ -930,7 +1049,7 @@ export async function instrumentAgentLoop(opts: { status: "error", errorMessage: interruptedMessage, metadata: null, - createdAt: runEnd, + createdAt: pending.startMs, }); } pendingTools.clear(); @@ -970,6 +1089,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 = @@ -995,12 +1129,27 @@ export async function instrumentAgentLoop(opts: { ? Math.max(0, usage.firstEngineEventAtMs - runStart) : undefined; const llmSpanId = spanId(); + const generationToolSpans = collectedToolSpans; + // 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, tools: loopOpts.tools, assistantText: assistantTextParts.join(""), - toolSpans: spans.filter((s) => s.spanType === "tool_call"), + toolSpans: generationToolSpans, }); const llmSpan: TraceSpan = { id: llmSpanId, @@ -1045,6 +1194,9 @@ export async function instrumentAgentLoop(opts: { : undefined, costCentsX100: usageReported ? costCentsX100 : undefined, durationMs: totalDurationMs, + llmDurationMs, + llmDurationMeasured: measuredModelDurationMs !== undefined, + llmCallCount, firstTokenMs, status: runStatus, errorMessage, @@ -1114,11 +1266,23 @@ 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 + // 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, @@ -1127,7 +1291,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 +1301,8 @@ export async function instrumentAgentLoop(opts: { : undefined, createdAt: runStart, browserSessionId, + inputState: traceInputState, + outputState: traceOutputState, extraProperties: { ...trackingIdentityProperties(), source: "agent_observability", @@ -1150,8 +1316,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, } : {}), }, @@ -1187,10 +1353,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.