diff --git a/packages/ai/CHANGELOG.md b/packages/ai/CHANGELOG.md index b06b70252..d265f5280 100644 --- a/packages/ai/CHANGELOG.md +++ b/packages/ai/CHANGELOG.md @@ -2,6 +2,15 @@ ## [Unreleased] +### Breaking Changes + +- Renamed provider request option `telemetryContext` to `telemetry?: TelemetrySpan`, without a compatibility alias. Pass a parent span, not an adapter. + +### Added + +- Added `AI_TELEMETRY_SCHEMA` and opt-in `pi.ai.request`/`pi.ai.poll` tracing around Models requests, with content-free first-event, block-size, and final usage attributes, plus duration, token, and USD cost metrics through `telemetry.metrics`. +- Failed model request spans report `provider_error` status with up to 500 error-message characters; cancelled requests keep `ok` status with `stop: "aborted"`. + ### Fixed - Fixed whitespace-only tool output (for example a bare `\r\n` from bash) being sent as-is to OpenAI Completions, OpenAI Responses, and Google providers; it now uses the same placeholder as empty output, since some providers reject whitespace-only tool content with a 400 ([#8720](https://github.com/earendil-works/pi/issues/8720)) diff --git a/packages/ai/README.md b/packages/ai/README.md index 7daa0ce47..c0db958ab 100644 --- a/packages/ai/README.md +++ b/packages/ai/README.md @@ -34,6 +34,7 @@ Unified LLM API with provider collections, automatic auth resolution, token and - [Provider-Specific Options](#provider-specific-options-streamcomplete) - [Streaming Thinking Content](#streaming-thinking-content) - [Stop Reasons](#stop-reasons) +- [Telemetry](#telemetry) - [Error Handling](#error-handling) - [Aborting Requests](#aborting-requests) - [Continuing After Abort](#continuing-after-abort) @@ -1070,6 +1071,40 @@ Every `AssistantMessage` includes a `stopReason` field that indicates how the ge `AssistantMessage` may also include `responseId`, a provider-specific upstream response or message identifier when the underlying API exposes one. Do not assume it is always present across providers. +## Telemetry + +Pass an explicit parent span (`TelemetrySpan`, not an adapter) through `telemetry`; omitting it uses the no-op span: + +```typescript +import { InMemoryTelemetryContext } from '@earendil-works/pi-telemetry'; + +const telemetry = new InMemoryTelemetryContext(); +await telemetry.startSpan({ name: 'application.turn' }, async (span) => { + await models.completeSimple(model, context, { telemetry: span }); +}); +``` + +`Models.stream()` and `streamSimple()` create `pi.ai.request`; `streamDeferred()` creates one `pi.ai.poll` per poll. Their completion helpers use the same spans. These spans include auth/setup, end at the terminal result, and do not require the caller to consume events. Direct provider/API calls are not instrumented. + +`AI_TELEMETRY_SCHEMA`, exported from the root and `@earendil-works/pi-ai/models`, defines the typed Pi-owned vocabulary: + +- Start attributes: `provider`, `api`, `model`, and `reasoning` only when `options.reasoning` is a string. Provider-native reasoning objects are ignored. +- End attributes: `stop`, `usage.input`, `usage.output`, `usage.cache_read`, `usage.cache_write`, `cost.total`, and optional `response.id`. `stop: "error"` sets error status with the fixed category `provider_error` and `AssistantMessage.errorMessage` truncated to 500 characters (empty when absent). Cancellation keeps status `ok` with `stop: "aborted"`. +- `pi.ai.first_chunk` marks the first normalized event, including setup errors. Each completed text, thinking, or tool-call block emits `pi.ai.block` with `type`, `index`, and `chars`; only tool calls include `tool`. Character counts use JavaScript string length; tool counts sum argument delta lengths without serializing arguments. + +When `options.telemetry.metrics` is available, the same requests record metrics: + +| Metric | Unit | Attributes | +| --- | --- | --- | +| `pi.ai.request.duration` | `ms` | `provider`, `model`, `stop` | +| `pi.ai.first_chunk.duration` | `ms` | `provider`, `model` | +| `pi.ai.tokens` | `token` | `provider`, `model`, `kind` (`input`, `output`, `cache_read`, `cache_write`) | +| `pi.ai.cost` | `USD` | `provider`, `model` | + +Durations use `performance.now()`. Pending/deferred polls do not add tokens or cost; final completed/error polls do. A parent span without metric capabilities remains valid and simply records no metrics. Adapter-created spans carry the same optional metric and propagation capabilities as their root. + +Telemetry does not record prompts, generated text, reasoning content, or arguments in attributes/events. Error status includes up to 500 characters of provider error text, which may contain sensitive data; apply your export policy accordingly. Telemetry observes the existing forwarding path without another stream consumer or per-delta events. Response identifiers and error messages never become metric attributes. + ## Error Handling Request failures after a stream is returned never throw: when a request ends with an error (including aborts and tool call validation errors), the streaming API emits an error event and the final message carries the details. Setup failures may emit `error` without `start`; failures after generation begins emit `start`, any observed updates, then `error`. Direct API `streamSimple()` calls throw synchronously when request auth is missing: diff --git a/packages/ai/src/api/lazy.ts b/packages/ai/src/api/lazy.ts index 33ca2ac25..d8db7440e 100644 --- a/packages/ai/src/api/lazy.ts +++ b/packages/ai/src/api/lazy.ts @@ -28,14 +28,28 @@ function hasResult( return typeof (source as { result?: unknown }).result === "function"; } +/** Synchronous, read-only observation of the stream's existing forwarding path. */ +export interface LazyStreamObserver { + onEvent?(event: AssistantMessageEvent): void; + onResult?(result: AssistantMessage | undefined): void; +} + async function forwardStream( target: AssistantMessageEventStream, source: AsyncIterable, + observer: LazyStreamObserver | undefined, + observeResult: (result: AssistantMessage | undefined) => void, ): Promise { + let result: AssistantMessage | undefined; for await (const event of source) { target.push(event); + observer?.onEvent?.(event); + if (event.type === "done") result = event.message; + else if (event.type === "error") result = event.error; } - target.end(hasResult(source) ? await source.result() : undefined); + if (hasResult(source)) result = await source.result(); + target.end(result); + observeResult(result); } /** @@ -46,16 +60,26 @@ async function forwardStream( export function lazyStream( model: Model, setup: () => Promise>, + observer?: LazyStreamObserver, ): AssistantMessageEventStream { const startedAt = Date.now(); const outer = new AssistantMessageEventStream(); + let observedResult = false; + const observeResult = (result: AssistantMessage | undefined): void => { + if (observedResult) return; + observedResult = true; + observer?.onResult?.(result); + }; setup() - .then((inner) => forwardStream(outer, inner)) + .then((inner) => forwardStream(outer, inner, observer, observeResult)) .catch((error) => { const message = createSetupErrorMessage(model, error, startedAt); - outer.push({ type: "error", reason: "error", error: message }); + const event: AssistantMessageEvent = { type: "error", reason: "error", error: message }; + outer.push(event); + observer?.onEvent?.(event); outer.end(message); + observeResult(message); }); return outer; diff --git a/packages/ai/src/api/simple-options.ts b/packages/ai/src/api/simple-options.ts index 7d287aa87..5b2d70c8a 100644 --- a/packages/ai/src/api/simple-options.ts +++ b/packages/ai/src/api/simple-options.ts @@ -45,7 +45,7 @@ export function buildBaseOptions( samplingParams, maxTokens: clampMaxTokensToContext(model, context, options?.maxTokens ?? model.maxTokens), signal: options?.signal, - telemetryContext: options?.telemetryContext, + telemetry: options?.telemetry, apiKey: apiKey || options?.apiKey, fetch: options?.fetch, transport: options?.transport, diff --git a/packages/ai/src/models.ts b/packages/ai/src/models.ts index 7c9be11bb..967496e88 100644 --- a/packages/ai/src/models.ts +++ b/packages/ai/src/models.ts @@ -20,6 +20,7 @@ import type { ProviderAuth, } from "./auth/types.ts"; import { InMemoryModelsStore, type ModelsStore, type ModelsStoreEntry } from "./models-store.ts"; +import { observeModelRequest } from "./telemetry.ts"; import type { AnyModel, Api, @@ -68,6 +69,7 @@ import { import { normalizeContext } from "./utils/transcript.ts"; export { ModelsError, type ModelsErrorCode } from "./auth/resolve.ts"; +export { AI_TELEMETRY_SCHEMA } from "./telemetry.ts"; export { getModelType, isModelType } from "./utils/model-operations.ts"; export interface ModelsPublication { @@ -886,14 +888,18 @@ class ModelsImpl implements MutableModels { options?: ModelsApiStreamOptions, ): AssistantMessageEventStream { const transcript = normalizeContext(context); - return lazyStream(model, async () => { - const provider = this.requireChatProvider(model); - const { requestModel, requestOptions } = await this.applyAuth( - model, - options as ModelsApiStreamOptions | undefined, - ); - return provider.stream(requestModel, transcript, requestOptions as ApiStreamOptions); - }); + return lazyStream( + model, + async () => { + const provider = this.requireChatProvider(model); + const { requestModel, requestOptions } = await this.applyAuth( + model, + options as ModelsApiStreamOptions | undefined, + ); + return provider.stream(requestModel, transcript, requestOptions as ApiStreamOptions); + }, + observeModelRequest(model, options, false), + ); } async complete( @@ -906,11 +912,15 @@ class ModelsImpl implements MutableModels { streamSimple(model: Model, context: Context, options?: ModelsSimpleStreamOptions): AssistantMessageEventStream { const transcript = normalizeContext(context); - return lazyStream(model, async () => { - const provider = this.requireChatProvider(model); - const { requestModel, requestOptions } = await this.applyAuth(model, options); - return provider.streamSimple(requestModel, transcript, requestOptions as SimpleStreamOptions); - }); + return lazyStream( + model, + async () => { + const provider = this.requireChatProvider(model); + const { requestModel, requestOptions } = await this.applyAuth(model, options); + return provider.streamSimple(requestModel, transcript, requestOptions as SimpleStreamOptions); + }, + observeModelRequest(model, options, false), + ); } async completeSimple( @@ -926,14 +936,18 @@ class ModelsImpl implements MutableModels { handle: DeferredHandle, options?: ModelsDeferredFetchOptions, ): AssistantMessageEventStream { - return lazyStream(model, async () => { - const provider = this.requireChatProvider(model); - if (!provider.fetchDeferred) { - throw new ModelsError("provider", `Provider ${model.provider} does not support deferred responses`); - } - const { requestModel, requestOptions } = await this.applyAuth(model, options); - return provider.fetchDeferred(requestModel, handle, requestOptions as DeferredFetchOptions); - }); + return lazyStream( + model, + async () => { + const provider = this.requireChatProvider(model); + if (!provider.fetchDeferred) { + throw new ModelsError("provider", `Provider ${model.provider} does not support deferred responses`); + } + const { requestModel, requestOptions } = await this.applyAuth(model, options); + return provider.fetchDeferred(requestModel, handle, requestOptions as DeferredFetchOptions); + }, + observeModelRequest(model, options, true), + ); } async fetchDeferred( diff --git a/packages/ai/src/telemetry.ts b/packages/ai/src/telemetry.ts new file mode 100644 index 000000000..683339939 --- /dev/null +++ b/packages/ai/src/telemetry.ts @@ -0,0 +1,209 @@ +import { + createTypedMetrics, + createTypedSpanStarter, + defineTelemetrySchema, + NOOP_TELEMETRY_CONTEXT, + NOOP_TELEMETRY_METRICS, + type SchemaTelemetrySpan, + type TelemetryMetrics, + type TelemetrySpan, +} from "@earendil-works/pi-telemetry"; +import type { LazyStreamObserver } from "./api/lazy.ts"; +import type { Api, Model } from "./types.ts"; + +const provider = { type: "string", description: "Provider identifier.", required: true } as const; +const model = { type: "string", description: "Requested model identifier.", required: true } as const; +const stop = { + type: "string", + description: "Normalized stop reason.", + values: ["pending", "stop", "length", "toolUse", "error", "aborted", "deferred"], +} as const; +const request = { + description: "One logical model request, including authentication and provider setup.", + parents: { kind: "any" }, + startAttributes: { + provider, + api: { type: "string", description: "API identifier.", required: true }, + model, + reasoning: { type: "string", description: "Scalar requested reasoning level.", required: false }, + }, + endAttributes: { + stop, + "usage.input": { type: "number", description: "Uncached input tokens." }, + "usage.output": { type: "number", description: "Output tokens." }, + "usage.cache_read": { type: "number", description: "Cache-read tokens." }, + "usage.cache_write": { type: "number", description: "Cache-write tokens." }, + "cost.total": { type: "number", description: "Total request cost in USD." }, + "response.id": { type: "string", description: "Provider response identifier.", cardinality: "high" }, + }, + events: { + "pi.ai.first_chunk": { description: "First normalized stream event delivered.", attributes: {} }, + "pi.ai.block": { + description: "A completed content block; content is never recorded.", + attributes: { + type: { + type: "string", + description: "Block kind.", + values: ["text", "thinking", "tool_call"], + required: true, + }, + index: { type: "number", description: "Content block index.", required: true }, + chars: { type: "number", description: "UTF-16 character count.", required: true }, + tool: { type: "string", description: "Tool name, for tool-call blocks only.", required: false }, + }, + }, + }, + status: { + default: "ok", + errorWhen: "Stop reason is error: provider_error with at most 500 error-message characters. Aborted stays ok.", + }, +} as const; + +/** Pi-owned request metadata, bounded error status, events, and low-cardinality metrics. */ +export const AI_TELEMETRY_SCHEMA = defineTelemetrySchema({ + version: 1, + spans: { + "pi.ai.request": request, + "pi.ai.poll": { ...request, description: "One deferred-response poll, not the deferred request's lifetime." }, + }, + metrics: { + "pi.ai.request.duration": { + kind: "histogram", + description: "Logical request or poll duration.", + unit: "ms", + attributes: { provider, model, stop: { ...stop, required: true } }, + }, + "pi.ai.first_chunk.duration": { + kind: "histogram", + description: "Time to the first normalized stream event.", + unit: "ms", + attributes: { provider, model }, + }, + "pi.ai.tokens": { + kind: "counter", + description: "Reported model token usage; pending and deferred polls are excluded.", + unit: "token", + attributes: { + provider, + model, + kind: { + type: "string", + description: "Token usage category.", + values: ["input", "output", "cache_read", "cache_write"], + required: true, + }, + }, + }, + "pi.ai.cost": { + kind: "counter", + description: "Reported model cost; pending and deferred polls are excluded.", + unit: "USD", + attributes: { provider, model }, + }, + }, +}); + +type RequestSpan = SchemaTelemetrySpan; + +function createInstruments(adapter: TelemetryMetrics) { + const metrics = createTypedMetrics(adapter, [AI_TELEMETRY_SCHEMA]); + return { + requestDuration: metrics.histogram("pi.ai.request.duration"), + firstChunkDuration: metrics.histogram("pi.ai.first_chunk.duration"), + tokens: metrics.counter("pi.ai.tokens"), + cost: metrics.counter("pi.ai.cost"), + }; +} + +const instrumentCache = new WeakMap>(); + +export function observeModelRequest( + requestedModel: Model, + options: { telemetry?: TelemetrySpan; reasoning?: unknown } | undefined, + poll: boolean, +): LazyStreamObserver { + const started = performance.now(); + const attributes = { provider: requestedModel.provider, model: requestedModel.id }; + const adapter = options?.telemetry?.metrics ?? NOOP_TELEMETRY_METRICS; + let instruments = instrumentCache.get(adapter); + if (!instruments) { + instruments = createInstruments(adapter); + instrumentCache.set(adapter, instruments); + } + const { requestDuration, firstChunkDuration, tokens, cost } = instruments; + let span!: RequestSpan; + let finish!: () => void; + let first = true; + const toolChars = new Map(); + const finished = new Promise((resolve) => { + finish = resolve; + }); + const run = (activeSpan: RequestSpan): Promise => { + span = activeSpan; + return finished; + }; + const startAttributes = { + ...attributes, + api: requestedModel.api, + ...(typeof options?.reasoning === "string" ? { reasoning: options.reasoning } : {}), + }; + const start = createTypedSpanStarter(options?.telemetry ?? NOOP_TELEMETRY_CONTEXT, [AI_TELEMETRY_SCHEMA]); + if (poll) void start("pi.ai.poll", startAttributes, run); + else void start("pi.ai.request", startAttributes, run); + + return { + onEvent(event) { + if (first) { + first = false; + span.addEvent("pi.ai.first_chunk"); + firstChunkDuration.record(performance.now() - started, attributes, span); + } + if (event.type === "toolcall_delta") { + toolChars.set(event.contentIndex, (toolChars.get(event.contentIndex) ?? 0) + event.delta.length); + } else if (event.type === "text_end" || event.type === "thinking_end") { + span.addEvent("pi.ai.block", { + type: event.type === "text_end" ? "text" : "thinking", + index: event.contentIndex, + chars: event.content.length, + }); + } else if (event.type === "toolcall_end") { + const chars = toolChars.get(event.contentIndex) ?? 0; + toolChars.delete(event.contentIndex); + span.addEvent("pi.ai.block", { + type: "tool_call", + index: event.contentIndex, + chars, + tool: event.toolCall.name, + }); + } + }, + onResult(message) { + if (message) { + span.setAttributes({ + stop: message.stopReason, + "usage.input": message.usage.input, + "usage.output": message.usage.output, + "usage.cache_read": message.usage.cacheRead, + "usage.cache_write": message.usage.cacheWrite, + "cost.total": message.usage.cost.total, + "response.id": message.responseId, + }); + if (message.stopReason === "error") { + span.setStatus({ + status: "error", + error: { name: "provider_error", message: message.errorMessage?.slice(0, 500) ?? "" }, + }); + } + requestDuration.record(performance.now() - started, { ...attributes, stop: message.stopReason }, span); + if (!poll || (message.stopReason !== "pending" && message.stopReason !== "deferred")) { + tokens.add(message.usage.input, { ...attributes, kind: "input" }); + tokens.add(message.usage.output, { ...attributes, kind: "output" }); + tokens.add(message.usage.cacheRead, { ...attributes, kind: "cache_read" }); + tokens.add(message.usage.cacheWrite, { ...attributes, kind: "cache_write" }); + cost.add(message.usage.cost.total, attributes); + } + } + finish(); + }, + }; +} diff --git a/packages/ai/src/types.ts b/packages/ai/src/types.ts index 302f95581..b729c1521 100644 --- a/packages/ai/src/types.ts +++ b/packages/ai/src/types.ts @@ -1,4 +1,4 @@ -import type { TelemetryContext } from "@earendil-works/pi-telemetry"; +import type { TelemetrySpan } from "@earendil-works/pi-telemetry"; import type { AnthropicOptions } from "./api/anthropic-messages.ts"; import type { AzureOpenAIResponsesOptions } from "./api/azure-openai-responses.ts"; import type { BedrockOptions } from "./api/bedrock-converse-stream.ts"; @@ -156,8 +156,8 @@ export interface ProviderResponse { /** Authentication, HTTP transport, and lifecycle callbacks shared by provider requests. */ export interface ProviderRequestOptions> { signal?: AbortSignal; - /** Explicit parent context for telemetry produced by this logical request. */ - telemetryContext?: TelemetryContext; + /** Explicit parent span for telemetry produced by this logical request. */ + telemetry?: TelemetrySpan; apiKey?: string; /** * Optional fetch implementation for provider HTTP requests. diff --git a/packages/ai/test/telemetry-options.test.ts b/packages/ai/test/telemetry-options.test.ts index 550d4d6e8..8d0be3a3c 100644 --- a/packages/ai/test/telemetry-options.test.ts +++ b/packages/ai/test/telemetry-options.test.ts @@ -1,4 +1,4 @@ -import { NOOP_TELEMETRY_CONTEXT, type TelemetryContext } from "@earendil-works/pi-telemetry"; +import { NOOP_TELEMETRY_CONTEXT, type TelemetrySpan } from "@earendil-works/pi-telemetry"; import { describe, expect, it } from "vitest"; import { buildBaseOptions } from "../src/api/simple-options.ts"; import { generateImages } from "../src/images.ts"; @@ -8,7 +8,7 @@ import type { DeferredHandle, ImageModel, ImagesContext, Model, ProviderRequestO import { AssistantMessageEventStream } from "../src/utils/event-stream.ts"; import { normalizeContext } from "../src/utils/transcript.ts"; -const telemetryContext: TelemetryContext = NOOP_TELEMETRY_CONTEXT; +const telemetry: TelemetrySpan = NOOP_TELEMETRY_CONTEXT; const context = normalizeContext({ messages: [] }); const imagesContext: ImagesContext = { input: [{ type: "text", text: "circle" }] }; @@ -65,15 +65,23 @@ function completedStream(requestModel: Model): AssistantMessageEventStre return stream; } -describe("ProviderRequestOptions.telemetryContext", () => { +describe("ProviderRequestOptions.telemetry", () => { it("is inherited by every request option surface and simple-stream conversion", () => { - const options = { telemetryContext } satisfies ProviderRequestOptions; - expect(options.telemetryContext).toBe(telemetryContext); - expect(buildBaseOptions(model, context, { telemetryContext }).telemetryContext).toBe(telemetryContext); + const options = { telemetry } satisfies ProviderRequestOptions; + expect(options.telemetry).toBe(telemetry); + expect(buildBaseOptions(model, context, { telemetry }).telemetry).toBe(telemetry); + const compileTimeFailures = () => { + const removed: ProviderRequestOptions = { + // @ts-expect-error telemetryContext was renamed, with no compatibility alias + telemetryContext: telemetry, + }; + return removed; + }; + expect(compileTimeFailures).toBeTypeOf("function"); }); it("survives provider and Models stream/deferred dispatch", async () => { - const observed: Array = []; + const observed: Array = []; const handle: DeferredHandle = { provider: model.provider, modelId: model.id, @@ -86,45 +94,45 @@ describe("ProviderRequestOptions.telemetryContext", () => { models: [model], api: { stream: (requestModel, _context, options) => { - observed.push(options?.telemetryContext); + observed.push(options?.telemetry); return completedStream(requestModel); }, streamSimple: (requestModel, _context, options) => { - observed.push(options?.telemetryContext); + observed.push(options?.telemetry); return completedStream(requestModel); }, fetchDeferred: (requestModel, _handle, options) => { - observed.push(options?.telemetryContext); + observed.push(options?.telemetry); return completedStream(requestModel); }, cancelDeferred: async (_requestModel, _handle, options) => { - observed.push(options?.telemetryContext); + observed.push(options?.telemetry); }, }, }); - await provider.stream(model, context, { telemetryContext }).result(); - await provider.streamSimple(model, context, { telemetryContext }).result(); - await provider.fetchDeferred!(model, handle, { telemetryContext }).result(); - await provider.cancelDeferred!(model, handle, { telemetryContext }); + await provider.stream(model, context, { telemetry }).result(); + await provider.streamSimple(model, context, { telemetry }).result(); + await provider.fetchDeferred!(model, handle, { telemetry }).result(); + await provider.cancelDeferred!(model, handle, { telemetry }); const models = createModels(); models.setProvider(provider); - await models.stream(model, context, { telemetryContext }).result(); - await models.streamSimple(model, context, { telemetryContext }).result(); - await models.fetchDeferred(model, handle, { telemetryContext }); - await models.cancelDeferred(model, handle, { telemetryContext }); + await models.stream(model, context, { telemetry }).result(); + await models.streamSimple(model, context, { telemetry }).result(); + await models.fetchDeferred(model, handle, { telemetry }); + await models.cancelDeferred(model, handle, { telemetry }); expect(observed).toHaveLength(8); - expect(observed.every((value) => value === telemetryContext)).toBe(true); + expect(observed.every((value) => value === telemetry)).toBe(true); }); it("survives direct and Models image dispatch", async () => { - const observed: Array = []; + const observed: Array = []; registerImagesApiProvider({ api: imageModel.api, generateImages: async (requestModel, _context, options) => { - observed.push(options?.telemetryContext); + observed.push(options?.telemetry); return { api: requestModel.api, provider: requestModel.provider, @@ -135,7 +143,7 @@ describe("ProviderRequestOptions.telemetryContext", () => { }; }, }); - await generateImages(imageModel, imagesContext, { telemetryContext }); + await generateImages(imageModel, imagesContext, { telemetry }); const models = createModels(); models.setProvider( @@ -146,7 +154,7 @@ describe("ProviderRequestOptions.telemetryContext", () => { images: { [imageModel.api]: { generateImages: async (requestModel, _context, options) => { - observed.push(options?.telemetryContext); + observed.push(options?.telemetry); return { api: requestModel.api, provider: requestModel.provider, @@ -160,8 +168,8 @@ describe("ProviderRequestOptions.telemetryContext", () => { }, }), ); - await models.generateImages(imageModel, imagesContext, { telemetryContext }); + await models.generateImages(imageModel, imagesContext, { telemetry }); - expect(observed).toEqual([telemetryContext, telemetryContext]); + expect(observed).toEqual([telemetry, telemetry]); }); }); diff --git a/packages/ai/test/telemetry.test.ts b/packages/ai/test/telemetry.test.ts new file mode 100644 index 000000000..41b9ba457 --- /dev/null +++ b/packages/ai/test/telemetry.test.ts @@ -0,0 +1,422 @@ +import { InMemoryTelemetryContext, type TelemetrySpan } from "@earendil-works/pi-telemetry"; +import { describe, expect, it, vi } from "vitest"; +import { lazyStream } from "../src/api/lazy.ts"; +import { AI_TELEMETRY_SCHEMA, createModels, createProvider } from "../src/models.ts"; +import { observeModelRequest } from "../src/telemetry.ts"; +import type { AssistantMessage, AssistantMessageEvent, DeferredHandle, Model } from "../src/types.ts"; +import { AssistantMessageEventStream } from "../src/utils/event-stream.ts"; + +const model: Model<"telemetry-test"> = { + id: "model", + name: "Model", + api: "telemetry-test", + provider: "test", + baseUrl: "https://example.test", + reasoning: true, + input: ["text"], + cost: { input: 1, output: 2, cacheRead: 3, cacheWrite: 4 }, + contextWindow: 1000, + maxTokens: 100, +}; +const handle: DeferredHandle = { provider: model.provider, modelId: model.id, api: model.api, id: "deferred-secret" }; + +function message(stopReason: AssistantMessage["stopReason"] = "stop"): AssistantMessage { + return { + role: "assistant", + api: model.api, + provider: model.provider, + model: model.id, + content: [ + { type: "text", text: "text-secret" }, + { type: "thinking", thinking: "thinking-secret" }, + { type: "toolCall", id: "call-secret", name: "lookup", arguments: { value: "argument-secret" } }, + ], + usage: { + input: 11, + output: 22, + cacheRead: 33, + cacheWrite: 44, + totalTokens: 110, + cost: { input: 0.1, output: 0.2, cacheRead: 0.3, cacheWrite: 0.4, total: 1 }, + }, + responseId: "response", + stopReason, + timestamp: Date.now(), + }; +} + +function events(result: AssistantMessage): AssistantMessageEvent[] { + const toolCall = result.content[2]; + if (toolCall.type !== "toolCall") throw new Error("Missing tool call"); + return [ + { type: "start", partial: result }, + { type: "text_delta", contentIndex: 0, delta: "text-secret", partial: result }, + { type: "text_end", contentIndex: 0, content: "text-secret", partial: result }, + { type: "thinking_end", contentIndex: 1, content: "thinking-secret", partial: result }, + { type: "toolcall_delta", contentIndex: 2, delta: '{"value":', partial: result }, + { type: "toolcall_delta", contentIndex: 2, delta: '"argument-secret"}', partial: result }, + { type: "toolcall_end", contentIndex: 2, toolCall, partial: result }, + result.stopReason === "error" || result.stopReason === "aborted" + ? { type: "error", reason: result.stopReason, error: result } + : { + type: "done", + reason: result.stopReason === "pending" ? "deferred" : result.stopReason, + message: result, + }, + ]; +} + +function setup(result: AssistantMessage = message()) { + const models = createModels(); + const streamEvents = events(result); + const respond = () => { + const stream = new AssistantMessageEventStream(); + for (const event of streamEvents) stream.push(event); + stream.end(result); + return stream; + }; + models.setProvider( + createProvider({ + id: model.provider, + models: [model], + auth: { apiKey: { name: "Test", resolve: async () => ({ auth: {} }) } }, + api: { stream: respond, streamSimple: respond, fetchDeferred: respond }, + }), + ); + return { models, streamEvents }; +} + +async function settled(telemetry: InMemoryTelemetryContext): Promise { + await vi.waitFor(() => expect(telemetry.getSpans().every((span) => span.settled)).toBe(true)); +} + +describe("AI telemetry", () => { + it.each(["stream", "streamSimple", "streamDeferred"] as const)( + "observes %s without changing delivered events or results", + async (method) => { + const telemetry = new InMemoryTelemetryContext(); + const result = message(); + const { models, streamEvents } = setup(result); + await telemetry.startSpan({ name: "caller" }, async (parent) => { + const stream = + method === "streamDeferred" + ? models.streamDeferred(model, handle, { telemetry: parent }) + : models[method](model, { messages: [] }, { telemetry: parent, reasoning: "high" }); + const received: AssistantMessageEvent[] = []; + for await (const event of stream) received.push(event); + expect(received).toEqual(streamEvents); + for (const [index, event] of received.entries()) expect(event).toBe(streamEvents[index]); + expect(await stream.result()).toBe(result); + }); + await settled(telemetry); + const [parent, span] = telemetry.getSpans(); + expect(span.name).toBe(method === "streamDeferred" ? "pi.ai.poll" : "pi.ai.request"); + expect(span.parentId).toBe(parent.id); + expect(span.attributes).toEqual({ + provider: "test", + api: "telemetry-test", + model: "model", + ...(method === "streamDeferred" ? {} : { reasoning: "high" }), + stop: "stop", + "usage.input": 11, + "usage.output": 22, + "usage.cache_read": 33, + "usage.cache_write": 44, + "cost.total": 1, + "response.id": "response", + }); + expect(span.events).toEqual([ + { name: "pi.ai.first_chunk", attributes: {} }, + { name: "pi.ai.block", attributes: { type: "text", index: 0, chars: 11 } }, + { name: "pi.ai.block", attributes: { type: "thinking", index: 1, chars: 15 } }, + { name: "pi.ai.block", attributes: { type: "tool_call", index: 2, chars: 27, tool: "lookup" } }, + ]); + expect(JSON.stringify(span)).not.toMatch( + /text-secret|thinking-secret|argument-secret|call-secret|deferred-secret/, + ); + const measurements = telemetry.getMetrics(); + expect(measurements).toHaveLength(7); + expect(measurements.filter((measurement) => measurement.kind === "counter").map(({ value }) => value)).toEqual( + [11, 22, 33, 44, 1], + ); + for (const measurement of measurements) { + expect(Object.keys(measurement.attributes).sort()).toEqual( + measurement.name === "pi.ai.tokens" + ? ["kind", "model", "provider"] + : measurement.name === "pi.ai.request.duration" + ? ["model", "provider", "stop"] + : ["model", "provider"], + ); + if (measurement.kind === "histogram") expect(measurement.context).toEqual(span.context); + } + }, + ); + + it.each(["error", "aborted"] as const)("reports %s status without error attributes or events", async (reason) => { + const telemetry = new InMemoryTelemetryContext(); + const result = { ...message(reason), errorMessage: "error-secret" }; + const { models } = setup(result); + expect( + await telemetry.startSpan({ name: "caller" }, (span) => + models.completeSimple(model, { messages: [] }, { telemetry: span }), + ), + ).toBe(result); + await settled(telemetry); + const [, span] = telemetry.getSpans(); + expect(span.status).toEqual( + reason === "error" + ? { status: "error", error: { name: "provider_error", message: "error-secret" } } + : { status: "ok" }, + ); + expect(span.attributes.stop).toBe(reason); + expect(JSON.stringify(span.attributes)).not.toContain("error-secret"); + expect(JSON.stringify(span.events)).not.toContain("error-secret"); + if (reason === "aborted") expect(JSON.stringify(span)).not.toContain("error-secret"); + }); + + it.each([false, true])("bounds poll error messages, including missing messages (missing=%s)", async (missing) => { + const telemetry = new InMemoryTelemetryContext(); + const result = message("error"); + if (!missing) result.errorMessage = `${"x".repeat(500)}discarded-tail`; + const { models } = setup(result); + expect( + await telemetry.startSpan({ name: "caller" }, (span) => + models.fetchDeferred(model, handle, { telemetry: span }), + ), + ).toBe(result); + await settled(telemetry); + const [, span] = telemetry.getSpans(); + expect(span.status).toEqual({ + status: "error", + error: { name: "provider_error", message: missing ? "" : "x".repeat(500) }, + }); + expect(JSON.stringify(span)).not.toContain("discarded-tail"); + expect(JSON.stringify(span.attributes)).not.toContain("xxx"); + expect(JSON.stringify(span.events)).not.toContain("xxx"); + }); + + it("includes setup failures and omits non-scalar native reasoning", async () => { + const telemetry = new InMemoryTelemetryContext(); + const models = createModels(); + const result = await telemetry.startSpan({ name: "caller" }, (span) => + models.complete( + model, + { messages: [] }, + { + telemetry: span, + reasoning: { effort: "native-secret" }, + }, + ), + ); + expect(result.stopReason).toBe("error"); + await settled(telemetry); + const [, span] = telemetry.getSpans(); + expect(span.attributes).not.toHaveProperty("reasoning"); + expect(span.events).toEqual([{ name: "pi.ai.first_chunk", attributes: {} }]); + expect(span.status).toEqual({ + status: "error", + error: { name: "provider_error", message: "Unknown provider: test" }, + }); + expect(JSON.stringify(span.attributes)).not.toContain("Unknown provider"); + expect(JSON.stringify(span)).not.toContain("native-secret"); + }); + + it("counts interleaved tool deltas independently without reading arguments", async () => { + const telemetry = new InMemoryTelemetryContext(); + const result = message(); + await telemetry.startSpan({ name: "caller" }, (span) => { + const observer = observeModelRequest(model, { telemetry: span }, false); + const toolCall = { + type: "toolCall" as const, + id: "call", + name: "lookup", + get arguments(): Record { + throw new Error("Telemetry must not inspect or serialize arguments"); + }, + }; + for (const [index, delta] of [ + [2, "ab"], + [3, "123"], + [2, "c"], + ] as const) { + observer.onEvent?.({ type: "toolcall_delta", contentIndex: index, delta, partial: result }); + } + observer.onEvent?.({ type: "toolcall_end", contentIndex: 3, toolCall, partial: result }); + observer.onEvent?.({ type: "toolcall_end", contentIndex: 2, toolCall, partial: result }); + observer.onEvent?.({ type: "toolcall_end", contentIndex: 4, toolCall, partial: result }); + observer.onResult?.(result); + }); + await settled(telemetry); + expect(telemetry.getSpans()[1].events.slice(1)).toEqual([ + { name: "pi.ai.block", attributes: { type: "tool_call", index: 3, chars: 3, tool: "lookup" } }, + { name: "pi.ai.block", attributes: { type: "tool_call", index: 2, chars: 3, tool: "lookup" } }, + { name: "pi.ai.block", attributes: { type: "tool_call", index: 4, chars: 0, tool: "lookup" } }, + ]); + }); + + it("supports a tracing-only span without metric capabilities", async () => { + const adapter = new InMemoryTelemetryContext(); + const { models } = setup(); + await adapter.startSpan({ name: "caller" }, (span) => { + const telemetry: TelemetrySpan = { ...span, metrics: undefined }; + return models.completeSimple(model, { messages: [] }, { telemetry }); + }); + await settled(adapter); + expect(adapter.getSpans()).toHaveLength(2); + expect(adapter.getMetrics()).toEqual([]); + }); + + it("defaults to no-op telemetry", async () => { + const { models } = setup(); + expect((await models.completeSimple(model, { messages: [] })).stopReason).toBe("stop"); + expect(AI_TELEMETRY_SCHEMA.spans["pi.ai.request"].startAttributes.provider.required).toBe(true); + }); + + it("records low-cardinality metrics with monotonic durations", async () => { + const telemetry = new InMemoryTelemetryContext(); + const result = message(); + let clock = 100; + const monotonic = vi.spyOn(performance, "now").mockImplementation(() => clock); + try { + await telemetry.startSpan({ name: "caller" }, (span) => { + const observer = observeModelRequest(model, { telemetry: span }, false); + clock = 125; + observer.onEvent?.({ type: "start", partial: result }); + clock = 175; + observer.onResult?.(result); + }); + await settled(telemetry); + } finally { + monotonic.mockRestore(); + } + const metrics = telemetry.getMetrics(); + expect(metrics.map(({ name, value, attributes, unit }) => ({ name, value, attributes, unit }))).toEqual([ + { + name: "pi.ai.first_chunk.duration", + value: 25, + attributes: { provider: "test", model: "model" }, + unit: "ms", + }, + { + name: "pi.ai.request.duration", + value: 75, + attributes: { provider: "test", model: "model", stop: "stop" }, + unit: "ms", + }, + ...[ + ["input", 11], + ["output", 22], + ["cache_read", 33], + ["cache_write", 44], + ].map(([kind, value]) => ({ + name: "pi.ai.tokens", + value, + attributes: { provider: "test", model: "model", kind }, + unit: "token", + })), + { name: "pi.ai.cost", value: 1, attributes: { provider: "test", model: "model" }, unit: "USD" }, + ]); + expect(metrics.slice(0, 2).every((measurement) => measurement.context !== null)).toBe(true); + }); + + it.each(["pending", "deferred", "stop", "error"] as const)( + "records usage for a %s poll only when final", + async (reason) => { + const telemetry = new InMemoryTelemetryContext(); + const { models } = setup(message(reason)); + await telemetry.startSpan({ name: "caller" }, (span) => + models.fetchDeferred(model, handle, { telemetry: span }), + ); + await settled(telemetry); + const counters = telemetry.getMetrics().filter((metric) => metric.kind === "counter"); + expect(counters).toHaveLength(reason === "pending" || reason === "deferred" ? 0 : 5); + }, + ); + + it("creates instruments once per metrics object across root and child requests", async () => { + const telemetry = new InMemoryTelemetryContext(); + const histogram = vi.spyOn(telemetry, "histogram"); + const counter = vi.spyOn(telemetry, "counter"); + const { models } = setup(); + await telemetry.startSpan({ name: "caller" }, (span) => + models.completeSimple(model, { messages: [] }, { telemetry: span }), + ); + await telemetry.startSpan({ name: "caller" }, (span) => models.fetchDeferred(model, handle, { telemetry: span })); + await telemetry.startSpan({ name: "caller" }, (span) => + models.complete(model, { messages: [] }, { telemetry: span }), + ); + await settled(telemetry); + expect(histogram.mock.calls.map(([name]) => name)).toEqual([ + "pi.ai.request.duration", + "pi.ai.first_chunk.duration", + ]); + expect(counter.mock.calls.map(([name]) => name)).toEqual(["pi.ai.tokens", "pi.ai.cost"]); + expect(telemetry.getMetrics()).toHaveLength(21); + }); +}); + +describe("lazyStream observation", () => { + it("uses one source iterator and observes after push, once per terminal result", async () => { + const result = message(); + const order: string[] = []; + let iterators = 0; + const source = { + async *[Symbol.asyncIterator]() { + iterators++; + yield { type: "done", reason: "stop", message: result } as const; + }, + result: async () => result, + }; + const stream = lazyStream(model, async () => source, { + onEvent: () => { + order.push("event"); + void stream.result().then(() => order.push("resolved")); + }, + onResult: (received) => { + expect(received).toBe(result); + order.push("result"); + }, + }); + expect(await stream.result()).toBe(result); + await vi.waitFor(() => expect(order).toEqual(["event", "resolved", "result"])); + expect(iterators).toBe(1); + }); + + it("reports a terminal result from an iterable without a result method", async () => { + const result = message(); + const observed: Array = []; + const source = { + async *[Symbol.asyncIterator]() { + yield { type: "done", reason: "stop", message: result } as const; + }, + }; + const stream = lazyStream(model, async () => source, { onResult: (value) => observed.push(value) }); + expect(await stream.result()).toBe(result); + await vi.waitFor(() => expect(observed).toEqual([result])); + }); + + it("observes a result-only source once", async () => { + const result = message(); + const observed: Array = []; + const source = { async *[Symbol.asyncIterator]() {}, result: async () => result }; + const stream = lazyStream(model, async () => source, { onResult: (value) => observed.push(value) }); + expect(await stream.result()).toBe(result); + expect(observed).toEqual([result]); + }); + + it("reports setup failure events and the result once", async () => { + const observed: string[] = []; + const stream = lazyStream( + model, + async () => { + throw new Error("setup-secret"); + }, + { + onEvent: (event) => observed.push(event.type), + onResult: (result) => observed.push(result?.stopReason ?? "missing"), + }, + ); + expect((await stream.result()).errorMessage).toBe("setup-secret"); + expect(observed).toEqual(["error", "error"]); + }); +}); diff --git a/packages/chord/CHANGELOG.md b/packages/chord/CHANGELOG.md index 0ad555288..8bd28808e 100644 --- a/packages/chord/CHANGELOG.md +++ b/packages/chord/CHANGELOG.md @@ -4,7 +4,7 @@ ### Breaking Changes -- Custom `Context` implementations must provide `telemetry: TelemetryContext`; use `NOOP_TELEMETRY_CONTEXT` when disabled. +- Custom `Context` implementations must provide `telemetry: TelemetrySpan`; use the no-op span `NOOP_TELEMETRY_CONTEXT` when disabled. `withTelemetry()` accepts spans, not adapters. ### Added diff --git a/packages/chord/README.md b/packages/chord/README.md index d05dc79f6..b3d2dc906 100644 --- a/packages/chord/README.md +++ b/packages/chord/README.md @@ -71,21 +71,23 @@ await host.root(async (ctx) => { ## Explicit Context telemetry -`Context` has a fixed `telemetry: TelemetryContext` member, alongside `abortSignal`. It is never undefined: `BACKGROUND_CONTEXT` and `TODO_CONTEXT` use `NOOP_TELEMETRY_CONTEXT` from `@earendil-works/pi-telemetry`. +`Context` always carries a `telemetry: TelemetrySpan`, alongside `abortSignal`. `BACKGROUND_CONTEXT` and `TODO_CONTEXT` use the shared no-op span `NOOP_TELEMETRY_CONTEXT`. Adapters (`TelemetryContext`) belong to hosts and start root spans; adapters are never placed in a `Context`. ```ts import { BACKGROUND_CONTEXT, traceIn, withTelemetry } from '@earendil-works/chord/context'; import { InMemoryTelemetryContext } from '@earendil-works/pi-telemetry'; const telemetry = new InMemoryTelemetryContext(); -const context = withTelemetry(telemetry, BACKGROUND_CONTEXT); -await traceIn(context, { name: 'app.load' }, async (child) => { - child.telemetry.addEvent('cache.miss'); - return traceIn(child, { name: 'app.read' }, (nested) => readAccount(nested)); +await telemetry.startSpan({ name: 'app.request' }, async (span) => { + const context = withTelemetry(span, BACKGROUND_CONTEXT); + await traceIn(context, { name: 'app.load' }, async (child) => { + child.telemetry.addEvent('cache.miss'); + return traceIn(child, { name: 'app.read' }, (nested) => readAccount(nested)); + }); }); ``` -`withTelemetry(telemetry, context)` derives a new context; it never changes its parent, cancellation, or typed values. `traceIn(context, options, fn)` creates a callback-managed child span, and `fn` receives the derived context with `telemetry` narrowed to `TelemetrySpan`, including `addLink()`. Values, cancellation, callback results, and rejection identities are preserved. Concurrent calls keep independent parents; there is no ambient current span. `value()`, `ContextKey`, and `withContextValue()` remain supported. +`withTelemetry(span, context)` derives a new context; it never changes its parent, cancellation, or typed values. `traceIn(context, options, fn)` creates a callback-managed child span, and `fn` receives its derived context. Every context already supports `telemetry.addEvent()` and `telemetry.addLink()`. Values, cancellation, callback results, and rejection identities are preserved. Concurrent calls keep independent parents; there is no ambient current span. `value()`, `ContextKey`, and `withContextValue()` remain supported. These helpers operate on the standalone `Context` API. They do not yet instrument Chord hosts, methods, or network frames. diff --git a/packages/chord/src/context/index.ts b/packages/chord/src/context/index.ts index 9df2bc23b..7e8da6688 100644 --- a/packages/chord/src/context/index.ts +++ b/packages/chord/src/context/index.ts @@ -1,9 +1,4 @@ -import { - NOOP_TELEMETRY_CONTEXT, - type SpanOptions, - type TelemetryContext, - type TelemetrySpan, -} from "@earendil-works/pi-telemetry"; +import { NOOP_TELEMETRY_CONTEXT, type SpanOptions, type TelemetrySpan } from "@earendil-works/pi-telemetry"; /** Typed identity for one value carried by a {@link Context}. */ export interface ContextKey { @@ -15,7 +10,7 @@ export interface ContextKey { /** Immutable invocation-scoped values passed explicitly through operations. */ export interface Context { readonly abortSignal: AbortSignal | undefined; - readonly telemetry: TelemetryContext; + readonly telemetry: TelemetrySpan; value(key: ContextKey): T | undefined; toString(): string; } @@ -24,7 +19,7 @@ const ABORT_SIGNAL_CONTEXT_KEY: ContextKey = Object.fre token: Symbol("chord.abortSignal"), }); -const TELEMETRY_CONTEXT_KEY: ContextKey = Object.freeze({ +const TELEMETRY_CONTEXT_KEY: ContextKey = Object.freeze({ token: Symbol("chord.telemetry"), }); @@ -36,7 +31,7 @@ abstract class BaseContext implements Context { return this.value(ABORT_SIGNAL_CONTEXT_KEY); } - get telemetry(): TelemetryContext { + get telemetry(): TelemetrySpan { return this.value(TELEMETRY_CONTEXT_KEY) ?? NOOP_TELEMETRY_CONTEXT; } } @@ -93,7 +88,7 @@ export function withContextValue(key: ContextKey, value: T, parent: Contex } /** Derive an explicit telemetry parent without changing cancellation or application values. */ -export function withTelemetry( +export function withTelemetry( telemetry: T, context: Context, ): Context & { readonly telemetry: T } { @@ -104,7 +99,7 @@ export function withTelemetry( export function traceIn( context: Context, options: SpanOptions, - fn: (context: Context & { readonly telemetry: TelemetrySpan }) => T | Promise, + fn: (context: Context) => T | Promise, ): Promise { return context.telemetry.startSpan(options, (span) => fn(withTelemetry(span, context))); } diff --git a/packages/chord/test/context.test.ts b/packages/chord/test/context.test.ts index d45b88d89..e9a51a744 100644 --- a/packages/chord/test/context.test.ts +++ b/packages/chord/test/context.test.ts @@ -78,70 +78,76 @@ describe("Context", () => { it("derives telemetry independently from values and cancellation", async () => { const telemetry = new InMemoryTelemetryContext(); const other = new InMemoryTelemetryContext(); - const key = createContextKey("principal"); - const controller = new AbortController(); - const base = withContextValue(key, "owner", withAbortSignal(controller.signal, BACKGROUND_CONTEXT)); - const context = withTelemetry(telemetry, base); - const replaced = withTelemetry(other, context); - expect(base.telemetry).toBe(NOOP_TELEMETRY_CONTEXT); - expect(context.telemetry).toBe(telemetry); - expect(replaced.telemetry).toBe(other); - expect(replaced.value(key)).toBe("owner"); - expect(replaced.abortSignal).toBe(base.abortSignal); - expect(withoutAbortSignal(context).telemetry).toBe(telemetry); - await traceIn(context, { name: "outer" }, async (child) => { - expect(child.value(key)).toBe("owner"); - expect(child.abortSignal).toBe(context.abortSignal); - child.telemetry.addEvent("started"); - await traceIn(child, { name: "inner" }, (nested) => { - nested.telemetry.addLink({ context: child.telemetry }); - return 42; - }); - }); - const [outer, inner] = telemetry.getSpans(); - expect(outer?.parentId).toBeNull(); - expect(inner?.parentId).toBe(outer?.id); - expect(inner?.links[0]?.context).toEqual(outer?.context); - expect(context.telemetry).toBe(telemetry); - controller.abort(); - expect(context.abortSignal?.aborted).toBe(true); + await telemetry.startSpan({ name: "caller" }, (parent) => + other.startSpan({ name: "other" }, async (otherSpan) => { + const key = createContextKey("principal"); + const controller = new AbortController(); + const base = withContextValue(key, "owner", withAbortSignal(controller.signal, BACKGROUND_CONTEXT)); + const context = withTelemetry(parent, base); + const replaced = withTelemetry(otherSpan, context); + expect(base.telemetry).toBe(NOOP_TELEMETRY_CONTEXT); + expect(context.telemetry).toBe(parent); + expect(replaced.telemetry).toBe(otherSpan); + expect(replaced.value(key)).toBe("owner"); + expect(replaced.abortSignal).toBe(base.abortSignal); + expect(withoutAbortSignal(context).telemetry).toBe(parent); + await traceIn(context, { name: "outer" }, async (child) => { + expect(child.value(key)).toBe("owner"); + expect(child.abortSignal).toBe(context.abortSignal); + child.telemetry.addEvent("started"); + await traceIn(child, { name: "inner" }, (nested) => { + nested.telemetry.addLink({ context: child.telemetry }); + return 42; + }); + }); + const [caller, outer, inner] = telemetry.getSpans(); + expect(outer?.parentId).toBe(caller?.id); + expect(inner?.parentId).toBe(outer?.id); + expect(inner?.links[0]?.context).toEqual(outer?.context); + expect(context.telemetry).toBe(parent); + controller.abort(); + expect(context.abortSignal?.aborted).toBe(true); + }), + ); }); it("isolates concurrent traceIn branches and preserves callback results and errors", async () => { const telemetry = new InMemoryTelemetryContext(); - const context = withTelemetry(telemetry, BACKGROUND_CONTEXT); - let release: (() => void) | undefined; - const gate = new Promise((resolve) => { - release = resolve; + await telemetry.startSpan({ name: "caller" }, async (parent) => { + const context = withTelemetry(parent, BACKGROUND_CONTEXT); + let release: (() => void) | undefined; + const gate = new Promise((resolve) => { + release = resolve; + }); + const first = traceIn(context, { name: "first" }, async (child) => { + await gate; + return traceIn(child, { name: "first.child" }, () => "first"); + }); + const second = traceIn(context, { name: "second" }, async (child) => { + const result = await traceIn(child, { name: "second.child" }, () => "second"); + release?.(); + return result; + }); + expect(await Promise.all([first, second])).toEqual(["first", "second"]); + const spans = telemetry.getSpans(); + for (const name of ["first", "second"]) { + const parent = spans.find((span) => span.name === name); + expect(spans.find((span) => span.name === `${name}.child`)?.parentId).toBe(parent?.id); + } + const failure = { reason: "same value" }; + await expect( + traceIn(context, { name: "throw" }, () => { + throw failure; + }), + ).rejects.toBe(failure); + await expect(traceIn(context, { name: "reject" }, () => Promise.reject(failure))).rejects.toBe(failure); + expect( + await traceIn(BACKGROUND_CONTEXT, { name: "noop" }, (child) => { + child.telemetry.addLink({ context: parent }); + return 42; + }), + ).toBe(42); }); - const first = traceIn(context, { name: "first" }, async (child) => { - await gate; - return traceIn(child, { name: "first.child" }, () => "first"); - }); - const second = traceIn(context, { name: "second" }, async (child) => { - const result = await traceIn(child, { name: "second.child" }, () => "second"); - release?.(); - return result; - }); - expect(await Promise.all([first, second])).toEqual(["first", "second"]); - const spans = telemetry.getSpans(); - for (const name of ["first", "second"]) { - const parent = spans.find((span) => span.name === name); - expect(spans.find((span) => span.name === `${name}.child`)?.parentId).toBe(parent?.id); - } - const failure = { reason: "same value" }; - await expect( - traceIn(context, { name: "throw" }, () => { - throw failure; - }), - ).rejects.toBe(failure); - await expect(traceIn(context, { name: "reject" }, () => Promise.reject(failure))).rejects.toBe(failure); - expect( - await traceIn(BACKGROUND_CONTEXT, { name: "noop" }, (child) => { - child.telemetry.addLink({ context: telemetry }); - return 42; - }), - ).toBe(42); }); it("stops waiting when the invocation is cancelled", async () => { diff --git a/packages/durable/CHANGELOG.md b/packages/durable/CHANGELOG.md index 419fc31f9..27536a160 100644 --- a/packages/durable/CHANGELOG.md +++ b/packages/durable/CHANGELOG.md @@ -12,7 +12,7 @@ ### Added -- `HarnessOptions.telemetry` accepts a host-owned telemetry context with optional propagation and metrics capabilities. This change adds the configuration type only; Durable instrumentation and persisted carriers are not yet implemented. +- `HarnessOptions.telemetry` emits the content-free `DURABLE_TELEMETRY_SCHEMA`: public submission admission spans, task phase spans (including extension tasks), committed entry and submission events, running phase-change checkpoints, and nested-tool replay events. Optional propagation stores opaque carriers on submissions and tasks so queued inputs and reopened tasks retain their trace; `TaskOptions.trace` accepts a carrier override or `"root"` (absence inherits the creator's carrier); creation-time `links` connect inputs sharing a run, while steer admissions link to the running trace. Internal admissions emit events without a submit span. Optional metrics record phase duration and live task counts. Failed phases record fixed error-status categories (`task_faulted`, `task_failed`, `task_orphaned`) and diagnostics capped at 500 characters; aborted phases keep status `ok`. Every `onReport` report also emits a fixed-field `pi.durable.report` event on its current span (dropped by the NOOP span when there is none), plus a `pi.durable.reports` counter by type; report telemetry contains no error payload and leaves the callback unchanged. Clock failures report without a phase context. Generation and compaction forward their phase context to pi-ai requests. - `settings.compaction.modelOverrides` sets compaction thresholds per model, keyed by exact `"provider/modelId"`, so one harness can serve small- and large-window models; the threshold check, overflow recovery, and the compaction task use the entry of the model they act for ([#10942](https://github.com/earendil-works/pi/issues/10942)). - Durable sleeps: a sleeping task holds no invocation, survives restarts, and resumes at its checkpoint once the Harness clock reaches `until`. - `HarnessOptions.setTimer` arms the timers of the Session, the scheduler, and its tasks (progress throttles, idle-memory eviction, sleeps), also for `createSession()`; with `now`, they run on a host or fake clock. A foreground timer the host throws on or declines falls back to `setTimeout`. `ToolExecutionApi.now()` reads the Harness clock. diff --git a/packages/durable/README.md b/packages/durable/README.md index c3f3d3521..60b50ed3d 100644 --- a/packages/durable/README.md +++ b/packages/durable/README.md @@ -75,9 +75,17 @@ What happened: - `submit()` durably admits your input and returns a `Submission`. A built-in generation task calls the model and appends the answer. - `wait()` resolves once the input is answered (`done`) or has failed (`unanswered`, with a reason). -Every async call takes a Chord `Context`, which carries cancellation and explicit telemetry. `BACKGROUND_CONTEXT` never cancels and uses no-op telemetry. Cancelling a wait only cancels that wait, never the work. +Every async call takes a Chord `Context`, which carries cancellation and its current `TelemetrySpan`. `BACKGROUND_CONTEXT` never cancels and uses a NOOP span. The Harness owns the root adapter; adapters are never stored in a `Context`. Cancelling a wait only cancels that wait, never the work. -`HarnessOptions.telemetry` accepts a host-owned `TelemetryContext` adapter, optionally implementing `TelemetryPropagation` and `TelemetryMetrics`, from `@earendil-works/pi-telemetry`. This reserves the adapter configuration boundary; Durable currently emits no spans or metrics and does not persist carriers. Its instrumentation and schema are separate work. +`HarnessOptions.telemetry` accepts a host-owned `TelemetryContext` from `@earendil-works/pi-telemetry`, with optional `propagation` and `metrics` capabilities; omitted, it is a no-op. `DURABLE_TELEMETRY_SCHEMA`, exported from the package root, documents its typed spans, events, and metrics. Attributes contain IDs and control metadata, never messages, arguments, or results; IDs point to the transcript. + +- `pi.durable.submit` covers the public submit call and its commit. Each input starts a new root trace with a link to its caller's current span; a write is a child of its caller. Duplicate `requestId` preserves the original submission and carrier. Internal admissions, such as compaction writes, emit events on their phase span without a submit span. +- `pi.durable.phase` covers one run or abort phase of every task, including its decision commit, never the next phase, a durable wait, or a restart. Its attributes identify the task, phase, attempt when present, `resumed`, and outcome. Tool phases also identify the tool and call. Nested tasks and background compactions inherit the creating phase; model requests receive that phase context. Hooks add no spans. +- Failed phase outcomes set error status with a fixed category (`task_faulted`, `task_failed`, or `task_orphaned`) and the outcome's diagnostic message, truncated to 500 characters (the reason for an orphaned task). Diagnostics can contain caller content; no error detail or exception name is recorded. An `aborted` outcome keeps status `ok`, including interruption by close or cancellation. +- Every `onReport` report also emits a `pi.durable.report` event on its current span. Without a span, the NOOP span drops the event; no root report span is created. Only `type`, optional fixed `reason`, `extension`, and `task.id` are recorded; no error payload is included. `pi.durable.reports` counts all reports by `type` only, including those without a span. Clock failures report without a phase context. The `onReport` callback is unchanged. +- Committed entries and settled submissions emit `pi.durable.entry` and `pi.durable.submission`. Committed running phase changes emit `pi.durable.checkpoint`; a nested call answered from its stored result emits `pi.durable.replay`. +- Propagation stores optional opaque `trace` carriers in submission and task JSON without a storage migration. Phase spans extract their task's stored carrier, or start at the adapter root when absent or unknown. `TaskOptions.trace` inherits the creator's carrier when absent, accepts an explicit carrier override, or uses `"root"` to start at the adapter root without storing a carrier. A run started for several queued inputs takes the first input's trace; its first invocation's phase spans link to the other inputs through immutable task `links`. A steer stays in the running trace and its submit span links to that run's stored carrier. A reopened task's first invocation has `resumed: true` in the same trace. +- Metrics record `pi.durable.phase.duration` (milliseconds; task, phase, outcome) and `pi.durable.tasks.active` (live tasks; task name), without record IDs. Closing the Harness releases its active counts. ## Concepts diff --git a/packages/durable/src/codemode/models.ts b/packages/durable/src/codemode/models.ts index 047d40062..ca22e96ea 100644 --- a/packages/durable/src/codemode/models.ts +++ b/packages/durable/src/codemode/models.ts @@ -261,6 +261,7 @@ export function createModelTools(): ToolRegistration[] { const model = resolveModel("models.classify", "classifier", args.model, api.models); const checked = checkClassifierContext(args.context); const result = await api.models.classify(model, checked, { + telemetry: context.telemetry, ...(context.abortSignal === undefined ? {} : { signal: context.abortSignal }), }); return modelResult(`classify ${model.provider}/${model.id}`, result, result); @@ -276,6 +277,7 @@ export function createModelTools(): ToolRegistration[] { const model = resolveModel("models.generateImages", "image", args.model, api.models); const checked = checkImagesContext(args.context); const result = await api.models.generateImages(model, checked, { + telemetry: context.telemetry, ...(context.abortSignal === undefined ? {} : { signal: context.abortSignal }), }); return modelResult(`generateImages ${model.provider}/${model.id}`, result, result); diff --git a/packages/durable/src/harness/compaction.ts b/packages/durable/src/harness/compaction.ts index 9196f967b..b7376a882 100644 --- a/packages/durable/src/harness/compaction.ts +++ b/packages/durable/src/harness/compaction.ts @@ -177,6 +177,7 @@ export const CompactionTask = defineTask runtime.now()) return runtime.sleepUntil(pollAt, task.state.checkpoint, context); const model = runtime.models.getModel(ref.provider, ref.modelId); if (model === undefined) return failNoModel(runtime, ref, context); - const message = await runtime.models.fetchDeferred(model, handle, { signal: runtime.signal }); + const message = await runtime.models.fetchDeferred(model, handle, { + signal: runtime.signal, + telemetry: context.telemetry, + }); const request = { attempt, compacted, model: ref, cutoff, pollAt }; await classify(runtime, request, message, context); }, @@ -282,7 +287,10 @@ export const GenerationTask = defineTask, inputs: SubmissionId[], ): Promise { - live.run = { taskId: await createGeneration(tx, conversationId), inputs }; + live.run = { taskId: await createGeneration(tx, conversationId, { submissionIds: inputs }), inputs }; } /** A generation owned by its conversation. */ -function createGeneration(tx: Tx, conversationId: ConversationId): Promise> { - return tx.createTask(GenerationTask, {}, { ownership: { kind: "conversation" }, conversationId }); +function createGeneration( + tx: Tx, + conversationId: ConversationId, + telemetry: Pick = {}, +): Promise> { + return tx.createTask(GenerationTask, {}, { ownership: { kind: "conversation" }, conversationId, ...telemetry }); } /** Hand run control from `from` to `to`; the run's inputs move with it. */ diff --git a/packages/durable/src/harness/harness.ts b/packages/durable/src/harness/harness.ts index ea4762572..6f368b0e6 100644 --- a/packages/durable/src/harness/harness.ts +++ b/packages/durable/src/harness/harness.ts @@ -1,6 +1,13 @@ import type { AttachedReplicatedState, Context, JsonValue } from "@earendil-works/chord"; import { withAbortSignal, withoutAbortSignal } from "@earendil-works/chord/context"; import type { Models } from "@earendil-works/pi-ai"; +import { + createTypedMetrics, + NOOP_TELEMETRY_CONTEXT, + NOOP_TELEMETRY_METRICS, + type SpanAttributes, + type TelemetryContext, +} from "@earendil-works/pi-telemetry"; import { ResetEntry } from "../entries.ts"; import type { ExecutionEnv } from "../env/index.ts"; import { contained, SessionImpl } from "../session/session.ts"; @@ -33,6 +40,7 @@ import { BUILTIN_TASKS } from "./registry.ts"; import { type InvocationBinding, TaskScheduler } from "./scheduler.ts"; import { Submissions } from "./submissions.ts"; import { type TaskGraph, TaskGraphView, type TaskGraphWatch } from "./task-graph.ts"; +import { DURABLE_TELEMETRY_SCHEMA } from "./telemetry.ts"; import type { Agent, AgentChange, @@ -184,14 +192,14 @@ function currentSettings(settings: HarnessOptions["settings"]): () => HarnessSet class HarnessImpl extends SessionImpl implements HarnessType { readonly #options: HarnessOptions; readonly #hostSettings: () => HarnessSettings | undefined; - readonly #report: (error: unknown, info: ReportInfo) => void; + readonly #report: (error: unknown, info: ReportInfo, context?: Context) => void; readonly #host: ConversationHost; readonly #tasks: TaskScheduler; readonly #submissions: Submissions; readonly #taskGraph: TaskGraphView; constructor(rawStorage: Storage, options: HarnessOptions, context: Context) { - const report = safeReport(options.onReport); + const report = safeReport(options.onReport, options.telemetry ?? NOOP_TELEMETRY_CONTEXT); const now = safeNow(options.now, report); const hostSettings = currentSettings(options.settings); // Read at each use, as all settings are, but only this field: it is read on every commit. @@ -203,6 +211,7 @@ class HarnessImpl extends SessionImpl implements this.#hostSettings = hostSettings; const settings = () => resolveSettings(hostSettings()); this.#tasks = new TaskScheduler({ + telemetry: options.telemetry, session: this, storage, registry: options.registry, @@ -223,7 +232,7 @@ class HarnessImpl extends SessionImpl implements }, context: withoutAbortSignal(context), }); - this.#submissions = new Submissions(this, storage, now, settings, () => this.#tasks.resume()); + this.#submissions = new Submissions(this, storage, now, settings, () => this.#tasks.resume(), options.telemetry); this.#taskGraph = new TaskGraphView(this, storage, { blocked: (record) => this.#tasks.blockedReason(record), subscribeBlocked: (listener) => this.#tasks.subscribeBlocked(listener), @@ -248,7 +257,7 @@ class HarnessImpl extends SessionImpl implements const registry = snapshot ?? this.#options.registry.snapshot(); const state = await this.snapshot(AgentDoc, id, context); return resolveAgent(state, registry, resolveSettings(this.#hostSettings()), (error, extension) => - this.#report(error, { type: "extension_error", conversationId: id, extension }), + this.#report(error, { type: "extension_error", conversationId: id, extension }, context), ); } @@ -365,8 +374,8 @@ class HarnessImpl extends SessionImpl implements return this.#create({ kind: "independent", ownership: options.ownership }, options, context); } - override report(error: unknown, info: ReportInfo = { type: "listener_error" }): void { - this.#report(error, info); + override report(error: unknown, info: ReportInfo = { type: "listener_error" }, context?: Context): void { + this.#report(error, info, context); } /** Signal and join task invocations after the close listeners and before Storage closes; writes no task outcome. */ @@ -408,15 +417,43 @@ class HarnessImpl extends SessionImpl implements } } -/** `onReport` that cannot fail: it is the last place an error goes, so its own throw or rejection is dropped. */ +/** Preserve the host callback's error containment; telemetry adapters are responsible for their own failures. */ function safeReport( onReport: ((error: unknown, info: ReportInfo) => void) | undefined, -): (error: unknown, info: ReportInfo) => void { - return (error, info) => + telemetry: TelemetryContext, +): (error: unknown, info: ReportInfo, context?: Context) => void { + const reports = createTypedMetrics(telemetry.metrics ?? NOOP_TELEMETRY_METRICS, [DURABLE_TELEMETRY_SCHEMA]).counter( + "pi.durable.reports", + ); + return (error, info, context) => { contained( () => onReport?.(error, info), () => {}, ); + const attributes: SpanAttributes = { + type: info.type, + }; + switch (info.type) { + case "task_faulted": + case "task_outdated": + attributes.reason = info.reason; + attributes.extension = info.extension; + attributes["task.id"] = info.task.id; + break; + case "task_parked": + case "migration_failed": + case "task_error": + case "extension_error": + attributes.extension = info.extension; + attributes["task.id"] = info.task?.id; + break; + case "host_error": + attributes["task.id"] = info.task?.id; + break; + } + reports.add(1, { type: info.type }); + context?.telemetry.addEvent("pi.durable.report", attributes); + }; } /** diff --git a/packages/durable/src/harness/scheduler.ts b/packages/durable/src/harness/scheduler.ts index f41557584..23951e899 100644 --- a/packages/durable/src/harness/scheduler.ts +++ b/packages/durable/src/harness/scheduler.ts @@ -1,6 +1,13 @@ import { type Context, copyJson, type JsonValue } from "@earendil-works/chord"; -import { awaitWithContext, withAbortSignal } from "@earendil-works/chord/context"; +import { awaitWithContext, withAbortSignal, withoutAbortSignal, withTelemetry } from "@earendil-works/chord/context"; import type { Models } from "@earendil-works/pi-ai"; +import { + createTypedMetrics, + createTypedSpanStarter, + NOOP_TELEMETRY_CONTEXT, + NOOP_TELEMETRY_METRICS, + type TelemetryCarrier, +} from "@earendil-works/pi-telemetry"; import type { ExecutionEnv } from "../env/index.ts"; import { errorMessage } from "../errors.ts"; import type { SessionImpl } from "../session/session.ts"; @@ -29,11 +36,13 @@ import type { } from "../types.ts"; import { agentHooks, DEFAULT_RESTART_LIMIT } from "./agent.ts"; import { type ContextRange, readContextFrom } from "./context.ts"; +import { DURABLE_TELEMETRY_SCHEMA } from "./telemetry.ts"; import type { Agent, AnyTask, ConversationHandle, HarnessInspection, + HarnessOptions, RegistryReader, RegistrySnapshot, Settings, @@ -49,7 +58,7 @@ type RunnableTaskRecord = Extract< AnyTaskRecord, { readonly state: { readonly status: "pending" | "running" | "waiting" | "sleeping" } } >; -type Checkpoint = { readonly phase: string }; +type Checkpoint = { readonly phase: string; readonly attempt?: number }; type ErasedDefinition = TaskDefinition; type ErasedRuntime = TaskRuntime; type ErasedRunningTask = RunningTask; @@ -102,8 +111,12 @@ type Invocation = { readonly conversationId: ConversationId; readonly mode: "run" | "abort"; readonly controller: AbortController; + links?: readonly TelemetryCarrier[]; /** Context passed to handlers; cancelled by `controller`. */ - readonly context: Context; + context: Context; + /** Keeps the terminal state available after it leaves the live index. Released when the invocation finishes. */ + record?: TaskRecord; + fault?: Extract, { readonly status: "faulted" }>; /** Watches acquired through the runtime; stopped at invocation end. */ readonly watches: Set>; /** Timers armed through the runtime; disarmed at invocation end. */ @@ -181,6 +194,7 @@ function parentNode(node: TaskNode): Node { type Scope = { readonly conversation: ConversationId } | { readonly roots: true }; export type TaskSchedulerOptions = { + readonly telemetry?: HarnessOptions["telemetry"]; readonly session: SessionImpl; readonly storage: Storage; readonly registry: RegistryReader; @@ -199,7 +213,7 @@ export type TaskSchedulerOptions = { readonly timers: Timers; /** While closing, on the line after admitted commits settle, write what the callback returns straight to Storage. */ readonly writeAtClose: (writes: () => readonly StorageWrite[]) => Promise; - readonly report: (error: unknown, info: ReportInfo) => void; + readonly report: (error: unknown, info: ReportInfo, context?: Context) => void; /** Harness cleanup staged in the commit that makes an outcome the scheduler wrote itself terminal. */ readonly settleOutcome: (tx: Transaction, record: AnyTaskRecord, outcome: SchedulerOutcome) => Promise; /** Withdraw a conversation's queued inputs, for conversation abort and abort cascades. */ @@ -237,6 +251,10 @@ export type TaskSchedulerOptions = { * step that decides its end, so a runtime commit it queued either lands before that decision or is rejected. */ export class TaskScheduler { + readonly #telemetry: NonNullable; + readonly #activeMetric; + readonly #durationMetric; + readonly #resumed = new Set(); readonly #session: SessionImpl; readonly #storage: Storage; readonly #registry: RegistryReader; @@ -248,7 +266,7 @@ export class TaskScheduler { readonly #onWake: ((wake: Wake) => void) | undefined; readonly #timers: Timers; readonly #writeAtClose: (writes: () => readonly StorageWrite[]) => Promise; - readonly #report: (error: unknown, info: ReportInfo) => void; + readonly #report: (error: unknown, info: ReportInfo, context?: Context) => void; readonly #settleOutcome: TaskSchedulerOptions["settleOutcome"]; readonly #withdrawInputs: TaskSchedulerOptions["withdrawInputs"]; readonly #conversation: TaskSchedulerOptions["conversation"]; @@ -327,6 +345,10 @@ export class TaskScheduler { #draining = false; constructor(options: TaskSchedulerOptions) { + this.#telemetry = options.telemetry ?? NOOP_TELEMETRY_CONTEXT; + const metrics = createTypedMetrics(this.#telemetry.metrics ?? NOOP_TELEMETRY_METRICS, [DURABLE_TELEMETRY_SCHEMA]); + this.#activeMetric = metrics.upDownCounter("pi.durable.tasks.active"); + this.#durationMetric = metrics.histogram("pi.durable.phase.duration"); this.#session = options.session; this.#storage = options.storage; this.#registry = options.registry; @@ -367,6 +389,7 @@ export class TaskScheduler { for (const records of scans) { for (const record of records) { this.#track(undefined, record); + this.#resumed.add(record.id); if (record.abandonOnRestart === true) this.#abandoned.add(record.id); if (record.state.status === "running") { const restarts = (record.restarts ?? 0) + 1; @@ -980,6 +1003,14 @@ export class TaskScheduler { */ #track(previous: AnyTaskRecord | undefined, record: AnyTaskRecord): void { const id = record.id; + const invocation = this.#invocations.get(id); + if (invocation !== undefined) invocation.record = record as TaskRecord; + if (record.state.status === "terminal") { + if (previous !== undefined && !this.#closing) this.#activeMetric.add(-1, { task: record.kind }); + this.#resumed.delete(id); + } else if (previous === undefined && !this.#closing) { + this.#activeMetric.add(1, { task: record.kind }); + } if (previous?.state.status === "waiting") for (const on of previous.state.on) deleteFrom(this.#waiters, on, id); if (record.state.status === "terminal") { const node = nodeOf(record); @@ -1257,12 +1288,14 @@ export class TaskScheduler { } /** Fail the Session, which reports it, for a throw in one of the scheduler's own commits; ignored once closing. */ - #failSession(error: unknown): void { - if (!this.#closing) this.#session.fail(error); + #failSession(error: unknown, context?: Context): void { + if (!this.#closing) this.#session.fail(error, context); } /** Close listener: runs synchronously once admission is sealed, before `join()`, or when the Session fails. */ #seal(): void { + for (const record of this.#live.values()) this.#activeMetric.add(-1, { task: record.kind }); + this.#resumed.clear(); this.#closing = true; try { this.#unsubscribeRegistry(); @@ -1515,7 +1548,7 @@ export class TaskScheduler { // Registered on the line, so marks and later reservations see it and close joins it; `#end` makes it a // candidate again. this.#runnable.delete(id); - const invocation = this.#createInvocation(record, mode, installerOf(snapshot, resolution.task)); + const invocation = this.#createInvocation(runnable, mode, installerOf(snapshot, resolution.task)); reservations.push({ invocation, task: resolution.task, snapshot }); } }, this.#context); @@ -1632,7 +1665,7 @@ export class TaskScheduler { return { kind: "ready", migrates: fit.migrates }; } - #createInvocation(record: AnyTaskRecord, mode: "run" | "abort", extension: string | undefined): Invocation { + #createInvocation(record: RunnableTaskRecord, mode: "run" | "abort", extension: string | undefined): Invocation { const controller = new AbortController(); const { promise: done, resolve: finish } = Promise.withResolvers(); const invocation: Invocation = { @@ -1642,7 +1675,9 @@ export class TaskScheduler { conversationId: record.conversationId, mode, controller, + links: record.startedAt === undefined ? record.links : undefined, context: withAbortSignal(controller.signal, this.#context), + record: record as TaskRecord, watches: new Set(), timers: new Set(), ended: false, @@ -1660,9 +1695,12 @@ export class TaskScheduler { if (invocation.mode === "run") await this.#run(reservation); else await this.#runAbort(reservation); } catch (error) { - this.#report(error, { type: "task_error", ...this.#aboutTask(invocation) }); + this.#report(error, { type: "task_error", ...this.#aboutTask(invocation) }, invocation.context); } finally { this.#end(invocation); + invocation.record = undefined; + invocation.links = undefined; + invocation.fault = undefined; invocation.finish(); this.#kick(); } @@ -1675,25 +1713,95 @@ export class TaskScheduler { const state = { task: reservation.task, snapshot: reservation.snapshot, reported: undefined as ReportedTask }; const phase: Phase = { snapshot: () => state.snapshot, task: () => state.task, agent: undefined }; const runtime = this.#runtime(invocation, phase); - let previous: PhaseResult | undefined; - for (;;) { - const current = await this.#step(invocation, (tx, current) => - this.#decide(tx, current, previous, state, invocation.extension), - ); - // Close may seal between the decision and dispatch. - if (current === undefined || this.#closing) return; - const checkpoint = current.state.checkpoint; - // Each phase handler resolves its agent afresh, at first use. - phase.agent = undefined; - try { - await erased(state.task).phases[checkpoint.phase]!(current, runtime, invocation.context); - previous = { checkpoint }; - } catch (error) { - previous = { checkpoint, failure: { error } }; - } + let current = await this.#step(invocation, (tx, next) => + this.#decide(tx, next, undefined, state, invocation.extension, invocation.context), + ); + while (current !== undefined && !this.#closing) { + const task = current; + current = await this.#phase(invocation, task, async () => { + const checkpoint = task.state.checkpoint; + // Each phase handler resolves its agent afresh, at first use. + phase.agent = undefined; + let previous: PhaseResult; + try { + await erased(state.task).phases[checkpoint.phase]!(task, runtime, invocation.context); + previous = { checkpoint }; + } catch (error) { + previous = { checkpoint, failure: { error } }; + } + return this.#step(invocation, (tx, next) => + this.#decide(tx, next, previous, state, invocation.extension, invocation.context), + ); + }); } } + /** A phase owns its decision commit, not the next handler, a durable wait, or recovery. */ + #phase(invocation: Invocation, task: ErasedRunningTask, run: () => Promise): Promise { + const parent = + task.trace === undefined + ? this.#telemetry + : (this.#telemetry.propagation?.extract(task.trace) ?? this.#telemetry); + const checkpoint = task.state.checkpoint; + const attempt = checkpoint.attempt; + const resumed = this.#resumed.delete(task.id); + return createTypedSpanStarter(parent, [DURABLE_TELEMETRY_SCHEMA])( + "pi.durable.phase", + { + "task.id": task.id, + "task.name": task.kind, + phase: checkpoint.phase, + kind: invocation.mode, + resumed, + ...(attempt === undefined ? {} : { attempt }), + }, + async (span) => { + if (span.propagation !== undefined && invocation.links !== undefined) { + for (const carrier of invocation.links) span.addLink({ context: span.propagation.extract(carrier) }); + } + const previous = invocation.context; + invocation.context = withTelemetry(span, previous); + const started = performance.now(); + try { + return await run(); + } finally { + invocation.context = previous; + const state = invocation.record!.state; + const terminal = + invocation.fault ?? + (state.status === "terminal" || state.status === "completing" ? state.outcome : undefined); + const outcome = + terminal !== undefined + ? terminal.status === "completed" + ? "done" + : terminal.status === "aborted" + ? "aborted" + : "faulted" + : state.status === "waiting" || state.status === "sleeping" + ? state.status + : invocation.ended || this.#closing + ? "aborted" + : `next=${state.checkpoint!.phase}`; + span.setAttributes({ outcome }); + if (terminal?.status === "faulted" || terminal?.status === "failed" || terminal?.status === "orphaned") { + const message = terminal.status === "orphaned" ? terminal.reason : terminal.error.message; + span.setStatus({ + status: "error", + error: { name: `task_${terminal.status}`, message: message.slice(0, 500) }, + }); + } else if (outcome === "aborted") { + span.setStatus({ status: "ok" }); + } + this.#durationMetric.record( + performance.now() - started, + { task: task.kind, phase: checkpoint.phase, outcome }, + span, + ); + } + }, + ); + } + /** * Precedence rules for a run invocation, on the line. Rules 1 (terminal, `completing`, `waiting`, or `sleeping`) and 2 * (closing) are applied by `#step`. Returns whether the invocation continues with the next phase. @@ -1704,6 +1812,7 @@ export class TaskScheduler { previous: PhaseResult | undefined, state: { task: AnyTask; snapshot: RegistrySnapshot; reported: ReportedTask }, extension: string | undefined, + context: Context, ): Decision { // 3. abort mark: end; a fresh abort invocation starts once the task's ordinary owned work is gone. if (current.abortRequested) return false; @@ -1731,11 +1840,15 @@ export class TaskScheduler { } if (state.reported === undefined || state.reported.task !== next) { state.reported = { task: next }; - this.#report(new Error(`Task ${current.id} keeps running under its old ${current.kind} definition`), { - type: "task_outdated", - ...this.#aboutTask({ ...recordTask(current), extension }), - reason: next === undefined ? "missing_task" : "incompatible_task", - }); + this.#report( + new Error(`Task ${current.id} keeps running under its old ${current.kind} definition`), + { + type: "task_outdated", + ...this.#aboutTask({ ...recordTask(current), extension }), + reason: next === undefined ? "missing_task" : "incompatible_task", + }, + context, + ); } } return true; @@ -1746,16 +1859,22 @@ export class TaskScheduler { const invocation = reservation.invocation; const current = this.#live.get(invocation.taskId) as ErasedRunningTask | undefined; if (current === undefined || this.#closing) return; - let failure: { readonly error: unknown } | undefined; - try { - const phase: Phase = { snapshot: () => reservation.snapshot, task: () => reservation.task, agent: undefined }; - const runtime = this.#runtime(invocation, phase); - await erased(reservation.task).abort(current, runtime, invocation.context); - } catch (error) { - failure = { error }; - } - const message = `Abort handler of task ${invocation.taskId} returned without a terminal outcome`; - await this.#step(invocation, () => ({ fault: failure?.error ?? new Error(message) })); + await this.#phase(invocation, current, async () => { + let failure: { readonly error: unknown } | undefined; + try { + const phase: Phase = { + snapshot: () => reservation.snapshot, + task: () => reservation.task, + agent: undefined, + }; + const runtime = this.#runtime(invocation, phase); + await erased(reservation.task).abort(current, runtime, invocation.context); + } catch (error) { + failure = { error }; + } + const message = `Abort handler of task ${invocation.taskId} returned without a terminal outcome`; + await this.#step(invocation, () => ({ fault: failure?.error ?? new Error(message) })); + }); } /** @@ -1779,19 +1898,24 @@ export class TaskScheduler { if (decision !== false) { fault = { error: decision.fault }; const message = errorMessage(decision.fault); - await this.#terminate(tx, current!, { status: "faulted", error: { message } }); + invocation.fault = { status: "faulted", error: { message } }; + await this.#terminate(tx, current!, invocation.fault); } return undefined; - }, this.#context); + }, withoutAbortSignal(invocation.context)); // Reported once the fault is durable: a host may count it, for example toward a breaker. if (fault !== undefined) - this.#report(fault.error, { type: "task_faulted", ...this.#aboutTask(invocation), reason: "threw" }); + this.#report( + fault.error, + { type: "task_faulted", ...this.#aboutTask(invocation), reason: "threw" }, + invocation.context, + ); return continued; } catch (error) { // The step writes the scheduler's own decision, a fault or a terminal record; a throw there would otherwise // leave the task running, to be reserved and run again. this.#end(invocation); - this.#failSession(error); + this.#failSession(error, invocation.context); return undefined; } } @@ -1978,7 +2102,11 @@ export class TaskScheduler { await invoke(handler.bind(handlers)); } catch (error) { if (invocation.controller.signal.aborted) throw error; - this.#report(error, { type: "extension_error", extension, task: reportTask(invocation) }); + this.#report( + error, + { type: "extension_error", extension, task: reportTask(invocation) }, + invocation.context, + ); } } }, @@ -2002,15 +2130,25 @@ export class TaskScheduler { get registry() { return phase.snapshot(); }, - commit: (change, context) => - this.#gated( + commit: async (change, context) => { + let checkpoint: string | undefined; + await this.#gated( invocation, async (tx, current) => { const next = await change(tx, current); if (next !== undefined) await this.#commitState(tx, invocation, current, next); + if (next?.status === "running" && current.state.checkpoint.phase !== next.checkpoint.phase) { + checkpoint = next.checkpoint.phase; + } }, context, - ), + ); + if (checkpoint !== undefined) { + invocation.context.telemetry.addEvent("pi.durable.checkpoint", { + phase: checkpoint, + }); + } + }, memo: ((name: string, ...rest: readonly unknown[]) => { if (rest.length === 1) { return this.#read(invocation, async () => memoOf(this.#live.get(invocation.taskId), name)); @@ -2173,6 +2311,7 @@ export class TaskScheduler { : from.type === "extension" ? { type: "extension_error", task, ...optionalExtension(from.extension) } : { type: "host_error", callback: from.callback, task }, + invocation.context, ); }, }; diff --git a/packages/durable/src/harness/submissions.ts b/packages/durable/src/harness/submissions.ts index d84226810..0cf838a93 100644 --- a/packages/durable/src/harness/submissions.ts +++ b/packages/durable/src/harness/submissions.ts @@ -1,4 +1,11 @@ import { type Context, copyJson, type JsonRepresentation } from "@earendil-works/chord"; +import { withTelemetry } from "@earendil-works/chord/context"; +import { + createTypedSpanStarter, + NOOP_TELEMETRY_CONTEXT, + type TelemetryContext, + type TelemetrySpan, +} from "@earendil-works/pi-telemetry"; import { ConversationBusy } from "../errors.ts"; import type { SessionImpl } from "../session/session.ts"; import type { @@ -24,13 +31,16 @@ import { removeInboxItem, } from "./inbox.ts"; import { LiveDoc } from "./live.ts"; +import { DURABLE_TELEMETRY_SCHEMA } from "./telemetry.ts"; import type { InputEntry, SettledSubmissionRecord, Submission, SubmissionDraft, UserInput } from "./types.ts"; import { closedError, Waiters } from "./util.ts"; type AbortResult = "aborted" | "already_placed" | "settled"; +type Admission = { readonly id: SubmissionId; readonly status: "queued" | "placed" | "done" }; /** Admission, waits, and withdrawal of the durable submissions of one Harness. */ export class Submissions { + readonly #telemetry: TelemetryContext; readonly #session: SessionImpl; readonly #storage: Storage; readonly #now: () => number; @@ -47,7 +57,9 @@ export class Submissions { now: () => number, queueModes: () => QueueModes, resume: () => void, + telemetry: TelemetryContext = NOOP_TELEMETRY_CONTEXT, ) { + this.#telemetry = telemetry; this.#session = session; this.#storage = storage; this.#now = now; @@ -63,11 +75,29 @@ export class Submissions { /** Admit a submission in one commit; see `admitSubmission()`. */ async submit(conversationId: ConversationId, draft: SubmissionDraft, context: Context): Promise { this.#resume(); - const id = await this.#session.commitWith( - (tx) => admitSubmission(tx, conversationId, draft, this.#now(), this.#queueModes()), - context, + const parent = draft.type === "input" ? this.#telemetry : context.telemetry; + return createTypedSpanStarter(parent, [DURABLE_TELEMETRY_SCHEMA])( + "pi.durable.submit", + { + "submission.type": draft.type, + "conversation.id": conversationId, + }, + async (span) => { + if (draft.type === "input") span.addLink({ context: context.telemetry }); + try { + const { id, status } = await this.#session.commitWith( + (tx) => admitSubmission(tx, conversationId, draft, this.#now(), this.#queueModes(), span), + withTelemetry(span, context), + ); + span.setAttributes({ "submission.id": id, result: status }); + return new SubmissionHandle(id, this); + } catch (error) { + // Error text may contain caller content. Record only the status. + span.setStatus({ status: "error" }); + throw error; + } + }, ); - return new SubmissionHandle(id, this); } /** Handle for an existing submission, or `undefined`. */ @@ -174,7 +204,8 @@ export async function admitSubmission( draft: SubmissionDraft, now: number, queueModes: QueueModes, -): Promise { + span?: TelemetrySpan, +): Promise { if (draft.type === "input" && draft.entry !== undefined) checkInputEntry(draft.entry); if (draft.requestId !== undefined) { const existing = await tx.submissionByRequest(conversationId, draft.requestId); @@ -182,28 +213,36 @@ export async function admitSubmission( if (existing.type !== draft.type) { throw new Error(`Request ${draft.requestId} already identifies a submission of type ${existing.type}`); } - return existing.id; + return { id: existing.id, status: existing.status === "unanswered" ? "done" : existing.status }; } } - const requestId = draft.requestId === undefined ? {} : { requestId: draft.requestId }; + const fields = { conversationId, requestId: draft.requestId, trace: span?.propagation?.inject(span) }; if ( draft.type === "write" && isDisplayOnly(draft.entry) && !hasQueuedReset((await tx.doc(InboxDoc, conversationId)).items) ) { const entry = await tx.appendEntry(conversationId, draft.entry); - const write = { conversationId, ...requestId, type: "write", status: "done", entry: entry.id } as const; - return (await tx.createSubmission(write)).id; + const write = { ...fields, type: "write", status: "done", entry: entry.id } as const; + return { id: (await tx.createSubmission(write)).id, status: "done" }; } const live = await tx.doc(LiveDoc, conversationId); const busy = live.run !== undefined; + if ( + draft.type === "input" && + draft.whenBusy === "steer" && + live.run !== undefined && + span?.propagation !== undefined + ) { + const run = await tx.task(live.run.taskId); + if (run?.trace !== undefined) span.addLink({ context: span.propagation.extract(run.trace) }); + } if (busy && draft.type === "input" && draft.whenBusy === "reject") throw new ConversationBusy(conversationId); // A boundary reads the table, so it is prepared before the first table write; a busy one needs none. const boundary = busy ? undefined : await prepareBoundary(tx, conversationId, queueModes); if (boundary === undefined || boundary.inbox.items.length > 0) { const { id } = await tx.createSubmission({ - conversationId, - ...requestId, + ...fields, type: draft.type, status: "queued", }); @@ -219,23 +258,26 @@ export async function admitSubmission( const entry = draft.entry === undefined ? {} : { entry: pickInputEntry(draft.entry) }; items.push({ id, mode, content, ...entry }); } - if (boundary === undefined) return id; + if (boundary === undefined) return { id, status: "queued" }; const { users } = await applyBoundary(tx, boundary, "final", now); if (users.length > 0) await startRun(tx, conversationId, live, users); - return id; + return { id, status: draft.type === "write" ? "done" : users.at(-1) === id ? "placed" : "queued" }; } if (draft.type === "write") { if (isStale(boundary, draft.entry)) { const stale = { status: "unanswered", reason: "stale" } as const; - return (await tx.createSubmission({ conversationId, ...requestId, type: "write", ...stale })).id; + return { + id: (await tx.createSubmission({ ...fields, type: "write", ...stale })).id, + status: "done", + }; } const entry = await tx.appendEntry(conversationId, draft.entry); - const write = { conversationId, ...requestId, type: "write", status: "done", entry: entry.id } as const; - return (await tx.createSubmission(write)).id; + const write = { ...fields, type: "write", status: "done", entry: entry.id } as const; + return { id: (await tx.createSubmission(write)).id, status: "done" }; } const entry = await appendInput(tx, conversationId, draft.content, draft.entry, now); - const input = { conversationId, ...requestId, type: "input", status: "placed", entry: entry.id } as const; + const input = { ...fields, type: "input", status: "placed", entry: entry.id } as const; const { id } = await tx.createSubmission(input); await startRun(tx, conversationId, live, [id]); - return id; + return { id, status: "placed" }; } diff --git a/packages/durable/src/harness/telemetry.ts b/packages/durable/src/harness/telemetry.ts new file mode 100644 index 000000000..ce8fa0bd6 --- /dev/null +++ b/packages/durable/src/harness/telemetry.ts @@ -0,0 +1,139 @@ +import { defineTelemetrySchema } from "@earendil-works/pi-telemetry"; + +const entry = { + description: "A transcript entry was committed; content remains in the transcript.", + attributes: { + "entry.id": { type: "number", required: true, description: "Transcript entry ID.", cardinality: "high" }, + "entry.kind": { type: "string", required: true, description: "Entry kind." }, + }, +} as const; +const reportAttributes = { + type: { + type: "string", + required: true, + description: "ReportInfo type.", + values: [ + "session_failed", + "task_faulted", + "task_parked", + "migration_failed", + "task_outdated", + "task_error", + "extension_error", + "host_error", + "listener_error", + ], + }, + reason: { + type: "string", + required: false, + description: "Fixed report reason, when present.", + values: ["threw", "restart_limit", "missing_task", "incompatible_task"], + }, + extension: { type: "string", required: false, description: "Registered extension name, when present." }, + "task.id": { type: "number", required: false, description: "Task ID, when present.", cardinality: "high" }, +} as const; +const report = { + description: "A report was raised; no error payload is recorded.", + attributes: reportAttributes, +} as const; +const submission = { + description: "A submission was settled.", + attributes: { + "submission.id": { type: "number", required: true, description: "Submission ID.", cardinality: "high" }, + status: { type: "string", required: true, values: ["done", "unanswered"], description: "Settlement." }, + "answer.entry_id": { type: "number", required: false, description: "Answer entry ID.", cardinality: "high" }, + }, +} as const; + +/** Durable's content-free span, event, and metric vocabulary. IDs address durable records, never content. */ +export const DURABLE_TELEMETRY_SCHEMA = defineTelemetrySchema({ + version: 1, + spans: { + "pi.durable.submit": { + description: + "Public submission admission and its commit. Inputs start root traces linked to their callers; writes are children. Internal admissions emit phase events only.", + parents: { kind: "any" }, + startAttributes: { + "submission.type": { + type: "string", + required: true, + values: ["input", "write"], + description: "Submission type.", + }, + "conversation.id": { type: "number", required: true, description: "Conversation ID.", cardinality: "high" }, + }, + endAttributes: { + "submission.id": { type: "number", description: "Admitted submission ID.", cardinality: "high" }, + result: { + type: "string", + values: ["queued", "placed", "done"], + description: "Admission result; stale writes report done.", + }, + }, + events: { "pi.durable.entry": entry, "pi.durable.submission": submission, "pi.durable.report": report }, + status: { default: "ok", errorWhen: "Admission failed." }, + }, + "pi.durable.phase": { + description: "One task phase invocation, including its decision commit, never a wait or restart.", + parents: { kind: "any" }, + startAttributes: { + "task.id": { type: "number", required: true, description: "Task ID.", cardinality: "high" }, + "task.name": { type: "string", required: true, description: "Registered task name." }, + phase: { type: "string", required: true, description: "Invoked checkpoint phase." }, + kind: { type: "string", required: true, values: ["run", "abort"], description: "Invocation kind." }, + attempt: { type: "number", required: false, description: "Checkpoint attempt, when present." }, + resumed: { + type: "boolean", + required: true, + description: "First invocation of a task loaded in this process.", + }, + }, + endAttributes: { + outcome: { type: "string", description: "next=, waiting, sleeping, done, faulted, or aborted." }, + "tool.name": { type: "string", description: "Called tool name." }, + "tool.call_id": { type: "string", description: "Transcript tool call ID.", cardinality: "high" }, + }, + events: { + "pi.durable.entry": entry, + "pi.durable.submission": submission, + "pi.durable.report": report, + "pi.durable.checkpoint": { + description: "The running checkpoint's phase changed while the invocation continued.", + attributes: { phase: { type: "string", required: true, description: "Committed checkpoint phase." } }, + }, + "pi.durable.replay": { + description: "A nested tool call was answered from its stored result.", + attributes: { "tool.name": { type: "string", required: true, description: "Called tool name." } }, + }, + }, + status: { + default: "ok", + errorWhen: + "Faulted, failed, and orphaned outcomes use task_faulted, task_failed, and task_orphaned with a diagnostic capped at 500 characters. Aborted outcomes keep status ok.", + }, + }, + }, + metrics: { + "pi.durable.reports": { + kind: "counter", + description: "Reports raised, grouped by their fixed ReportInfo type.", + attributes: { type: reportAttributes.type }, + }, + "pi.durable.phase.duration": { + kind: "histogram", + unit: "ms", + description: "Duration of a phase invocation and its decision commit.", + attributes: { + task: { type: "string", required: true, description: "Registered task name." }, + phase: { type: "string", required: true, description: "Invoked checkpoint phase." }, + outcome: { type: "string", required: true, description: "Phase outcome." }, + }, + }, + "pi.durable.tasks.active": { + kind: "upDownCounter", + description: "Live tasks held by this Harness; decremented at terminal settlement or close.", + attributes: { task: { type: "string", required: true, description: "Registered task name." } }, + }, + }, +}); diff --git a/packages/durable/src/harness/tool.ts b/packages/durable/src/harness/tool.ts index 709a8c180..f82c041f8 100644 --- a/packages/durable/src/harness/tool.ts +++ b/packages/durable/src/harness/tool.ts @@ -222,7 +222,13 @@ async function resolveTool( /** The call: from the input for a nested call, which hooks see with its parent, else from the assistant entry. */ async function readCall(runtime: Runtime, input: ToolTaskInput, context: Context): Promise { - if (input.kind === "nested") return { ...input.call, parent: { taskId: input.parent, callId: input.parentCallId } }; + if (input.kind === "nested") { + context.telemetry.setAttributes({ + "tool.name": input.call.name, + "tool.call_id": input.call.id, + }); + return { ...input.call, parent: { taskId: input.parent, callId: input.parentCallId } }; + } const entry = await runtime.entry(AssistantEntry, input.assistant, context); const message = entry?.model?.[0]; const call = @@ -232,6 +238,10 @@ async function readCall(runtime: Runtime, input: ToolTaskInput, context: Context ) : undefined; if (call === undefined) throw new Error(`Entry ${input.assistant} has no tool call ${input.callId}`); + context.telemetry.setAttributes({ + "tool.name": call.name, + "tool.call_id": call.id, + }); return call; } @@ -728,6 +738,7 @@ async function startNestedCall( arguments: copyJson(args, { omitUndefinedProperties: true }) as JsonObject, }; let id: TaskId | undefined; + let replayed = false; await runtime.commit(async (tx) => { // Opened, or created empty for a key not made yet. const state = await tx.doc(NestedCallDoc, runtime.taskId, key, null); @@ -740,6 +751,7 @@ async function startNestedCall( jsonEqual(input.call.arguments as JsonValue, call.arguments as JsonValue); if (!same) throw new Error(`Nested call ${call.id} was already made with another tool or other arguments`); id = existing as TaskId; + replayed = state.result !== undefined; return undefined; } const input: ToolTaskInput = { @@ -770,6 +782,9 @@ async function startNestedCall( id = created; return undefined; }, context); + if (replayed) { + context.telemetry.addEvent("pi.durable.replay", { "tool.name": name }); + } return id!; } diff --git a/packages/durable/src/harness/types.ts b/packages/durable/src/harness/types.ts index 690caf2e4..8b33e2baf 100644 --- a/packages/durable/src/harness/types.ts +++ b/packages/durable/src/harness/types.ts @@ -14,7 +14,7 @@ import type { Usage, UserMessage, } from "@earendil-works/pi-ai"; -import type { TelemetryContext, TelemetryMetrics, TelemetryPropagation } from "@earendil-works/pi-telemetry"; +import type { TelemetryContext } from "@earendil-works/pi-telemetry"; import type { ExecutionEnv, ShellOutputSkip, ShellOutputWindow } from "../env/index.ts"; import type { ConversationId, @@ -606,8 +606,8 @@ export type EnvTarget = { }; export type HarnessOptions = { - /** Host-owned adapter; propagation and metrics are optional. Durable instrumentation is not yet emitted. */ - readonly telemetry?: TelemetryContext & Partial; + /** Host-owned adapter for content-free admission/phase telemetry; propagation and metrics are optional. */ + readonly telemetry?: TelemetryContext; /** * pi-ai model access used by generation, compaction, hooks and tools: a `Models`, or a function returning the current * one, called at each use, so a host can replace its model configuration without reopening the Harness. diff --git a/packages/durable/src/index.ts b/packages/durable/src/index.ts index 74408d514..e4881c536 100644 --- a/packages/durable/src/index.ts +++ b/packages/durable/src/index.ts @@ -53,6 +53,7 @@ export { ProviderDoc, type ProviderState } from "./harness/provider.ts"; export { createRegistry } from "./harness/registry.ts"; export type { BlockedReason } from "./harness/scheduler.ts"; export type { TaskGraph, TaskGraphNode, TaskGraphState, TaskGraphWatch } from "./harness/task-graph.ts"; +export { DURABLE_TELEMETRY_SCHEMA } from "./harness/telemetry.ts"; export { NestedCallDoc, type NestedCallState, diff --git a/packages/durable/src/session/session.ts b/packages/durable/src/session/session.ts index a94b32719..b22e9c56a 100644 --- a/packages/durable/src/session/session.ts +++ b/packages/durable/src/session/session.ts @@ -219,14 +219,14 @@ export class SessionImpl implements Session { * now; they read the error from `failure`. The Storage guard calls this; the Harness also calls it for a throw in its * scheduler's own commits. */ - fail(error: unknown): void { + fail(error: unknown, context?: Context): void { if (this.#failure !== undefined) return; this.#failure = { error }; this.#failed.reject(new SessionFailed(error)); // Seal first, so a report handler that calls back finds the Session failed. Closing runs the close listeners // synchronously; a failing backend close is the caller's to see, and here nobody waits. this.close(BACKGROUND_CONTEXT).catch(() => {}); - this.report(error, { type: "session_failed" }); + this.report(error, { type: "session_failed" }, context); } /** @@ -541,7 +541,7 @@ export class SessionImpl implements Session { * Internal: the Session's failure, and errors of listeners, which never fail what ran them; `info` defaults to a * listener. A plain Session drops them. */ - report(_error: unknown, _info: ReportInfo = LISTENER): void {} + report(_error: unknown, _info: ReportInfo = LISTENER, _context?: Context): void {} /** * Runs inside every transaction that creates or forks a conversation, after the conversation record is staged. A @@ -773,30 +773,46 @@ export class SessionImpl implements Session { documents: readonly DocumentCommitChange[], context: Context, ): void { - if (this.#commitListeners.size === 0 && this.#internalListeners.size === 0) return; - const changes: CommitChange[] = []; + const changes: CommitChange[] | undefined = + this.#commitListeners.size > 0 || this.#internalListeners.size > 0 ? [] : undefined; for (const write of writes) { switch (write.type) { - case "conversation": case "entry": - case "task": + context.telemetry.addEvent("pi.durable.entry", { + "entry.id": write.value.id, + "entry.kind": write.value.kind, + }); + changes?.push(write); + break; case "submission": - changes.push(write); + if (write.value.status === "done" || write.value.status === "unanswered") { + context.telemetry.addEvent("pi.durable.submission", { + "submission.id": write.value.id, + status: write.value.status, + "answer.entry_id": write.value.answer, + }); + } + changes?.push(write); + break; + case "conversation": + case "task": + changes?.push(write); } } + if (changes === undefined) return; for (const document of documents) changes.push(document); const publication: CommitPublication = { seq, changes }; // The commit is durable: a failing listener neither fails the commit nor skips the others. for (const listener of [...this.#internalListeners]) { contained( () => listener(publication, context), - (error) => this.fail(error), + (error) => this.fail(error, context), ); } for (const listener of [...this.#commitListeners]) { contained( () => listener(publication, context), - (error) => this.report(error), + (error) => this.report(error, LISTENER, context), ); } } diff --git a/packages/durable/src/session/transaction.ts b/packages/durable/src/session/transaction.ts index d97d56418..c0909aaa0 100644 --- a/packages/durable/src/session/transaction.ts +++ b/packages/durable/src/session/transaction.ts @@ -1,5 +1,7 @@ import { type Context, copyJson, type Draft, type JsonValue } from "@earendil-works/chord"; +import { BACKGROUND_CONTEXT } from "@earendil-works/chord/context"; import { type Change, type Op, type Prepared, type Tracker, track } from "@earendil-works/chord/delta"; +import type { TelemetryCarrier } from "@earendil-works/pi-telemetry"; import { type AnyDocDefinition, type AnyDocToken, @@ -124,6 +126,9 @@ type TransactionTask = { publicationConversationId?: ConversationId; }; +/** Internal run creation resolves submission carriers against staged records before reading storage. */ +export type TaskCreationOptions = TaskOptions & { readonly submissionIds?: readonly SubmissionId[] }; + /** Defaults a commit binds to: `tx.createTask()` conversation and the task attributed to appended entries. */ export type TransactionScope = { readonly conversationId?: ConversationId; @@ -193,7 +198,7 @@ type DocumentPlan = { */ export class Transaction implements Tx { readonly #host: TransactionHost; - readonly #context: Context; + #context: Context; readonly #scope: TransactionScope; readonly #pendingOperations = new Set>(); #sealed = false; @@ -383,9 +388,23 @@ export class Transaction implements Tx { createTask( task: Task, input: I, - options: TaskOptions, + options: TaskCreationOptions, ): Promise> { return this.#write(async () => { + if (options.submissionIds !== undefined) { + let trace: TaskOptions["trace"]; + let links: TelemetryCarrier[] | undefined; + for (let index = 0; index < options.submissionIds.length; index++) { + const id = options.submissionIds[index]!; + const submission = this.#submissions.get(id) ?? (await this.#host.storage.submission(id, this.#context)); + if (index === 0) trace = submission?.trace ?? "root"; + else if (submission?.trace !== undefined) { + links ??= []; + links.push(submission.trace); + } + } + options = { ...options, trace, links }; + } const ownership = options.ownership; let owner: AnyTaskRecord | undefined; if (ownership.kind === "task") { @@ -413,6 +432,11 @@ export class Transaction implements Tx { kind: definition.name, version: definition.version, input, + trace: + options.trace === "root" + ? undefined + : (options.trace ?? this.#context.telemetry.propagation?.inject(this.#context.telemetry)), + links: options.links, ...(owner === undefined ? {} : { owner: owner.id }), background: options.background ?? false, abortRequested: false, @@ -666,6 +690,7 @@ export class Transaction implements Tx { this.#sealed = true; this.#abortChanges(); await Promise.allSettled(this.#pendingOperations); + this.#context = BACKGROUND_CONTEXT; } /** @@ -677,6 +702,7 @@ export class Transaction implements Tx { if (this.#pendingOperations.size > 0) { this.#abortChanges(); await Promise.allSettled(this.#pendingOperations); + this.#context = BACKGROUND_CONTEXT; throw new Error("Session commit callback settled before its pending Tx operations"); } try { @@ -688,6 +714,8 @@ export class Transaction implements Tx { } catch (error) { this.#abortChanges(); throw error; + } finally { + this.#context = BACKGROUND_CONTEXT; } } diff --git a/packages/durable/src/types.ts b/packages/durable/src/types.ts index 2042b62cc..d307f258b 100644 --- a/packages/durable/src/types.ts +++ b/packages/durable/src/types.ts @@ -1,6 +1,7 @@ import type { AttachedReplicatedState, Context, Draft, JsonValue } from "@earendil-works/chord"; import type { Op } from "@earendil-works/chord/delta"; import type { Message, Models } from "@earendil-works/pi-ai"; +import type { TelemetryCarrier } from "@earendil-works/pi-telemetry"; import type { ExecutionEnv } from "./env/index.ts"; import type { Agent, @@ -368,6 +369,10 @@ export type JoinPolicy = "failFast" | "allSettled"; /** Creation options for a durable task. */ export type TaskOptions = { + /** Omitted: inherit the creator's carrier. "root": start at the adapter root without a stored carrier. */ + readonly trace?: TelemetryCarrier | "root"; + /** Immutable creation-time links, attached to the spans of this task's first invocation. */ + readonly links?: readonly TelemetryCarrier[]; /** Required: a task always names its owner (spec §5.5). */ readonly ownership: TaskOwnership; /** @@ -459,6 +464,8 @@ export interface Entry { /** Identity fields shared by every durable submission state. */ type SubmissionRecordBase = { + /** Adapter-owned context of the admission span; absent without propagation. */ + readonly trace?: TelemetryCarrier; readonly id: SubmissionId; readonly conversationId: ConversationId; /** Host-provided deduplication key, scoped to the conversation. */ @@ -637,6 +644,10 @@ export type TaskState = /** Identity, definition, and scheduling fields shared by every task state. */ type TaskRecordBase = { + /** Adapter-owned context that created this task; phase invocations extract it as their parent. */ + readonly trace?: TelemetryCarrier; + /** Immutable creation-time links for the task's first invocation. */ + readonly links?: readonly TelemetryCarrier[]; readonly id: TaskId; readonly conversationId: ConversationId; /** Registered task definition name. */ diff --git a/packages/durable/test/harness-lifecycle.test.ts b/packages/durable/test/harness-lifecycle.test.ts index 395e94ccb..a961af1c3 100644 --- a/packages/durable/test/harness-lifecycle.test.ts +++ b/packages/durable/test/harness-lifecycle.test.ts @@ -2,6 +2,7 @@ import { mkdtemp, rm } from "node:fs/promises"; import { tmpdir } from "node:os"; import { join } from "node:path"; import type { Context, JsonValue } from "@earendil-works/chord"; +import { withAbortSignal } from "@earendil-works/chord/context"; import { createModels, fauxAssistantMessage, fauxText, fauxToolCall, Type } from "@earendil-works/pi-ai"; import { type Conversation, @@ -55,7 +56,7 @@ function unloadDocuments(harness: Harness): Promise { } function withSignal(signal: AbortSignal): Context { - return { ...context, abortSignal: signal }; + return withAbortSignal(signal, context); } /** Whether a raw Storage read still succeeds, as code of a joined invocation relies on. */ diff --git a/packages/durable/test/harness-tasks.test.ts b/packages/durable/test/harness-tasks.test.ts index f617dc6c9..899d4fe59 100644 --- a/packages/durable/test/harness-tasks.test.ts +++ b/packages/durable/test/harness-tasks.test.ts @@ -1,5 +1,5 @@ import type { Context } from "@earendil-works/chord"; -import { withCancel } from "@earendil-works/chord/context"; +import { withAbortSignal, withCancel } from "@earendil-works/chord/context"; import { createModels, Type } from "@earendil-works/pi-ai"; import { type Conversation, @@ -79,7 +79,7 @@ async function markDurably( } function withSignal(signal: AbortSignal): Context { - return { ...context, abortSignal: signal }; + return withAbortSignal(signal, context); } describe("task phases", () => { diff --git a/packages/durable/test/harness-telemetry-options.test.ts b/packages/durable/test/harness-telemetry-options.test.ts index a63532e20..e623b833d 100644 --- a/packages/durable/test/harness-telemetry-options.test.ts +++ b/packages/durable/test/harness-telemetry-options.test.ts @@ -11,7 +11,7 @@ describe("HarnessOptions.telemetry", () => { expect(full.telemetry).toBe(adapter); expect(contextOnly.telemetry).toBe(NOOP_TELEMETRY_CONTEXT); expect(omitted.telemetry).toBeUndefined(); - expectTypeOf(full.telemetry?.inject).toExtend< + expectTypeOf(full.telemetry?.propagation?.inject).toExtend< ((context: NonNullable) => unknown) | undefined >(); const compileTimeFailures = () => { diff --git a/packages/durable/test/harness-telemetry.test.ts b/packages/durable/test/harness-telemetry.test.ts new file mode 100644 index 000000000..20bf7f15f --- /dev/null +++ b/packages/durable/test/harness-telemetry.test.ts @@ -0,0 +1,988 @@ +import { withTelemetry } from "@earendil-works/chord/context"; +import { fauxAssistantMessage, fauxToolCall, Type } from "@earendil-works/pi-ai"; +import { CodemodeSandbox } from "@earendil-works/pi-codemode"; +import { + CompactionTask, + defineTask, + defineTool, + GenerationTask, + Harness, + MemoryStorage, + type Storage, + type TaskId, +} from "@earendil-works/pi-durable"; +import { InMemoryTelemetryContext } from "@earendil-works/pi-telemetry"; +import { describe, expect, it, vi } from "vitest"; +import { createCodemodeTool } from "../src/codemode/codemode.ts"; +import { type ChatSetup, chatSetup, waitFor } from "./chat-support.ts"; +import { addHooks, addTask, addTool } from "./harness-support.ts"; +import { ControlledStorage, context } from "./session-support.ts"; +import { aborted } from "./task-support.ts"; + +async function openTracked(storage: Storage, setup: ChatSetup, telemetry: InMemoryTelemetryContext) { + const harness = await Harness.open( + storage, + { + models: setup.models, + registry: setup.registry, + settings: setup.settings, + now: () => setup.now(), + telemetry, + onReport: (error) => setup.reports.push(error), + }, + context, + ); + const root = await harness.root(context, { agent: { model: { provider: "faux", modelId: "faux-1" } } }); + return { harness, root }; +} + +const toolReply = (name: string, args: Record = {}) => + fauxAssistantMessage([fauxToolCall(name, args, { id: "call-1" })], { stopReason: "toolUse" }); + +describe("Durable telemetry", () => { + it("records content-free submit and phase spans, nested parents, checkpoints, entry events, and metrics", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + addTool( + setup.registry, + defineTool({ + name: "inner", + description: "inner", + parameters: Type.Object({ secret: Type.String() }), + execute: async () => ({ output: [{ type: "text", text: "private-result" }] }), + }), + ); + addTool( + setup.registry, + defineTool({ + name: "outer", + description: "outer", + parameters: Type.Object({}), + execute: async (_args, api, ctx) => { + await api.executeTool("inner", { secret: "private-argument" }, ctx); + return { output: [{ type: "text", text: "private-output" }] }; + }, + }), + ); + setup.faux.setResponses([toolReply("outer"), fauxAssistantMessage("private-answer")]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const submitted = await root.submit({ type: "input", content: "private-input", requestId: "dedupe" }, context); + await submitted.wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const record = await submitted.status(context); + const again = await root.submit( + { type: "input", content: "another-private-input", requestId: "dedupe" }, + context, + ); + expect(await again.status(context)).toEqual(record); + const spans = telemetry.getSpans(); + const submit = spans.find((span) => span.name === "pi.durable.submit")!; + expect(submit).toMatchObject({ parentId: null, attributes: { "submission.id": submitted.id, result: "placed" } }); + expect(record.trace).toEqual(submit.context); + const phases = spans.filter((span) => span.name === "pi.durable.phase"); + expect(phases.length).toBeGreaterThan(4); + const requests = spans.filter((span) => span.name === "pi.ai.request"); + expect(requests).toHaveLength(2); + for (const request of requests) + expect(phases.find((phase) => phase.id === request.parentId)?.attributes.phase).toBe("request"); + expect(phases[0]).toMatchObject({ + parentContext: submit.context, + attributes: { phase: "prepare", resumed: false, outcome: "next=request" }, + }); + const outer = phases.find((span) => span.attributes["tool.name"] === "outer")!; + const inner = phases.find((span) => span.attributes["tool.name"] === "inner")!; + expect(inner.parentContext).toEqual(outer.context); + expect(outer.attributes).toMatchObject({ phase: "call", outcome: "done", "tool.call_id": "call-1" }); + expect(outer.events).toContainEqual({ name: "pi.durable.checkpoint", attributes: { phase: "execute" } }); + expect(phases.some((span) => span.attributes.outcome === "waiting")).toBe(true); + expect(submit.events).toContainEqual({ + name: "pi.durable.entry", + attributes: { "entry.id": record.entry, "entry.kind": "pi.user" }, + }); + expect(phases.flatMap((span) => span.events)).toContainEqual({ + name: "pi.durable.submission", + attributes: { "submission.id": submitted.id, status: "done", "answer.entry_id": record.answer }, + }); + const recorded = JSON.stringify(spans.map(({ attributes, events }) => ({ attributes, events }))); + for (const content of [ + "private-input", + "private-answer", + "private-output", + "private-result", + "private-argument", + "secret", + "gen_ai", + ]) + expect(recorded).not.toContain(content); + await harness.close(context); + const metrics = telemetry.getMetrics(); + expect(metrics.filter((metric) => metric.name === "pi.durable.phase.duration")).toHaveLength(phases.length); + expect( + metrics + .filter((metric) => metric.name === "pi.durable.tasks.active") + .reduce((sum, metric) => sum + metric.value, 0), + ).toBe(0); + for (const metric of metrics.filter((metric) => metric.name.startsWith("pi.durable."))) + expect(Object.keys(metric.attributes).some((key) => key.includes("id"))).toBe(false); + expect(setup.reports).toEqual([]); + }); + + it("returns admission results without re-reading records or probing root link targets", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const storage = new ControlledStorage(); + const gate = Promise.withResolvers(); + const reached = Promise.withResolvers(); + setup.faux.setResponses([ + async () => { + reached.resolve(); + await gate.promise; + return fauxAssistantMessage("first"); + }, + fauxAssistantMessage("second"), + ]); + const { harness, root } = await openTracked(storage, setup, telemetry); + const reads = vi.spyOn(storage, "submission"); + const inject = vi.spyOn(telemetry.propagation, "inject"); + const extract = vi.spyOn(telemetry.propagation, "extract"); + const ctx = context; + const first = await root.submit({ type: "input", content: "first" }, ctx); + await reached.promise; + const second = await root.submit({ type: "input", content: "second", requestId: "queued" }, ctx); + const duplicate = await root.submit({ type: "input", content: "ignored", requestId: "queued" }, ctx); + expect(duplicate.id).toBe(second.id); + expect(reads).not.toHaveBeenCalled(); + expect(inject.mock.calls.some(([target]) => target === telemetry)).toBe(false); + expect(extract.mock.calls.some(([carrier]) => carrier === undefined)).toBe(false); + expect( + telemetry + .getSpans() + .filter((span) => span.name === "pi.durable.submit") + .map((span) => span.attributes.result), + ).toEqual(["placed", "queued", "queued"]); + reads.mockRestore(); + inject.mockRestore(); + extract.mockRestore(); + gate.resolve(); + await first.wait(context); + await second.wait(context); + await harness.close(context); + }); + + it("inherits omitted or undefined task traces and stores no carrier for an explicit root", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const Task = defineTask({ + name: "test.trace", + version: 1, + initial: () => ({ phase: "finish" }), + phases: { + finish: async (_task, runtime, ctx) => { + await runtime.commit( + () => ({ status: "terminal", outcome: { status: "completed", result: null } }), + ctx, + ); + }, + }, + abort: async (_task, runtime, ctx) => { + await runtime.commit(() => ({ status: "terminal", outcome: { status: "aborted" } }), ctx); + }, + }); + addTask(setup.registry, Task); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const ids = await telemetry.startSpan({ name: "creator" }, (span) => + root.commit( + async (tx) => [ + await tx.createTask(Task, null, { ownership: { kind: "conversation" } }), + await tx.createTask(Task, null, { ownership: { kind: "conversation" }, trace: undefined }), + await tx.createTask(Task, null, { ownership: { kind: "conversation" }, trace: "root" }), + ], + withTelemetry(span, context), + ), + ); + for (const id of ids) await harness.waitForTask(id, context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const creator = telemetry.getSpans()[0]!; + const records = await Promise.all(ids.map((id) => harness.getTask(id, context))); + expect(records.map((record) => record!.trace)).toEqual([creator.context, creator.context, undefined]); + const phases = telemetry.getSpans().filter((span) => span.name === "pi.durable.phase"); + expect(phases.map((span) => span.parentContext)).toEqual([creator.context, creator.context, null]); + await harness.close(context); + }); + + it("records checkpoints only when the running phase changes", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const Task = defineTask({ + name: "test.checkpoint", + version: 1, + initial: () => ({ phase: "call", count: 0 }), + phases: { + call: async (_task, runtime, ctx) => { + await runtime.commit(() => ({ status: "running", checkpoint: { phase: "call", count: 1 } }), ctx); + await runtime.commit(() => ({ status: "running", checkpoint: { phase: "call", count: 2 } }), ctx); + await runtime.commit(() => ({ status: "running", checkpoint: { phase: "finish", count: 2 } }), ctx); + }, + finish: async (_task, runtime, ctx) => { + await runtime.commit( + () => ({ status: "terminal", outcome: { status: "completed", result: null } }), + ctx, + ); + }, + }, + abort: async (_task, runtime, ctx) => { + await runtime.commit(() => ({ status: "terminal", outcome: { status: "aborted" } }), ctx); + }, + }); + addTask(setup.registry, Task); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const id = await root.commit((tx) => tx.createTask(Task, null, { ownership: { kind: "conversation" } }), context); + await harness.waitForTask(id, context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + expect( + telemetry + .getSpans() + .flatMap((span) => span.events) + .filter((event) => event.name === "pi.durable.checkpoint"), + ).toEqual([{ name: "pi.durable.checkpoint", attributes: { phase: "finish" } }]); + await harness.close(context); + }); + + it("starts each queued input's run in its admission trace and links input roots to their caller", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const gate = Promise.withResolvers(); + const reached = Promise.withResolvers(); + setup.faux.setResponses([ + async () => { + reached.resolve(); + await gate.promise; + return fauxAssistantMessage("first"); + }, + fauxAssistantMessage("second"), + ]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + await telemetry.startSpan({ name: "caller" }, async (caller) => { + const ctx = withTelemetry(caller, context); + const first = await root.submit({ type: "input", content: "first" }, ctx); + await reached.promise; + const second = await root.submit({ type: "input", content: "second" }, ctx); + expect((await second.status(ctx)).status).toBe("queued"); + gate.resolve(); + await first.wait(ctx); + await second.wait(ctx); + }); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const spans = telemetry.getSpans(); + const caller = spans.find((span) => span.name === "caller")!; + const submits = spans.filter((span) => span.name === "pi.durable.submit"); + expect(submits).toHaveLength(2); + for (const submit of submits) { + expect(submit.parentId).toBeNull(); + expect(submit.links).toEqual([{ context: caller.context, attributes: {} }]); + expect( + spans.some( + (span) => + span.name === "pi.durable.phase" && + span.attributes.phase === "prepare" && + JSON.stringify(span.parentContext) === JSON.stringify(submit.context), + ), + ).toBe(true); + } + expect(submits[0]!.context).not.toEqual(submits[1]!.context); + await harness.close(context); + }); + + it("links the other queued inputs to the first invocation of their shared run", async () => { + const setup = chatSetup(); + setup.settings.followUpMode = "all"; + const telemetry = new InMemoryTelemetryContext(); + const gate = Promise.withResolvers(); + const reached = Promise.withResolvers(); + setup.faux.setResponses([ + async () => { + reached.resolve(); + await gate.promise; + return fauxAssistantMessage("first"); + }, + fauxAssistantMessage("shared"), + ]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const first = await root.submit({ type: "input", content: "first" }, context); + await reached.promise; + const second = await root.submit({ type: "input", content: "second" }, context); + const third = await root.submit({ type: "input", content: "third" }, context); + const secondTrace = (await second.status(context)).trace; + const thirdTrace = (await third.status(context)).trace; + gate.resolve(); + await first.wait(context); + await second.wait(context); + await third.wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const tasks = await harness.commit((tx) => tx.scanTasks({ kind: "pi.generation" }, 10), context); + expect(tasks.items[1]).toMatchObject({ trace: secondTrace, links: [thirdTrace] }); + const phases = telemetry + .getSpans() + .filter((span) => span.name === "pi.durable.phase" && span.attributes["task.id"] === tasks.items[1]!.id); + expect(phases.map((span) => span.attributes.phase)).toEqual(["prepare", "request"]); + for (const phase of phases) expect(phase.links).toEqual([{ context: thirdTrace, attributes: {} }]); + await harness.close(context); + }); + + it("links a steer admission to the current run without moving its work into the steer's trace", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const gate = Promise.withResolvers(); + const reached = Promise.withResolvers(); + addTool( + setup.registry, + defineTool({ + name: "hold", + description: "hold", + parameters: Type.Object({}), + execute: async () => { + reached.resolve(); + await gate.promise; + return { output: [] }; + }, + }), + ); + setup.faux.setResponses([toolReply("hold"), fauxAssistantMessage("answer")]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const first = await root.submit({ type: "input", content: "first" }, context); + await reached.promise; + const run = (await harness.inspect(context)).tasks.find((task) => task.record.kind === "pi.generation")!.record; + const steer = await root.submit({ type: "input", content: "steer", whenBusy: "steer" }, context); + const steerTrace = (await steer.status(context)).trace; + const steerSpan = telemetry.getSpans().find((span) => span.attributes["submission.id"] === steer.id)!; + expect(steerSpan).toMatchObject({ parentId: null, links: [{ context: run.trace, attributes: {} }] }); + gate.resolve(); + await first.wait(context); + await steer.wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + expect( + telemetry + .getSpans() + .filter((span) => span.name === "pi.durable.phase") + .some((span) => JSON.stringify(span.parentContext) === JSON.stringify(steerTrace)), + ).toBe(false); + await harness.close(context); + }); + + it("keeps a public write admission open through commit as a child of its caller", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const storage = new ControlledStorage(); + const { harness, root } = await openTracked(storage, setup, telemetry); + await telemetry.startSpan({ name: "caller" }, async (caller) => { + const held = storage.holdCommits(); + const writing = root.submit( + { type: "write", entry: { kind: "app.note", data: "private-note" } }, + withTelemetry(caller, context), + ); + await held.entered; + const inFlight = telemetry.getSpans().find((span) => span.name === "pi.durable.submit")!; + expect(inFlight).toMatchObject({ settled: false, events: [] }); + held.release(); + const submission = await writing; + const record = await submission.status(context); + const span = telemetry.getSpans().find((span) => span.name === "pi.durable.submit")!; + expect(span).toMatchObject({ + parentContext: telemetry.getSpans()[0]!.context, + settled: true, + attributes: { result: "done" }, + }); + expect(record.trace).toEqual(span.context); + expect(span.events.map((event) => event.name)).toEqual(["pi.durable.entry", "pi.durable.submission"]); + }); + await harness.close(context); + }); + + it("links an input submitted inside a turn to the calling phase without parenting it", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + addTool( + setup.registry, + defineTool({ + name: "delegate", + description: "delegate", + parameters: Type.Object({}), + execute: async (_args, api, ctx) => { + const child = await api.commit( + (tx) => tx.createConversation({ ownership: { kind: "task", taskId: api.taskId } }), + ctx, + ); + const conversation = (await api.conversation(child.id, ctx))!; + await (await conversation.submit({ type: "input", content: "child" }, ctx)).wait(ctx); + return { output: [] }; + }, + }), + ); + setup.faux.setResponses([ + toolReply("delegate"), + fauxAssistantMessage("child answer"), + fauxAssistantMessage("parent answer"), + ]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + await (await root.submit({ type: "input", content: "parent" }, context)).wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const spans = telemetry.getSpans(); + const tool = spans.find((span) => span.attributes["tool.name"] === "delegate")!; + const child = spans.filter((span) => span.name === "pi.durable.submit")[1]!; + expect(child.parentId).toBeNull(); + expect(child.links).toEqual([{ context: tool.context, attributes: {} }]); + await harness.close(context); + }); + + it("parents background compaction to the prepare phase that creates it", async () => { + const setup = chatSetup({ models: [{ id: "faux-1", contextWindow: 1000, maxTokens: 100 }] }); + setup.settings.compaction = { enabled: true, reserveTokens: 300, keepRecentTokens: 150, backgroundTokens: 1000 }; + const telemetry = new InMemoryTelemetryContext(); + addHooks(setup.registry, CompactionTask, { beforeCompact: () => ({ decline: true }) }); + setup.faux.setResponses([fauxAssistantMessage("done")]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + await root.commit(async (tx) => { + await tx.appendEntry(root.id, { + kind: "pi.user", + model: [{ role: "user", content: "x".repeat(400), timestamp: 1 }], + }); + await tx.appendEntry(root.id, { kind: "pi.assistant", model: [fauxAssistantMessage("y".repeat(400))] }); + }, context); + await (await root.submit({ type: "input", content: "z".repeat(400) }, context)).wait(context); + await harness.waitForIdle(context); + await waitFor(() => + telemetry.getSpans().some((span) => span.attributes["task.name"] === "pi.compaction" && span.settled), + ); + const spans = telemetry.getSpans(); + const prepare = spans.find( + (span) => span.attributes["task.name"] === "pi.generation" && span.attributes.phase === "prepare", + )!; + const compaction = spans.find((span) => span.attributes["task.name"] === "pi.compaction")!; + expect(compaction.parentContext).toEqual(prepare.context); + const tasks = await harness.commit((tx) => tx.scanTasks({ kind: "pi.compaction" }, 10), context); + expect(tasks.items[0]).toMatchObject({ background: true, trace: prepare.context }); + await harness.close(context); + }); + + it("marks only the first invocation after reopen resumed, retaining its stored parent", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const storage = new ControlledStorage(); + let recover = false; + const reached = Promise.withResolvers(); + const Task = defineTask({ + name: "test.resume", + version: 1, + initial: () => ({ phase: "hold" }), + phases: { + hold: async (_task, runtime, ctx) => { + if (!recover) { + reached.resolve(); + await aborted(ctx.abortSignal!); + } + await runtime.commit(() => ({ status: "running", checkpoint: { phase: "finish" } }), ctx); + }, + finish: async (_task, runtime, ctx) => { + await runtime.commit( + () => ({ status: "terminal", outcome: { status: "completed", result: null } }), + ctx, + ); + }, + }, + abort: async (_task, runtime, ctx) => { + await runtime.commit(() => ({ status: "terminal", outcome: { status: "aborted" } }), ctx); + }, + }); + addTask(setup.registry, Task); + let { harness, root } = await openTracked(storage, setup, telemetry); + let id!: TaskId; + await telemetry.startSpan({ name: "creator" }, async (span) => { + id = await root.commit( + (tx) => tx.createTask(Task, null, { ownership: { kind: "conversation" } }), + withTelemetry(span, context), + ); + }); + harness.resume(); + await reached.promise; + const before = (await harness.getTask(id, context))!; + await harness.close(context); + recover = true; + const reopenedTelemetry = new InMemoryTelemetryContext(); + ({ harness, root } = await openTracked(storage.reopen(), setup, reopenedTelemetry)); + await harness.waitForTask(id, context); + await waitFor(() => reopenedTelemetry.getSpans().every((span) => span.settled)); + const phases = [...telemetry.getSpans(), ...reopenedTelemetry.getSpans()].filter( + (span) => span.name === "pi.durable.phase", + ); + expect(phases.map((span) => span.attributes.resumed)).toEqual([false, true, false]); + expect(phases[0]!.attributes.outcome).toBe("aborted"); + expect(phases[0]!.status).toEqual({ status: "ok" }); + for (const phase of phases) expect(phase.parentContext).toEqual(before.trace); + await harness.close(context); + expect( + [...telemetry.getMetrics(), ...reopenedTelemetry.getMetrics()] + .filter((metric) => metric.name === "pi.durable.tasks.active") + .map((metric) => metric.value), + ).toEqual([1, -1, 1, -1]); + }); + + it("emits entry and settlement events only after successful storage commits", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const storage = new ControlledStorage(); + const { harness, root } = await openTracked(storage, setup, telemetry); + await telemetry.startSpan({ name: "caller" }, async (span) => { + const ctx = withTelemetry(span, context); + await expect( + root.commit(async (tx) => { + await tx.appendEntry(root.id, { kind: "app.rolled-back", data: "private-rolled-back" }); + throw new Error("rollback"); + }, ctx), + ).rejects.toThrow("rollback"); + expect(telemetry.getSpans()[0]!.events).toEqual([]); + const held = storage.holdCommits(); + const writing = root.commit( + (tx) => tx.appendEntry(root.id, { kind: "app.note", data: "private-content" }), + ctx, + ); + await held.entered; + expect(telemetry.getSpans()[0]!.events).toEqual([]); + held.release(); + const entry = await writing; + const submission = await root.commit( + (tx) => tx.createSubmission({ conversationId: root.id, type: "write", status: "done", entry: entry.id }), + ctx, + ); + expect(telemetry.getSpans()[0]!.events).toEqual([ + { name: "pi.durable.entry", attributes: { "entry.id": entry.id, "entry.kind": "app.note" } }, + { name: "pi.durable.submission", attributes: { "submission.id": submission.id, status: "done" } }, + ]); + }); + await harness.close(context); + }); + + it("records internal compaction admissions as phase events without a submit span", async () => { + const setup = chatSetup(); + setup.settings.compaction = { keepRecentTokens: 1 }; + const telemetry = new InMemoryTelemetryContext(); + const storage = new ControlledStorage(); + let held: ReturnType | undefined; + addHooks(setup.registry, CompactionTask, { + beforeCompact: () => { + held = storage.holdCommits(); + return { summary: "private-summary" }; + }, + }); + const { harness, root } = await openTracked(storage, setup, telemetry); + await root.commit(async (tx) => { + await tx.appendEntry(root.id, { kind: "pi.user", model: [{ role: "user", content: "old", timestamp: 1 }] }); + await tx.appendEntry(root.id, { kind: "pi.assistant", model: [fauxAssistantMessage("answer")] }); + }, context); + const id = await root.compact(undefined, context); + await waitFor(() => held !== undefined); + await held!.entered; + expect(telemetry.getSpans().some((span) => span.name === "pi.durable.submit")).toBe(false); + expect(telemetry.getSpans().find((span) => span.attributes["task.name"] === "pi.compaction")).toMatchObject({ + settled: false, + events: [], + }); + held!.release(); + await harness.waitForTask(id, context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const spans = telemetry.getSpans(); + const phase = spans.find((span) => span.attributes["task.name"] === "pi.compaction")!; + expect(spans.some((span) => span.name === "pi.durable.submit")).toBe(false); + expect(phase.events.some((event) => event.name === "pi.durable.entry")).toBe(true); + expect( + phase.events.some((event) => event.name === "pi.durable.submission" && event.attributes.status === "done"), + ).toBe(true); + expect(JSON.stringify(spans)).not.toContain("private-summary"); + await harness.close(context); + }); + + it.each(["faulted", "failed", "orphaned"] as const)( + "records a fixed %s category and a bounded diagnostic", + async (status) => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const message = "diagnostic ".repeat(80); + const Task = defineTask({ + name: "test.fault", + version: 1, + initial: () => ({ phase: "fail" }), + phases: { + fail: async (_task, runtime, ctx) => { + if (status === "faulted") { + const error = new Error(message); + error.name = "private-exception-name"; + throw error; + } + await runtime.commit( + () => ({ + status: "terminal", + outcome: + status === "orphaned" + ? { status, reason: message } + : { status, error: { message, detail: "private-error-detail" } }, + }), + ctx, + ); + }, + }, + abort: async (_task, runtime, ctx) => { + await runtime.commit(() => ({ status: "terminal", outcome: { status: "aborted" } }), ctx); + }, + }); + addTask(setup.registry, Task); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const id = await root.commit( + (tx) => tx.createTask(Task, null, { ownership: { kind: "conversation" }, trace: { unknown: "carrier" } }), + context, + ); + const record = await harness.waitForTask(id, context); + expect(record.state.outcome).toMatchObject( + status === "orphaned" ? { status, reason: message } : { status, error: { message } }, + ); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const span = telemetry.getSpans().find((span) => span.name === "pi.durable.phase")!; + expect(span).toMatchObject({ parentId: null, attributes: { outcome: "faulted" } }); + expect(span.status).toEqual({ + status: "error", + error: { name: `task_${status}`, message: message.slice(0, 500) }, + }); + if (status === "faulted") + expect(span.events).toContainEqual({ + name: "pi.durable.report", + attributes: { type: "task_faulted", reason: "threw", extension: "task:test.fault", "task.id": id }, + }); + expect(JSON.stringify(span)).not.toContain("private-exception-name"); + expect(JSON.stringify(span)).not.toContain("private-error-detail"); + expect(JSON.stringify({ attributes: span.attributes, events: span.events })).not.toContain("diagnostic"); + await harness.close(context); + }, + ); + + it("keeps both interrupted runs and explicit abort handlers at status ok", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const reached = Promise.withResolvers(); + const Task = defineTask({ + name: "test.abort", + version: 1, + initial: () => ({ phase: "hold" }), + phases: { + hold: async (_task, _runtime, ctx) => { + reached.resolve(); + await aborted(ctx.abortSignal!); + }, + }, + abort: async (_task, runtime, ctx) => { + await runtime.commit( + () => ({ status: "terminal", outcome: { status: "aborted", reason: "private-abort-reason" } }), + ctx, + ); + }, + }); + addTask(setup.registry, Task); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const id = await root.commit((tx) => tx.createTask(Task, null, { ownership: { kind: "conversation" } }), context); + harness.resume(); + await reached.promise; + await harness.abortTask(id, context); + await harness.waitForTask(id, context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const phases = telemetry.getSpans().filter((span) => span.name === "pi.durable.phase"); + expect(phases.map((span) => span.attributes.kind)).toEqual(["run", "abort"]); + for (const span of phases) { + expect(span.attributes.outcome).toBe("aborted"); + expect(span.status).toEqual({ status: "ok" }); + } + expect(JSON.stringify(phases)).not.toContain("private-abort-reason"); + await harness.close(context); + }); + + it("mirrors runtime reports as fixed-field phase events and type-only counters", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const error = new Error("private-report-payload"); + const Task = defineTask({ + name: "test.report", + version: 1, + initial: () => ({ phase: "report" }), + phases: { + report: async (_task, runtime, ctx) => { + runtime.report(error); + runtime.report(error, { type: "extension", extension: "reporting-extension" }); + runtime.report(error, { type: "host", callback: "models" }); + await runtime.commit( + () => ({ status: "terminal", outcome: { status: "completed", result: null } }), + ctx, + ); + }, + }, + abort: async (_task, runtime, ctx) => { + await runtime.commit(() => ({ status: "terminal", outcome: { status: "aborted" } }), ctx); + }, + }); + addTask(setup.registry, Task); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const id = await root.commit((tx) => tx.createTask(Task, null, { ownership: { kind: "conversation" } }), context); + await harness.waitForTask(id, context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const span = telemetry.getSpans().find((span) => span.name === "pi.durable.phase")!; + expect(span.events).toEqual([ + { + name: "pi.durable.report", + attributes: { type: "task_error", extension: "task:test.report", "task.id": id }, + }, + { + name: "pi.durable.report", + attributes: { type: "extension_error", extension: "reporting-extension", "task.id": id }, + }, + { name: "pi.durable.report", attributes: { type: "host_error", "task.id": id } }, + ]); + expect(setup.reports).toEqual([error, error, error]); + expect(telemetry.getSpans().some((span) => span.name === "pi.durable.report")).toBe(false); + expect( + telemetry + .getMetrics() + .filter((metric) => metric.name === "pi.durable.reports") + .map(({ attributes, value }) => ({ attributes, value })), + ).toEqual([ + { attributes: { type: "task_error" }, value: 1 }, + { attributes: { type: "extension_error" }, value: 1 }, + { attributes: { type: "host_error" }, value: 1 }, + ]); + expect(JSON.stringify(telemetry.getSpans())).not.toContain("private-report-payload"); + await harness.close(context); + }); + + it("reports hook failures on the phase and clock failures without a phase context", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const hookError = new Error("private-hook-error"); + addHooks( + setup.registry, + GenerationTask, + { + beforeRequest: () => { + throw hookError; + }, + }, + "reporting-hooks", + ); + setup.faux.setResponses([fauxAssistantMessage("answer")]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + await (await root.submit({ type: "input", content: "input" }, context)).wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const request = telemetry + .getSpans() + .find((span) => span.name === "pi.durable.phase" && span.attributes.phase === "request")!; + expect(request.events).toContainEqual({ + name: "pi.durable.report", + attributes: { + type: "extension_error", + extension: "reporting-hooks", + "task.id": request.attributes["task.id"], + }, + }); + const clockError = new Error("private-clock-error"); + const Task = defineTask({ + name: "test.clock", + version: 1, + initial: () => ({ phase: "clock" }), + phases: { + clock: async (_task, runtime, ctx) => { + setup.now = () => { + throw clockError; + }; + runtime.now(); + setup.now = Date.now; + await runtime.commit( + () => ({ status: "terminal", outcome: { status: "completed", result: null } }), + ctx, + ); + }, + }, + abort: async (_task, runtime, ctx) => { + await runtime.commit(() => ({ status: "terminal", outcome: { status: "aborted" } }), ctx); + }, + }); + addTask(setup.registry, Task); + const id = await root.commit((tx) => tx.createTask(Task, null, { ownership: { kind: "conversation" } }), context); + await harness.waitForTask(id, context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const clock = telemetry.getSpans().find((span) => span.attributes["task.name"] === "test.clock")!; + expect(clock.events).toEqual([]); + expect(telemetry.getSpans().some((span) => span.name === "pi.durable.report")).toBe(false); + expect( + telemetry + .getMetrics() + .filter((metric) => metric.name === "pi.durable.reports") + .map((metric) => metric.attributes), + ).toEqual([{ type: "extension_error" }, { type: "host_error" }]); + expect(setup.reports).toEqual([hookError, clockError]); + expect(JSON.stringify(telemetry.getSpans())).not.toContain("private-hook-error"); + expect(JSON.stringify(telemetry.getSpans())).not.toContain("private-clock-error"); + await harness.close(context); + }); + + it("counts an outside-span session failure without starting a span", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const storage = new ControlledStorage(); + const { harness, root } = await openTracked(storage, setup, telemetry); + const error = new Error("private-storage-error"); + storage.failNextCommit(error); + await expect(root.commit((tx) => tx.appendEntry(root.id, { kind: "app.failed" }), context)).rejects.toBe(error); + await harness.closed; + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + expect(setup.reports).toEqual([error]); + expect(telemetry.getSpans()).toEqual([]); + expect(JSON.stringify(telemetry.getMetrics())).not.toContain("private-storage-error"); + expect( + telemetry + .getMetrics() + .filter((metric) => metric.name === "pi.durable.reports") + .map((metric) => metric.attributes), + ).toEqual([{ type: "session_failed" }]); + }); + + it("counts reports raised with a NOOP span without creating a root", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const error = new Error("private-noop-report"); + const unsubscribe = harness.subscribeCommits(() => { + throw error; + }); + await root.commit((tx) => tx.appendEntry(root.id, { kind: "app.note" }), context); + expect(setup.reports).toEqual([error]); + expect(telemetry.getSpans()).toEqual([]); + expect( + telemetry + .getMetrics() + .filter((metric) => metric.name === "pi.durable.reports") + .map((metric) => metric.attributes), + ).toEqual([{ type: "listener_error" }]); + unsubscribe(); + await harness.close(context); + }); + + it("attaches synchronous commit-listener reports to the active submission span", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + setup.faux.setResponses([fauxAssistantMessage("answer")]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const error = new Error("private-listener-error"); + const unsubscribe = harness.subscribeCommits((publication) => { + if (publication.changes.some((change) => change.type === "entry" && change.value.kind === "pi.user")) + throw error; + }); + await (await root.submit({ type: "input", content: "input" }, context)).wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + expect(setup.reports).toEqual([error]); + const span = telemetry.getSpans().find((span) => span.name === "pi.durable.submit")!; + expect(span.events).toContainEqual({ name: "pi.durable.report", attributes: { type: "listener_error" } }); + expect(JSON.stringify(telemetry.getSpans())).not.toContain("private-listener-error"); + unsubscribe(); + await harness.close(context); + }); + + it("preserves async listener error containment and report counting", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + setup.faux.setResponses([fauxAssistantMessage("answer")]); + const { harness, root } = await openTracked(new MemoryStorage(), setup, telemetry); + const failed = Promise.withResolvers(); + const unsubscribe = harness.subscribeCommits((publication) => { + if (publication.changes.some((change) => change.type === "entry" && change.value.kind === "pi.user")) + return failed.promise; + }); + await (await root.submit({ type: "input", content: "input" }, context)).wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + const error = new Error("private-async-listener-error"); + failed.reject(error); + await waitFor(() => setup.reports.length === 1 && telemetry.getSpans().every((span) => span.settled)); + expect(setup.reports).toEqual([error]); + expect( + telemetry + .getMetrics() + .filter((metric) => metric.name === "pi.durable.reports") + .map((metric) => metric.attributes), + ).toEqual([{ type: "listener_error" }]); + expect(JSON.stringify(telemetry.getSpans())).not.toContain("private-async-listener-error"); + unsubscribe(); + await harness.close(context); + }); + + it("emits replay for a codemode journal result without rerunning its nested tool", async () => { + const setup = chatSetup(); + const telemetry = new InMemoryTelemetryContext(); + const storage = new ControlledStorage(); + const sandbox = new CodemodeSandbox({ memoryLimitBytes: 64 * 1024 * 1024 }); + let runs = 0; + let recover = false; + const reached = Promise.withResolvers(); + addTool(setup.registry, createCodemodeTool({ sandbox, models: false })); + addTool( + setup.registry, + defineTool({ + name: "once", + description: "once", + parameters: Type.Object({}), + execute: async () => { + runs++; + return { output: [] }; + }, + }), + ); + addTool( + setup.registry, + defineTool({ + name: "hold", + description: "hold", + replay: "safe", + parameters: Type.Object({}), + execute: async (_args, _api, ctx) => { + if (!recover) { + reached.resolve(); + await aborted(ctx.abortSignal!); + } + return { output: [] }; + }, + }), + ); + setup.faux.setResponses([ + toolReply("codemode", { code: "await tools.once({}); await tools.hold({});" }), + fauxAssistantMessage("done"), + ]); + let { harness } = await openTracked(storage, setup, telemetry); + const root = await harness.root(context); + const submission = await root.submit({ type: "input", content: "run" }, context); + await reached.promise; + await harness.close(context); + recover = true; + ({ harness } = await openTracked(storage.reopen(), setup, telemetry)); + await (await harness.submission(submission.id, context))!.wait(context); + await harness.waitForIdle(context); + await waitFor(() => telemetry.getSpans().every((span) => span.settled)); + expect(runs).toBe(1); + expect( + telemetry + .getSpans() + .flatMap((span) => span.events) + .filter((event) => event.name === "pi.durable.replay"), + ).toContainEqual({ name: "pi.durable.replay", attributes: { "tool.name": "once" } }); + await harness.close(context); + await sandbox.close(); + }); +}); diff --git a/packages/telemetry/CHANGELOG.md b/packages/telemetry/CHANGELOG.md index c094cb21f..37ae6ad52 100644 --- a/packages/telemetry/CHANGELOG.md +++ b/packages/telemetry/CHANGELOG.md @@ -5,12 +5,15 @@ ### Breaking Changes - Adapters must implement `TelemetrySpan.addLink()`. Normalized span snapshots include carrier-shaped context and parent identities and ordered links. +- Adapters with optional metric or propagation capabilities must carry them through `TelemetryContext.metrics` and `TelemetryContext.propagation` on roots, spans, and extracted parents. ### Added - Opaque string-map carriers and optional `TelemetryPropagation` injection/extraction, with passive root fallback for absent or invalid carriers and shared `NOOP_TELEMETRY_PROPAGATION`. - Initial `SpanOptions.links` and late `span.addLink()` with context targets and optional attributes, including settled target spans and extracted remote parents. - Optional `TelemetryMetrics` counters, up-down counters, and histograms with boundary hints and exemplar contexts, plus shared `NOOP_TELEMETRY_METRICS` instruments. +- Optional context capability members, populated by the no-op and in-memory adapters and checked by adapter conformance. +- `NOOP_TELEMETRY_CONTEXT` is typed as `TelemetrySpan`, matching the shared inert span it provides. - Metric schema definitions and `createTypedMetrics()` with exact instrument names, kinds, and required/optional low-cardinality attributes. - In-memory propagation across processes, link and measurement snapshots, and adapter conformance cases for propagation, links, and optional metrics. diff --git a/packages/telemetry/README.md b/packages/telemetry/README.md index 8bfc5d480..a8cd21426 100644 --- a/packages/telemetry/README.md +++ b/packages/telemetry/README.md @@ -67,7 +67,7 @@ A span is diagnostic data, not business state. Recording it must not change whet ## Core Context API -A `TelemetryContext` starts a span around a callback. The callback receives a `TelemetrySpan`, which is also the explicit parent context for child spans. +A `TelemetryContext` starts a span around a callback. The callback receives a `TelemetrySpan`, which is also the explicit parent context for child spans. Contexts optionally expose their adapter's `metrics?: TelemetryMetrics` and `propagation?: TelemetryPropagation` capabilities; child spans and extracted parents carry the same capabilities. A `TelemetryContext` adapter starts root spans; hosts retain this adapter. Invocation contexts and pi-ai request options carry a `TelemetrySpan`, never the adapter. A tracing adapter that only implements `startSpan()` is still valid. ```typescript import { @@ -124,6 +124,7 @@ return telemetryContext.startSpan({ name: 'example.save' }, async (span) => { An adapter implements `TelemetryContext` and bridges the generic API to its backend. It must: - create a child span and invoke the callback synchronously, exactly once; +- expose optional metric and propagation capabilities on its contexts, child spans, and extracted parents, including inert fallback spans; - preserve the callback's returned value and rejection value, returning a promise rejected with the same value after a synchronous throw; - keep the native span open until a returned promise settles; - treat normal completion as `ok` and throws/rejections as errors unless an explicit status was set; @@ -137,7 +138,7 @@ Adapters may activate backend-native ambient context internally for automatic in ## Propagation and Span Links -An adapter may also implement `TelemetryPropagation`. Keep that capability on the one adapter configured by the application, not on every context: +An adapter may also implement `TelemetryPropagation`. Expose it through `context.propagation` so code can inject or extract using the context it already has. The root, spans, and extracted parents share the adapter's capability object: ```typescript interface TelemetryPropagation { @@ -181,7 +182,7 @@ Link targets are `TelemetryContext` handles, including spans and extracted remot ## Metrics -An adapter may implement `TelemetryMetrics` alongside `TelemetryContext` and `TelemetryPropagation`. Applications configure one adapter, not separate backends for each capability: +An adapter may implement `TelemetryMetrics` alongside `TelemetryContext` and `TelemetryPropagation`. Applications configure one adapter, not separate backends for each capability. Expose the shared capability through `context.metrics`; child spans retain it, so nested model calls can record metrics without a separate configuration option. The in-memory adapter also implements the factory methods directly: ```typescript const bytes = telemetry.counter('network.bytes', { @@ -252,6 +253,7 @@ The no-op context: - invokes callbacks synchronously; - preserves returned values and asynchronous rejections, and converts a synchronous throw to a promise rejected with the same value; - uses one shared frozen inert span, including for nested spans; +- exposes `NOOP_TELEMETRY_METRICS` and `NOOP_TELEMETRY_PROPAGATION` on its root and spans; - does not inspect or retain names, attributes, events, or statuses. ## In-Memory Reference Adapter @@ -311,7 +313,7 @@ for (const group of new Set(conformance.map((testCase) => testCase.group))) { } ``` -The suite checks synchronous single admission, result and rejection identity, automatic and explicit status, attribute merging, event ordering, inert post-settlement calls, nested and concurrent parentage, links, and suppression of unreadable telemetry payload failures. Fixtures may supply `propagation` to additionally check JSON round trips, multiple adapter hops, and safe fallback for malformed carriers. Fixtures may also supply `metrics` and `getMetrics()` to check ordered measurements, histogram exemplars, input copying, and atomic suppression of invalid metadata or measurements. `getSpans()` may flush an asynchronous exporter before returning. The testing subpath uses Node's assertion APIs; the root telemetry package remains runtime-neutral. +The suite checks capability identity on roots, child spans, extracted parents and inert spans, synchronous single admission, result and rejection identity, automatic and explicit status, attribute merging, event ordering, inert post-settlement calls, nested and concurrent parentage, links, and suppression of unreadable telemetry payload failures. Fixtures may supply `propagation` to additionally check JSON round trips, multiple adapter hops, and safe fallback for malformed carriers. Fixtures may also supply `metrics` and `getMetrics()` to check ordered measurements, histogram exemplars, input copying, and atomic suppression of invalid metadata or measurements. `getSpans()` may flush an asynchronous exporter before returning. The testing subpath uses Node's assertion APIs; the root telemetry package remains runtime-neutral. ## Typed Schemas @@ -472,20 +474,16 @@ Adapters do not need to understand schema objects. Instrumentation helpers and t Package ownership is intentionally split: - `@earendil-works/pi-telemetry` owns the vendor-neutral contract, no-op and in-memory reference contexts, schema utilities, and adapter conformance suite; -- `@earendil-works/pi-ai` accepts and propagates `telemetryContext` in provider request options but owns no telemetry schema; -- `@earendil-works/pi-agent-core` owns and exports the pi AI-request and harness schemas, their combined readonly schema tuple, and typed span helpers. +- `@earendil-works/pi-ai` accepts a parent `TelemetrySpan` through `telemetry` in provider request options and exports `AI_TELEMETRY_SCHEMA` from its root and `./models` entry points; +- `@earendil-works/pi-durable` exports `DURABLE_TELEMETRY_SCHEMA` for short task-handler and submission spans, events, and metrics; +- `@earendil-works/pi-agent-core` retains its existing agent-loop and session instrumentation and schemas. ```typescript -import { - AGENT_TELEMETRY_SCHEMAS, - AI_TELEMETRY_SCHEMA, - HARNESS_TELEMETRY_SCHEMA, - startAiSpan, - startHarnessSpan, -} from '@earendil-works/pi-agent-core'; +import { AI_TELEMETRY_SCHEMA } from '@earendil-works/pi-ai/models'; +import { DURABLE_TELEMETRY_SCHEMA } from '@earendil-works/pi-durable'; ``` -The pi schemas use pi-owned `pi.ai.*`, `pi.harness.*`, and `pi.session.*` names. Adapters may translate them to backend conventions without changing the emitted pi vocabulary. +The AI and Durable schemas use pi-owned `pi.ai.*` and `pi.durable.*` names. Adapters may translate them to backend conventions without changing the emitted pi vocabulary. ## Security and Portability @@ -501,7 +499,7 @@ The package does not use `AsyncLocalStorage` or another runtime-specific ambient | Export | Purpose | |---|---| -| `TelemetryContext` | Starts callback-managed child spans | +| `TelemetryContext` | Starts callback-managed child spans and optionally exposes adapter metrics/propagation | | `TelemetrySpan` | Records attributes, events, and status; also acts as a child context | | `SpanOptions` | Span name, optional start attributes and links | | `SpanLink` | Context target and optional link attributes | diff --git a/packages/telemetry/src/index.ts b/packages/telemetry/src/index.ts index 4d76e73a0..fbea18135 100644 --- a/packages/telemetry/src/index.ts +++ b/packages/telemetry/src/index.ts @@ -1,4 +1,4 @@ -import type { TelemetryMetricDefinition } from "./metrics.ts"; +import type { TelemetryMetricDefinition, TelemetryMetrics } from "./metrics.ts"; export type AttributeValue = string | number | boolean | readonly string[] | readonly number[] | readonly boolean[]; @@ -29,6 +29,9 @@ export interface SpanOptions { export type SpanStatus = { status: "ok" } | { status: "error"; error?: { name: string; message: string } }; export interface TelemetryContext { + /** Adapter capabilities remain available on child spans and extracted parents. */ + readonly metrics?: TelemetryMetrics; + readonly propagation?: TelemetryPropagation; startSpan(options: SpanOptions, callback: (span: TelemetrySpan) => T | Promise): Promise; } diff --git a/packages/telemetry/src/memory.ts b/packages/telemetry/src/memory.ts index 2db67fe4a..dd9934297 100644 --- a/packages/telemetry/src/memory.ts +++ b/packages/telemetry/src/memory.ts @@ -85,6 +85,8 @@ interface InMemoryParent { const contextCarriers = new WeakMap(); interface InMemoryTelemetryState { + metrics: TelemetryMetrics; + propagation: TelemetryPropagation; scope: string; spans: MutableRecordedTelemetrySpan[]; measurements: RecordedTelemetryMeasurement[]; @@ -185,23 +187,43 @@ function createSpan( }; } +function startInertSpan( + state: InMemoryTelemetryState, + options: SpanOptions, + callback: (span: TelemetrySpan) => T | Promise, +): Promise { + return NOOP_TELEMETRY_CONTEXT.startSpan(options, (noop) => + callback({ + ...noop, + metrics: state.metrics, + propagation: state.propagation, + startSpan: ( + childOptions: SpanOptions, + childCallback: (span: TelemetrySpan) => Result | Promise, + ) => startInertSpan(state, childOptions, childCallback), + }), + ); +} + function startInMemorySpan( state: InMemoryTelemetryState, parent: InMemoryParent | undefined, options: SpanOptions, callback: (span: TelemetrySpan) => T | Promise, ): Promise { - if (parent?.span?.settled) return NOOP_TELEMETRY_CONTEXT.startSpan(options, callback); + if (parent?.span?.settled) return startInertSpan(state, options, callback); let recordedSpan: MutableRecordedTelemetrySpan; try { recordedSpan = createSpan(state, parent, options); state.spans.push(recordedSpan); } catch { - return NOOP_TELEMETRY_CONTEXT.startSpan(options, callback); + return startInertSpan(state, options, callback); } const span: TelemetrySpan = { + metrics: state.metrics, + propagation: state.propagation, startSpan: ( childOptions: SpanOptions, childCallback: (child: TelemetrySpan) => Result | Promise, @@ -316,7 +338,11 @@ function createMeasurementRecorder( * Create a fresh instance to isolate tests or independent recording scopes. */ export class InMemoryTelemetryContext implements TelemetryContext, TelemetryPropagation, TelemetryMetrics { + readonly metrics: TelemetryMetrics = this; + readonly propagation: TelemetryPropagation = this; private readonly state: InMemoryTelemetryState = { + metrics: this, + propagation: this, scope: crypto.randomUUID(), spans: [], measurements: [], @@ -352,6 +378,8 @@ export class InMemoryTelemetryContext implements TelemetryContext, TelemetryProp ? Number(span) : null; const parent: TelemetryContext = { + metrics: this, + propagation: this, startSpan: (options: SpanOptions, callback: (span: TelemetrySpan) => T | Promise) => startInMemorySpan(this.state, { context, localId }, options, callback), }; diff --git a/packages/telemetry/src/noop.ts b/packages/telemetry/src/noop.ts index 5527b47da..0e39acb11 100644 --- a/packages/telemetry/src/noop.ts +++ b/packages/telemetry/src/noop.ts @@ -1,4 +1,4 @@ -import type { SpanOptions, TelemetryContext, TelemetryPropagation, TelemetrySpan } from "./index.ts"; +import type { SpanOptions, TelemetryPropagation, TelemetrySpan } from "./index.ts"; import type { TelemetryCounter, TelemetryHistogram, TelemetryMetrics, TelemetryUpDownCounter } from "./metrics.ts"; function startNoopSpan(_options: SpanOptions, callback: (span: TelemetrySpan) => T | Promise): Promise { @@ -9,24 +9,6 @@ function startNoopSpan(_options: SpanOptions, callback: (span: TelemetrySpan) } } -const noopTelemetrySpan: TelemetrySpan = { - startSpan: startNoopSpan, - addLink: () => {}, - addEvent: () => {}, - setAttributes: () => {}, - setStatus: () => {}, -}; -Object.freeze(noopTelemetrySpan); - -/** Shared telemetry context used when an application does not provide one. */ -export const NOOP_TELEMETRY_CONTEXT: TelemetryContext = noopTelemetrySpan; - -/** Shared propagation capability that neither inspects nor retains its inputs. */ -export const NOOP_TELEMETRY_PROPAGATION: TelemetryPropagation = Object.freeze({ - inject: () => undefined, - extract: () => NOOP_TELEMETRY_CONTEXT, -}); - const noopCounter: TelemetryCounter = Object.freeze({ add: () => {} }); const noopUpDownCounter: TelemetryUpDownCounter = Object.freeze({ add: () => {} }); const noopHistogram: TelemetryHistogram = Object.freeze({ record: () => {} }); @@ -37,3 +19,23 @@ export const NOOP_TELEMETRY_METRICS: TelemetryMetrics = Object.freeze({ upDownCounter: () => noopUpDownCounter, histogram: () => noopHistogram, }); + +/** Shared propagation capability that neither inspects nor retains its inputs. */ +export const NOOP_TELEMETRY_PROPAGATION: TelemetryPropagation = Object.freeze({ + inject: () => undefined, + extract: () => NOOP_TELEMETRY_CONTEXT, +}); + +const noopTelemetrySpan: TelemetrySpan = { + metrics: NOOP_TELEMETRY_METRICS, + propagation: NOOP_TELEMETRY_PROPAGATION, + startSpan: startNoopSpan, + addLink: () => {}, + addEvent: () => {}, + setAttributes: () => {}, + setStatus: () => {}, +}; +Object.freeze(noopTelemetrySpan); + +/** Shared telemetry context used when an application does not provide one. */ +export const NOOP_TELEMETRY_CONTEXT: TelemetrySpan = noopTelemetrySpan; diff --git a/packages/telemetry/src/testing/conformance.ts b/packages/telemetry/src/testing/conformance.ts index df147246e..a8b16e46a 100644 --- a/packages/telemetry/src/testing/conformance.ts +++ b/packages/telemetry/src/testing/conformance.ts @@ -6,6 +6,7 @@ import { type SpanOptions, type SpanStatus, type TelemetryCarrier, + type TelemetryContext, type TelemetrySpan, } from "../index.ts"; import type { RecordedTelemetrySpan } from "../memory.ts"; @@ -70,6 +71,33 @@ export function createTelemetryAdapterConformance( factory: TelemetryAdapterFixtureFactory, ): readonly TelemetryAdapterConformanceCase[] { return [ + createCase( + factory, + "capabilities", + "carries adapter capabilities through contexts and spans", + async (fixture) => { + const metrics = fixture.metrics ?? fixture.context.metrics; + const propagation = fixture.propagation ?? fixture.context.propagation; + const assertCapabilities = (context: TelemetryContext): void => { + strictEqual(context.metrics, metrics); + strictEqual(context.propagation, propagation); + }; + assertCapabilities(fixture.context); + let settled: TelemetrySpan | undefined; + await fixture.context.startSpan({ name: "capabilities" }, async (span) => { + settled = span; + assertCapabilities(span); + await span.startSpan({ name: "capabilities.child" }, assertCapabilities); + if (propagation) { + const parent = propagation.extract(propagation.inject(span)); + assertCapabilities(parent); + await parent.startSpan({ name: "capabilities.extracted" }, assertCapabilities); + } + }); + ok(settled); + await settled.startSpan({ name: "capabilities.inert" }, assertCapabilities); + }, + ), createCase( factory, "metrics", diff --git a/packages/telemetry/test/telemetry.test.ts b/packages/telemetry/test/telemetry.test.ts index fbbbb1040..bcd31fe32 100644 --- a/packages/telemetry/test/telemetry.test.ts +++ b/packages/telemetry/test/telemetry.test.ts @@ -4,6 +4,8 @@ import { defineTelemetrySchema, InMemoryTelemetryContext, NOOP_TELEMETRY_CONTEXT, + NOOP_TELEMETRY_METRICS, + NOOP_TELEMETRY_PROPAGATION, type SchemaTelemetrySpan, type SpanAttributes, type SpanOptions, @@ -168,6 +170,10 @@ describe("NOOP_TELEMETRY_CONTEXT", () => { expect(admitted).toBe(true); expect(await result).toBe(42); expect(Object.isFrozen(firstSpan)).toBe(true); + expect(NOOP_TELEMETRY_CONTEXT.metrics).toBe(NOOP_TELEMETRY_METRICS); + expect(NOOP_TELEMETRY_CONTEXT.propagation).toBe(NOOP_TELEMETRY_PROPAGATION); + expect(firstSpan?.metrics).toBe(NOOP_TELEMETRY_METRICS); + expect(firstSpan?.propagation).toBe(NOOP_TELEMETRY_PROPAGATION); }); it("preserves synchronous and asynchronous rejection values", async () => { diff --git a/scripts/check-entry-graphs.mjs b/scripts/check-entry-graphs.mjs index 7dde4e553..63e61082e 100644 --- a/scripts/check-entry-graphs.mjs +++ b/scripts/check-entry-graphs.mjs @@ -36,8 +36,10 @@ const WORKSPACE = { const BUDGETS = { "packages/ai": { "./models": { - maxFiles: 15, + // Request telemetry reaches pi-ai's telemetry.ts and pi-telemetry's root (index, noop, metrics, memory). + maxFiles: 18, forbid: ["providers/", "models.generated.ts", "index.ts", "utils/validation.ts", "utils/typebox-helpers.ts"], + allow: ["packages/telemetry/src/index.ts"], }, "./utils/*": { maxFiles: 3, forbid: ["providers/", "api/", "index.ts"] }, }, @@ -60,8 +62,8 @@ const BUDGETS = { // Tool argument validation reaches TypeBox; provider-session creation reaches pi-ai's lean UUID utility; the // memory and SQLite storages share scan order and cursor handling. Values from Chord's root (copyJson, // replicatedState) reach its host runtime through the root barrel. Chord's context reaches pi-telemetry's root - // (index, noop, metrics, memory) for its NOOP telemetry default. - maxFiles: 70, + // (index, noop, metrics, memory) for its NOOP telemetry default; harness/telemetry.ts is Durable's schema. + maxFiles: 71, forbid: [ "packages/ai/src/index.ts", "packages/ai/src/utils/typebox-helpers.ts", @@ -155,7 +157,7 @@ for (const [pkgDir, budgets] of Object.entries(BUDGETS)) { failures += 1; } for (const pattern of budget.forbid ?? []) { - const hit = graph.filter((file) => file.includes(pattern)); + const hit = graph.filter((file) => file.includes(pattern) && !(budget.allow ?? []).some((allowed) => file.endsWith(allowed))); if (hit.length > 0) { console.error(`${pkgDir} export "${name}" must not reach ${pattern}:\n${hit.map((f) => ` ${f}`).join("\n")}`); failures += 1;