diff --git a/packages/adapter-utils/src/acpx-engine/execute.test.ts b/packages/adapter-utils/src/acpx-engine/execute.test.ts index c222fa0553..b6e3ec409d 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.test.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.test.ts @@ -92,16 +92,7 @@ function createLocalSandboxRunner( }) => void, ) { let counter = 0; - // Synthetic provider-duration accumulators so per-step payload assertions can - // verify the `providerExecMs`/`providerGetMs` threading end-to-end (the real - // sandbox runner sources these from the Daytona plugin's result metadata; this - // double stands in for that with a fixed per-exec cost). - let providerExecMs = 0; - let providerGetMs = 0; return { - execCount: () => counter, - providerExecMs: () => providerExecMs, - providerGetMs: () => providerGetMs, execute: async (input: { command: string; args?: string[]; @@ -113,8 +104,6 @@ function createLocalSandboxRunner( onSpawn?: (meta: { pid: number; startedAt: string }) => Promise; }) => { counter += 1; - providerExecMs += 600; - providerGetMs += 15; onExecute?.(input); const command = input.command === "bash" ? "/bin/bash" : input.command; return await runChildProcess(`acpx-sandbox-run-${counter}`, command, input.args ?? [], { @@ -3605,7 +3594,7 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () => } }); - it("carries roundTrips + provider durations for sequential startup steps and keeps concurrent bridge steps duration-only", async () => { + it("emits only the high-level fields on every startup-step payload, never the detailed timing or counts", async () => { const root = await makeTempRoot(); const stateDir = path.join(root, "state"); const localCwd = path.join(root, "worktree"); @@ -3626,65 +3615,20 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () => ); const steps = stepEvents(events); - const seen = new Map(steps.map((event) => [String(event.payload?.step), event])); + expect(steps.length).toBeGreaterThan(0); - // Every timed boundary still records duration. + // Every timed boundary still records the high-level duration and outcome. + // The detailed per-step round-trip and provider-duration numbers ride the + // OTel spans now, so no payload carries them. for (const event of steps) { - expect(typeof event.payload?.durationMs).toBe("number"); + const payload = event.payload ?? {}; + expect(typeof payload.durationMs).toBe("number"); + expect(payload).not.toHaveProperty("roundTrips"); + expect(payload).not.toHaveProperty("providerExecMs"); + expect(payload).not.toHaveProperty("providerGetMs"); + expect(payload).not.toHaveProperty("createRuntimeMs"); + expect(payload).not.toHaveProperty("ensureSessionMs"); } - // Sequential boundaries retain runner-counter attribution. - for (const step of ["workspace.resolve", "stage.sync", "acp.handshake"]) { - expect(typeof seen.get(step)?.payload?.roundTrips).toBe("number"); - } - // workspace.resolve is host-only → zero host→sandbox execs. - expect(seen.get("workspace.resolve")?.payload?.roundTrips).toBe(0); - // stage.sync ships the workspace over the exec seam → at least one round-trip, - // and the accumulated provider durations scale with it. - const stageSync = seen.get("stage.sync"); - expect(stageSync?.payload?.roundTrips as number).toBeGreaterThan(0); - expect(stageSync?.payload?.providerExecMs).toBe( - (stageSync?.payload?.roundTrips as number) * 600, - ); - expect(stageSync?.payload?.providerGetMs).toBe( - (stageSync?.payload?.roundTrips as number) * 15, - ); - // Concurrent bridge steps are duration-only so they do not double-count - // shared runner counters while their lifecycles overlap. - for (const step of ["bridge.paperclip", "bridge.process-session"]) { - expect(seen.get(step)?.payload?.roundTrips).toBeUndefined(); - expect(seen.get(step)?.payload?.providerExecMs).toBeUndefined(); - expect(seen.get(step)?.payload?.providerGetMs).toBeUndefined(); - } - // The external ACP client crosses no host exec seam. - expect(seen.get("acp.handshake")?.payload?.roundTrips).toBe(0); - }); - - it("splits acp.handshake into createRuntimeMs and ensureSessionMs sub-phases", 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 }); - const executionTarget = { - kind: "remote", - transport: "sandbox", - providerKey: "fake-plugin", - remoteCwd, - runner: createLocalSandboxRunner(), - }; - - const { events } = await runExecutor( - { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd }, - { authToken: "real-run-jwt", executionTarget }, - ); - - const handshake = stepEvents(events).find((event) => event.payload?.step === "acp.handshake"); - expect(handshake).toBeTruthy(); - expect(typeof handshake!.payload?.createRuntimeMs).toBe("number"); - expect(handshake!.payload?.createRuntimeMs as number).toBeGreaterThanOrEqual(0); - expect(typeof handshake!.payload?.ensureSessionMs).toBe("number"); - expect(handshake!.payload?.ensureSessionMs as number).toBeGreaterThanOrEqual(0); }); it("emits a skipped acp.handshake event when a warm-handle hit skips the handshake", async () => { diff --git a/packages/adapter-utils/src/acpx-engine/execute.ts b/packages/adapter-utils/src/acpx-engine/execute.ts index 786a43d10b..71344f5d0d 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.ts @@ -95,7 +95,6 @@ import { type StartupStepMeasureOptions, type StartupTraceContext, } from "./startup-timing.js"; -import type { CommandManagedRuntimeRunner } from "../command-managed-runtime.js"; const defaultModuleDir = path.dirname(fileURLToPath(import.meta.url)); const PAPERCLIP_MANAGED_CODEX_SKILLS_MANIFEST = ".paperclip-managed-skills.json"; @@ -1346,22 +1345,6 @@ async function stageAcpRemoteRuntime(input: { }); } -// Bind a startup-step round-trip/provider-duration reader set to a runner's -// cumulative counters (Open Q1). Only the sandbox runner instruments the exec -// seam, so a runner without `execCount` (SSH, or none) yields an empty option -// set and the affected steps omit the fields entirely. Reader closures are -// passed — not the runner — so `measureStartupStep` stays runner-agnostic. -function buildStartupStepMetrics( - runner: CommandManagedRuntimeRunner | undefined, -): StartupStepMeasureOptions { - if (!runner) return {}; - return { - ...(runner.execCount ? { roundTrips: () => runner.execCount!() } : {}), - ...(runner.providerExecMs ? { providerExecMs: () => runner.providerExecMs!() } : {}), - ...(runner.providerGetMs ? { providerGetMs: () => runner.providerGetMs!() } : {}), - }; -} - async function buildRuntime(input: { ctx: AdapterExecutionContext; engine: AcpxEngineSettings; @@ -1450,28 +1433,13 @@ async function buildRuntime(input: { ? remoteExecutionIdentity.remoteCwd : cwd; const executionTargetIsRemote = remoteExecutionIdentity !== null; - // Round-trip / provider-duration readers for per-step attribution (Open Q1), - // sourced from the sandbox runner's cumulative counters. `measureStartupStep` - // reads each as a `() => number` closure (never the runner itself, Risk R1) - // and emits the per-step delta. Empty when there is no runner (local runs, - // the runner-less ACP→CLI fallback, or an SSH runner that does not - // instrument the seam), so those steps simply omit the fields. // Merge the injected tracer + root parent-context into every step option set, // so each boundary span parents to the root span. With no injected trace // context both fields are no-ops and the span path stays inert. const stepMetrics: StartupStepMeasureOptions = { - ...buildStartupStepMetrics( - executionTarget?.kind === "remote" && executionTarget.transport === "sandbox" - ? executionTarget.runner - : undefined, - ), ...input.spanParent, }; - // The two bridge-start steps intentionally overlap, so their runner counters - // 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. A shared `batch` tag marks + // The two bridge-start steps intentionally overlap. 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 = { @@ -1971,10 +1939,8 @@ async function buildRuntime(input: { // dir/script setup first, then awaits that thunk right before its launch, so // the launch always observes the merged paperclip env. // - // Measurement caveat: both starts share ONE runner counter, so their - // overlapping `providerExecMs`/`roundTrips` deltas are approximate (the same - // caveat as `acp.handshake`). Both `run.startup.step` events still emit — - // `measureStartupStep` records them in a `finally`, even on a start failure. + // Both `run.startup.step` events still emit — `measureStartupStep` records + // them in a `finally`, even on a start failure. const paperclipStart = measureStartupStep(input.ctx, nowMs, "bridge.paperclip", () => startAdapterExecutionTargetPaperclipBridge({ runId, @@ -3153,9 +3119,8 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { try { // Step 7 — acp.handshake: ACP session establishment (session/new or // resume). A throwing handshake still reports its duration before the - // resume-retry path below runs. `roundTrips` is expected to be 0 (the - // ACP client is external, not the host exec seam); the payload also - // carries the createRuntime/ensureSession sub-split (Open Q2). + // resume-retry path below runs. The createRuntime/ensureSession + // sub-split rides the step span as fixed, closed keys (Open Q2). let ensureSessionMs: number | undefined; handle = await measureStartupStep(ctx, now, "acp.handshake", async () => { const ensureSessionStart = now(); @@ -3171,11 +3136,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { return established; }, { ...prepared.stepMetrics, - extra: () => ({ - ...(createRuntimeMs !== undefined ? { createRuntimeMs } : {}), - ...(ensureSessionMs !== undefined ? { ensureSessionMs } : {}), - }), - // The same two sub-times ride the span as fixed, closed keys. + // The two sub-times ride the span as fixed, closed keys. spanWallTimes: () => ({ createRuntime: createRuntimeMs, ensureSession: ensureSessionMs, @@ -3206,9 +3167,6 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { return established; }, { ...prepared.stepMetrics, - 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 }), 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 f625909eb6..91255745d8 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts @@ -82,60 +82,9 @@ describe("measureStartupStep", () => { expect(events[0]!.message).toBe("startup step: stage.sync (150ms)"); }); - it("includes the roundTrips delta in the payload when a round-trip reader is supplied", async () => { + it("emits only the high-level fields (step, durationMs, outcome) on the payload", async () => { let t = 0; const now = () => t; - // Cumulative host→sandbox exec counter; the step performs 3 execs. - let execCount = 5; - const events: AdapterRuntimeEvent[] = []; - const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { - events.push(event); - }); - - await measureStartupStep({ onEvent }, now, "stage.sync", async () => { - t = 90; - execCount += 3; - return "ok"; - }, { roundTrips: () => execCount }); - - expect(events[0]!.payload).toMatchObject({ - step: "stage.sync", - durationMs: 90, - roundTrips: 3, - }); - }); - - it("reports roundTrips: 0 for a step that performs no execs (reader supplied)", async () => { - const now = () => 0; - const events: AdapterRuntimeEvent[] = []; - const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { - events.push(event); - }); - - await measureStartupStep({ onEvent }, now, "workspace.resolve", async () => "ok", { - roundTrips: () => 7, - }); - - expect(events[0]!.payload).toMatchObject({ step: "workspace.resolve", roundTrips: 0 }); - }); - - it("omits roundTrips from the payload when no reader is supplied", async () => { - const now = () => 0; - const events: AdapterRuntimeEvent[] = []; - const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { - events.push(event); - }); - - await measureStartupStep({ onEvent }, now, "workspace.resolve", async () => "ok"); - - expect(events[0]!.payload).not.toHaveProperty("roundTrips"); - }); - - it("accumulates provider exec/get durations and merges extra fields into the payload", async () => { - let t = 0; - const now = () => t; - let execMs = 100; - let getMs = 40; const events: AdapterRuntimeEvent[] = []; const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { events.push(event); @@ -143,23 +92,18 @@ describe("measureStartupStep", () => { await measureStartupStep({ onEvent }, now, "acp.handshake", async () => { t = 7000; - execMs += 600; // one provider executeCommand round-trip - getMs += 15; // one client.get re-fetch return "handle"; - }, { - providerExecMs: () => execMs, - providerGetMs: () => getMs, - extra: () => ({ createRuntimeMs: 12, ensureSessionMs: 6988 }), }); - expect(events[0]!.payload).toMatchObject({ - step: "acp.handshake", - durationMs: 7000, - providerExecMs: 600, - providerGetMs: 15, - createRuntimeMs: 12, - ensureSessionMs: 6988, - }); + // The detailed per-step round-trip and provider-duration numbers ride the + // OTel spans now, so the run-log payload keeps only the high-level fields. + const payload = events[0]!.payload as Record; + expect(Object.keys(payload).sort()).toEqual(["durationMs", "outcome", "step"]); + expect(payload).not.toHaveProperty("roundTrips"); + expect(payload).not.toHaveProperty("providerExecMs"); + expect(payload).not.toHaveProperty("providerGetMs"); + expect(payload).not.toHaveProperty("createRuntimeMs"); + expect(payload).not.toHaveProperty("ensureSessionMs"); }); it("returns the wrapped fn result unchanged", async () => { @@ -282,64 +226,27 @@ describe("measureStartupStep", () => { expect(spans[0]!.status?.code).toBe(2); }); - it("keeps the roundTrips / providerExecMs / providerGetMs deltas on the payload but off the span", async () => { - let t = 0; - const now = () => t; - let execCount = 5; - let execMs = 100; - let getMs = 40; + it("carries only the allowlisted attributes on the step span, never the removed round-trip detail", async () => { const events: AdapterRuntimeEvent[] = []; const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { events.push(event); }); const { tracer, spans } = makeMockTracer(); - await measureStartupStep({ onEvent }, now, "stage.sync", async () => { - t = 90; - execCount += 3; - execMs += 600; - getMs += 15; - return "ok"; - }, { + await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", { tracer, - roundTrips: () => execCount, - providerExecMs: () => execMs, - providerGetMs: () => getMs, + provider: "daytona", }); - // 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 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 () => { - const events: AdapterRuntimeEvent[] = []; - const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => { - events.push(event); - }); - const { tracer, spans } = makeMockTracer(); - - await measureStartupStep({ onEvent }, () => 0, "workspace.resolve", async () => "ok", { - tracer, - // A reader may return undefined when the counter is unavailable. The guard - // must omit the attribute rather than emit NaN or 0. - roundTrips: () => undefined as unknown as number, - providerExecMs: () => undefined as unknown as number, - }); - - expect(spans[0]!.attributes).not.toHaveProperty(A.roundTripsCount); - expect(spans[0]!.attributes).not.toHaveProperty(A.providerExecSumMs); - expect(Object.values(spans[0]!.attributes).some((v) => Number.isNaN(v))).toBe(false); + // The step span carries only the closed allowlist. The per-execution + // `sandbox.exec` spans carry the round-trip and provider-duration detail. + expect(Object.keys(spans[0]!.attributes).sort()).toEqual( + [A.provider, A.stepWallMs, A.outcome].sort(), + ); const payload = events[0]!.payload as Record; expect(payload).not.toHaveProperty("roundTrips"); expect(payload).not.toHaveProperty("providerExecMs"); + expect(payload).not.toHaveProperty("providerGetMs"); }); it("normalizes a plugin-backed provider key to plugin and keeps a built-in family as-is", async () => { @@ -376,20 +283,11 @@ describe("measureStartupStep", () => { await measureStartupStep({ onEvent }, () => 0, "acp.handshake", async () => "ok", { tracer, provider: "daytona", - roundTrips: () => 3, - providerExecMs: () => 600, - providerGetMs: () => 15, - // extra() carries caller-measured numbers into the EVENT payload only. - // It must never widen the span-attribute set. - extra: () => ({ createRuntimeMs: 12, ensureSessionMs: 6988 }), }); expect(Object.keys(spans[0]!.attributes).sort()).toEqual( [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"); // 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)) { @@ -411,9 +309,7 @@ describe("measureStartupStep", () => { // No tracer supplied. The helper must still emit the event and return the // value without throwing. - const result = await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", { - roundTrips: () => 3, - }); + const result = await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok"); expect(result).toBe("ok"); expect(events[0]!.payload).toMatchObject({ step: "stage.sync" }); @@ -471,9 +367,6 @@ describe("measureStartupStep", () => { 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); @@ -481,12 +374,9 @@ describe("measureStartupStep", () => { 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. + // The step wall time uses its type suffix. 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); }); }); diff --git a/packages/adapter-utils/src/acpx-engine/startup-timing.ts b/packages/adapter-utils/src/acpx-engine/startup-timing.ts index 4bd2fbbc7f..1de2ceeb88 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.ts @@ -53,7 +53,6 @@ export const SANDBOX_STARTUP_SPAN_ATTR_PREFIX = "paperclip.sandbox.startup."; * 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 @@ -66,12 +65,6 @@ export const SANDBOX_STARTUP_SPAN_ATTRS = { 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. */ @@ -368,47 +361,20 @@ function setFiniteNumberAttr( } /** - * Compute a counter delta from a reader. Return `undefined` when the reader is - * absent, or when either the start or the end snapshot is not a finite number. - * A `undefined` result yields no payload field and no span attribute. - */ -function finiteDelta( - read: (() => number) | undefined, - start: number | undefined, -): number | undefined { - if (!read) return undefined; - const end = read(); - if (typeof end !== "number" || !Number.isFinite(end)) return undefined; - const base = typeof start === "number" && Number.isFinite(start) ? start : 0; - return end - base; -} - -/** - * Optional per-step attribution attached to a `run.startup.step` event, all - * additive to the free-form jsonb payload (no schema change). Each reader is a - * plain `() => number` closure so the timing helper stays decoupled from the - * runner/provider it reads (Risk R1): `measureStartupStep` snapshots the reader - * before `fn` and again in `finally`, emitting the delta. + * Optional per-step attribution for a `run.startup.step` event and its span. + * The event payload carries only the high-level fields (`step`, `durationMs`, + * `outcome`). The detailed per-step round-trip and provider-duration numbers + * ride the OTel spans (the per-execution `sandbox.exec` child spans and the + * step span), not the payload. These options configure the span path and the + * step context. * - * - `roundTrips` — cumulative host→sandbox `runner.execute` count; the delta is - * how many round-trips the step performed (Open Q1, host boundary). - * - `providerExecMs` / `providerGetMs` — cumulative provider-reported wall-time - * (ms) for the `executeCommand` REST call vs the `client.get` sandbox - * re-fetch; the delta attributes the step's round-trip time to its parts - * (Open Q1, finer provider attribution). - * - `extra` — a reader (called once in `finally`, after `fn` settles) returning - * any additional numeric fields to merge into the payload; used by - * `acp.handshake` to carry its `createRuntimeMs` / `ensureSessionMs` sub-split - * (Open Q2), which are measured by the caller rather than read from a counter. - * The `extra` map feeds the EVENT payload only. Its keys never become span - * attributes, so a free-form key cannot widen the closed span allowlist. * - `tracer` — an injected structural tracer. It defaults to a no-op, so the * span path changes no runtime behavior until the server injects a real * tracer. The span carries only the closed attribute allowlist 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. + * round-trip and provider-duration detail rides 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 @@ -418,10 +384,6 @@ function finiteDelta( * low-cardinality `provider` span attribute. It never sets the raw key. */ export interface StartupStepMeasureOptions { - roundTrips?: () => number; - providerExecMs?: () => number; - providerGetMs?: () => number; - extra?: () => Record; tracer?: StartupTracer; parentContext?: StartupSpanContext; provider?: string; @@ -477,8 +439,8 @@ function buildStepEvent(payload: Record): AdapterRuntimeEvent { /** * Time `fn` with the injected `now` clock and emit exactly one - * `run.startup.step` event carrying `{ step, durationMs }` plus any counters - * supplied via `options`. The event fires in a `finally`, so a throwing step + * `run.startup.step` event carrying only the high-level `{ step, durationMs, + * outcome }`. The event fires in a `finally`, so a throwing step * still reports its duration before the error is re-thrown. `now` is injected * (never `Date.now()` here) so callers/tests stay deterministic, and * `ctx.onEvent` is optional — a missing sink is a no-op that neither throws nor @@ -490,7 +452,8 @@ function buildStepEvent(payload: Record): AdapterRuntimeEvent { * 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 + * outcome is `failed`. The round-trip and provider-duration detail rides the + * spans, not the 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. @@ -503,9 +466,6 @@ export async function measureStartupStep( options: StartupStepMeasureOptions = {}, ): Promise { const start = now(); - const roundTripsStart = options.roundTrips?.(); - const providerExecStart = options.providerExecMs?.(); - const providerGetStart = options.providerGetMs?.(); // Open the span with only the low-cardinality allowlisted attributes known at // the start: the normalized provider family. The span name already carries @@ -554,28 +514,16 @@ export async function measureStartupStep( } finally { const durationMs = now() - start; - // One attribute-build block feeds both the event payload and the span, so - // the two paths never drift. `undefined` deltas produce neither a payload - // field nor a span attribute (fail open — never `NaN`, never `0`). - const roundTrips = finiteDelta(options.roundTrips, roundTripsStart); - const providerExecMs = finiteDelta(options.providerExecMs, providerExecStart); - const providerGetMs = finiteDelta(options.providerGetMs, providerGetStart); - // 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; + // The payload carries only the high-level fields. The detailed per-step + // round-trip and provider-duration numbers ride the OTel spans now, so the + // run-log copy is gone. const payload: Record = { step, durationMs, outcome }; - if (roundTrips !== undefined) payload.roundTrips = roundTrips; - if (providerExecMs !== undefined) payload.providerExecMs = providerExecMs; - if (providerGetMs !== undefined) payload.providerGetMs = providerGetMs; - if (options.extra) { - // `extra` feeds the EVENT payload only. Its keys never become span - // attributes, so it cannot widen the closed span allowlist. - Object.assign(payload, options.extra()); - } try { if (stepFailed) span.setStatus({ code: SPAN_STATUS_CODE_ERROR }); diff --git a/packages/adapter-utils/src/command-managed-runtime.ts b/packages/adapter-utils/src/command-managed-runtime.ts index fc9b0f0cc8..823766ee13 100644 --- a/packages/adapter-utils/src/command-managed-runtime.ts +++ b/packages/adapter-utils/src/command-managed-runtime.ts @@ -25,25 +25,6 @@ export interface CommandManagedRuntimeRunner { * and let the caller choose a chunked upload path when progress is requested. */ supportsSingleStreamStdinProgress?: boolean; - /** - * Cumulative count of host→sandbox `execute` round-trips this runner has - * performed (Open Q1). Present only on runners that instrument the single - * exec seam (the sandbox runner); the per-step delta is emitted as - * `run.startup.step` `payload.roundTrips`. A `() => number` reader, never the - * runner itself, is threaded into `measureStartupStep` so the timing helper - * stays runner-agnostic. - */ - execCount?(): number; - /** - * Cumulative provider-reported wall-time (ms) for the `executeCommand` REST - * call ({@link providerExecMs}) vs the `client.get` sandbox re-fetch that - * precedes it ({@link providerGetMs}), accumulated across every `execute` - * round-trip (Open Q1, finer attribution). Present only when the provider - * surfaces these durations on its result metadata; the per-step deltas are - * emitted as `payload.providerExecMs` / `payload.providerGetMs`. - */ - providerExecMs?(): number; - providerGetMs?(): number; execute(input: { command: string; args?: string[]; @@ -354,8 +335,7 @@ export function createCommandManagedRuntimeClient(input: { // replace untar for directories, direct `writeFile` for single files), then run // the operation's ordered `postUploadCommands` fail-fast. Byte-for-byte // behavior-equivalent to the caller-inlined tar path it will replace. All exec - // rides the shared `execute` seam so `execCount`/`providerExecMs` still - // attribute (Open Q1). + // rides the shared `execute` seam. const fallbackSyncIn = async (operations: SandboxSyncOperation[]): Promise => { const resultOperations: SandboxSyncResult["operations"] = []; const tempDir = await fs.mkdtemp(path.join(os.tmpdir(), "paperclip-syncin-fallback-")); diff --git a/packages/shared/src/telemetry/README.md b/packages/shared/src/telemetry/README.md index b916542ae3..b86c7ea09d 100644 --- a/packages/shared/src/telemetry/README.md +++ b/packages/shared/src/telemetry/README.md @@ -226,6 +226,31 @@ record, so a worker can never forge a parent. The host validates the trace context the worker sends no span, so the whole provider-span path is a no-op. +## Sandbox Startup Run-Log Event + +Paperclip writes one `run.startup.step` event to the run log for each bring-up +step. This event is a run-log record, not a first-party telemetry event. The +generated telemetry contract does not cover it, so this section is its canonical +contract. + +The event payload carries only three fields. + +| Field | Type | Meaning | +| --- | --- | --- | +| `step` | string | The bring-up step name, for example `stage.sync`. | +| `durationMs` | number | The wall time of the step. A skipped step reports `0`. | +| `outcome` | string | The step outcome (`ok`, `skipped`, or `failed`). | + +The event no longer carries the per-step round-trip count or the provider +duration fields. It dropped `roundTrips`, `providerExecMs`, `providerGetMs`, +`createRuntimeMs`, and `ensureSessionMs`. The startup spans in the section above +carry that detail now. The `sandbox.exec` child spans hold the round-trip and +provider durations. The `acp.handshake` step span holds the create-runtime and +ensure-session sub-times. + +To read the detailed timing, use the startup spans. The spans need an OTLP +endpoint. A run with no endpoint keeps only the three run-log fields above. + ## Dimension Values Telemetry dimension values must be primitives. Use only the value types allowed diff --git a/server/src/__tests__/environment-execution-target.test.ts b/server/src/__tests__/environment-execution-target.test.ts index 61eb5fba5b..e59e6022e7 100644 --- a/server/src/__tests__/environment-execution-target.test.ts +++ b/server/src/__tests__/environment-execution-target.test.ts @@ -367,7 +367,7 @@ describe("resolveEnvironmentExecutionTarget", () => { expect(target).not.toHaveProperty("paperclipApiUrl"); }); - it("exposes a sandbox runner that counts round-trips and accumulates provider durations", async () => { + it("exposes a sandbox runner with single-stream stdin upload disabled", async () => { mockResolveEnvironmentDriverConfigForRuntime.mockResolvedValue({ driver: "sandbox", config: { @@ -377,8 +377,6 @@ describe("resolveEnvironmentExecutionTarget", () => { }, }); - // Each exec reports its provider-boundary durations on the free-form result - // metadata (the Daytona plugin does this); the runner accumulates them. const environmentRuntime = { execute: vi.fn().mockResolvedValue({ exitCode: 0, @@ -404,66 +402,18 @@ describe("resolveEnvironmentExecutionTarget", () => { const runner = (target as { runner?: { supportsSingleStreamStdinProgress?: boolean; - execCount(): number; - providerExecMs(): number; - providerGetMs(): number; execute(input: { command: string; args?: string[] }): Promise; } }).runner; expect(runner).toBeTruthy(); - // Single-stream stdin upload is enabled (research A1 / PAP-3159 #2): a - // ≤96 MiB writeFile collapses to one round-trip. + // Provider-backed sandbox RPCs do not surface bounded mid-stream progress + // for a single stdin upload, so the runner leaves the capability disabled. expect(runner!.supportsSingleStreamStdinProgress).toBe(false); - expect(runner!.execCount()).toBe(0); - expect(runner!.providerExecMs()).toBe(0); - expect(runner!.providerGetMs()).toBe(0); + // The exec seam still runs each command; the run-log no longer carries the + // detailed per-step round-trip or provider-duration counts. await runner!.execute({ command: "echo", args: ["a"] }); await runner!.execute({ command: "echo", args: ["b"] }); - - expect(runner!.execCount()).toBe(2); - expect(runner!.providerExecMs()).toBe(1200); - expect(runner!.providerGetMs()).toBe(30); - }); - - it("tolerates a provider result with no timing metadata (counts the round-trip, accumulates nothing)", async () => { - mockResolveEnvironmentDriverConfigForRuntime.mockResolvedValue({ - driver: "sandbox", - config: { provider: "fake-plugin", reuseLease: false, timeoutMs: 30_000 }, - }); - - const environmentRuntime = { - execute: vi.fn().mockResolvedValue({ - exitCode: 0, - signal: null, - timedOut: false, - stdout: "", - stderr: "", - }), - supportsSync: vi.fn().mockReturnValue(false), - }; - - const target = await resolveEnvironmentExecutionTarget({ - db: {} as never, - companyId: "company-1", - adapterType: "codex_local", - environment: { id: "env-1", driver: "sandbox", config: { provider: "fake-plugin" } }, - leaseId: "lease-1", - leaseMetadata: { remoteCwd: "/workspace" }, - lease: { id: "lease-1" } as never, - environmentRuntime: environmentRuntime as never, - }); - - const runner = (target as { runner?: { - execCount(): number; - providerExecMs(): number; - providerGetMs(): number; - execute(input: { command: string }): Promise; - } }).runner; - await runner!.execute({ command: "echo" }); - - expect(runner!.execCount()).toBe(1); - expect(runner!.providerExecMs()).toBe(0); - expect(runner!.providerGetMs()).toBe(0); + expect(environmentRuntime.execute).toHaveBeenCalledTimes(2); }); // A recording tracer that captures each provider-exec span's name, attribute diff --git a/server/src/services/environment-execution-target.ts b/server/src/services/environment-execution-target.ts index 3c3e26aa9d..c18b27564b 100644 --- a/server/src/services/environment-execution-target.ts +++ b/server/src/services/environment-execution-target.ts @@ -214,20 +214,6 @@ export async function resolveEnvironmentExecutionTarget(input: { ? input.leaseMetadata.shellCommand : null; - // Per-lease-runner cumulative counters for startup-step attribution (Open - // Q1). Closed over by the `runner.execute` seam below and read back as - // deltas by `measureStartupStep`. - let execCount = 0; - let providerExecMs = 0; - let providerGetMs = 0; - const accumulateProviderDurations = (metadata: Record | undefined): void => { - if (!metadata) return; - const exec = metadata.durationMs; - const get = metadata.getDurationMs; - if (typeof exec === "number" && Number.isFinite(exec)) providerExecMs += exec; - if (typeof get === "number" && Number.isFinite(get)) providerGetMs += get; - }; - // The low-cardinality public provider family. A plugin-backed / operator- // defined key maps to `plugin`, so a raw unbounded key never rides a span. const providerFamily = normalizeProviderFamily(parsed.config.provider); @@ -255,17 +241,7 @@ export async function resolveEnvironmentExecutionTarget(input: { // here. The client falls back to the chunked upload path when this is // false. supportsSingleStreamStdinProgress: false, - // Round-trip counter + provider-duration accumulators on the single - // host→sandbox exec seam (Open Q1). `measureStartupStep` reads the - // per-step delta of each via the `() => number` closures below. The - // provider durations ride the exec result's free-form `metadata` - // (set by the Daytona plugin), so no protocol/schema change is - // needed and providers that omit them simply accumulate nothing. - execCount: () => execCount, - providerExecMs: () => providerExecMs, - providerGetMs: () => providerGetMs, execute: async (commandInput) => { - execCount += 1; // 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(); @@ -324,7 +300,6 @@ export async function resolveEnvironmentExecutionTarget(input: { 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