diff --git a/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts b/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts index 70a51899a7..650da20739 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts @@ -1,6 +1,49 @@ import { describe, expect, it, vi } from "vitest"; import type { AdapterRuntimeEvent } from "../types.js"; -import { measureStartupStep } from "./startup-timing.js"; +import type { StartupSpan, StartupTracer } from "./startup-timing.js"; +import { measureStartupStep, normalizeProviderFamily } from "./startup-timing.js"; + +/** + * A recording span for the mock tracer. It captures the attribute set, the + * status, and the end count so a test can assert the emitted span shape. + */ +class MockSpan implements StartupSpan { + readonly attributes: Record = {}; + status: { code: number; message?: string } | undefined; + endCount = 0; + + constructor( + readonly name: string, + initial: Record | undefined, + ) { + if (initial) Object.assign(this.attributes, initial); + } + + setAttribute(key: string, value: string | number | boolean): void { + this.attributes[key] = value; + } + + setStatus(status: { code: number; message?: string }): void { + this.status = status; + } + + end(): void { + this.endCount += 1; + } +} + +/** A recording tracer that keeps every span it opens for assertions. */ +function makeMockTracer(): { tracer: StartupTracer; spans: MockSpan[] } { + const spans: MockSpan[] = []; + const tracer: StartupTracer = { + startSpan(name, options) { + const span = new MockSpan(name, options?.attributes); + spans.push(span); + return span; + }, + }; + return { tracer, spans }; +} describe("measureStartupStep", () => { it("emits one run.startup.step event with the step name and measured durationMs", async () => { @@ -193,4 +236,165 @@ describe("measureStartupStep", () => { }), ).rejects.toBe(boom); }); + + it("opens one span and ends it once for a normal step", async () => { + const { tracer, spans } = makeMockTracer(); + const onEvent = vi.fn(async () => {}); + + await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", { + tracer, + }); + + expect(spans).toHaveLength(1); + expect(spans[0]!.name).toBe("stage.sync"); + expect(spans[0]!.attributes.step).toBe("stage.sync"); + expect(spans[0]!.endCount).toBe(1); + }); + + it("ends the span and sets an error status when fn throws, then re-throws", async () => { + const { tracer, spans } = makeMockTracer(); + const onEvent = vi.fn(async () => {}); + const boom = new Error("step failed"); + + await expect( + measureStartupStep({ onEvent }, () => 0, "acp.handshake", async () => { + throw boom; + }, { tracer }), + ).rejects.toBe(boom); + + expect(spans).toHaveLength(1); + expect(spans[0]!.endCount).toBe(1); + // SpanStatusCode.ERROR === 2 in @opentelemetry/api. + expect(spans[0]!.status?.code).toBe(2); + }); + + it("sets the same roundTrips / providerExecMs / providerGetMs deltas on the payload and the span", async () => { + let t = 0; + const now = () => t; + let execCount = 5; + let execMs = 100; + let getMs = 40; + const events: AdapterRuntimeEvent[] = []; + const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { + events.push(event); + }); + const { tracer, spans } = makeMockTracer(); + + await measureStartupStep({ onEvent }, now, "stage.sync", async () => { + t = 90; + execCount += 3; + execMs += 600; + getMs += 15; + return "ok"; + }, { + tracer, + roundTrips: () => execCount, + providerExecMs: () => execMs, + providerGetMs: () => getMs, + }); + + const payload = events[0]!.payload as Record; + expect(payload.roundTrips).toBe(3); + expect(payload.providerExecMs).toBe(600); + expect(payload.providerGetMs).toBe(15); + // The span carries the identical deltas — one build block feeds both. + expect(spans[0]!.attributes.roundTrips).toBe(3); + expect(spans[0]!.attributes.providerExecMs).toBe(600); + expect(spans[0]!.attributes.providerGetMs).toBe(15); + }); + + it("sets no span attribute (and no payload field) when a reader returns undefined", async () => { + const events: AdapterRuntimeEvent[] = []; + const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { + events.push(event); + }); + const { tracer, spans } = makeMockTracer(); + + await measureStartupStep({ onEvent }, () => 0, "workspace.resolve", async () => "ok", { + tracer, + // A reader may return undefined when the counter is unavailable. The guard + // must omit the attribute rather than emit NaN or 0. + roundTrips: () => undefined as unknown as number, + providerExecMs: () => undefined as unknown as number, + }); + + expect(spans[0]!.attributes).not.toHaveProperty("roundTrips"); + expect(spans[0]!.attributes).not.toHaveProperty("providerExecMs"); + expect(Object.values(spans[0]!.attributes).some((v) => Number.isNaN(v))).toBe(false); + const payload = events[0]!.payload as Record; + expect(payload).not.toHaveProperty("roundTrips"); + expect(payload).not.toHaveProperty("providerExecMs"); + }); + + it("normalizes a plugin-backed provider key to plugin and keeps a built-in family as-is", async () => { + const onEvent = vi.fn(async () => {}); + + const custom = makeMockTracer(); + await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", { + tracer: custom.tracer, + provider: "acme-cloud-runner", + }); + expect(custom.spans[0]!.attributes.provider).toBe("plugin"); + + const builtIn = makeMockTracer(); + await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", { + tracer: builtIn.tracer, + provider: "daytona", + }); + expect(builtIn.spans[0]!.attributes.provider).toBe("daytona"); + }); + + it("normalizeProviderFamily maps every non-built-in key to plugin", () => { + for (const key of ["daytona", "kubernetes", "e2b", "cloudflare", "exe-dev", "modal", "novita"]) { + expect(normalizeProviderFamily(key)).toBe(key); + } + for (const key of ["acme", "my-plugin", "", "DAYTONA", undefined]) { + expect(normalizeProviderFamily(key)).toBe("plugin"); + } + }); + + it("emits exactly the allowlisted span-attribute key set and no command / path / ID / error-text key", async () => { + const onEvent = vi.fn(async () => {}); + const { tracer, spans } = makeMockTracer(); + + await measureStartupStep({ onEvent }, () => 0, "acp.handshake", async () => "ok", { + tracer, + provider: "daytona", + roundTrips: () => 3, + providerExecMs: () => 600, + providerGetMs: () => 15, + // extra() carries caller-measured numbers into the EVENT payload only. + // It must never widen the span-attribute set. + extra: () => ({ createRuntimeMs: 12, ensureSessionMs: 6988 }), + }); + + expect(Object.keys(spans[0]!.attributes).sort()).toEqual( + ["provider", "providerExecMs", "providerGetMs", "roundTrips", "step"], + ); + // extra() keys stay off the span. + expect(spans[0]!.attributes).not.toHaveProperty("createRuntimeMs"); + expect(spans[0]!.attributes).not.toHaveProperty("ensureSessionMs"); + // No free-form identifier / command / path key leaks in. The pattern uses + // no `i` flag, so the camelCase `Id` matches `runId` / `userId` but not the + // "id" inside the allowlisted `provider`. + for (const key of Object.keys(spans[0]!.attributes)) { + expect(key).not.toMatch(/command|args|env|stdout|stderr|path|url|repo|ref|branch|Id|_id|error|message/); + } + }); + + it("uses a no-op tracer by default so a call without a tracer changes nothing", async () => { + const events: AdapterRuntimeEvent[] = []; + const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { + events.push(event); + }); + + // No tracer supplied. The helper must still emit the event and return the + // value without throwing. + const result = await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", { + roundTrips: () => 3, + }); + + expect(result).toBe("ok"); + expect(events[0]!.payload).toMatchObject({ step: "stage.sync" }); + }); }); diff --git a/packages/adapter-utils/src/acpx-engine/startup-timing.ts b/packages/adapter-utils/src/acpx-engine/startup-timing.ts index 7e3f55941d..90f26a1b77 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.ts @@ -9,6 +9,113 @@ import type { AdapterExecutionContext, AdapterRuntimeEvent } from "../types.js"; */ export const RUN_STARTUP_STEP_EVENT_TYPE = "run.startup.step"; +/** + * The public built-in sandbox provider families. A key in this set is safe to + * emit as a low-cardinality span attribute. Any other key is operator-defined + * (plugin-backed) and unbounded, so `normalizeProviderFamily` maps it to the + * generic value `plugin`. Keep this list closed and small. + */ +const BUILT_IN_PROVIDER_FAMILIES: ReadonlySet = new Set([ + "daytona", + "kubernetes", + "e2b", + "cloudflare", + "exe-dev", + "modal", + "novita", +]); + +/** The generic family for any provider key outside the built-in list. */ +const PLUGIN_PROVIDER_FAMILY = "plugin"; + +/** + * Map a raw provider key to a low-cardinality public family. Return the key + * unchanged when it is a built-in family. Return `plugin` for every other + * value, so an operator-defined plugin key never becomes an unbounded span + * attribute. A missing or empty key also maps to `plugin`. + */ +export function normalizeProviderFamily(key: string | undefined): string { + if (key && BUILT_IN_PROVIDER_FAMILIES.has(key)) return key; + return PLUGIN_PROVIDER_FAMILY; +} + +/** + * The value of `SpanStatusCode.ERROR` in `@opentelemetry/api`. `adapter-utils` + * stays OTel-free, so the timing helper uses the numeric value directly. A real + * injected OTel span reads it as the error status. + */ +const SPAN_STATUS_CODE_ERROR = 2; + +/** + * A minimal, OTel-free span contract. The server injects a real + * `@opentelemetry/api` span, which satisfies this shape structurally. The + * default is a no-op span, so a step with no injected tracer changes nothing. + */ +export interface StartupSpan { + setAttribute(key: string, value: string | number | boolean): void; + setStatus(status: { code: number; message?: string }): void; + end(): void; +} + +/** + * A minimal, OTel-free tracer contract. The server injects a real + * `@opentelemetry/api` tracer, which satisfies this shape structurally. The + * `startSpan` signature is a subset of the OTel one, so a real tracer is + * assignable here. + */ +export interface StartupTracer { + startSpan( + name: string, + options?: { attributes?: Record }, + ): StartupSpan; +} + +const NOOP_SPAN: StartupSpan = { + setAttribute() {}, + setStatus() {}, + end() {}, +}; + +/** + * The default tracer. It opens no real span, so `measureStartupStep` behaves + * exactly as before when the caller injects no tracer. + */ +const NOOP_TRACER: StartupTracer = { + startSpan: () => NOOP_SPAN, +}; + +/** + * Set a numeric span attribute only when the value is a finite number. A reader + * that returns `undefined` (the counter is unavailable) yields no attribute, + * never `NaN` and never a misleading `0`. This mirrors the host counter guard + * at `environment-execution-target.ts`. + */ +function setFiniteNumberAttr( + span: StartupSpan, + key: string, + value: number | undefined, +): void { + if (typeof value === "number" && Number.isFinite(value)) { + span.setAttribute(key, value); + } +} + +/** + * Compute a counter delta from a reader. Return `undefined` when the reader is + * absent, or when either the start or the end snapshot is not a finite number. + * A `undefined` result yields no payload field and no span attribute. + */ +function finiteDelta( + read: (() => number) | undefined, + start: number | undefined, +): number | undefined { + if (!read) return undefined; + const end = read(); + if (typeof end !== "number" || !Number.isFinite(end)) return undefined; + const base = typeof start === "number" && Number.isFinite(start) ? start : 0; + return end - base; +} + /** * Optional per-step attribution attached to a `run.startup.step` event, all * additive to the free-form jsonb payload (no schema change). Each reader is a @@ -26,12 +133,23 @@ export const RUN_STARTUP_STEP_EVENT_TYPE = "run.startup.step"; * any additional numeric fields to merge into the payload; used by * `acp.handshake` to carry its `createRuntimeMs` / `ensureSessionMs` sub-split * (Open Q2), which are measured by the caller rather than read from a counter. + * The `extra` map feeds the EVENT payload only. Its keys never become span + * attributes, so a free-form key cannot widen the closed span allowlist. + * - `tracer` — an injected structural tracer. It defaults to a no-op, so the + * span path changes no runtime behavior until the server injects a real + * tracer. The span carries only the closed attribute allowlist (`step`, the + * normalized `provider`, and the finite counter deltas). + * - `provider` — the raw provider key for the step. `measureStartupStep` + * normalizes it through `normalizeProviderFamily` before it sets the + * low-cardinality `provider` span attribute. It never sets the raw key. */ export interface StartupStepMeasureOptions { roundTrips?: () => number; providerExecMs?: () => number; providerGetMs?: () => number; extra?: () => Record; + tracer?: StartupTracer; + provider?: string; } function buildStepEvent(payload: Record): AdapterRuntimeEvent { @@ -55,6 +173,16 @@ function buildStepEvent(payload: Record): AdapterRuntimeEvent { * `ctx.onEvent` is optional — a missing sink is a no-op that neither throws nor * swallows `fn`'s return value or error. A step skipped by a warm cache never * calls this helper, so it emits no event (never a zero). + * + * When `options.tracer` is injected, the helper also opens one span at `start` + * and ends it in the `finally`. The span carries a closed attribute allowlist: + * `step`, the normalized `provider`, and the finite counter deltas + * (`roundTrips` / `providerExecMs` / `providerGetMs`). A throwing `fn` sets the + * span error status before the span ends. The span build reuses the same delta + * values as the event payload, so the two paths never drift. The tracer + * defaults to a no-op, so a caller with no tracer changes nothing. Every span + * call sits inside the same error swallow as the event sink, so a throwing + * tracer never changes startup control flow. */ export async function measureStartupStep( ctx: Pick, @@ -67,23 +195,58 @@ export async function measureStartupStep( const roundTripsStart = options.roundTrips?.(); const providerExecStart = options.providerExecMs?.(); const providerGetStart = options.providerGetMs?.(); + + // Open the span with only the low-cardinality allowlisted attributes known at + // the start: the step name and the normalized provider family. + const tracer = options.tracer ?? NOOP_TRACER; + const startAttributes: Record = { step }; + if (options.provider !== undefined) { + startAttributes.provider = normalizeProviderFamily(options.provider); + } + let span: StartupSpan; + try { + span = tracer.startSpan(step, { attributes: startAttributes }); + } catch { + // A throwing tracer must not change startup control flow. + span = NOOP_SPAN; + } + + let stepFailed = false; try { return await fn(); + } catch (err) { + stepFailed = true; + throw err; } finally { const durationMs = now() - start; + + // One attribute-build block feeds both the event payload and the span, so + // the two paths never drift. `undefined` deltas produce neither a payload + // field nor a span attribute (fail open — never `NaN`, never `0`). + const roundTrips = finiteDelta(options.roundTrips, roundTripsStart); + const providerExecMs = finiteDelta(options.providerExecMs, providerExecStart); + const providerGetMs = finiteDelta(options.providerGetMs, providerGetStart); + const payload: Record = { step, durationMs }; - if (options.roundTrips) { - payload.roundTrips = options.roundTrips() - (roundTripsStart ?? 0); - } - if (options.providerExecMs) { - payload.providerExecMs = options.providerExecMs() - (providerExecStart ?? 0); - } - if (options.providerGetMs) { - payload.providerGetMs = options.providerGetMs() - (providerGetStart ?? 0); - } + if (roundTrips !== undefined) payload.roundTrips = roundTrips; + if (providerExecMs !== undefined) payload.providerExecMs = providerExecMs; + if (providerGetMs !== undefined) payload.providerGetMs = providerGetMs; if (options.extra) { + // `extra` feeds the EVENT payload only. Its keys never become span + // attributes, so it cannot widen the closed span allowlist. Object.assign(payload, options.extra()); } + + try { + if (stepFailed) span.setStatus({ code: SPAN_STATUS_CODE_ERROR }); + setFiniteNumberAttr(span, "roundTrips", roundTrips); + setFiniteNumberAttr(span, "providerExecMs", providerExecMs); + setFiniteNumberAttr(span, "providerGetMs", providerGetMs); + span.end(); + } catch { + // Observability must not change startup control flow. + } + try { await ctx.onEvent?.(buildStepEvent(payload)); } catch { diff --git a/server/src/__tests__/instrumentation.test.ts b/server/src/__tests__/instrumentation.test.ts index 68134870a5..41c8407906 100644 --- a/server/src/__tests__/instrumentation.test.ts +++ b/server/src/__tests__/instrumentation.test.ts @@ -87,6 +87,44 @@ describe("instrumentationReady", () => { }); }); +describe("getStartupTracer", () => { + it("returns a usable tracer-shaped object when OTEL_EXPORTER_OTLP_ENDPOINT is unset", async () => { + const { getStartupTracer } = await importFreshInstrumentation(); + + const tracer = getStartupTracer(); + + // The accessor never returns null. The result exposes the span surface the + // startup seam calls, so the caller needs no null check. + expect(tracer).not.toBeNull(); + expect(typeof tracer.startSpan).toBe("function"); + // A no-op tracer must open and end a span without throwing. + expect(() => tracer.startSpan("workspace.resolve").end()).not.toThrow(); + }); + + it("loads no OTel SDK package when the endpoint is unset", async () => { + const warn = vi.spyOn(console, "warn").mockImplementation(() => {}); + + const { getStartupTracer, instrumentationReady } = await importFreshInstrumentation(); + + // The endpoint is unset, so the bootstrap never runs and no SDK package + // import is attempted; readiness resolves at once. + await expect(instrumentationReady).resolves.toBeUndefined(); + + // The accessor still returns a usable tracer even though no @opentelemetry + // SDK package is installed. That proves it never imported the SDK: a hard + // dependency on the SDK would throw here instead. + const tracer = getStartupTracer(); + expect(typeof tracer.startSpan).toBe("function"); + expect(() => tracer.startSpan("stage.sync").end()).not.toThrow(); + + // The bootstrap "packages are not installed" diagnostic must not fire on + // this path. That message comes only from the endpoint-set bootstrap. + for (const call of warn.mock.calls) { + expect(String(call[0])).not.toContain("@opentelemetry/* packages are not installed"); + } + }); +}); + describe("shutdownInstrumentation", () => { it("is a no-op when tracing is off and idempotent across calls", async () => { const { shutdownInstrumentation } = await importFreshInstrumentation(); diff --git a/server/src/instrumentation.ts b/server/src/instrumentation.ts index 24109b22e0..8b29894353 100644 --- a/server/src/instrumentation.ts +++ b/server/src/instrumentation.ts @@ -26,11 +26,77 @@ // exit via `shutdownInstrumentation()`, which index.ts awaits in its signal // handler before `process.exit`. +import { createRequire } from "node:module"; + const endpoint = process.env.OTEL_EXPORTER_OTLP_ENDPOINT; let sdkShutdown: (() => Promise) | null = null; let shutdownPromise: Promise | null = null; +/** + * A minimal, structural span/tracer surface. It is the subset of the + * `@opentelemetry/api` `Span` / `Tracer` shape that the startup timing seam + * calls. A real OTel tracer satisfies it. The no-op fallback below implements + * it too, so the caller never needs a null check. + */ +interface StartupTracerHandle { + startSpan( + name: string, + options?: unknown, + ): { + setAttribute(key: string, value: unknown): void; + setStatus(status: { code: number; message?: string }): void; + end(): void; + }; +} + +const NOOP_SPAN = { + setAttribute() {}, + setStatus() {}, + end() {}, +}; + +/** + * The no-op tracer returned when `@opentelemetry/api` is absent or a lookup + * fails. It opens a span that does nothing, so startup tracing stays a no-op + * without an installed OTel package. + */ +const NOOP_TRACER: StartupTracerHandle = { + startSpan: () => NOOP_SPAN, +}; + +let tracerApiLoadFailed = false; + +/** + * Return a startup tracer. When `@opentelemetry/api` is installed, it returns + * `trace.getTracer(name)`. The `api` package itself returns a no-op tracer + * while no SDK is registered, so an unset endpoint still yields a safe no-op + * without loading any OTel SDK package. The api package loads lazily through + * `require`, so the module graph stays OTel-free until the first call. The + * accessor never throws: a load or lookup failure logs once and returns the + * local no-op tracer (fail open). + */ +export function getStartupTracer(name = "paperclip.startup"): StartupTracerHandle { + try { + const require = createRequire(import.meta.url); + const api = require("@opentelemetry/api") as { + trace?: { getTracer(n: string): StartupTracerHandle }; + }; + const tracer = api.trace?.getTracer(name); + return tracer ?? NOOP_TRACER; + } catch (err) { + if (!tracerApiLoadFailed) { + tracerApiLoadFailed = true; + // eslint-disable-next-line no-console + console.warn( + "[paperclip] @opentelemetry/api is not available; startup tracing uses a no-op tracer.", + err, + ); + } + return NOOP_TRACER; + } +} + /** * Resolves once the OTel SDK has started (or once bootstrap has failed and * logged, or immediately when the feature is off). Await before constructing