Skip to content

Commit 0bf0bab

Browse files
committed
fix(agent): end run telemetry at the in-process terminal point
Local verification of the telemetry branch showed logs and the turn span landing in ClickHouse but never the task_run root span, even after the run reached completed and extra delay. Root cause: the root span only ended in cleanupSession, which is only reachable via SIGTERM or the close command - and sandbox teardown never delivers SIGTERM to agent-server, because it is an exec'd process (docker stop signals only the container's PID 1; Modal terminate is immediate). The root span was still open when the process was killed, so it never exported. The turn span survived only because it ended mid-run and the 2s batch exporter got it out. Fix: end telemetry eagerly at the run's in-process terminal points instead of relying on teardown: - finalizeRunTelemetry: full telemetry shutdown (ends the root span with the resolved status and drains both exporters) when a background run's initial or resume prompt settles - the run is over in-sandbox at that point; the workflow marks the terminal status and destroys the sandbox right after. - signalTaskComplete: upgrade the terminal-failure flush to a full shutdown, after the error mirror is appended, so failed runs export a root span with ERROR status. - cleanupSession remains the path for interactive close. Known limitation, now documented: an interactive session ended by hard teardown (e.g. inactivity timeout) loses the root span; its turn/tool spans and logs still assemble under the same trace id. Tests: order assertion that the error mirror lands before the terminal shutdown, and a parameterized check that finalizeRunTelemetry fires for background runs only. The full agent-server + telemetry suites pass (161). Stacked on posthog-code/agent-run-otel-telemetry (pure fast-forward). Generated-By: PostHog Code Task-Id: 0c511836-2180-455a-9b58-45df2a0661ec
1 parent f3f1bdc commit 0bf0bab

4 files changed

Lines changed: 153 additions & 8 deletions

File tree

REPORT.md

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -67,7 +67,7 @@ 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 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.
70+
- `task_run` root span (kind SERVER): opened at session init, closed at the run's in-process terminal point — a background run's prompt settling (`finalizeRunTelemetry`), a terminal failure (`signalTaskComplete`), or session cleanup (interactive `close`). 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.
7373
- 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.
@@ -76,8 +76,8 @@ Bodies are capped at 2000 chars; free-text attribute values at 200 chars (the `l
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).
79-
Spans export when they end (tools mid-turn, turns at `turn_complete`, root at cleanup).
80-
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.
79+
Spans export when they end (tools mid-turn, turns at `turn_complete`, root at the run's terminal point).
80+
Sandbox teardown can NOT be a flush point: agent-server is an exec'd process inside the sandbox, so `docker stop` signals only the container's PID 1 and Modal terminate is immediate — the process's SIGTERM handler never runs and anything still queued (or a still-open root span) is lost. Telemetry is therefore ended eagerly at the in-process terminal points: `finalizeRunTelemetry` when a background run's prompt settles, a full shutdown after a terminal failure in `signalTaskComplete`, and `cleanupSession` for interactive `close`. Known limitation: an interactive session ended by hard teardown (e.g. inactivity timeout) loses the root span; its turn/tool spans and logs still assemble under the same trace id.
8181
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.
8282

8383
## Changes in PostHog/code (this branch)
@@ -86,11 +86,11 @@ Flush and shutdown are best-effort and per-signal independent (`Promise.allSettl
8686
- `packages/agent/src/otel-trace-builder.ts` (new): `RunTraceBuilder`, the span state machine described above; `handle(entry)` returns the context each log record should attach to.
8787
- `packages/agent/src/otel-attributes.ts` (new): shared pure helpers (`strAttr`, `numAttr`, `usageAttributes`, truncation, caps).
8888
- `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.
89-
- `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.
89+
- `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, and ends it at the run's in-process terminal points: `finalizeRunTelemetry` (full shutdown when a background run's initial/resume prompt settles — verified necessary because sandbox teardown never delivers SIGTERM to the exec'd process, so waiting for `cleanupSession` left the root span unexported), a shutdown after terminal failures in `signalTaskComplete`, and `cleanupSession` for interactive `close`. `enqueueTaskTerminalEvent` payloads are mirrored 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.
9090
- `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).
9191
- `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.
9292
- 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).
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).
93+
- Tests (74 passing in the telemetry suites, plus agent-server terminal-point tests): 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`, 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), and agent-server tests asserting the error mirror lands before the terminal shutdown and that `finalizeRunTelemetry` fires for background runs only.
9494
- `packages/agent/README.md`: documents the env vars and behavior.
9595

9696
## Changes in PostHog/posthog (companion branch)

packages/agent/README.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -174,6 +174,8 @@ Optional run telemetry (the logs pair must both be set, otherwise telemetry stay
174174

175175
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

177+
The `task_run` root span is ended and exported at the run's in-process terminal point — a background run's prompt settling, a terminal failure, or session cleanup (`close`). It cannot wait for teardown: agent-server is an exec'd process inside the sandbox, so `docker stop` / Modal terminate kill it without SIGTERM ever arriving, and a span still open at that moment is lost. Interactive sessions that end via hard teardown (e.g. inactivity timeout) therefore lose the root span; turn/tool spans and logs still assemble under the same trace id.
178+
177179
## Agent SDK
178180

179181
The `Agent` class (`src/agent.ts`) is the entrypoint for local/programmatic usage. It handles LLM gateway configuration, log writer setup, and model filtering — then delegates to `createAcpConnection()`.

packages/agent/src/server/agent-server.test.ts

Lines changed: 118 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -908,6 +908,124 @@ describe("AgentServer HTTP Mode", () => {
908908
);
909909
});
910910

911+
// Sandbox teardown kills the exec'd agent-server without SIGTERM, so the
912+
// trace's root span only exports if telemetry is shut down at the run's
913+
// in-process terminal points.
914+
it("shuts down telemetry after mirroring the terminal failure record", async () => {
915+
const order: string[] = [];
916+
const testServer = new AgentServer({
917+
port,
918+
jwtPublicKey: TEST_PUBLIC_KEY,
919+
repositoryPath: repo.path,
920+
apiUrl: "http://localhost:8000",
921+
apiKey: "test-api-key",
922+
projectId: 1,
923+
mode: "interactive",
924+
taskId: "test-task-id",
925+
runId: "test-run-id",
926+
}) as unknown as {
927+
session: {
928+
payload: { run_id: string };
929+
logWriter: { flush: ReturnType<typeof vi.fn> };
930+
telemetry: {
931+
append: ReturnType<typeof vi.fn>;
932+
shutdown: ReturnType<typeof vi.fn>;
933+
};
934+
};
935+
eventStreamSender: {
936+
enqueue: (event: Record<string, unknown>) => void;
937+
stop: () => Promise<void>;
938+
};
939+
posthogAPI: {
940+
updateTaskRun: (
941+
taskId: string,
942+
runId: string,
943+
payload: Record<string, unknown>,
944+
) => Promise<unknown>;
945+
};
946+
signalTaskComplete(
947+
payload: JwtPayload,
948+
stopReason: string,
949+
errorMessage?: string,
950+
): Promise<void>;
951+
};
952+
testServer.eventStreamSender = {
953+
enqueue: vi.fn(),
954+
stop: vi.fn(async () => {}),
955+
};
956+
testServer.posthogAPI = {
957+
updateTaskRun: vi.fn(async () => ({})),
958+
};
959+
testServer.session = {
960+
payload: { run_id: "run-1" },
961+
logWriter: { flush: vi.fn(async () => {}) },
962+
telemetry: {
963+
append: vi.fn(() => {
964+
order.push("append");
965+
}),
966+
shutdown: vi.fn(async () => {
967+
order.push("shutdown");
968+
}),
969+
},
970+
};
971+
972+
await testServer.signalTaskComplete(
973+
{
974+
run_id: "run-1",
975+
task_id: "task-1",
976+
team_id: 1,
977+
user_id: 1,
978+
distinct_id: "distinct-id",
979+
mode: "background",
980+
},
981+
"error",
982+
"boom",
983+
);
984+
985+
// The error mirror must land before shutdown so the root span exports
986+
// with ERROR status.
987+
expect(order).toEqual(["append", "shutdown"]);
988+
});
989+
990+
it.each([
991+
{ mode: "background" as const, shutdownCalls: 1 },
992+
{ mode: "interactive" as const, shutdownCalls: 0 },
993+
])(
994+
"finalizeRunTelemetry shuts down telemetry only for $mode runs",
995+
async ({ mode, shutdownCalls }) => {
996+
const testServer = new AgentServer({
997+
port,
998+
jwtPublicKey: TEST_PUBLIC_KEY,
999+
repositoryPath: repo.path,
1000+
apiUrl: "http://localhost:8000",
1001+
apiKey: "test-api-key",
1002+
projectId: 1,
1003+
mode: "interactive",
1004+
taskId: "test-task-id",
1005+
runId: "test-run-id",
1006+
}) as unknown as {
1007+
session: { telemetry: { shutdown: ReturnType<typeof vi.fn> } };
1008+
finalizeRunTelemetry(payload: JwtPayload): Promise<void>;
1009+
};
1010+
testServer.session = {
1011+
telemetry: { shutdown: vi.fn(async () => {}) },
1012+
};
1013+
1014+
await testServer.finalizeRunTelemetry({
1015+
run_id: "run-1",
1016+
task_id: "task-1",
1017+
team_id: 1,
1018+
user_id: 1,
1019+
distinct_id: "distinct-id",
1020+
mode,
1021+
});
1022+
1023+
expect(testServer.session.telemetry.shutdown).toHaveBeenCalledTimes(
1024+
shutdownCalls,
1025+
);
1026+
},
1027+
);
1028+
9111029
function createFailureTestServer() {
9121030
const appendRawLine = vi.fn();
9131031
const testServer = new AgentServer({

packages/agent/src/server/agent-server.ts

Lines changed: 28 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1844,6 +1844,8 @@ export class AgentServer {
18441844
if (result.stopReason === "end_turn") {
18451845
await this.relayAgentResponse(payload);
18461846
}
1847+
1848+
await this.finalizeRunTelemetry(payload);
18471849
} catch (error) {
18481850
this.logger.error("Failed to send initial task message", error);
18491851
if (this.session) {
@@ -2060,6 +2062,8 @@ export class AgentServer {
20602062
if (result.stopReason === "end_turn") {
20612063
await this.relayAgentResponse(payload);
20622064
}
2065+
2066+
await this.finalizeRunTelemetry(payload);
20632067
} catch (error) {
20642068
this.logger.error(`Failed to send ${logLabel.toLowerCase()}`, error);
20652069
if (this.session) {
@@ -3303,6 +3307,25 @@ ${signedCommitInstructions}${prLinkInstructions}${shellEfficiencyInstructions}
33033307
}
33043308
}
33053309

3310+
/**
3311+
* Ends the run's telemetry (root span + final flush) at the in-sandbox
3312+
* terminal point of a background run. Sandbox teardown cannot be relied on
3313+
* for this: agent-server is an exec'd process inside the sandbox, so
3314+
* `docker stop` signals only the container's PID 1 and Modal terminate is
3315+
* immediate — the SIGTERM handler (and thus cleanupSession) never runs, and
3316+
* an unended root span would never export. Once the background prompt
3317+
* settles the run is over in-sandbox; the workflow marks the terminal
3318+
* status and destroys the sandbox right after.
3319+
*/
3320+
private async finalizeRunTelemetry(payload: JwtPayload): Promise<void> {
3321+
if (this.getEffectiveMode(payload) !== "background") return;
3322+
try {
3323+
await this.session?.telemetry?.shutdown();
3324+
} catch (error) {
3325+
this.logger.debug("Failed to finalize run telemetry", error);
3326+
}
3327+
}
3328+
33063329
private async signalTaskComplete(
33073330
payload: JwtPayload,
33083331
stopReason: string,
@@ -3348,9 +3371,11 @@ ${signedCommitInstructions}${prLinkInstructions}${shellEfficiencyInstructions}
33483371
} finally {
33493372
await this.emitRtkSavings();
33503373
await this.eventStreamSender?.stop();
3351-
// The sandbox can be torn down right after the failed status lands;
3352-
// don't leave the terminal record sitting in the OTel batch queue.
3353-
await this.session?.telemetry?.flush().catch(() => {});
3374+
// The run is terminal and the sandbox is torn down right after — and
3375+
// teardown kills this exec'd process without SIGTERM, so this is the
3376+
// last chance to end the root span and drain the OTel queues. The
3377+
// error mirror was appended above, so the root span exports as ERROR.
3378+
await this.session?.telemetry?.shutdown().catch(() => {});
33543379
}
33553380
}
33563381

0 commit comments

Comments
 (0)