Skip to content

Commit 717954f

Browse files
committed
Emit PostHog AI observability spans and generations per turn
PostHog's LLM analytics views query the $ai_-prefixed properties and nothing else, so the documented names are not ours to choose: an unprefixed property still arrives on the event but is invisible to every trace, cost, and latency view. $ai_latency is a duration in seconds, while the runtime measures milliseconds throughout. Only ids, enums, and counts leave the process. A tool name and a provider error message are both free text that routinely embed a local path or a prompt excerpt, so each is classified into a fixed enum at the boundary and the original discarded. The trace is deliberately flat: PostHog accepts a trace id as a span's parent, and top-level tool calls are all the turn record exposes.
1 parent 369f8fb commit 717954f

8 files changed

Lines changed: 593 additions & 9 deletions

File tree

docs/TELEMETRY.md

Lines changed: 45 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -6,13 +6,15 @@ includes prompts, code, file contents, or paths.
66

77
## What's collected
88

9-
Three events, each with a small set of properties:
9+
Five events, each with a small set of properties:
1010

1111
| Event | When | Properties |
1212
|---|---|---|
1313
| `cli_start` | Once per used session (see First-run disclosure) | (none beyond common properties) |
1414
| `session_end` | When a TUI session finishes | `status`, `turn_count`, `duration_ms`, `session_mode`, `exit_reason` |
1515
| `inference_turn` | Once per completed turn | `provider_id`, `model_id`, `input_tokens`, `output_tokens`, `cache_read_tokens`, `cache_write_tokens`, `thinking_tokens`, `duration_ms` |
16+
| `$ai_generation` | Once per turn — on completion, and again on a turn that ends in an error | `$ai_trace_id`, `$ai_provider`, `$ai_model`, `$ai_input_tokens`, `$ai_output_tokens`, `$ai_latency`, `$ai_is_error`, `$ai_error`, `cache_read_tokens`, `cache_write_tokens`, `thinking_tokens` |
17+
| `$ai_span` | Once per top-level tool call in a completed turn | `$ai_trace_id`, `$ai_span_id`, `$ai_parent_id`, `$ai_span_name`, `$ai_is_error` |
1618

1719
Common properties attached to every event: a random installation UUID
1820
(`distinct_id`), `session_id`, `service_version`, `os_type`, `os_arch`, and a
@@ -24,12 +26,51 @@ request IP; no location data is collected by the client.
2426
Every event is capped to an explicit property allowlist before it leaves the
2527
process — no other field can ever be attached, even by accident.
2628

27-
`provider_id` is the canonical provider kind resolved by the runtime (e.g.
28-
`openai-compatible`), never the free-text name you gave the provider in
29-
onboarding or settings. `model_id` is the model identifier exactly as
29+
`provider_id` (and its AI-event equivalent `$ai_provider`) is the canonical
30+
provider kind resolved by the runtime (e.g. `openai-compatible`), never the
31+
free-text name you gave the provider in onboarding or settings. `model_id`
32+
(equivalently `$ai_model`) is the model identifier exactly as
3033
configured — it is the one user-entered string that is sent, so do not put
3134
anything identifying in a model name.
3235

36+
## AI observability events
37+
38+
`$ai_generation` and `$ai_span` are the two PostHog AI observability events,
39+
emitted from `src/telemetry/ai-observability.ts`. PostHog's LLM analytics
40+
views query the `$ai_`-prefixed properties and nothing else, which is why
41+
these names are not ours to choose. `$ai_latency` is a duration in **seconds**
42+
as a float, per PostHog's schema — the runtime measures milliseconds and
43+
converts.
44+
45+
The trace is **flat**. Every turn gets one `$ai_trace_id` derived from the
46+
runtime's session id and the turn index; the turn's `$ai_generation` and each
47+
of its `$ai_span`s carry it, and every span's `$ai_parent_id` is that same
48+
trace id rather than another span. PostHog documents `$ai_parent_id` as
49+
accepting either a trace id or a span id, so this is a legal trace, and it is
50+
all the runtime can honestly describe: the turn record only exposes top-level
51+
tool calls. No `$ai_trace` event is emitted — PostHog synthesises the trace
52+
from its children.
53+
54+
`$ai_span_id` is the provider-generated opaque tool call id. It identifies
55+
the call within the trace and carries nothing else.
56+
57+
`$ai_span_name` is one of a fixed enum (`tool_call`, `subagent_call`). The raw
58+
tool name is never sent: an MCP tool name embeds the server identifier it was
59+
configured under, which can be a local path.
60+
61+
`$ai_error` is likewise one of a fixed enum (`rate_limit`, `auth`, `timeout`,
62+
`cancelled`, `inference_failed`). The provider's error message is classified
63+
into one of these and then discarded — a raw message routinely embeds the
64+
request URL, a prompt excerpt, or a file path.
65+
66+
The cache and thinking token counts keep unprefixed names because PostHog does
67+
not publish property names for them in its manual-capture schema; a guessed
68+
`$ai_` name would land as an unread custom property either way.
69+
70+
A turn that is abandoned rather than failed — cancelled mid-approval, or
71+
suspended and never resumed — emits nothing, because the runtime raises no
72+
event for it.
73+
3374
## What's never collected
3475

3576
- Prompts, model output, or any conversation content

src/session/run-sink.test.ts

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -77,6 +77,31 @@ describe("createRunSink", () => {
7777
expect(runSink.getTokenUsage()).toEqual({ input: 1, output: 1, cacheRead: 0, cacheWrite: 0, thinking: 0 });
7878
});
7979

80+
test("reports the in-flight turn to onTurnFailed when a turn errors instead of completing", () => {
81+
const failures: { turnIndex: number; error: string }[] = [];
82+
const completions: number[] = [];
83+
const runSink = createRunSink({
84+
emitter: new EventEmitter(),
85+
hookManager: stubHookManager([]),
86+
onTurnComplete: (ctx) => completions.push(ctx.turnIndex),
87+
onTurnFailed: (info) => failures.push(info),
88+
});
89+
90+
runSink.sink(event("inference.done", {
91+
turn: { role: "assistant", content: [], model: "test", timestamp: 0 },
92+
usage: { input: 1, output: 1, cacheRead: 0, cacheWrite: 0, thinking: 0 },
93+
source: { provider: "test", model: "test" },
94+
}));
95+
runSink.sink(event("inference.error", { error: { message: "429 rate limit" } }));
96+
runSink.sink(event("reactor.error", { error: "reactor gave up" }));
97+
98+
expect(completions).toEqual([0]);
99+
expect(failures).toEqual([
100+
{ turnIndex: 1, error: "429 rate limit" },
101+
{ turnIndex: 1, error: "reactor gave up" },
102+
]);
103+
});
104+
80105
test("seeds the turn count from a resumed session's prior turnsUsed", () => {
81106
const runSink = createRunSink({
82107
emitter: new EventEmitter(),

src/session/run-sink.ts

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,12 @@ export type RunSinkArgs = {
2020
// turn actually ran against, so consumers report per-turn provider/model
2121
// even if the live selection changed mid-run.
2222
onTurnComplete?: (ctx: import("./hooks.js").TurnContext) => void;
23+
// Fired when a turn ends in an error instead of completing. onTurnComplete
24+
// only ever sees turns that produced a full TurnContext, so a consumer
25+
// relying on it alone goes silent exactly when a run goes wrong. The turn
26+
// index is the collector's current count: the in-flight turn is the one
27+
// that would have been recorded next.
28+
onTurnFailed?: (info: { turnIndex: number; error: string }) => void;
2329
// Continues a resumed session's persisted run.json turn count instead of
2430
// restarting the collector at zero.
2531
initialTurnCount?: number;
@@ -81,7 +87,8 @@ export function resolveExecRunStatus(args: {
8187
}
8288

8389
export function createRunSink(args: RunSinkArgs): RunSink {
84-
const { emitter, hookManager, onTurnComplete, initialTurnCount, onTurnBoundarySnapshot } = args;
90+
const { emitter, hookManager, onTurnComplete, onTurnFailed, initialTurnCount, onTurnBoundarySnapshot } =
91+
args;
8592

8693
function hasConfiguredHooks(): boolean {
8794
return hookManager.getStatuses().length > 0;
@@ -131,10 +138,12 @@ export function createRunSink(args: RunSinkArgs): RunSink {
131138
if (event.type === "reactor.error") {
132139
const data = event.data as { error: string };
133140
runError = data.error;
141+
onTurnFailed?.({ turnIndex: turnCollector.getTurnCount(), error: data.error });
134142
}
135143
if (event.type === "inference.error") {
136144
const data = event.data as { error: { message: string } };
137145
runError = data.error.message;
146+
onTurnFailed?.({ turnIndex: turnCollector.getTurnCount(), error: data.error.message });
138147
}
139148
emitter.emit("event", event);
140149
};
Lines changed: 237 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,237 @@
1+
import { describe, expect, test } from "bun:test";
2+
import type { ToolCall, ToolResult } from "@intx/types/runtime";
3+
import type { Telemetry } from "./index.js";
4+
import type { TurnContext } from "../session/hooks.js";
5+
import {
6+
classifyErrorKind,
7+
classifySpanKind,
8+
emitAiObservability,
9+
emitAiTurnFailure,
10+
secondsFromMs,
11+
turnTraceId,
12+
} from "./ai-observability.js";
13+
14+
const SUBAGENT_TOOL_NAME = "task";
15+
const SESSION_ID = "0199-parent-session";
16+
17+
function fakeTelemetry(): { telemetry: Telemetry; captured: { event: string; properties: Record<string, unknown> }[] } {
18+
const captured: { event: string; properties: Record<string, unknown> }[] = [];
19+
const telemetry: Telemetry = {
20+
enabled: true,
21+
capture: (event, properties = {}) => {
22+
captured.push({ event, properties });
23+
},
24+
flush: async () => {},
25+
discard: () => {},
26+
};
27+
return { telemetry, captured };
28+
}
29+
30+
function fakeTurnContext(overrides: Partial<TurnContext> = {}): TurnContext {
31+
const toolCalls: ToolCall[] = [
32+
{
33+
id: "call-1",
34+
name: "read_file",
35+
arguments: { path: "/Users/attacker/secret-project/plan.md" },
36+
},
37+
{
38+
id: "call-2",
39+
name: SUBAGENT_TOOL_NAME,
40+
arguments: { description: "explore", prompt: "find the leaked API key XYZ-SECRET-123" },
41+
},
42+
];
43+
const toolResults: ToolResult[] = [
44+
{ callId: "call-1", content: "file contents: super secret prompt text" },
45+
{ callId: "call-2", content: "sub-agent report containing prompt XYZ-SECRET-123", isError: true },
46+
];
47+
return {
48+
turnIndex: 3,
49+
assistantTurn: {
50+
role: "assistant",
51+
content: [{ type: "text", text: "here is the plan: XYZ-SECRET-123" }],
52+
model: "model-x",
53+
timestamp: 0,
54+
},
55+
toolCalls,
56+
toolResults,
57+
usage: { input: 10, output: 20, cacheRead: 1, cacheWrite: 2, thinking: 3 },
58+
source: { provider: "openai-compatible", model: "model-x" },
59+
durationMs: 4560,
60+
...overrides,
61+
} as TurnContext;
62+
}
63+
64+
const emitOptions = { sessionId: SESSION_ID, subagentToolName: SUBAGENT_TOOL_NAME };
65+
66+
describe("secondsFromMs", () => {
67+
test("converts milliseconds to fractional seconds, the unit PostHog documents", () => {
68+
expect(secondsFromMs(361)).toBe(0.361);
69+
expect(secondsFromMs(4560)).toBe(4.56);
70+
expect(secondsFromMs(0)).toBe(0);
71+
});
72+
});
73+
74+
describe("classifySpanKind", () => {
75+
test("classifies the subagent tool as subagent_call", () => {
76+
expect(classifySpanKind(SUBAGENT_TOOL_NAME, SUBAGENT_TOOL_NAME)).toBe("subagent_call");
77+
});
78+
79+
test("classifies every other tool as tool_call, regardless of name", () => {
80+
expect(classifySpanKind("read_file", SUBAGENT_TOOL_NAME)).toBe("tool_call");
81+
expect(classifySpanKind("mcp__acme__fetch_secret", SUBAGENT_TOOL_NAME)).toBe("tool_call");
82+
});
83+
});
84+
85+
describe("classifyErrorKind", () => {
86+
test("reduces provider messages to fixed reasons", () => {
87+
expect(classifyErrorKind("HTTP 429 rate limit exceeded")).toBe("rate_limit");
88+
expect(classifyErrorKind("401 Unauthorized")).toBe("auth");
89+
expect(classifyErrorKind("request timed out after 60s")).toBe("timeout");
90+
expect(classifyErrorKind("The operation was aborted")).toBe("cancelled");
91+
expect(classifyErrorKind("upstream returned garbage")).toBe("inference_failed");
92+
});
93+
});
94+
95+
describe("turnTraceId", () => {
96+
test("derives from the runtime session id and turn index rather than inventing a random id", () => {
97+
expect(turnTraceId("session-abc", 3)).toBe("session-abc:turn:3");
98+
expect(turnTraceId("session-abc", 3)).toBe(turnTraceId("session-abc", 3));
99+
});
100+
101+
test("a sub-agent turn never collides with the parent turn of the same index", () => {
102+
// Sub-agents run in this same process, so a process-wide scope would make
103+
// these identical and silently merge two unrelated traces.
104+
expect(turnTraceId("parent-session", 3)).not.toBe(turnTraceId("subagent-session", 3));
105+
});
106+
});
107+
108+
describe("emitAiObservability", () => {
109+
test("emits one $ai_generation and one $ai_span per tool call", () => {
110+
const { telemetry, captured } = fakeTelemetry();
111+
112+
emitAiObservability(telemetry, fakeTurnContext(), emitOptions);
113+
114+
expect(captured.length).toBe(3);
115+
expect(captured[0]?.event).toBe("$ai_generation");
116+
expect(captured[1]?.event).toBe("$ai_span");
117+
expect(captured[2]?.event).toBe("$ai_span");
118+
});
119+
120+
test("reports latency in seconds, not milliseconds", () => {
121+
const { telemetry, captured } = fakeTelemetry();
122+
123+
emitAiObservability(telemetry, fakeTurnContext({ durationMs: 361 }), emitOptions);
124+
125+
const generation = captured.find((c) => c.event === "$ai_generation");
126+
expect(generation?.properties.$ai_latency).toBe(0.361);
127+
expect(generation?.properties.$ai_latency).not.toBe(361);
128+
});
129+
130+
test("names every field PostHog's LLM analytics views actually query", () => {
131+
const { telemetry, captured } = fakeTelemetry();
132+
133+
emitAiObservability(telemetry, fakeTurnContext(), emitOptions);
134+
135+
const generation = captured.find((c) => c.event === "$ai_generation");
136+
expect(generation?.properties.$ai_provider).toBe("openai-compatible");
137+
expect(generation?.properties.$ai_model).toBe("model-x");
138+
expect(generation?.properties.$ai_input_tokens).toBe(10);
139+
expect(generation?.properties.$ai_output_tokens).toBe(20);
140+
expect(generation?.properties).not.toHaveProperty("provider_id");
141+
expect(generation?.properties).not.toHaveProperty("input_tokens");
142+
expect(generation?.properties).not.toHaveProperty("duration_ms");
143+
});
144+
145+
test("flat trace: spans parent onto the trace id, not onto each other", () => {
146+
const { telemetry, captured } = fakeTelemetry();
147+
const ctx = fakeTurnContext();
148+
149+
emitAiObservability(telemetry, ctx, emitOptions);
150+
151+
const traceId = turnTraceId(SESSION_ID, ctx.turnIndex);
152+
const generation = captured.find((c) => c.event === "$ai_generation");
153+
const spans = captured.filter((c) => c.event === "$ai_span");
154+
155+
expect(generation?.properties.$ai_trace_id).toBe(traceId);
156+
for (const span of spans) {
157+
expect(span.properties.$ai_trace_id).toBe(traceId);
158+
expect(span.properties.$ai_parent_id).toBe(traceId);
159+
}
160+
expect(spans[0]?.properties.$ai_span_id).toBe("call-1");
161+
expect(spans[1]?.properties.$ai_span_id).toBe("call-2");
162+
});
163+
164+
test("names the span by fixed enum, never the raw tool name", () => {
165+
const { telemetry, captured } = fakeTelemetry();
166+
167+
emitAiObservability(telemetry, fakeTurnContext(), emitOptions);
168+
169+
const spans = captured.filter((c) => c.event === "$ai_span");
170+
expect(spans[0]?.properties.$ai_span_name).toBe("tool_call");
171+
expect(spans[1]?.properties.$ai_span_name).toBe("subagent_call");
172+
for (const span of spans) {
173+
expect(span.properties.$ai_span_name).not.toBe("read_file");
174+
expect(span.properties.$ai_span_name).not.toBe(SUBAGENT_TOOL_NAME);
175+
}
176+
});
177+
178+
test("propagates tool error state onto the span without the result content", () => {
179+
const { telemetry, captured } = fakeTelemetry();
180+
181+
emitAiObservability(telemetry, fakeTurnContext(), emitOptions);
182+
183+
const spans = captured.filter((c) => c.event === "$ai_span");
184+
expect(spans[0]?.properties.$ai_is_error).toBe(false);
185+
expect(spans[1]?.properties.$ai_is_error).toBe(true);
186+
});
187+
188+
test("never leaks prompt text, tool arguments, tool results, or file paths", () => {
189+
const { telemetry, captured } = fakeTelemetry();
190+
191+
emitAiObservability(telemetry, fakeTurnContext(), emitOptions);
192+
193+
const serialized = JSON.stringify(captured);
194+
expect(serialized).not.toContain("secret-project");
195+
expect(serialized).not.toContain("plan.md");
196+
expect(serialized).not.toContain("XYZ-SECRET-123");
197+
expect(serialized).not.toContain("super secret prompt text");
198+
expect(serialized).not.toContain("find the leaked");
199+
expect(serialized).not.toContain("here is the plan");
200+
expect(serialized).not.toContain("/Users/attacker");
201+
});
202+
});
203+
204+
describe("emitAiTurnFailure", () => {
205+
test("emits an errored $ai_generation for a turn that never completed", () => {
206+
const { telemetry, captured } = fakeTelemetry();
207+
208+
emitAiTurnFailure(telemetry, {
209+
sessionId: SESSION_ID,
210+
turnIndex: 7,
211+
error: "HTTP 429 rate limit exceeded",
212+
});
213+
214+
expect(captured.length).toBe(1);
215+
expect(captured[0]?.event).toBe("$ai_generation");
216+
expect(captured[0]?.properties.$ai_trace_id).toBe(turnTraceId(SESSION_ID, 7));
217+
expect(captured[0]?.properties.$ai_is_error).toBe(true);
218+
expect(captured[0]?.properties.$ai_error).toBe("rate_limit");
219+
});
220+
221+
test("never leaks the raw provider error message", () => {
222+
const { telemetry, captured } = fakeTelemetry();
223+
224+
emitAiTurnFailure(telemetry, {
225+
sessionId: SESSION_ID,
226+
turnIndex: 7,
227+
error:
228+
"429 rate limit on https://api.internal.acme.corp/v1/chat while reading /Users/attacker/secret-project/plan.md: XYZ-SECRET-123",
229+
});
230+
231+
const serialized = JSON.stringify(captured);
232+
expect(serialized).not.toContain("acme.corp");
233+
expect(serialized).not.toContain("/Users/attacker");
234+
expect(serialized).not.toContain("secret-project");
235+
expect(serialized).not.toContain("XYZ-SECRET-123");
236+
});
237+
});

0 commit comments

Comments
 (0)