Skip to content

Commit 4b92e4e

Browse files
committed
fix(agent): export error provenance only and isolate telemetry flush
Addresses four review findings on the run telemetry export: - _posthog/error records and the root span no longer carry the raw error string: it is free text that can embed prompt or repo content (exception paths, provider errors). Exported signal is now the generic "run error" body plus error_source/stop_reason attributes; the full message stays in the session log and the task run's error_message. - Telemetry flush/shutdown use Promise.allSettled so logs and traces complete independently, and both batch processors cap exports at 5s (exportTimeoutMillis) instead of the SDK's 30s default - a rejecting or hanging traces endpoint can no longer starve log delivery or delay session cleanup. - A run error now closes still-open tool spans as ERROR with tool_status=interrupted, so APM never shows a healthy-looking active tool under a failed run. - OtelTransportConfig/AgentConfig.otelTransport are restored as @deprecated ignored stubs: @posthog/agent is published, so removing exported types is an API break reserved for a major. Generated-By: PostHog Code Task-Id: 0c511836-2180-455a-9b58-45df2a0661ec
1 parent 213b0fb commit 4b92e4e

7 files changed

Lines changed: 149 additions & 38 deletions

File tree

REPORT.md

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -54,7 +54,7 @@ Exported events (allowlist, everything else is dropped):
5454
| `_posthog/usage_update` (and the `session/update` variant) | info | `tokens_input/output/cached_read/cached_write`, `cost_usd` |
5555
| `_posthog/turn_complete` | info | `stop_reason` |
5656
| `_posthog/task_complete` | info | `stop_reason` |
57-
| `_posthog/error` | **error** | `error_source`, `stop_reason`, message in body (capped) |
57+
| `_posthog/error` | **error** | `error_source`, `stop_reason`; body is the generic "run error" — the raw message is free text that can embed prompt/repo content, so it stays in the session log and the run's `error_message` |
5858
| `_posthog/progress` | info | `progress_group/step/status` |
5959
| `_posthog/git_checkpoint`, `_posthog/branch_created` | info | `branch` |
6060
| `_posthog/mode_change`, `_posthog/compact_boundary` | info | |
@@ -67,17 +67,18 @@ Bodies are capped at 2000 chars; free-text attribute values at 200 chars (the `l
6767

6868
### APM trace (one per run)
6969

70-
- `task_run` root span (kind SERVER): opened at session init, closed at session cleanup. Status is resolved at shutdown from the latest turn outcome (the sandbox never emits `task_complete` for successful runs — the terminal "completed" status is decided by the workflow outside — so the last turn is the in-sandbox success signal): OK when the last turn ended with `end_turn`, ERROR with the error message on `_posthog/error` (an error always wins, later turn completions cannot flip it back) or when the last turn stopped with `error`, unset otherwise (cancelled / refused / timed out / no completed turns). Resolving at shutdown rather than per-turn means an early clean turn cannot leave a stale OK on a run whose final turn was cancelled.
70+
- `task_run` root span (kind SERVER): opened at session init, closed at session cleanup. Status is resolved at shutdown from the latest turn outcome (the sandbox never emits `task_complete` for successful runs — the terminal "completed" status is decided by the workflow outside — so the last turn is the in-sandbox success signal): OK when the last turn ended with `end_turn`, ERROR on `_posthog/error` (an error always wins, later turn completions cannot flip it back; `error_source` lands as a root-span attribute while the raw message is withheld — see the error row above) or when the last turn stopped with `error`, unset otherwise (cancelled / refused / timed out / no completed turns). Resolving at shutdown rather than per-turn means an early clean turn cannot leave a stale OK on a run whose final turn was cancelled.
7171
- `turn` child spans: opened on each ACP `session/prompt` (used purely as a boundary marker; its content is never read), closed on `_posthog/turn_complete`; attributes `turn_index`, `stop_reason`, plus the turn's token counts and `cost_usd` lifted from usage updates, so APM can rank slow or expensive turns directly.
7272
- `tool_call:<kind>` grandchild spans (`execute`, `read`, `edit`, ...): opened on `tool_call`, closed on the terminal `tool_call_update`; status ERROR on `failed`; attributes `tool_call_id`, `tool_kind`, `tool_status`. Per-kind span names stay low-cardinality and make APM latency breakdowns by tool kind useful.
73-
- Robustness: orphaned spans are closed (status unset) and exported at shutdown; a new prompt while a turn is open closes the stale turn; duplicate `tool_call` events are idempotent; an error cascades ERROR status through open tool and turn spans to the root.
73+
- Robustness: orphaned spans are closed (status unset) and exported at shutdown; a new prompt while a turn is open closes the stale turn; duplicate `tool_call` events are idempotent; a run error cascades ERROR status to the open turn and the root, and closes still-open tool spans as ERROR with `tool_status=interrupted` so APM never shows a healthy-looking active tool under a failed run.
7474
- Every log record is emitted under the OTel context of the span it belongs to (tool logs on the tool span, lifecycle logs on the root), so `trace_id`/`span_id` land in the `logs` table columns and the UI links Logs ⇄ trace waterfall.
7575

7676
### Delivery timing
7777

7878
Telemetry is near-realtime, not end-of-turn: records are created the moment each notification flows through the writer and batched for at most 2 s (`BatchLogRecordProcessor` / `BatchSpanProcessor`, `scheduledDelayMillis` 2000).
7979
Spans export when they end (tools mid-turn, turns at `turn_complete`, root at cleanup).
8080
Flush safety nets: an explicit flush after a terminal error in `signalTaskComplete`, a full shutdown-flush in `cleanupSession` (which SIGTERM reaches via `stop()`), so sandbox teardown cannot eat the tail of a run's telemetry.
81+
Flush and shutdown are best-effort and per-signal independent (`Promise.allSettled`), and every export is capped at 5 s (`exportTimeoutMillis`, down from the SDK's 30 s default), so a rejecting or hanging traces endpoint can neither starve log delivery nor hold up session cleanup.
8182

8283
## Changes in PostHog/code (this branch)
8384

@@ -87,9 +88,9 @@ Flush safety nets: an explicit flush after a terminal error in `signalTaskComple
8788
- `packages/agent/src/session-log-writer.ts`: optional `sinks: SessionLogSink[]`, teed in `appendRawLine` after the entry is built; a throwing sink warns once and can never break product log persistence; message chunks never reach sinks. `SessionContext` moved here from the otel module.
8889
- `packages/agent/src/server/agent-server.ts`: builds the telemetry per session from config (`createRunTelemetry`), passes it as the writer sink, stores it on the session, shuts it down in `cleanupSession`, flushes after terminal errors, and mirrors `enqueueTaskTerminalEvent` payloads into it directly (terminal `_posthog/error` events bypass `SessionLogWriter`, and a failed run is exactly what telemetry must record). Fatal crashes (`reportFatalError`, the uncaught-exception/unhandled-rejection path) also mirror an error record (`error_source=agent_server_crash`) and shut telemetry down, so hard process deaths reach the telemetry project instead of vanishing.
8990
- `packages/agent/src/server/bin.ts` + `server/types.ts`: zod-validated env `POSTHOG_AGENT_OTEL_LOGS_URL`, `POSTHOG_AGENT_OTEL_LOGS_TOKEN`, `POSTHOG_AGENT_OTEL_TRACES_URL``AgentServerConfig.otelLogsUrl/otelLogsToken/otelTracesUrl`. Telemetry is off unless the logs pair is set; spans additionally require the traces URL (per-signal kill switch).
90-
- `packages/agent/src/types.ts`: deleted the dead `OtelTransportConfig`/`AgentConfig.otelTransport` left over from the February attempt.
91+
- `packages/agent/src/types.ts`: the February `OtelTransportConfig`/`AgentConfig.otelTransport` remain as `@deprecated`, ignored stubs — `@posthog/agent` is a published package, so removing exported types is an API break reserved for a major.
9192
- Dependencies: `@opentelemetry/api`, `@opentelemetry/sdk-trace-base`, `@opentelemetry/exporter-trace-otlp-http`, version-aligned with the existing logs SDK (0.208.x experimental / 2.x stable line).
92-
- Tests (71 passing): parameterized log-mapping matrix, a hard privacy test asserting exported payloads never contain tool args/titles/output, per-user resource attributes, session-mismatch guard, never-throws guard, sink isolation in `SessionLogWriter`, and four trace tests (span tree + statuses + attributes, log⇄span id correlation, error cascade, orphan export on shutdown).
93+
- Tests (74 passing): parameterized log-mapping matrix, hard privacy tests asserting exported payloads never contain tool args/titles/output or raw error messages, per-user resource attributes, session-mismatch guard, never-throws guard, sink isolation in `SessionLogWriter`, and five trace tests (span tree + statuses + attributes, log⇄span id correlation, error cascade incl. interrupted tools, orphan export on shutdown, log shutdown isolated from a failing traces endpoint).
9394
- `packages/agent/README.md`: documents the env vars and behavior.
9495

9596
## Changes in PostHog/posthog (companion branch)
@@ -117,7 +118,7 @@ Flush safety nets: an explicit flush after a terminal error in `signalTaskComple
117118

118119
## Verification
119120

120-
- `PostHog/code`: 71 tests pass in the agent package (including the new telemetry suite), `tsc --noEmit` clean via turbo, biome clean on all touched files (one pre-existing warning untouched). The package's pre-existing test failures in this environment (missing Postgres/git fixtures) were confirmed byte-identical with and without these changes by running the failing files against a stashed tree.
121+
- `PostHog/code`: 74 tests pass in the agent package (including the new telemetry suite), `tsc --noEmit` clean via turbo, biome clean on all touched files (one pre-existing warning untouched). The package's pre-existing test failures in this environment (missing Postgres/git fixtures) were confirmed byte-identical with and without these changes by running the failing files against a stashed tree.
121122
- `PostHog/posthog`: 21 tests pass across `test_provision_sandbox.py` and the new `TestBuildSandboxEnvironmentVariables`; `ruff check`/`format` clean on all touched files. DB-dependent suites in this sandbox fail identically with and without the change (no Postgres available).
122123
- Local-dev routing verified: Caddy serves `/i/v1/logs`/`/i/v1/traces` on `localhost:8000` and proxies to `capture-logs`, and the Docker URL rewrite covers the new vars.
123124

packages/agent/README.md

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -172,7 +172,7 @@ Optional run telemetry (the logs pair must both be set, otherwise telemetry stay
172172
- `POSTHOG_AGENT_OTEL_LOGS_TOKEN` — project API key of the telemetry project
173173
- `POSTHOG_AGENT_OTEL_TRACES_URL` — full OTLP traces URL, e.g. `https://us.i.posthog.com/i/v1/traces`; additionally enables one APM trace per run
174174

175-
When set, `AgentServer` ships an allowlisted metadata subset of the session log (run/turn/tool lifecycle, usage, errors — never message content or tool arguments; see `src/otel-telemetry.ts`) to PostHog Logs, tagged with `service.name=posthog-code-agent` and `run_id`/`task_id`/`team_id`/`user_id`/`distinct_id` resource attributes so cloud runs are filterable per user. With the traces URL set, each run also produces an APM trace (`task_run` root span, a `turn` span per prompt, a `tool_call:<kind>` span per tool call; see `src/otel-trace-builder.ts`), and log records carry the matching trace/span ids so Logs and APM cross-link.
175+
When set, `AgentServer` ships an allowlisted metadata subset of the session log (run/turn/tool lifecycle, usage, error provenance — never message content, tool arguments, or raw error text; see `src/otel-telemetry.ts`) to PostHog Logs, tagged with `service.name=posthog-code-agent` and `run_id`/`task_id`/`team_id`/`user_id`/`distinct_id` resource attributes so cloud runs are filterable per user. With the traces URL set, each run also produces an APM trace (`task_run` root span, a `turn` span per prompt, a `tool_call:<kind>` span per tool call; see `src/otel-trace-builder.ts`), and log records carry the matching trace/span ids so Logs and APM cross-link.
176176

177177
## Agent SDK
178178

@@ -214,7 +214,7 @@ Logs serve two purposes: real-time observability and session resume. Every ACP m
214214

215215
`SessionLogWriter` (`src/session-log-writer.ts`) is a per-session multiplexer that buffers raw ndJson lines. On flush (auto-scheduled 500ms after writes, or explicit), it POSTs batched `StoredNotification` entries to the Django API via `PostHogAPIClient.appendTaskRunLog()`; the API stores them in S3 as the task run's `log_url`. This S3 log is the source of truth for the full transcript and for session resume.
216216

217-
Independently of that flush cycle, the writer tees every parsed non-chunk entry to optional `SessionLogSink`s at append time. In cloud, `OtelRunTelemetry` (`src/otel-telemetry.ts`) is wired as a sink and exports an allowlisted metadata subset (run/turn/tool lifecycle, usage, errors — never message content or tool arguments) to PostHog Logs, plus an APM trace per run when configured. See "Optional run telemetry" above for the env vars and behavior. Sink failures can never break S3 log persistence.
217+
Independently of that flush cycle, the writer tees every parsed non-chunk entry to optional `SessionLogSink`s at append time. In cloud, `OtelRunTelemetry` (`src/otel-telemetry.ts`) is wired as a sink and exports an allowlisted metadata subset (run/turn/tool lifecycle, usage, error provenance — never message content, tool arguments, or raw error text) to PostHog Logs, plus an APM trace per run when configured. See "Optional run telemetry" above for the env vars and behavior. Sink failures can never break S3 log persistence.
218218

219219
### Resuming from logs
220220

packages/agent/src/otel-attributes.ts

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,11 +2,14 @@ const MAX_BODY_CHARS = 2000;
22
// PostHog Logs only facets attribute key/value pairs shorter than 256 chars,
33
// so free-text attribute values are capped well below that.
44
const MAX_ATTR_CHARS = 200;
5+
// The SDK default export timeout is 30s; a hanging endpoint must not hold up
6+
// session cleanup (the sandbox can be torn down right after), so keep it short.
7+
const EXPORT_TIMEOUT_MS = 5000;
58

69
export type AttributeValue = string | number | boolean;
710
export type Attributes = Record<string, AttributeValue>;
811

9-
export { MAX_ATTR_CHARS, MAX_BODY_CHARS };
12+
export { EXPORT_TIMEOUT_MS, MAX_ATTR_CHARS, MAX_BODY_CHARS };
1013

1114
export function truncate(value: string, max: number): string {
1215
return value.length <= max ? value : `${value.slice(0, max)}…`;

packages/agent/src/otel-telemetry.test.ts

Lines changed: 72 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -11,17 +11,20 @@ const mockSpanExport = vi.fn((_spans, callback) => {
1111
callback({ code: 0 }); // Success
1212
});
1313

14+
const mockLogShutdown = vi.fn(() => Promise.resolve());
15+
const mockSpanShutdown = vi.fn(() => Promise.resolve());
16+
1417
vi.mock("@opentelemetry/exporter-logs-otlp-http", () => ({
1518
OTLPLogExporter: class {
1619
export = mockLogExport;
17-
shutdown = vi.fn().mockResolvedValue(undefined);
20+
shutdown = mockLogShutdown;
1821
},
1922
}));
2023

2124
vi.mock("@opentelemetry/exporter-trace-otlp-http", () => ({
2225
OTLPTraceExporter: class {
2326
export = mockSpanExport;
24-
shutdown = vi.fn().mockResolvedValue(undefined);
27+
shutdown = mockSpanShutdown;
2528
},
2629
}));
2730

@@ -88,6 +91,8 @@ describe("OtelRunTelemetry", () => {
8891
beforeEach(() => {
8992
mockLogExport.mockClear();
9093
mockSpanExport.mockClear();
94+
mockLogShutdown.mockClear();
95+
mockSpanShutdown.mockClear();
9196
});
9297

9398
describe("mapNotificationToLogRecord", () => {
@@ -164,11 +169,12 @@ describe("OtelRunTelemetry", () => {
164169
name: "error",
165170
entry: makeEntry("_posthog/error", {
166171
source: "agent_server",
172+
stopReason: "error",
167173
error: "boom",
168174
}),
169175
severityText: "ERROR",
170-
body: "error: boom",
171-
attrs: { error_source: "agent_server" },
176+
body: "run error",
177+
attrs: { error_source: "agent_server", stop_reason: "error" },
172178
},
173179
{
174180
name: "progress",
@@ -324,11 +330,29 @@ describe("OtelRunTelemetry", () => {
324330
expect(mapNotificationToLogRecord(entry)).toBeNull();
325331
});
326332

327-
it("caps body length", () => {
333+
// Run errors export provenance only: the raw message is free text that
334+
// can embed prompt or repo content (exception paths, provider errors).
335+
it("never exports the raw error message", () => {
328336
const mapped = mapNotificationToLogRecord(
329337
makeEntry("_posthog/error", {
330-
source: "agent_server",
331-
error: "x".repeat(5000),
338+
source: "agent_server_crash",
339+
error: "Agent server crashed: ENOENT open '/repos/acme/SECRET/.env'",
340+
}),
341+
);
342+
343+
expect(mapped).not.toBeNull();
344+
expect(JSON.stringify([mapped?.body, mapped?.attributes])).not.toContain(
345+
"SECRET",
346+
);
347+
});
348+
349+
it("caps body length", () => {
350+
const mapped = mapNotificationToLogRecord(
351+
makeEntry("_posthog/progress", {
352+
group: "setup:run-1",
353+
step: "agent",
354+
status: "completed",
355+
label: "x".repeat(5000),
332356
}),
333357
);
334358

@@ -574,7 +598,7 @@ describe("OtelRunTelemetry", () => {
574598
}
575599
});
576600

577-
it("marks failed tools, errored turns, and the errored run", async () => {
601+
it("marks failed tools, interrupted tools, errored turns, and the errored run", async () => {
578602
telemetry.append(RUN_ID, makeEntry("session/prompt", {}));
579603
telemetry.append(
580604
RUN_ID,
@@ -592,11 +616,21 @@ describe("OtelRunTelemetry", () => {
592616
status: "failed",
593617
}),
594618
);
619+
// Still open when the run error below lands.
620+
telemetry.append(
621+
RUN_ID,
622+
sessionUpdate({
623+
sessionUpdate: "tool_call",
624+
toolCallId: "t2",
625+
kind: "fetch",
626+
}),
627+
);
595628
telemetry.append(
596629
RUN_ID,
597630
makeEntry("_posthog/error", {
598631
source: "agent_server",
599-
error: "gateway exploded",
632+
stopReason: "error",
633+
error: "gateway exploded reading SECRET",
600634
}),
601635
);
602636
// A turn completion arriving after the error must not flip the run
@@ -611,10 +645,37 @@ describe("OtelRunTelemetry", () => {
611645
expect(spanByName("tool_call:execute").status.code).toBe(
612646
SpanStatusCode.ERROR,
613647
);
614-
expect(spanByName("turn").status.code).toBe(SpanStatusCode.ERROR);
648+
const interrupted = spanByName("tool_call:fetch");
649+
expect(interrupted.status.code).toBe(SpanStatusCode.ERROR);
650+
expect(interrupted.attributes).toMatchObject({
651+
tool_status: "interrupted",
652+
});
653+
const turn = spanByName("turn");
654+
expect(turn.status.code).toBe(SpanStatusCode.ERROR);
655+
expect(turn.attributes).toMatchObject({ stop_reason: "error" });
615656
const root = spanByName("task_run");
616657
expect(root.status.code).toBe(SpanStatusCode.ERROR);
617-
expect(root.status.message).toBe("gateway exploded");
658+
expect(root.attributes).toMatchObject({ error_source: "agent_server" });
659+
// The raw error message is free text; it must not reach span status
660+
// messages or attributes.
661+
const surface = JSON.stringify(
662+
exportedSpans().map((span) => [
663+
span.name,
664+
span.attributes,
665+
span.status,
666+
]),
667+
);
668+
expect(surface).not.toContain("SECRET");
669+
});
670+
671+
it("shuts down logs even when the traces endpoint fails", async () => {
672+
mockSpanShutdown.mockRejectedValueOnce(new Error("traces endpoint down"));
673+
telemetry.append(RUN_ID, makeEntry("_posthog/run_started", {}));
674+
675+
await expect(telemetry.shutdown()).resolves.toBeUndefined();
676+
677+
expect(mockLogShutdown).toHaveBeenCalled();
678+
expect(exportedLogs().map((log) => log.body)).toContain("run started");
618679
});
619680

620681
it("exports open spans on shutdown even without terminal events", async () => {

0 commit comments

Comments
 (0)