Fix PostHog LLM analytics so trace, span and generation metrics match PostHog's schema

.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

.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.

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,14 +52,15 @@ function trackAiEvent(
   name: string,
   properties: Record<string, unknown>,
   userId: string | null,
+  occurredAt: number,
 ): void {
   for (const key of Object.keys(properties)) {
     if (properties[key] === undefined) delete properties[key];
   }
   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,
   );
 }