diff --git a/packages/adapter-utils/src/acpx-engine/execute.test.ts b/packages/adapter-utils/src/acpx-engine/execute.test.ts index b2b7e64fe2..c222fa0553 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.test.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.test.ts @@ -35,6 +35,7 @@ import { type AcpxEngineExecutorOptions, } from "./execute.js"; import { runChildProcess } from "../server-utils.js"; +import { SANDBOX_STARTUP_SPAN_ATTRS } from "./startup-timing.js"; const tempRoots: string[] = []; @@ -278,15 +279,29 @@ function createRecordingStartupTrace() { return { traceContext, spans }; } -// The closed span-attribute allowlist for a sandbox-start span (Phase 2 + 3). -// A test asserts every recorded attribute key is in this set, so a command, -// path, id, or error-text key can never ride a span. -const ALLOWED_STARTUP_SPAN_ATTRIBUTE_KEYS = new Set([ - "step", - "provider", - "roundTrips", - "providerExecMs", - "providerGetMs", +// The closed span-attribute allowlist for a sandbox-start span. A test asserts +// every recorded attribute key is in this set, so a command, path, id, or +// error-text key can never ride a span. Every key uses the closed +// `paperclip.sandbox.startup.` prefix from the attribute contract. +const A = SANDBOX_STARTUP_SPAN_ATTRS; +const ALLOWED_STARTUP_SPAN_ATTRIBUTE_KEYS = new Set([ + // Step-span keys. + A.provider, + A.stepWallMs, + A.outcome, + // Root-span keys. + A.rootWallMs, + A.rootWorkMs, + A.rootDiffMs, + A.coldStart, + A.region, + A.imageId, + A.sandboxId, + A.leaseId, + // Handshake sub-times and the parallel-batch tag. + A.handshakeCreateRuntimeWallMs, + A.handshakeEnsureSessionWallMs, + A.batch, ]); describe("shared ACPX engine runtime behavior", () => { @@ -3233,6 +3248,91 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = } }); + it("records root wall / work / diff times and the bounded context on the root span", async () => { + const root = await makeTempRoot(); + const stateDir = path.join(root, "state"); + const localCwd = path.join(root, "worktree"); + const remoteCwd = path.join(root, "remote-workspace"); + await fs.mkdir(localCwd, { recursive: true }); + await fs.mkdir(remoteCwd, { recursive: true }); + // A plugin-backed target with a lease id. The provider clamps to `plugin` + // and the lease id rides only as a hash. + const executionTarget = { + kind: "remote", + transport: "sandbox", + providerKey: "fake-plugin", + leaseId: "lease-super-secret-internal-id", + remoteCwd, + runner: createLocalSandboxRunner(), + }; + const { traceContext, spans } = createRecordingStartupTrace(); + + await runExecutor( + { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd }, + { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, + ); + + const rootSpan = spans.find((span) => span.name === "sandbox.startup" && span.parent === null); + expect(rootSpan).toBeTruthy(); + // The three timing numbers are present, finite, and non-negative. + for (const key of [A.rootWallMs, A.rootWorkMs, A.rootDiffMs]) { + expect(typeof rootSpan!.attributes[key], `attribute ${key}`).toBe("number"); + expect(Number.isFinite(rootSpan!.attributes[key] as number)).toBe(true); + } + expect(rootSpan!.attributes[A.rootWorkMs] as number).toBeGreaterThanOrEqual(0); + // A cold start (no warm handle) and the clamped provider family. + expect(rootSpan!.attributes[A.coldStart]).toBe(true); + expect(rootSpan!.attributes[A.provider]).toBe("plugin"); + // The lease id rides only as a non-reversible hash, never the raw value. + expect(rootSpan!.attributes[A.leaseId]).toMatch(/^[0-9a-f]{12}$/); + expect(String(rootSpan!.attributes[A.leaseId])).not.toContain("secret"); + // The absent region, image id, and sandbox id set no attribute (fail open). + expect(rootSpan!.attributes).not.toHaveProperty(A.region); + expect(rootSpan!.attributes).not.toHaveProperty(A.imageId); + expect(rootSpan!.attributes).not.toHaveProperty(A.sandboxId); + }); + + it("excludes the nested skills.reconcile wall time from the root work sum (no double count)", async () => { + const root = await makeTempRoot(); + const stateDir = path.join(root, "state"); + const localCwd = path.join(root, "worktree"); + const codexHome = path.join(root, "codex-home"); + await fs.mkdir(localCwd, { recursive: true }); + await fs.mkdir(codexHome, { recursive: true }); + const executionTarget = await remoteSandboxTarget(root); + const { traceContext, spans } = createRecordingStartupTrace(); + + // A codex bring-up runs the codex-home.seed step, which nests skills.reconcile. + const { events } = await runExecutor( + { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, + ); + + const stepEvents = events.filter((event) => event.eventType === "run.startup.step"); + // The nested skills.reconcile step still emits its own boundary event. + const reconcile = stepEvents.find((event) => event.payload?.step === "skills.reconcile"); + expect(reconcile, "skills.reconcile must still emit its own step event").toBeTruthy(); + + // The root work sum is the sum of the top-level step walls only. The nested + // skills.reconcile wall sits inside the codex-home.seed wall, so it must not + // ride the sum a second time. The sum of every step wall except + // skills.reconcile equals the recorded root work sum exactly; each step + // reports the same duration to the event and to the root accumulator. + const sumExceptReconcile = stepEvents + .filter((event) => event.payload?.step !== "skills.reconcile") + .reduce((total, event) => total + (event.payload?.durationMs as number), 0); + + const rootSpan = spans.find((span) => span.name === "sandbox.startup" && span.parent === null); + expect(rootSpan).toBeTruthy(); + expect(rootSpan!.attributes[A.rootWorkMs]).toBe(sumExceptReconcile); + }); + it("parents both concurrent bridge spans to the root (neither orphans)", async () => { const root = await makeTempRoot(); const stateDir = path.join(root, "state"); @@ -3252,6 +3352,33 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = const processSession = spans.find((span) => span.name === "bridge.process-session"); expect(paperclip?.parent).toBe(rootSpan); expect(processSession?.parent).toBe(rootSpan); + // Both bridge spans carry the same batch tag, so the trace marks them as one + // parallel batch. + expect(paperclip?.attributes[A.batch]).toBe("bridge"); + expect(processSession?.attributes[A.batch]).toBe("bridge"); + expect(paperclip?.attributes[A.batch]).toBe(processSession?.attributes[A.batch]); + }); + + it("records the handshake create-runtime and ensure-session sub-times on the acp.handshake span", async () => { + const root = await makeTempRoot(); + const stateDir = path.join(root, "state"); + const localCwd = path.join(root, "worktree"); + await fs.mkdir(localCwd, { recursive: true }); + const executionTarget = await remoteSandboxTarget(root); + const { traceContext, spans } = createRecordingStartupTrace(); + + await runExecutor( + { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd }, + { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, + ); + + const handshake = spans.find((span) => span.name === "acp.handshake"); + expect(handshake).toBeTruthy(); + // A cold start records both sub-times as finite float ms on the span. + expect(typeof handshake!.attributes[A.handshakeCreateRuntimeWallMs]).toBe("number"); + expect(handshake!.attributes[A.handshakeCreateRuntimeWallMs] as number).toBeGreaterThanOrEqual(0); + expect(typeof handshake!.attributes[A.handshakeEnsureSessionWallMs]).toBe("number"); + expect(handshake!.attributes[A.handshakeEnsureSessionWallMs] as number).toBeGreaterThanOrEqual(0); }); it("keeps every span attribute inside the closed allowlist (no command/path/id keys)", async () => { @@ -3560,7 +3687,7 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () => expect(handshake!.payload?.ensureSessionMs as number).toBeGreaterThanOrEqual(0); }); - it("emits no acp.handshake event when a warm-handle hit skips the handshake", async () => { + it("emits a skipped acp.handshake event when a warm-handle hit skips the handshake", async () => { const root = await makeTempRoot(); const stateDir = path.join(root, "state"); const warmHandles = new Map(); @@ -3586,8 +3713,9 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () => onMeta: async () => {}, onEvent: async () => {}, } as never); - // The second run reuses the warm handle, so the whole handshake block is - // skipped — it must emit NO acp.handshake event (not a zero-duration one). + // The second run reuses the warm handle, so the handshake does no work. It + // must emit exactly one acp.handshake event with outcome = skipped and a + // zero wall time, not a misleading zero-work `ok` event. await execute({ runId: "run-warm-2", agent: { id: "agent-1", companyId: "company-1" }, @@ -3601,10 +3729,12 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () => }, } as never); - const handshakeEmitted = secondEvents.some( + const handshakeEvents = secondEvents.filter( (event) => event.eventType === "run.startup.step" && event.payload?.step === "acp.handshake", ); - expect(handshakeEmitted).toBe(false); + expect(handshakeEvents).toHaveLength(1); + expect(handshakeEvents[0]!.payload?.outcome).toBe("skipped"); + expect(handshakeEvents[0]!.payload?.durationMs).toBe(0); }); it("does not emit startup-step events on a local (non-sandbox) run except workspace.resolve", async () => { diff --git a/packages/adapter-utils/src/acpx-engine/execute.ts b/packages/adapter-utils/src/acpx-engine/execute.ts index 29b584c391..786a43d10b 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.ts @@ -84,9 +84,12 @@ import { DEFAULT_ACP_ENGINE_WARM_HANDLE_IDLE_MS, } from "./constants.js"; import { + emitSkippedStartupStep, measureStartupStep, NOOP_STARTUP_SPAN, NOOP_STARTUP_TRACE_CONTEXT, + setSandboxRootSpanAttributes, + type SandboxRootSpanContext, type StartupSpan, type StartupSpanContext, type StartupStepMeasureOptions, @@ -972,7 +975,15 @@ async function prepareCodexSkillRuntime(input: { const skillsHome = path.join(effectiveCodexHome, "skills"); await fs.mkdir(skillsHome, { recursive: true }); // Step 3 — skills.reconcile: nested inside the codex-home seed (step 2), so it - // emits its own boundary event at this call-site. + // emits its own boundary event and span at this call-site. It must NOT add its + // wall time to the root work sum. The enclosing step 2 wall already covers this + // interval, so a second `onWallMs` call would count the same milliseconds + // twice. Drop `onWallMs` for the nested step; keep every other attribution + // field. + const nestedStepMetrics: StartupStepMeasureOptions = { + ...(input.stepMetrics ?? {}), + onWallMs: undefined, + }; await measureStartupStep({ onEvent: input.onEvent }, now, "skills.reconcile", () => reconcileManagedCodexSkills({ skillsHome, @@ -980,7 +991,7 @@ async function prepareCodexSkillRuntime(input: { selectedSkills, onLog: input.onLog, }), - input.stepMetrics ?? {}, + nestedStepMetrics, ); for (const entry of selectedSkills) { @@ -1355,10 +1366,12 @@ async function buildRuntime(input: { ctx: AdapterExecutionContext; engine: AcpxEngineSettings; deps: AcpxEngineExecutorOptions; - // The injected tracer plus the root-span parent-context token. Merged into - // every startup-step option set, so each boundary span parents to the one - // root span (`sandbox.startup`) that the executor opens. - spanParent: Pick; + // The injected tracer, the root-span parent-context token, and the + // context-builder. Merged into every startup-step option set, so each + // boundary span parents to the one root span (`sandbox.startup`) that the + // executor opens, and each step publishes its own child context for an inner + // exec span to parent to. + spanParent: Pick; }): Promise { const { runId, agent, config, context, authToken } = input.ctx; // Injectable monotonic clock for per-step startup timing. Hoisted above the @@ -1458,8 +1471,14 @@ async function buildRuntime(input: { // would double-count each other if we sampled them here. Keep the shared // counter attribution on the sequential startup phases only; the concurrent // bridge steps still emit duration telemetry (and a span), just not - // misleading per-step round-trip/provider deltas. - const concurrentBridgeStepMetrics: StartupStepMeasureOptions = { ...input.spanParent }; + // misleading per-step round-trip/provider deltas. A shared `batch` tag marks + // the two spans as one parallel batch, and `criticalPath: false` keeps their + // inner exec spans off the critical path (their wall time overlaps). + const concurrentBridgeStepMetrics: StartupStepMeasureOptions = { + ...input.spanParent, + batch: STARTUP_BRIDGE_BATCH, + criticalPath: false, + }; const shapedWorkspaceEnv = shapePaperclipWorkspaceEnvForExecution({ workspaceCwd: effectiveWorkspaceCwd, workspaceWorktreePath, @@ -2873,6 +2892,11 @@ function warmHandleMatches( * low-cardinality constant, never derived from run/user data. */ const STARTUP_ROOT_SPAN_NAME = "sandbox.startup"; +/** The shared batch tag for the two parallel bridge steps. It is a fixed + * low-cardinality literal, so it marks the two spans as one batch without + * carrying run or user data. */ +const STARTUP_BRIDGE_BATCH = "bridge"; + /** * Open the one root span for a sandbox bring-up and return its parent-context * token plus a guarded `end`. The span parents every startup boundary span: @@ -2882,7 +2906,14 @@ const STARTUP_ROOT_SPAN_NAME = "sandbox.startup"; * flow. With no injected trace context, the tracer is a no-op and the span is * a no-op. */ -function openStartupRootSpan(tracing: StartupTraceContext): { +function openStartupRootSpan( + tracing: StartupTraceContext, + nowMs: () => number, + // Return the final root-span numbers and context at end time. The work sum + // and the cold-start flag are known only after the bring-up runs, so the + // caller reads them lazily here. + finalize: () => { workMs: number; context: SandboxRootSpanContext }, +): { parentContext: StartupSpanContext; end: (failed: boolean) => void; } { @@ -2898,6 +2929,7 @@ function openStartupRootSpan(tracing: StartupTraceContext): { } catch { parentContext = undefined; } + const startedAtMs = nowMs(); let ended = false; return { parentContext, @@ -2905,6 +2937,11 @@ function openStartupRootSpan(tracing: StartupTraceContext): { if (ended) return; ended = true; try { + // The root span records its own wall time, the step-work sum, and the + // bounded context. `setSandboxRootSpanAttributes` sets only the closed + // allowlist, so no raw id or image reference rides the span. + const { workMs, context } = finalize(); + setSandboxRootSpanAttributes(span, { wallMs: nowMs() - startedAtMs, workMs }, context); // `2` is `SpanStatusCode.ERROR`. `adapter-utils` stays OTel-free, so it // uses the numeric value that a real injected span reads as the error // status. @@ -2956,8 +2993,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { executionTarget: ctx.executionTarget, legacyRemoteExecution: ctx.executionTransport?.remoteExecution, }); - const targetsRemoteSandbox = - startupExecutionTarget?.kind === "remote" && startupExecutionTarget.transport === "sandbox"; + const sandboxTarget = + startupExecutionTarget?.kind === "remote" && startupExecutionTarget.transport === "sandbox" + ? startupExecutionTarget + : null; + const targetsRemoteSandbox = sandboxTarget !== null; // Open the one root span for this bring-up. It spans `buildRuntime` through // `acp.handshake`, so every startup boundary span parents to it. `spanParent` // carries the injected tracer + the root parent-context token into each @@ -2968,10 +3008,40 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { targetsRemoteSandbox && ctx.startupTraceContext ? ctx.startupTraceContext : NOOP_STARTUP_TRACE_CONTEXT; - const rootSpan = openStartupRootSpan(tracing); - const spanParent: Pick = { + // The sum of the step wall times. The root span records it as `root.work_ms` + // and the difference from its own wall time as `root.diff_ms` (the overlap + // the parallel steps saved). Every step reports its wall time through + // `onWallMs`; a skipped step adds zero. + let stepWallSumMs = 0; + // Whether this bring-up is a cold start (no warm handle). Set once the warm- + // handle lookup runs below; it stays undefined on an early build failure, so + // the root span omits the attribute (fail open). + let coldStart: boolean | undefined; + const rootSpan = openStartupRootSpan(tracing, now, () => ({ + workMs: stepWallSumMs, + context: { + coldStart, + // The provider key and the lease id are the only low-cardinality + // context values this provider-agnostic layer holds. The region, the + // image id, and the sandbox id are not threaded here, so the root span + // omits them (fail open). The lease id rides only as a hash. + provider: sandboxTarget?.providerKey ?? undefined, + leaseId: sandboxTarget?.leaseId ?? undefined, + }, + })); + const spanParent: Pick< + StartupStepMeasureOptions, + "tracer" | "parentContext" | "contextWithSpan" | "onWallMs" + > = { tracer: tracing.tracer, parentContext: rootSpan.parentContext, + // Each step uses this to publish its own child context, so an inner exec + // span parents to the step span, not to the root. + contextWithSpan: (span) => tracing.contextWithSpan(span), + // Accumulate each step wall time into the root work sum. + onWallMs: (wallMs) => { + stepWallSumMs += wallMs; + }, }; let prepared: AcpxPreparedRuntime; try { @@ -3056,6 +3126,9 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { // split reports nothing for it. let createRuntimeMs: number | undefined; let runtime: AcpRuntime; + // A warm handle reuses the running ACP runtime; a miss constructs one. The + // root span records this as `cold_start`. + coldStart = !cached?.runtime; if (cached?.runtime) { runtime = cached.runtime; } else { @@ -3102,6 +3175,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { ...(createRuntimeMs !== undefined ? { createRuntimeMs } : {}), ...(ensureSessionMs !== undefined ? { ensureSessionMs } : {}), }), + // The same two sub-times ride the span as fixed, closed keys. + spanWallTimes: () => ({ + createRuntime: createRuntimeMs, + ensureSession: ensureSessionMs, + }), }); } catch (err) { if (!resumeSessionId || !isResumeFailure(err)) throw err; @@ -3131,8 +3209,21 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { extra: () => ({ ...(retryEnsureSessionMs !== undefined ? { ensureSessionMs: retryEnsureSessionMs } : {}), }), + // The retry reuses the runtime from the first attempt, so it reports + // only its own ensure-session sub-time on the span. + spanWallTimes: () => ({ ensureSession: retryEnsureSessionMs }), }); } + } else { + // Warm-handle hit: a compatible cached handle reuses the running ACP + // agent, so the `acp.handshake` step does no work. Emit a step span and + // event with `outcome = skipped` and a zero wall time, so the trace and + // the run log show the skip as a distinct outcome, never a misleading + // zero-work `ok` step. + await emitSkippedStartupStep(ctx, "acp.handshake", { + tracer: prepared.stepMetrics.tracer, + parentContext: prepared.stepMetrics.parentContext, + }); } // A compatible warm handle reuses the already-running ACP agent and does // not emit another spawn event. Persist its known identity on this run 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 650da20739..f625909eb6 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts @@ -1,7 +1,18 @@ import { describe, expect, it, vi } from "vitest"; import type { AdapterRuntimeEvent } from "../types.js"; import type { StartupSpan, StartupTracer } from "./startup-timing.js"; -import { measureStartupStep, normalizeProviderFamily } from "./startup-timing.js"; +import { + clampSpanLabel, + emitSkippedStartupStep, + getActiveStepContext, + measureStartupStep, + normalizeProviderFamily, + SANDBOX_STARTUP_SPAN_ATTR_PREFIX, + SANDBOX_STARTUP_SPAN_ATTRS, + setSandboxRootSpanAttributes, +} from "./startup-timing.js"; + +const A = SANDBOX_STARTUP_SPAN_ATTRS; /** * A recording span for the mock tracer. It captures the attribute set, the @@ -247,7 +258,10 @@ describe("measureStartupStep", () => { expect(spans).toHaveLength(1); expect(spans[0]!.name).toBe("stage.sync"); - expect(spans[0]!.attributes.step).toBe("stage.sync"); + // The span name carries the step; no redundant `step` attribute rides it. + expect(spans[0]!.attributes).not.toHaveProperty("step"); + // The step wall time rides the closed, type-suffixed attribute key. + expect(spans[0]!.attributes[A.stepWallMs]).toBe(0); expect(spans[0]!.endCount).toBe(1); }); @@ -268,7 +282,7 @@ describe("measureStartupStep", () => { expect(spans[0]!.status?.code).toBe(2); }); - it("sets the same roundTrips / providerExecMs / providerGetMs deltas on the payload and the span", async () => { + it("keeps the roundTrips / providerExecMs / providerGetMs deltas on the payload but off the span", async () => { let t = 0; const now = () => t; let execCount = 5; @@ -293,14 +307,16 @@ describe("measureStartupStep", () => { providerGetMs: () => getMs, }); + // The counter deltas still ride the event payload. 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); + // The per-execution `sandbox.exec` spans now carry the round-trip detail, so + // the step span no longer duplicates it. + expect(spans[0]!.attributes).not.toHaveProperty(A.roundTripsCount); + expect(spans[0]!.attributes).not.toHaveProperty(A.providerExecSumMs); + expect(spans[0]!.attributes).not.toHaveProperty(A.providerGetSumMs); }); it("sets no span attribute (and no payload field) when a reader returns undefined", async () => { @@ -318,8 +334,8 @@ describe("measureStartupStep", () => { providerExecMs: () => undefined as unknown as number, }); - expect(spans[0]!.attributes).not.toHaveProperty("roundTrips"); - expect(spans[0]!.attributes).not.toHaveProperty("providerExecMs"); + expect(spans[0]!.attributes).not.toHaveProperty(A.roundTripsCount); + expect(spans[0]!.attributes).not.toHaveProperty(A.providerExecSumMs); 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"); @@ -334,14 +350,14 @@ describe("measureStartupStep", () => { tracer: custom.tracer, provider: "acme-cloud-runner", }); - expect(custom.spans[0]!.attributes.provider).toBe("plugin"); + expect(custom.spans[0]!.attributes[A.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"); + expect(builtIn.spans[0]!.attributes[A.provider]).toBe("daytona"); }); it("normalizeProviderFamily maps every non-built-in key to plugin", () => { @@ -369,16 +385,21 @@ describe("measureStartupStep", () => { }); expect(Object.keys(spans[0]!.attributes).sort()).toEqual( - ["provider", "providerExecMs", "providerGetMs", "roundTrips", "step"], + [A.provider, A.stepWallMs, A.outcome].sort(), ); // 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`. + // Every key uses the closed prefix, so no free-form command / path / id key + // can ride the span. 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/); + expect(key.startsWith(SANDBOX_STARTUP_SPAN_ATTR_PREFIX)).toBe(true); + } + // No forbidden segment (command / arg / env / output / path / raw id) rides + // the span key set, even after the prefix. + for (const key of Object.keys(spans[0]!.attributes)) { + const suffix = key.slice(SANDBOX_STARTUP_SPAN_ATTR_PREFIX.length); + expect(suffix).not.toMatch(/command|args|env|stdout|stderr|path|url|repo|ref|branch|error|message/); } }); @@ -397,4 +418,230 @@ describe("measureStartupStep", () => { expect(result).toBe("ok"); expect(events[0]!.payload).toMatchObject({ step: "stage.sync" }); }); + + it("sets a batch tag on the span from the batch option", async () => { + const { tracer, spans } = makeMockTracer(); + await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "bridge.paperclip", async () => "ok", { + tracer, + batch: "bridge", + }); + expect(spans[0]!.attributes[A.batch]).toBe("bridge"); + }); + + it("maps handshake sub-times to fixed span keys and skips a non-finite one", async () => { + const { tracer, spans } = makeMockTracer(); + await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "acp.handshake", async () => "ok", { + tracer, + spanWallTimes: () => ({ createRuntime: 12, ensureSession: 6988 }), + }); + expect(spans[0]!.attributes[A.handshakeCreateRuntimeWallMs]).toBe(12); + expect(spans[0]!.attributes[A.handshakeEnsureSessionWallMs]).toBe(6988); + + // A retry reports only its own ensure-session sub-time; the absent create- + // runtime value sets no attribute. + const retry = makeMockTracer(); + await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "acp.handshake", async () => "ok", { + tracer: retry.tracer, + spanWallTimes: () => ({ ensureSession: 40 }), + }); + expect(retry.spans[0]!.attributes[A.handshakeEnsureSessionWallMs]).toBe(40); + expect(retry.spans[0]!.attributes).not.toHaveProperty(A.handshakeCreateRuntimeWallMs); + }); + + it("sets outcome = ok on a settled step and outcome = failed on a throwing step", async () => { + const okEvents: AdapterRuntimeEvent[] = []; + const ok = makeMockTracer(); + await measureStartupStep({ onEvent: vi.fn(async (e: AdapterRuntimeEvent) => { okEvents.push(e); }) }, + () => 0, "stage.sync", async () => "ok", { tracer: ok.tracer }); + expect(ok.spans[0]!.attributes[A.outcome]).toBe("ok"); + expect((okEvents[0]!.payload as Record).outcome).toBe("ok"); + + const failEvents: AdapterRuntimeEvent[] = []; + const fail = makeMockTracer(); + await expect( + measureStartupStep({ onEvent: vi.fn(async (e: AdapterRuntimeEvent) => { failEvents.push(e); }) }, + () => 0, "acp.handshake", async () => { throw new Error("boom"); }, { tracer: fail.tracer }), + ).rejects.toThrow("boom"); + expect(fail.spans[0]!.attributes[A.outcome]).toBe("failed"); + expect((failEvents[0]!.payload as Record).outcome).toBe("failed"); + }); + + it("sets each step-span attribute key with the closed prefix and a type suffix", async () => { + const { tracer, spans } = makeMockTracer(); + await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "stage.sync", async () => "ok", { + tracer, + provider: "daytona", + roundTrips: () => 3, + providerExecMs: () => 600, + providerGetMs: () => 15, + }); + + const keys = Object.keys(spans[0]!.attributes); + expect(keys.length).toBeGreaterThan(0); + for (const key of keys) { + expect(key.startsWith(SANDBOX_STARTUP_SPAN_ATTR_PREFIX)).toBe(true); + } + // The step wall time and the counters use their type suffixes. + expect(keys).toContain(A.stepWallMs); + expect(A.stepWallMs.endsWith(".wall_ms")).toBe(true); + expect(A.roundTripsCount.endsWith(".count")).toBe(true); + expect(A.providerExecSumMs.endsWith(".sum_ms")).toBe(true); + expect(A.providerGetSumMs.endsWith(".sum_ms")).toBe(true); + }); +}); + +describe("setSandboxRootSpanAttributes", () => { + it("records wall / work / diff and bounds the context, hashing ids and image", () => { + const span = new MockSpan("sandbox.startup", undefined); + setSandboxRootSpanAttributes(span, { wallMs: 800, workMs: 1000 }, { + coldStart: true, + provider: "acme-custom-runner", + region: "us-east-1", + imageId: "registry.internal/team/secret-codename:sha-1234", + sandboxId: "sbx-secret-internal-id", + leaseId: "lease-secret-internal-id", + }); + + expect(span.attributes[A.rootWallMs]).toBe(800); + expect(span.attributes[A.rootWorkMs]).toBe(1000); + expect(span.attributes[A.rootDiffMs]).toBe(200); + expect(span.attributes[A.coldStart]).toBe(true); + // Provider clamps to the bounded family; region stays a known value. + expect(span.attributes[A.provider]).toBe("plugin"); + expect(span.attributes[A.region]).toBe("us-east-1"); + // The image id and both ids ride only as non-reversible hashes. + for (const key of [A.imageId, A.sandboxId, A.leaseId]) { + expect(String(span.attributes[key])).toMatch(/^[0-9a-f]{12}$/); + } + for (const value of Object.values(span.attributes).map(String)) { + expect(value).not.toContain("secret"); + expect(value).not.toContain("codename"); + expect(value).not.toContain("registry.internal"); + } + }); + + it("maps an unknown region to `unknown` and omits every absent context value", () => { + const span = new MockSpan("sandbox.startup", undefined); + setSandboxRootSpanAttributes(span, { wallMs: 5, workMs: 5 }, { region: "moon-base-1" }); + expect(span.attributes[A.region]).toBe("unknown"); + expect(span.attributes).not.toHaveProperty(A.coldStart); + expect(span.attributes).not.toHaveProperty(A.provider); + expect(span.attributes).not.toHaveProperty(A.imageId); + expect(span.attributes).not.toHaveProperty(A.sandboxId); + expect(span.attributes).not.toHaveProperty(A.leaseId); + }); +}); + +describe("emitSkippedStartupStep", () => { + it("emits a span and event with outcome = skipped and a zero wall time", async () => { + const { tracer, spans } = makeMockTracer(); + const events: AdapterRuntimeEvent[] = []; + const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { + events.push(event); + }); + + await emitSkippedStartupStep({ onEvent }, "acp.handshake", { tracer }); + + expect(spans).toHaveLength(1); + expect(spans[0]!.name).toBe("acp.handshake"); + expect(spans[0]!.attributes[A.stepWallMs]).toBe(0); + expect(spans[0]!.attributes[A.outcome]).toBe("skipped"); + expect(spans[0]!.endCount).toBe(1); + + expect(events).toHaveLength(1); + expect(events[0]!.payload).toMatchObject({ + step: "acp.handshake", + durationMs: 0, + outcome: "skipped", + }); + }); + + it("emits the event with no injected tracer and does not throw", async () => { + const events: AdapterRuntimeEvent[] = []; + await emitSkippedStartupStep( + { onEvent: vi.fn(async (e: AdapterRuntimeEvent) => { events.push(e); }) }, + "acp.handshake", + ); + expect(events[0]!.payload).toMatchObject({ step: "acp.handshake", outcome: "skipped" }); + }); +}); + +describe("getActiveStepContext", () => { + it("returns null when no measured step runs", () => { + expect(getActiveStepContext()).toBeNull(); + }); + + it("exposes the active step context to inner code while fn runs, then clears it", async () => { + const { tracer, spans } = makeMockTracer(); + let seen: ReturnType = null; + + await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "stage.sync", async () => { + // Inner code reads the active step context through the getter. + seen = getActiveStepContext(); + return "ok"; + }, { + tracer, + // The server builds a child-context token whose active span is the step + // span. Model it as `{ span }`, the same shape the recording tracer reads. + contextWithSpan: (span) => ({ span }), + }); + + expect(seen).not.toBeNull(); + // The published span is the one open step span. + expect(seen!.span).toBe(spans[0]); + // The parent token points at the step span, so an inner exec span parents + // to it. + expect(seen!.parentContext).toEqual({ span: spans[0] }); + // A regular step is on the critical path by default. + expect(seen!.criticalPath).toBe(true); + // The context clears once the step body settles. + expect(getActiveStepContext()).toBeNull(); + }); + + it("carries criticalPath = false when the step opts out (parallel steps)", async () => { + let seen: ReturnType = null; + await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "bridge.paperclip", async () => { + seen = getActiveStepContext(); + }, { criticalPath: false }); + expect(seen!.criticalPath).toBe(false); + }); +}); + +describe("clampSpanLabel", () => { + it("returns a known command label unchanged and maps an unknown command to `other`", () => { + expect(clampSpanLabel("command", "sh")).toBe("sh"); + expect(clampSpanLabel("command", "git")).toBe("git"); + // A full command line, a path, or a secret-like argument is not a known + // basename, so it maps to the bounded fallback and never leaks. + expect(clampSpanLabel("command", "bash -lc 'rm -rf /secret/path'")).toBe("other"); + expect(clampSpanLabel("command", "/usr/local/bin/node")).toBe("other"); + expect(clampSpanLabel("command", undefined)).toBe("other"); + }); + + it("returns a known region unchanged and maps an unknown region to `unknown`", () => { + expect(clampSpanLabel("region", "us-east-1")).toBe("us-east-1"); + expect(clampSpanLabel("region", "moon-base-1")).toBe("unknown"); + expect(clampSpanLabel("region", undefined)).toBe("unknown"); + }); + + it("hashes an id or image label to a non-reversible short digest and never returns the raw value", () => { + const raw = "lease-super-secret-internal-codename"; + for (const label of ["image_id", "sandbox_id", "lease_id"]) { + const clamped = clampSpanLabel(label, raw); + expect(clamped).toBeTruthy(); + expect(clamped).not.toBe(raw); + expect(clamped).not.toContain("secret"); + expect(clamped).not.toContain("codename"); + // A stable 12-hex-character digest prefix. + expect(clamped).toMatch(/^[0-9a-f]{12}$/); + } + // A missing id yields no attribute (fail open — never a raw value). + expect(clampSpanLabel("sandbox_id", undefined)).toBeUndefined(); + expect(clampSpanLabel("sandbox_id", "")).toBeUndefined(); + }); + + it("drops an unknown label name so the caller sets no attribute for it", () => { + expect(clampSpanLabel("nonsense", "anything")).toBeUndefined(); + expect(clampSpanLabel("stdout", "secret output")).toBeUndefined(); + }); }); diff --git a/packages/adapter-utils/src/acpx-engine/startup-timing.ts b/packages/adapter-utils/src/acpx-engine/startup-timing.ts index 434e607cd8..ada1877fee 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.ts @@ -1,3 +1,5 @@ +import { AsyncLocalStorage } from "node:async_hooks"; +import { createHash } from "node:crypto"; import type { AdapterExecutionContext, AdapterRuntimeEvent } from "../types.js"; /** @@ -39,6 +41,183 @@ export function normalizeProviderFamily(key: string | undefined): string { return PLUGIN_PROVIDER_FAMILY; } +/** + * The common prefix for every sandbox-startup span attribute. One prefix keeps + * the attribute namespace closed and easy to find in the telemetry backend. + */ +export const SANDBOX_STARTUP_SPAN_ATTR_PREFIX = "paperclip.sandbox.startup."; + +/** + * The closed attribute-name contract for every sandbox-startup span. This is + * the single source of truth for the harness span attributes. Each name uses + * the `paperclip.sandbox.startup.` prefix and a type suffix: + * + * - `*.wall_ms` — one wall-clock time in float milliseconds. + * - `*.sum_ms` — a sum of wall-clock times in float milliseconds. + * - `*.count` — a count. + * + * The producer sets only these keys. It never sets a free-form key, so a + * command, a path, an argument, or an environment value can never ride a span. + */ +export const SANDBOX_STARTUP_SPAN_ATTRS = { + /** The low-cardinality provider family (through `normalizeProviderFamily`). */ + provider: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}provider`, + /** The step or execution outcome: `ok`, `skipped`, or `failed`. */ + outcome: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}outcome`, + /** The wall-clock time of one measured step. */ + stepWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}step.wall_ms`, + /** The number of host-to-sandbox round trips a step made. */ + roundTripsCount: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}round_trips.count`, + /** The sum of provider `executeCommand` wall time a step made. */ + providerExecSumMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}provider_exec.sum_ms`, + /** The sum of provider handle-refetch wall time a step made. */ + providerGetSumMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}provider_get.sum_ms`, + /** The clamped `argv[0]` command label of one execution. */ + execCommand: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.command`, + /** The numeric process exit code of one execution. */ + execExitCode: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.exit_code`, + /** The host-measured wall time of one execution. */ + execWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.wall_ms`, + /** The provider handle-fetch wait before one execution ran. */ + execWaitBeforeMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.wait_before_ms`, + /** The in-sandbox run time of one execution. */ + execSandboxMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.sandbox_ms`, + /** The transport time the host adds around one execution. */ + execNetworkMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.network_ms`, + /** Whether one execution sits on the startup critical path. */ + execCriticalPath: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.critical_path`, + /** The root-span wall time of the whole bring-up. */ + rootWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}root.wall_ms`, + /** The sum of the step wall times of the whole bring-up. */ + rootWorkMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}root.work_ms`, + /** The difference between the work sum and the wall time (overlap). */ + rootDiffMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}root.diff_ms`, + /** Whether this bring-up is a cold start (no warm handle). */ + coldStart: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}cold_start`, + /** The clamped region label (through `clampSpanLabel`). */ + region: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}region`, + /** The hashed image-id label (through `clampSpanLabel`). */ + imageId: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}image_id`, + /** The hashed sandbox-id label (through `clampSpanLabel`). */ + sandboxId: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}sandbox_id`, + /** The hashed lease-id label (through `clampSpanLabel`). */ + leaseId: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}lease_id`, + /** The create-runtime sub-time of the `acp.handshake` step. */ + handshakeCreateRuntimeWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}handshake.create_runtime.wall_ms`, + /** The ensure-session sub-time of the `acp.handshake` step. */ + handshakeEnsureSessionWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}handshake.ensure_session.wall_ms`, + /** A shared low-cardinality tag that marks two steps as one parallel batch. */ + batch: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}batch`, +} as const; + +/** The closed value set for the `outcome` attribute. */ +export const SANDBOX_STARTUP_OUTCOME = { + ok: "ok", + skipped: "skipped", + failed: "failed", +} as const; + +export type SandboxStartupOutcome = + (typeof SANDBOX_STARTUP_OUTCOME)[keyof typeof SANDBOX_STARTUP_OUTCOME]; + +/** + * The known command labels. A raw `argv[0]` outside this set maps to `other`, + * so a full command line, a path, or an argument never rides a span. Keep this + * list closed and small; a new command that is safe to name adds one entry. + */ +const KNOWN_COMMAND_LABELS: ReadonlySet = new Set([ + "sh", + "bash", + "env", + "mkdir", + "rm", + "mv", + "cp", + "ln", + "cat", + "echo", + "printf", + "test", + "chmod", + "true", + "tar", + "git", + "node", + "npm", + "pnpm", + "sudo", + "bwrap", +]); + +/** + * The known region labels. A raw region outside this set maps to `unknown`, so + * a free-form region string never widens the attribute cardinality. Keep this + * list closed; a new supported region adds one entry. + */ +const KNOWN_REGION_LABELS: ReadonlySet = new Set([ + "us-east-1", + "us-east-2", + "us-west-1", + "us-west-2", + "eu-west-1", + "eu-central-1", + "ap-southeast-1", + "ap-southeast-2", + "ap-northeast-1", +]); + +/** The fallback value for a raw command outside the known-command allowlist. */ +const OTHER_COMMAND_LABEL = "other"; +/** The fallback value for a raw region outside the known-region allowlist. */ +const UNKNOWN_REGION_LABEL = "unknown"; + +/** + * Map a raw label value to a non-reversible short hash. An id or an image + * reference can hold an internal codename or a secret-like string, so the span + * carries a hash, never the raw value. The hash is a stable 12-hex-character + * prefix of the SHA-256 digest; it is not reversible and it is low-collision + * for correlation. + */ +function hashLabelValue(value: string): string { + return createHash("sha256").update(value).digest("hex").slice(0, 12); +} + +/** + * Bound a span label value to a closed, low-cardinality set. This is the one + * boundary function for every free-form label. It is a hard-coded per-label + * map, the same pattern as `normalizeProviderFamily`: + * + * - `command` — a known command basename maps to itself; any other value maps + * to `other`, so a full command line, a path, or an argument never leaks. + * - `region` — a known region maps to itself; any other value maps to + * `unknown`. + * - `image_id` / `sandbox_id` / `lease_id` — the raw value maps to a + * non-reversible short hash, because it can hold an internal codename or a + * secret-like string, and the telemetry backend may index it. + * + * An unknown label name returns `undefined`, so the caller drops it. A missing + * value for a hashed label returns `undefined` too (fail open — never a raw + * value, never an empty attribute). + */ +export function clampSpanLabel(name: string, value: string | undefined): string | undefined { + switch (name) { + case "command": + return value !== undefined && KNOWN_COMMAND_LABELS.has(value) + ? value + : OTHER_COMMAND_LABEL; + case "region": + return value !== undefined && KNOWN_REGION_LABELS.has(value) + ? value + : UNKNOWN_REGION_LABEL; + case "image_id": + case "sandbox_id": + case "lease_id": + return value && value.length > 0 ? hashLabelValue(value) : undefined; + default: + return undefined; + } +} + /** * The value of `SpanStatusCode.ERROR` in `@opentelemetry/api`. `adapter-utils` * stays OTel-free, so the timing helper uses the numeric value directly. A real @@ -127,6 +306,43 @@ export const NOOP_STARTUP_TRACE_CONTEXT: StartupTraceContext = { contextWithSpan: () => undefined, }; +/** + * The active step context that `measureStartupStep` publishes while it runs the + * step body `fn`. Inner code (for example the host→sandbox exec seam) reads it + * through `getActiveStepContext()` to parent a child span to the step span. + * + * - `span` — the open step span. A child span may set its status or read it. + * - `parentContext` — a parent-context token whose active span is the step span. + * A child span opened with this token parents to the step span. It is opaque + * to `adapter-utils`; the server builds it through `contextWithSpan`. + * - `criticalPath` — whether the step sits on the startup critical path. Two + * overlapping steps (the parallel bridges) set it `false`; every other step + * is `true`. + */ +export interface ActiveStepContext { + readonly span: StartupSpan; + readonly parentContext: StartupSpanContext; + readonly criticalPath: boolean; +} + +/** + * The one storage for the active step context. `measureStartupStep` runs the + * step body inside it; inner code reads it with `getActiveStepContext()`. It is + * a module-level singleton, so the value propagates across `await` boundaries + * and across package boundaries that share this module. + */ +const activeStepContextStorage = new AsyncLocalStorage(); + +/** + * Return the active step context, or `null` when no measured step is running. + * Inner code parents a child span to the step span through + * `getActiveStepContext()?.parentContext`. A `null` result is a no-op: the + * caller opens no child span or opens an unparented span. + */ +export function getActiveStepContext(): ActiveStepContext | null { + return activeStepContextStorage.getStore() ?? null; +} + /** * 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, @@ -180,8 +396,11 @@ function finiteDelta( * 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). + * tracer. The span carries only the closed attribute allowlist from + * `SANDBOX_STARTUP_SPAN_ATTRS`: the normalized `provider`, the step wall time, + * and the outcome. The step name rides the span name, not an attribute. The + * round-trip and provider-duration detail stays on the payload and on the + * per-execution `sandbox.exec` child spans. * - `parentContext` — an opaque parent-context token from the root span. When * set, the step's span parents to that root. `measureStartupStep` forwards it * to `startSpan` and never inspects it, so parenting stays explicit and does @@ -198,6 +417,42 @@ export interface StartupStepMeasureOptions { tracer?: StartupTracer; parentContext?: StartupSpanContext; provider?: string; + /** + * Build a parent-context token whose active span is a given span. The server + * binds it to `@opentelemetry/api`. `measureStartupStep` uses it once, after + * it opens the step span, to publish the step's child context on the active + * step context. Inner code reads that context to parent an exec span to the + * step span. When absent, the active step context carries no parent token, so + * an inner exec span opens unparented (a no-op when tracing is off). + */ + contextWithSpan?: (span: StartupSpan) => StartupSpanContext; + /** + * Whether the step sits on the startup critical path. It rides the active + * step context, so an inner exec span records it. Two overlapping steps (the + * parallel bridges) pass `false`; every other step defaults to `true`. + */ + criticalPath?: boolean; + /** + * Report the step wall time (float ms) once the step settles. The executor + * accumulates it into the root-span work sum. A throwing reporter never + * changes startup control flow. + */ + onWallMs?: (wallMs: number) => void; + /** + * A shared low-cardinality batch tag. Two steps that run in parallel (the + * bridges) pass the same value, so the trace marks them as one batch. It + * rides the span as the closed `…batch` attribute. Pass only a fixed literal, + * never run or user data. + */ + batch?: string; + /** + * Named wall-time sub-splits (float ms) that ride the step span as fixed, + * closed attribute keys. Only `acp.handshake` uses it today, for the + * create-runtime and ensure-session sub-times. The helper maps each value to + * a hard-coded attribute key, so a free-form key can never widen the closed + * span allowlist. A non-finite value sets no attribute. + */ + spanWallTimes?: () => Partial>; } function buildStepEvent(payload: Record): AdapterRuntimeEvent { @@ -223,11 +478,11 @@ function buildStepEvent(payload: Record): AdapterRuntimeEvent { * 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 + * and ends it in the `finally`. The span carries a closed attribute allowlist + * from `SANDBOX_STARTUP_SPAN_ATTRS`: the normalized `provider`, the step wall + * time, and the outcome (`ok` or `failed`). The step name rides the span name. + * A throwing `fn` sets the span error status before the span ends and the + * outcome is `failed`. The counter deltas stay on the event payload. 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. @@ -245,11 +500,15 @@ export async function measureStartupStep( 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. + // the start: the normalized provider family. The span name already carries + // the step name, so no redundant `step` attribute rides the span. const tracer = options.tracer ?? NOOP_TRACER; - const startAttributes: Record = { step }; + const startAttributes: Record = {}; if (options.provider !== undefined) { - startAttributes.provider = normalizeProviderFamily(options.provider); + startAttributes[SANDBOX_STARTUP_SPAN_ATTRS.provider] = normalizeProviderFamily(options.provider); + } + if (options.batch !== undefined) { + startAttributes[SANDBOX_STARTUP_SPAN_ATTRS.batch] = options.batch; } let span: StartupSpan; try { @@ -259,9 +518,28 @@ export async function measureStartupStep( span = NOOP_SPAN; } + // Publish the active step context while `fn` runs. Inner code (the host→ + // sandbox exec seam) reads it to parent an exec span to this step span. The + // parent token is the step span's own child context; a missing + // `contextWithSpan` (no injected trace context) yields `undefined`, so an + // inner exec span opens unparented — a no-op when tracing is off. The + // `contextWithSpan` call is guarded, so a throwing helper never changes + // startup control flow. + let stepChildContext: StartupSpanContext; + try { + stepChildContext = options.contextWithSpan?.(span); + } catch { + stepChildContext = undefined; + } + const activeStep: ActiveStepContext = { + span, + parentContext: stepChildContext, + criticalPath: options.criticalPath ?? true, + }; + let stepFailed = false; try { - return await fn(); + return await activeStepContextStorage.run(activeStep, fn); } catch (err) { stepFailed = true; throw err; @@ -275,7 +553,13 @@ export async function measureStartupStep( const providerExecMs = finiteDelta(options.providerExecMs, providerExecStart); const providerGetMs = finiteDelta(options.providerGetMs, providerGetStart); - const payload: Record = { step, durationMs }; + // The step outcome. A throwing `fn` is `failed`; a settled `fn` is `ok`. A + // step that a warm cache skips uses `emitSkippedStartupStep` instead. + const outcome: SandboxStartupOutcome = stepFailed + ? SANDBOX_STARTUP_OUTCOME.failed + : SANDBOX_STARTUP_OUTCOME.ok; + + const payload: Record = { step, durationMs, outcome }; if (roundTrips !== undefined) payload.roundTrips = roundTrips; if (providerExecMs !== undefined) payload.providerExecMs = providerExecMs; if (providerGetMs !== undefined) payload.providerGetMs = providerGetMs; @@ -287,14 +571,29 @@ export async function measureStartupStep( try { if (stepFailed) span.setStatus({ code: SPAN_STATUS_CODE_ERROR }); - setFiniteNumberAttr(span, "roundTrips", roundTrips); - setFiniteNumberAttr(span, "providerExecMs", providerExecMs); - setFiniteNumberAttr(span, "providerGetMs", providerGetMs); + // The step span carries only the step wall time and the outcome. The + // per-execution `sandbox.exec` child spans now carry the round-trip and + // provider-duration detail, so the step span no longer duplicates them. + setFiniteNumberAttr(span, SANDBOX_STARTUP_SPAN_ATTRS.stepWallMs, durationMs); + span.setAttribute(SANDBOX_STARTUP_SPAN_ATTRS.outcome, outcome); + if (options.spanWallTimes) { + // Map each named sub-time to a hard-coded, closed attribute key, so a + // caller cannot widen the span allowlist with a free-form key. + const sub = options.spanWallTimes(); + setFiniteNumberAttr(span, SANDBOX_STARTUP_SPAN_ATTRS.handshakeCreateRuntimeWallMs, sub.createRuntime); + setFiniteNumberAttr(span, SANDBOX_STARTUP_SPAN_ATTRS.handshakeEnsureSessionWallMs, sub.ensureSession); + } span.end(); } catch { // Observability must not change startup control flow. } + try { + options.onWallMs?.(durationMs); + } catch { + // Observability must not change startup control flow. + } + try { await ctx.onEvent?.(buildStepEvent(payload)); } catch { @@ -302,3 +601,114 @@ export async function measureStartupStep( } } } + +/** + * The two root-span timing numbers. `wallMs` is the root span's own wall time. + * `workMs` is the sum of the step wall times. The difference (`workMs − wallMs`) + * is the overlap the parallel steps saved. + */ +export interface SandboxRootSpanTimings { + wallMs: number; + workMs: number; +} + +/** + * The low-cardinality root-span context. Each field is optional and omitted + * when absent (fail open — never an invented value). The helper below bounds + * each value: `provider` through `normalizeProviderFamily`, `region` through a + * small allowlist, and each id or image through a non-reversible hash. + */ +export interface SandboxRootSpanContext { + coldStart?: boolean; + provider?: string; + region?: string; + imageId?: string; + sandboxId?: string; + leaseId?: string; +} + +/** + * Assemble every root-span (`sandbox.startup`) attribute in one place. This is + * the single producer-side boundary for the root span: it sets only the closed + * `paperclip.sandbox.startup.` allowlist. It records the wall, work, and diff + * times, and the bounded context. A raw id, an image reference, or a region + * never rides the span un-bounded, and an absent value sets no attribute. + */ +export function setSandboxRootSpanAttributes( + span: StartupSpan, + timings: SandboxRootSpanTimings, + context: SandboxRootSpanContext, +): void { + const A = SANDBOX_STARTUP_SPAN_ATTRS; + setFiniteNumberAttr(span, A.rootWallMs, timings.wallMs); + setFiniteNumberAttr(span, A.rootWorkMs, timings.workMs); + setFiniteNumberAttr(span, A.rootDiffMs, timings.workMs - timings.wallMs); + if (context.coldStart !== undefined) span.setAttribute(A.coldStart, context.coldStart); + if (context.provider !== undefined) { + span.setAttribute(A.provider, normalizeProviderFamily(context.provider)); + } + // A region rides only when a value is present; an unknown region maps to + // `unknown`, never a free-form string. + if (context.region !== undefined) { + const region = clampSpanLabel("region", context.region); + if (region !== undefined) span.setAttribute(A.region, region); + } + // The image id and the ids ride only as non-reversible hashes. + const imageId = clampSpanLabel("image_id", context.imageId); + if (imageId !== undefined) span.setAttribute(A.imageId, imageId); + const sandboxId = clampSpanLabel("sandbox_id", context.sandboxId); + if (sandboxId !== undefined) span.setAttribute(A.sandboxId, sandboxId); + const leaseId = clampSpanLabel("lease_id", context.leaseId); + if (leaseId !== undefined) span.setAttribute(A.leaseId, leaseId); +} + +/** The options a skipped step reuses from a measured step: the tracer, the root + * parent-context token, and the raw provider key. */ +export type SkippedStartupStepOptions = Pick< + StartupStepMeasureOptions, + "tracer" | "parentContext" | "provider" +>; + +/** + * Emit one `run.startup.step` span and event for a step that a warm cache + * skips, with `outcome = skipped` and a zero wall time. A skipped step runs no + * work, so this helper opens and ends the span without a body. It shows the + * skip as a real, distinct outcome, never a misleading zero-work `ok` step. + * + * The span and the event carry the closed allowlist: the step name (the span + * name), the normalized `provider` (when given), `step.wall_ms = 0`, and + * `outcome = skipped`. Every tracer and sink call sits inside an error swallow, + * so a throwing tracer or sink never changes startup control flow. The tracer + * defaults to a no-op, so a caller with no tracer only emits the event. + */ +export async function emitSkippedStartupStep( + ctx: Pick, + step: string, + options: SkippedStartupStepOptions = {}, +): Promise { + const tracer = options.tracer ?? NOOP_TRACER; + const startAttributes: Record = {}; + if (options.provider !== undefined) { + startAttributes[SANDBOX_STARTUP_SPAN_ATTRS.provider] = normalizeProviderFamily(options.provider); + } + let span: StartupSpan; + try { + span = tracer.startSpan(step, { attributes: startAttributes }, options.parentContext); + } catch { + span = NOOP_SPAN; + } + try { + span.setAttribute(SANDBOX_STARTUP_SPAN_ATTRS.stepWallMs, 0); + span.setAttribute(SANDBOX_STARTUP_SPAN_ATTRS.outcome, SANDBOX_STARTUP_OUTCOME.skipped); + span.end(); + } catch { + // Observability must not change startup control flow. + } + try { + await ctx.onEvent?.( + buildStepEvent({ step, durationMs: 0, outcome: SANDBOX_STARTUP_OUTCOME.skipped }), + ); + } catch { + // Observability must not change startup control flow. + } +} diff --git a/packages/adapter-utils/src/server-utils.ts b/packages/adapter-utils/src/server-utils.ts index bb3e11762b..401ae2c27e 100644 --- a/packages/adapter-utils/src/server-utils.ts +++ b/packages/adapter-utils/src/server-utils.ts @@ -23,6 +23,12 @@ export interface RunProcessResult { stderr: string; pid: number | null; startedAt: string | null; + // The stop timestamp and the measured wall time of one execution. Both are + // optional and additive: a producer that does not measure them leaves them + // absent, so the many existing `RunProcessResult` producers stay unchanged. + // The sandbox runner sets them, so the exec span records a true wall time. + finishedAt?: string | null; + durationMs?: number | null; terminalResultCleanup?: TerminalResultCleanupEvidence | null; } diff --git a/packages/shared/src/telemetry/README.md b/packages/shared/src/telemetry/README.md index 20d9d35985..b01540b661 100644 --- a/packages/shared/src/telemetry/README.md +++ b/packages/shared/src/telemetry/README.md @@ -67,10 +67,19 @@ configured. With no endpoint the whole span path is a no-op. Paperclip opens the spans only for a run that targets a remote sandbox. A local run and an SSH run stay out of these spans. -Span attributes use a closed allowlist. A command, an argument, an environment -value, a file path, an identifier, or program output never rides a span. It rides -neither as an attribute nor as an event. Each numeric attribute is finite. -Paperclip omits an attribute when its value is absent. +Every span attribute uses the closed `paperclip.sandbox.startup.` prefix and +rides a fixed allowlist. A command line, an argument, an environment value, a +file path, program output, or a raw identifier never rides a span. It rides +neither as an attribute nor as an event. The producer bounds each free-form +value: + +- A command basename maps to a small known set. Any other value maps to `other`. +- A region maps to a small known set. Any other value maps to `unknown`. +- An image id, a sandbox id, and a lease id ride only as a non-reversible short + hash. + +Each numeric attribute is finite. Paperclip omits an attribute when its value is +absent, never a misleading `0`. ### Spans @@ -84,38 +93,76 @@ Paperclip omits an attribute when its value is absent. | `bridge.paperclip` | Paperclip bridge start step. | `sandbox.startup` | | `bridge.process-session` | Process-session bridge start step. | `sandbox.startup` | | `acp.handshake` | ACP session handshake step. | `sandbox.startup` | -| `provider.execute` | One host-to-sandbox provider exec call. | none | +| `sandbox.exec` | One host-to-sandbox execution. | the active step span | + +A step span name is the step name. The `sandbox.exec` span parents to the step +span that runs the execution, so each execution nests under its step. With no +active trace context the exec span opens unparented. The root span sets the error status when the bring-up fails. Each step span sets -the error status when its step fails. +the error status when its step fails. The `sandbox.exec` span sets the error +status when the exit code is non-zero or the execution throws. -### Startup span attributes +### Outcome values -The bring-up step spans use this closed attribute allowlist. +The `paperclip.sandbox.startup.outcome` attribute uses a closed value set: + +- `ok` — the step or the execution settled with a success result. +- `skipped` — a warm cache skipped the step; the step ran no work. +- `failed` — the step or the execution threw, or the exit code was non-zero. + +### Root span attributes + +The `sandbox.startup` root span uses this closed attribute allowlist. | Attribute | Type | Optional | Meaning | | --- | --- | --- | --- | -| `step` | string | no | The bring-up step name. | -| `provider` | string | yes | The normalized provider family. | -| `roundTrips` | number | yes | Host-to-sandbox round trips for the step. | -| `providerExecMs` | number | yes | Provider-reported exec time for the step, in milliseconds. | -| `providerGetMs` | number | yes | Provider-reported fetch time for the step, in milliseconds. | +| `paperclip.sandbox.startup.root.wall_ms` | number | no | The root-span wall time of the whole bring-up. | +| `paperclip.sandbox.startup.root.work_ms` | number | no | The sum of the step wall times. | +| `paperclip.sandbox.startup.root.diff_ms` | number | no | `work_ms − wall_ms`; the overlap the parallel steps saved. | +| `paperclip.sandbox.startup.provider` | string | yes | The normalized provider family. | +| `paperclip.sandbox.startup.cold_start` | boolean | yes | Whether the bring-up is a cold start. | +| `paperclip.sandbox.startup.region` | string | yes | The clamped region label. | +| `paperclip.sandbox.startup.image_id` | string | yes | The hashed image id. | +| `paperclip.sandbox.startup.sandbox_id` | string | yes | The hashed sandbox id. | +| `paperclip.sandbox.startup.lease_id` | string | yes | The hashed lease id. | -### Provider exec span attributes +### Step span attributes -The `provider.execute` span uses this closed attribute allowlist. Paperclip omits -a duration attribute when the provider does not report the value. +Each bring-up step span uses this closed attribute allowlist. The step name +rides the span name, so no `step` attribute repeats it. | Attribute | Type | Optional | Meaning | | --- | --- | --- | --- | -| `provider` | string | no | The normalized provider family. | -| `exit` | string | no | `ok` when the exit code is 0, else `error`. | -| `provider.exec.duration_ms` | number | yes | Provider-reported exec wall time, in milliseconds. | -| `provider.get.duration_ms` | number | yes | Provider-reported fetch wall time, in milliseconds. | +| `paperclip.sandbox.startup.step.wall_ms` | number | no | The wall time of the step. | +| `paperclip.sandbox.startup.outcome` | string | no | The step outcome (`ok`, `skipped`, or `failed`). | +| `paperclip.sandbox.startup.provider` | string | yes | The normalized provider family. | +| `paperclip.sandbox.startup.batch` | string | yes | A shared tag that marks two parallel steps as one batch. | +| `paperclip.sandbox.startup.handshake.create_runtime.wall_ms` | number | yes | The create-runtime sub-time of the `acp.handshake` step. | +| `paperclip.sandbox.startup.handshake.ensure_session.wall_ms` | number | yes | The ensure-session sub-time of the `acp.handshake` step. | -To add a startup span attribute or a provider span attribute, extend the -allowlist in the code first. Keep the attribute low-cardinality and free of user -content. +The round-trip count and the provider durations no longer ride a step span. The +per-execution `sandbox.exec` child spans carry that detail. + +### `sandbox.exec` span attributes + +The `sandbox.exec` span uses this closed attribute allowlist. Paperclip omits a +numeric attribute when the provider does not report the value. + +| Attribute | Type | Optional | Meaning | +| --- | --- | --- | --- | +| `paperclip.sandbox.startup.provider` | string | no | The normalized provider family. | +| `paperclip.sandbox.startup.exec.command` | string | no | The clamped `argv[0]` command label. | +| `paperclip.sandbox.startup.exec.exit_code` | number | yes | The numeric process exit code. | +| `paperclip.sandbox.startup.exec.wall_ms` | number | no | The host-measured wall time of the execution. | +| `paperclip.sandbox.startup.exec.wait_before_ms` | number | yes | The provider handle-fetch wait before the execution ran. | +| `paperclip.sandbox.startup.exec.sandbox_ms` | number | yes | The in-sandbox run time of the execution. | +| `paperclip.sandbox.startup.exec.network_ms` | number | yes | The transport time the host adds; `wall_ms − wait_before_ms − sandbox_ms`. | +| `paperclip.sandbox.startup.exec.critical_path` | boolean | no | Whether the execution sits on the startup critical path. | +| `paperclip.sandbox.startup.outcome` | string | no | The execution outcome (`ok` or `failed`). | + +To add a span attribute, extend the `SANDBOX_STARTUP_SPAN_ATTRS` allowlist in +the code first. Keep the attribute low-cardinality and free of user content. ## Dimension Values diff --git a/server/src/__tests__/environment-execution-target.test.ts b/server/src/__tests__/environment-execution-target.test.ts index 97be2de23c..a07cb68759 100644 --- a/server/src/__tests__/environment-execution-target.test.ts +++ b/server/src/__tests__/environment-execution-target.test.ts @@ -8,11 +8,56 @@ vi.mock("../services/environment-config.js", () => ({ resolveEnvironmentDriverConfigForRuntime: mockResolveEnvironmentDriverConfigForRuntime, })); +import { + measureStartupStep, + SANDBOX_STARTUP_SPAN_ATTRS, +} from "@paperclipai/adapter-utils/acpx-engine/startup-timing"; import { DEFAULT_SANDBOX_REMOTE_CWD, resolveEnvironmentExecutionTarget, } from "../services/environment-execution-target.js"; +const A = SANDBOX_STARTUP_SPAN_ATTRS; + +// A recording trace context that models the OTel parenting contract: +// `startSpan(name, options, context)` reads the parent from the explicit +// `context` token that `contextWithSpan` built. A test asserts the exact parent +// of each child span without an OTel package. +function createRecordingTrace() { + const spans: Array<{ + name: string; + attributes: Record; + parent: unknown; + ended: boolean; + setAttribute(key: string, value: unknown): void; + end(): void; + }> = []; + const tracer = { + startSpan(name: string, _options?: unknown, context?: unknown) { + const parent = + context && typeof context === "object" && "span" in context + ? (context as { span: unknown }).span + : null; + const span = { + name, + attributes: {} as Record, + parent, + ended: false, + setAttribute(key: string, value: unknown) { + span.attributes[key] = value; + }, + end() { + span.ended = true; + }, + }; + spans.push(span); + return span; + }, + }; + const contextWithSpan = (span: unknown) => ({ span }); + return { tracer, contextWithSpan, spans }; +} + describe("resolveEnvironmentExecutionTarget", () => { beforeEach(() => { mockResolveEnvironmentDriverConfigForRuntime.mockReset(); @@ -424,16 +469,25 @@ describe("resolveEnvironmentExecutionTarget", () => { // A recording tracer that captures each provider-exec span's name, attribute // map, and end. It satisfies the structural tracer the seam calls. function createRecordingExecTracer() { - const spans: Array<{ name: string; attributes: Record; ended: boolean }> = []; + const spans: Array<{ + name: string; + attributes: Record; + status: { code: number; message?: string } | null; + ended: boolean; + }> = []; const tracer = { startSpan(name: string) { const span = { name, attributes: {} as Record, + status: null as { code: number; message?: string } | null, ended: false, setAttribute(key: string, value: unknown) { span.attributes[key] = value; }, + setStatus(status: { code: number; message?: string }) { + span.status = status; + }, end() { span.ended = true; }, @@ -445,25 +499,50 @@ describe("resolveEnvironmentExecutionTarget", () => { return { tracer, spans }; } - // The closed span-attribute allowlist for a provider-exec span (Phase 4). - const ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS = new Set([ - "provider", - "exit", - "provider.exec.duration_ms", - "provider.get.duration_ms", + // The value of `SpanStatusCode.ERROR` in `@opentelemetry/api`. A failed exec + // span must carry this native status, not only the `failed` outcome attribute. + const SPAN_STATUS_CODE_ERROR = 2; + + // The closed span-attribute allowlist for a `sandbox.exec` span. A test + // asserts every recorded key is in this set, so a command, an argument, a + // path, an id, or an error-text key can never ride the span. + const ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS = new Set([ + A.provider, + A.execCommand, + A.execExitCode, + A.execWallMs, + A.execWaitBeforeMs, + A.execSandboxMs, + A.execNetworkMs, + A.execCriticalPath, + A.outcome, ]); async function runnerFor(input: { provider: string; execResult: Record; tracer: unknown; + }) { + return runnerWithExecute({ + provider: input.provider, + tracer: input.tracer, + execute: vi.fn().mockResolvedValue(input.execResult), + }); + } + + // Build the sandbox runner with a custom provider-exec implementation, so a + // test can drive a thrown execution or assert the span order around the await. + async function runnerWithExecute(input: { + provider: string; + tracer: unknown; + execute: (...args: unknown[]) => Promise; }) { mockResolveEnvironmentDriverConfigForRuntime.mockResolvedValue({ driver: "sandbox", config: { provider: input.provider, reuseLease: false, timeoutMs: 30_000 }, }); const environmentRuntime = { - execute: vi.fn().mockResolvedValue(input.execResult), + execute: input.execute, supportsSync: vi.fn().mockReturnValue(false), }; const target = await resolveEnvironmentExecutionTarget({ @@ -501,12 +580,22 @@ describe("resolveEnvironmentExecutionTarget", () => { expect(spans).toHaveLength(1); const span = spans[0]!; - expect(span.name).toBe("provider.execute"); + expect(span.name).toBe("sandbox.exec"); expect(span.ended).toBe(true); - expect(span.attributes["provider.exec.duration_ms"]).toBe(600); - expect(span.attributes["provider.get.duration_ms"]).toBe(15); - expect(span.attributes.provider).toBe("daytona"); - expect(span.attributes.exit).toBe("ok"); + // `sandbox_ms` = provider in-sandbox run; `wait_before_ms` = handle-fetch. + expect(span.attributes[A.execSandboxMs]).toBe(600); + expect(span.attributes[A.execWaitBeforeMs]).toBe(15); + expect(span.attributes[A.provider]).toBe("daytona"); + // `echo` is a known command basename, so it rides as a clamped label. + expect(span.attributes[A.execCommand]).toBe("echo"); + expect(span.attributes[A.execExitCode]).toBe(0); + expect(span.attributes[A.outcome]).toBe("ok"); + // A successful exec leaves the native span status unset (default OTel status). + expect(span.status).toBeNull(); + expect(span.attributes[A.execCriticalPath]).toBe(true); + // The wall time is a real, finite, non-negative number. + expect(typeof span.attributes[A.execWallMs]).toBe("number"); + expect(span.attributes[A.execWallMs] as number).toBeGreaterThanOrEqual(0); }); it("omits each duration attribute when a provider returns no timing (does not throw, keeps provider)", async () => { @@ -521,10 +610,12 @@ describe("resolveEnvironmentExecutionTarget", () => { expect(spans).toHaveLength(1); const span = spans[0]!; - expect("provider.exec.duration_ms" in span.attributes).toBe(false); - expect("provider.get.duration_ms" in span.attributes).toBe(false); + expect(A.execSandboxMs in span.attributes).toBe(false); + expect(A.execWaitBeforeMs in span.attributes).toBe(false); + // With no provider durations, the derived network time is also omitted. + expect(A.execNetworkMs in span.attributes).toBe(false); // The provider attribute is always present so a trace shows which provider ran. - expect(span.attributes.provider).toBe("kubernetes"); + expect(span.attributes[A.provider]).toBe("kubernetes"); }); it("never emits a `0` duration attribute for a Daytona timeout that omits durationMs", async () => { @@ -546,12 +637,18 @@ describe("resolveEnvironmentExecutionTarget", () => { await runner.execute({ command: "sleep", args: ["999"] }); const span = spans[0]!; - expect("provider.exec.duration_ms" in span.attributes).toBe(false); - expect(span.attributes["provider.get.duration_ms"]).toBe(20); - expect(span.attributes.exit).toBe("error"); + expect(A.execSandboxMs in span.attributes).toBe(false); + expect(span.attributes[A.execWaitBeforeMs]).toBe(20); + // A non-zero exit yields `failed`; the exit code rides as a number. + expect(span.attributes[A.outcome]).toBe("failed"); + // A failed exec also sets the native span status to ERROR. + expect(span.status).toEqual({ code: SPAN_STATUS_CODE_ERROR }); + expect(span.attributes[A.execExitCode]).toBe(124); + // `sleep` is not in the known-command allowlist, so it clamps to `other`. + expect(span.attributes[A.execCommand]).toBe("other"); }); - it("never sets a command, arg, or non-allowlisted key as an indexed span attribute", async () => { + it("never sets a command, arg, env, cwd, or stream text as a span attribute, even with secret-like input", async () => { const { tracer, spans } = createRecordingExecTracer(); const runner = await runnerFor({ provider: "daytona", @@ -559,22 +656,48 @@ describe("resolveEnvironmentExecutionTarget", () => { exitCode: 0, signal: null, timedOut: false, - stdout: "", - stderr: "", + // Secret-like standard-stream text must never ride the span. + stdout: "AKIAIOSFODNN7EXAMPLE token=s3cr3t-stdout", + stderr: "error at /home/agent/.ssh/id_rsa: s3cr3t-stderr", metadata: { durationMs: 5, getDurationMs: 1 }, }, tracer, }); - await runner.execute({ command: "bash -lc 'rm -rf /secret/path'", args: ["--token", "s3cr3t"] }); + await runner.execute({ + // A full command line, a secret-like argument, a secret-like env value, a + // stdin blob, and a path-like cwd — none may ride the span. + command: "bash -lc 'rm -rf /secret/path'", + args: ["--token", "s3cr3t-arg", "--password", "hunter2"], + env: { AWS_SECRET_ACCESS_KEY: "s3cr3t-env", HOME: "/home/agent" }, + cwd: "/home/agent/secret-workspace/.git", + stdin: "s3cr3t-stdin-blob", + }); const span = spans[0]!; for (const key of Object.keys(span.attributes)) { expect(ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS.has(key), `non-allowlisted key "${key}"`).toBe(true); } + // The command clamps to the bounded `other` fallback (not a known basename). + expect(span.attributes[A.execCommand]).toBe("other"); + // No forbidden substring rides any attribute value. const values = Object.values(span.attributes).map(String); - expect(values.some((value) => value.includes("rm -rf"))).toBe(false); - expect(values.some((value) => value.includes("s3cr3t"))).toBe(false); + for (const forbidden of [ + "rm -rf", + "s3cr3t", + "hunter2", + "AKIA", + "id_rsa", + "/secret/path", + "/home/agent", + "secret-workspace", + "stdin", + ]) { + expect( + values.some((value) => value.includes(forbidden)), + `attribute value leaked "${forbidden}"`, + ).toBe(false); + } }); it("normalizes a plugin-backed provider key to `plugin` and keeps a built-in family as-is", async () => { @@ -585,7 +708,7 @@ describe("resolveEnvironmentExecutionTarget", () => { tracer: plugin.tracer, }); await pluginRunner.execute({ command: "echo" }); - expect(plugin.spans[0]!.attributes.provider).toBe("plugin"); + expect(plugin.spans[0]!.attributes[A.provider]).toBe("plugin"); const builtIn = createRecordingExecTracer(); const builtInRunner = await runnerFor({ @@ -594,6 +717,139 @@ describe("resolveEnvironmentExecutionTarget", () => { tracer: builtIn.tracer, }); await builtInRunner.execute({ command: "echo" }); - expect(builtIn.spans[0]!.attributes.provider).toBe("e2b"); + expect(builtIn.spans[0]!.attributes[A.provider]).toBe("e2b"); + }); + + it("parents the exec span to the active step span when the exec runs inside a measured step", async () => { + const { tracer, contextWithSpan, spans } = createRecordingTrace(); + const runner = await runnerFor({ + provider: "daytona", + execResult: { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" }, + tracer, + }); + + // The exec seam reads the active step context through `getActiveStepContext`. + // Wrap the exec in one measured step and assert the exec span parents to the + // step span, not to nothing. + await measureStartupStep({}, () => 0, "stage.sync", () => runner.execute({ command: "echo" }), { + tracer, + contextWithSpan, + }); + + const stepSpan = spans.find((span) => span.name === "stage.sync"); + const execSpan = spans.find((span) => span.name === "sandbox.exec"); + expect(stepSpan).toBeTruthy(); + expect(execSpan).toBeTruthy(); + expect(execSpan!.parent).toBe(stepSpan); + }); + + it("opens an unparented exec span when the exec runs outside any measured step", async () => { + const { tracer, spans } = createRecordingTrace(); + const runner = await runnerFor({ + provider: "daytona", + execResult: { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" }, + tracer, + }); + + // No measured step wraps the exec, so the active step context is null and + // the exec span opens unparented (a no-op when tracing is off). + await runner.execute({ command: "echo" }); + + const execSpan = spans.find((span) => span.name === "sandbox.exec"); + expect(execSpan).toBeTruthy(); + expect(execSpan!.parent).toBeNull(); + }); + + it("opens the exec span before the provider await so the span wraps the execution", async () => { + const { tracer, spans } = createRecordingExecTracer(); + // Assert the span is already open (started, not ended) while the provider + // runs. If the seam opened the span after the await, no open span would + // exist here and the native span duration would be near zero. + const runner = await runnerWithExecute({ + provider: "daytona", + tracer, + execute: vi.fn().mockImplementation(async () => { + const open = spans.find((span) => span.name === "sandbox.exec"); + expect(open, "the exec span must be open during the provider await").toBeTruthy(); + expect(open!.ended).toBe(false); + return { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" }; + }), + }); + + await runner.execute({ command: "echo" }); + + const span = spans.find((s) => s.name === "sandbox.exec"); + expect(span!.ended).toBe(true); + expect(span!.attributes[A.outcome]).toBe("ok"); + }); + + it("records a failed exec span and rethrows when the provider execution throws", async () => { + const { tracer, spans } = createRecordingExecTracer(); + const runner = await runnerWithExecute({ + provider: "daytona", + tracer, + execute: vi.fn().mockRejectedValue(new Error("provider transport failed")), + }); + + // The original error rides through unchanged; observability never swallows it. + await expect(runner.execute({ command: "echo" })).rejects.toThrow("provider transport failed"); + + // A thrown execution still produces one ended span with the `failed` outcome, + // instead of no span at all. + const span = spans.find((s) => s.name === "sandbox.exec"); + expect(span).toBeTruthy(); + expect(span!.ended).toBe(true); + expect(span!.attributes[A.outcome]).toBe("failed"); + // A thrown execution also sets the native span status to ERROR. + expect(span!.status).toEqual({ code: SPAN_STATUS_CODE_ERROR }); + expect(span!.attributes[A.provider]).toBe("daytona"); + // `echo` is a known basename, so the clamped command rides the span. + expect(span!.attributes[A.execCommand]).toBe("echo"); + // No exec result exists, so the exit code never rides the span. + expect(A.execExitCode in span!.attributes).toBe(false); + // The wall time is a real, finite, non-negative number. + expect(typeof span!.attributes[A.execWallMs]).toBe("number"); + expect(span!.attributes[A.execWallMs] as number).toBeGreaterThanOrEqual(0); + // Only allowlisted keys ride the failed span. + for (const key of Object.keys(span!.attributes)) { + expect(ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS.has(key), `non-allowlisted key "${key}"`).toBe(true); + } + }); + + it("keeps the exec span outcome `ok` when the execution succeeds but a log callback rejects", async () => { + const { tracer, spans } = createRecordingExecTracer(); + // The provider execution succeeds and returns stdout, so the seam invokes + // the log callback. The callback rejects, which models a downstream log-sink + // failure. The rejection must reach the caller, but it must never reclassify + // the successful execution as a failed span. + const runner = await runnerWithExecute({ + provider: "daytona", + tracer, + execute: vi.fn().mockResolvedValue({ + exitCode: 0, + signal: null, + timedOut: false, + stdout: "hello", + stderr: "", + }), + }); + + const onLog = vi.fn().mockRejectedValue(new Error("log sink rejected")); + // The rejection rides through unchanged; observability never swallows it. + await expect( + (runner as { execute(input: unknown): Promise }).execute({ command: "echo", onLog }), + ).rejects.toThrow("log sink rejected"); + + // The span ended with the successful outcome from the command result, not + // the failed outcome. A log failure never marks the execution failed. + const span = spans.find((s) => s.name === "sandbox.exec"); + expect(span).toBeTruthy(); + expect(span!.ended).toBe(true); + expect(span!.attributes[A.outcome]).toBe("ok"); + // A log-callback rejection never marks the span as ERROR; the status stays unset. + expect(span!.status).toBeNull(); + expect(span!.attributes[A.execExitCode]).toBe(0); + // The seam reached the log callback exactly once (the stdout delivery). + expect(onLog).toHaveBeenCalledTimes(1); }); }); diff --git a/server/src/instrumentation.ts b/server/src/instrumentation.ts index e96ed82f0d..b8f30c0cb3 100644 --- a/server/src/instrumentation.ts +++ b/server/src/instrumentation.ts @@ -43,6 +43,11 @@ interface StartupTracerHandle { startSpan( name: string, options?: unknown, + // The optional explicit parent-context token. A real OTel + // `startSpan(name, options, context)` parents the new span to the span that + // `context` carries. The no-op tracer ignores it. The exec seam passes the + // active step context here, so an exec span parents to its step span. + context?: unknown, ): { setAttribute(key: string, value: unknown): void; setStatus(status: { code: number; message?: string }): void; diff --git a/server/src/services/environment-execution-target.ts b/server/src/services/environment-execution-target.ts index 2e3016dff5..93611b0954 100644 --- a/server/src/services/environment-execution-target.ts +++ b/server/src/services/environment-execution-target.ts @@ -5,7 +5,13 @@ import { adapterExecutionTargetToRemoteSpec, type AdapterExecutionTarget, } from "@paperclipai/adapter-utils/execution-target"; -import { normalizeProviderFamily } from "@paperclipai/adapter-utils/acpx-engine/startup-timing"; +import { + clampSpanLabel, + getActiveStepContext, + normalizeProviderFamily, + SANDBOX_STARTUP_OUTCOME, + SANDBOX_STARTUP_SPAN_ATTRS, +} from "@paperclipai/adapter-utils/acpx-engine/startup-timing"; import { parseObject } from "../adapters/utils.js"; import { getStartupTracer } from "../instrumentation.js"; import { resolveEnvironmentDriverConfigForRuntime } from "./environment-config.js"; @@ -17,12 +23,25 @@ export const DEFAULT_SANDBOX_REMOTE_CWD = "/tmp"; * span satisfies it; the no-op tracer's span satisfies it too. */ type ExecSpan = { setAttribute(key: string, value: string | number | boolean): void; + setStatus(status: { code: number; message?: string }): void; end(): void; }; +/** + * The value of `SpanStatusCode.ERROR` in `@opentelemetry/api`. The server injects + * a real OTel span, but this module stays OTel-free, so it uses the numeric value + * directly. A failed exec span sets this status, so a trace UI counts and filters + * the failure through the native span status, not only the `outcome` attribute. + */ +const SPAN_STATUS_CODE_ERROR = 2; + /** The minimal tracer surface the provider-exec seam calls. `getStartupTracer` - * returns a real or no-op implementation that satisfies it. */ -type ExecTracer = { startSpan(name: string): ExecSpan }; + * returns a real or no-op implementation that satisfies it. The optional third + * argument is the explicit parent-context token: the seam passes the active + * step context, so the exec span parents to its step span. */ +type ExecTracer = { + startSpan(name: string, options?: unknown, context?: unknown): ExecSpan; +}; /** * Set a numeric span attribute only when the value is a finite number. A value @@ -36,6 +55,96 @@ function setFiniteNumberAttr(span: ExecSpan, key: string, value: unknown): void } } +/** Read a free-form metadata value as a finite number, or `undefined`. The + * provider durations ride the exec result's untyped `metadata`, so a provider + * that omits or mistypes one yields no attribute — never a misleading `0`. */ +function toFiniteNumber(value: unknown): number | undefined { + return typeof value === "number" && Number.isFinite(value) ? value : undefined; +} + +/** + * The closed input for one `sandbox.exec` span. The seam builds it from the + * exec result and the active step context. Every field is already bounded or + * numeric; the raw command clamps inside the helper below. + */ +interface SandboxExecSpanInput { + /** The low-cardinality provider family (already through `normalizeProviderFamily`). */ + provider: string; + /** The raw `argv[0]`. The helper clamps it; the raw value never rides the span. */ + command: string; + /** The numeric process exit code, or `null`. */ + exitCode: number | null; + /** The host-measured wall time of the execution. */ + wallMs: number; + /** The provider handle-fetch wait before the execution ran. */ + waitBeforeMs: number | undefined; + /** The in-sandbox run time of the execution. */ + sandboxMs: number | undefined; + /** Whether the execution sits on the startup critical path. */ + criticalPath: boolean; +} + +/** + * Assemble every `sandbox.exec` span attribute in one place. This is the single + * producer-side boundary for the exec span: it sets only the closed + * `paperclip.sandbox.startup.exec.*` allowlist. The command rides only as a + * clamped label, so a full command line, an argument, a path, an environment + * value, or any standard-stream text can never ride the span. A non-finite + * numeric input yields no attribute (fail open — never `NaN`, never a + * misleading `0`). + */ +function setSandboxExecSpanAttributes(span: ExecSpan, input: SandboxExecSpanInput): void { + const A = SANDBOX_STARTUP_SPAN_ATTRS; + span.setAttribute(A.provider, input.provider); + const command = clampSpanLabel("command", input.command); + if (command !== undefined) span.setAttribute(A.execCommand, command); + if (typeof input.exitCode === "number" && Number.isFinite(input.exitCode)) { + span.setAttribute(A.execExitCode, input.exitCode); + } + setFiniteNumberAttr(span, A.execWallMs, input.wallMs); + setFiniteNumberAttr(span, A.execWaitBeforeMs, input.waitBeforeMs); + setFiniteNumberAttr(span, A.execSandboxMs, input.sandboxMs); + // The transport time the host adds around the provider work: wall minus the + // handle-fetch wait minus the in-sandbox run. Set it only when both parts are + // present, so a provider that reports no durations yields no derived value. + if (input.waitBeforeMs !== undefined && input.sandboxMs !== undefined) { + setFiniteNumberAttr(span, A.execNetworkMs, input.wallMs - input.waitBeforeMs - input.sandboxMs); + } + span.setAttribute(A.execCriticalPath, input.criticalPath); + const failed = input.exitCode !== 0; + span.setAttribute( + A.outcome, + failed ? SANDBOX_STARTUP_OUTCOME.failed : SANDBOX_STARTUP_OUTCOME.ok, + ); + // A non-zero exit code is a failed execution, so set the native span status to + // ERROR too. The success path leaves the status unset, so a successful exec + // keeps the default OTel status. A `null` exit code counts as failed here. + if (failed) span.setStatus({ code: SPAN_STATUS_CODE_ERROR }); +} + +/** + * Record a failed `sandbox.exec` span when the provider execution throws. There + * is no exec result, so only the bounded provider family, the clamped command + * label, the measured wall time, the critical-path flag, and the `failed` + * outcome ride the span. The raw command never rides the span. A thrown + * execution now still produces a span, instead of no span at all. + */ +function setSandboxExecSpanFailure( + span: ExecSpan, + input: { provider: string; command: string; wallMs: number; criticalPath: boolean }, +): void { + const A = SANDBOX_STARTUP_SPAN_ATTRS; + span.setAttribute(A.provider, input.provider); + const command = clampSpanLabel("command", input.command); + if (command !== undefined) span.setAttribute(A.execCommand, command); + setFiniteNumberAttr(span, A.execWallMs, input.wallMs); + span.setAttribute(A.execCriticalPath, input.criticalPath); + span.setAttribute(A.outcome, SANDBOX_STARTUP_OUTCOME.failed); + // A thrown execution is a failed execution, so set the native span status to + // ERROR too, not only the `outcome` attribute. + span.setStatus({ code: SPAN_STATUS_CODE_ERROR }); +} + export async function resolveEnvironmentExecutionTarget(input: { db: Db; companyId: string; @@ -141,49 +250,112 @@ export async function resolveEnvironmentExecutionTarget(input: { providerGetMs: () => providerGetMs, execute: async (commandInput) => { execCount += 1; - const startedAt = new Date().toISOString(); - const result = await input.environmentRuntime!.execute({ - environment: input.environment as Environment, - lease: input.lease!, - command: commandInput.command, - args: commandInput.args, - cwd: commandInput.cwd ?? remoteCwd, - env: commandInput.env, - stdin: commandInput.stdin, - timeoutMs: commandInput.timeoutMs, - }); - accumulateProviderDurations(result.metadata); - // Emit one span for this host→sandbox exec (opt-in; a no-op tracer - // when tracing is off). It carries ONLY closed-allowlist, - // low-cardinality attributes: the normalized provider family, the - // exit status (a two-value enum), and the host-received provider - // durations (per field, only when finite). The full command, args, - // env, stdout, and stderr never ride a span — not as an attribute - // and not as an event. The span name is the fixed operation label. + // Record true start and stop timestamps around the provider await, + // so the exec span and the result carry a real wall time. + const startedAtMs = Date.now(); + const startedAt = new Date(startedAtMs).toISOString(); + // Open one `sandbox.exec` span BEFORE the provider await, so the + // native span duration covers the whole execution and a thrown + // execution still produces a span. The span parents to the active + // step span. `startSpan` sits inside a guard; observability must + // never change execution control flow, and a no-op tracer + // (tracing off) makes the whole block inert. + const activeStep = getActiveStepContext(); + const criticalPath = activeStep?.criticalPath ?? true; + let span: ExecSpan | null = null; try { - const span = tracer.startSpan("provider.execute"); - try { - span.setAttribute("provider", providerFamily); - span.setAttribute("exit", result.exitCode === 0 ? "ok" : "error"); - setFiniteNumberAttr(span, "provider.exec.duration_ms", result.metadata?.durationMs); - setFiniteNumberAttr(span, "provider.get.duration_ms", result.metadata?.getDurationMs); - } finally { - span.end(); - } + span = tracer.startSpan("sandbox.exec", undefined, activeStep?.parentContext); } catch { - // Observability must not change execution control flow. + span = null; + } + try { + // Classify the span outcome from the provider execution ONLY. + // The inner try/catch wraps just the provider await, so a thrown + // provider execution marks the span failed. A later log-callback + // rejection sits outside this block and never flips a successful + // execution to failed. + let result; + try { + result = await input.environmentRuntime!.execute({ + environment: input.environment as Environment, + lease: input.lease!, + command: commandInput.command, + args: commandInput.args, + cwd: commandInput.cwd ?? remoteCwd, + env: commandInput.env, + stdin: commandInput.stdin, + timeoutMs: commandInput.timeoutMs, + }); + } catch (error) { + // The provider execution threw. Mark the span failed with the + // measured wall time, then rethrow the original error unchanged. + if (span) { + try { + setSandboxExecSpanFailure(span, { + provider: providerFamily, + command: commandInput.command, + wallMs: Date.now() - startedAtMs, + criticalPath, + }); + } catch { + // Observability must not change execution control flow. + } + } + throw error; + } + // The provider execution succeeded. The span timing and outcome + // come from the command result, not from the log callbacks below. + const finishedAtMs = Date.now(); + const finishedAt = new Date(finishedAtMs).toISOString(); + const durationMs = finishedAtMs - startedAtMs; + accumulateProviderDurations(result.metadata); + // `setSandboxExecSpanAttributes` sets ONLY the closed + // `paperclip.sandbox.startup.exec.*` allowlist: the normalized + // provider family, the clamped command label, the numeric exit + // code, the wall / wait-before / sandbox / network times, the + // critical-path flag, and the outcome. The full command, args, + // env, stdout, and stderr never ride the span. + if (span) { + try { + setSandboxExecSpanAttributes(span, { + provider: providerFamily, + command: commandInput.command, + exitCode: result.exitCode, + wallMs: durationMs, + waitBeforeMs: toFiniteNumber(result.metadata?.getDurationMs), + sandboxMs: toFiniteNumber(result.metadata?.durationMs), + criticalPath, + }); + } catch { + // Observability must not change execution control flow. + } + } + // Deliver the captured output. A rejected `onLog` still + // propagates to the caller (control flow is unchanged), but the + // span already carries the successful outcome, so a log failure + // never marks the execution failed. + if (result.stdout) await commandInput.onLog?.("stdout", result.stdout); + if (result.stderr) await commandInput.onLog?.("stderr", result.stderr); + return { + exitCode: result.exitCode, + signal: result.signal ?? null, + timedOut: result.timedOut, + stdout: result.stdout, + stderr: result.stderr, + pid: null, + startedAt, + finishedAt, + durationMs, + }; + } finally { + if (span) { + try { + span.end(); + } catch { + // Observability must not change execution control flow. + } + } } - if (result.stdout) await commandInput.onLog?.("stdout", result.stdout); - if (result.stderr) await commandInput.onLog?.("stderr", result.stderr); - return { - exitCode: result.exitCode, - signal: result.signal ?? null, - timedOut: result.timedOut, - stdout: result.stdout, - stderr: result.stderr, - pid: null, - startedAt, - }; }, // Expose the native file-sync capability only when the provider's // worker advertises BOTH sync verbs; otherwise leave syncIn/syncOut