From c647b8cc2ea61f5f6a2010b238629f6627a6be45 Mon Sep 17 00:00:00 2001 From: Nicky Leach Date: Tue, 4 Aug 2026 15:32:41 -0700 Subject: [PATCH] feat(acpx-engine): give sandbox.exec spans real parents (#10852) ## Thinking Path > - Paperclip uses spans and traces to show how work moves through agents and tools > - sandbox.exec spans need a real parent so the trace tree matches the work tree > - Wrong parent links make execution history hard to read and hard to debug > - This pull request adds a single task.run root span and re-parents live work to the nearest active span > - The change keeps detached work under the closest live span instead of the HTTP root > - The benefit is a clear trace tree for sandbox.exec work and better execution diagnosis ## Linked Issues or Issue Description **What happened?** sandbox.exec spans attached to the wrong parent or to no live parent in some paths. **Expected behavior** Each sandbox.exec span should attach to the nearest live span. **Steps to reproduce** 1. Run work that creates sandbox.exec spans during startup and callback bridge paths. 2. Inspect the trace tree. 3. Observe an orphaned span or a span with the wrong parent. **Paperclip version or commit** `672e9de9c8b004aebc1f08e24b612ab067735ad1` **Deployment mode** Local dev. **Additional context** The branch adds the task.run root span, parents sandbox.startup to it, and re-parents detached bridge work to the nearest live span. ## What Changed - Added a task.run root span for the run tree. - Re-parented sandbox.startup, agent.turn, and detached bridge work to the nearest live span. - Added end-to-end trace-tree assertions for the full parent chain. - Added negative coverage so sandbox.exec does not parent to the HTTP root. ## Verification - Focused Vitest suite passed: `packages/adapter-utils/src/acpx-engine/execute.test.ts`, `packages/adapter-utils/src/acpx-engine/startup-timing.test.ts`, `packages/adapter-utils/src/execution-target-sandbox.test.ts`, `packages/adapter-utils/src/sandbox-callback-bridge.test.ts`, and `server/src/__tests__/environment-execution-target.test.ts`. - Result: 5 files passed, 204 tests passed. - The submitted branch also reported `adapter-utils` checks, `server` seam checks, and `tsc` exit 0 in the handoff state. ## Risks - This change can alter trace tree shape in tools that read parent spans. - A missed bridge path could still point to the wrong live span. - Low risk for runtime behavior, because the change only changes span parent attribution. ## Model Used OpenAI GPT-5, tool-use capable. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes: #` / `Refs: #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [ ] All Paperclip CI gates are green - [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [ ] I will address all Greptile and reviewer comments before requesting merge --------- Co-authored-by: Paperclip --- .../src/acpx-engine/execute.test.ts | 677 +++++++- .../adapter-utils/src/acpx-engine/execute.ts | 1372 ++++++++++------- .../src/acpx-engine/startup-timing.test.ts | 37 + .../src/acpx-engine/startup-timing.ts | 46 +- .../src/execution-target-sandbox.test.ts | 233 +++ .../adapter-utils/src/execution-target.ts | 83 +- .../src/sandbox-callback-bridge.test.ts | 121 ++ .../src/sandbox-callback-bridge.ts | 22 +- .../environment-execution-target.test.ts | 98 ++ 9 files changed, 2058 insertions(+), 631 deletions(-) diff --git a/packages/adapter-utils/src/acpx-engine/execute.test.ts b/packages/adapter-utils/src/acpx-engine/execute.test.ts index b6e3ec409d..dfd16318ba 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.test.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.test.ts @@ -35,7 +35,11 @@ import { type AcpxEngineExecutorOptions, } from "./execute.js"; import { runChildProcess } from "../server-utils.js"; -import { SANDBOX_STARTUP_SPAN_ATTRS } from "./startup-timing.js"; +import { + getActiveStepContext, + runWithRuntimeParent, + SANDBOX_STARTUP_SPAN_ATTRS, +} from "./startup-timing.js"; const tempRoots: string[] = []; @@ -216,8 +220,15 @@ interface RecordingSpan { name: string; attributes: Record; parent: RecordingSpan | null; + // The raw third `startSpan` argument — the parent-context token — before the + // recorder resolves it to a parent span. A root span receives `undefined` + // here, so a test asserts the trace-root shape from the argument itself. + parentContextArg: unknown; status: { code: number } | null; ended: boolean; + // The count of `end` calls. A guarded `end` closure ends the span at most + // once, so a test asserts this count equals one for the run root span. + endCalls: number; setAttribute(key: string, value: string | number | boolean): void; setStatus(status: { code: number; message?: string }): void; end(): void; @@ -245,8 +256,10 @@ function createRecordingStartupTrace() { name, attributes: { ...(options?.attributes ?? {}) }, parent, + parentContextArg: context, status: null, ended: false, + endCalls: 0, setAttribute(key: string, value: string | number | boolean) { span.attributes[key] = value; }, @@ -255,6 +268,7 @@ function createRecordingStartupTrace() { }, end() { span.ended = true; + span.endCalls += 1; }, }; spans.push(span); @@ -268,6 +282,19 @@ function createRecordingStartupTrace() { return { traceContext, spans }; } +// Mirror the production host-to-sandbox exec seam for one execution. The real +// seam reads the runtime-parent store with `getActiveStepContext()` and opens a +// `sandbox.exec` span whose third `startSpan` argument is the stored +// parent-context token. This test copy issues that same span through the +// injected recorder, so a test asserts which context a startup-body exec parents +// to at the point the run issues it. The recorder pushes the span into `spans`. +function issueSandboxExecFromStore( + tracing: NonNullable, +): void { + const activeStep = getActiveStepContext(); + tracing.tracer.startSpan("sandbox.exec", undefined, activeStep?.parentContext); +} + // 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 @@ -293,6 +320,21 @@ const ALLOWED_STARTUP_SPAN_ATTRIBUTE_KEYS = new Set([ A.batch, ]); +// The closed attribute allowlist for the run root span. It carries only a +// non-reversible run-id hash and its own wall time, so no command, path, id, or +// error text can ride the `task.run` span. +const ALLOWED_RUN_SPAN_ATTRIBUTE_KEYS = new Set([ + "paperclip.task.run.run_id", + "paperclip.task.run.wall_ms", +]); + +// The closed attribute allowlist for the agent turn span. It carries only its +// own wall time, so no command, path, id, prompt, or error text can ride the +// `agent.turn` span. +const ALLOWED_TURN_SPAN_ATTRIBUTE_KEYS = new Set([ + "paperclip.agent.turn.wall_ms", +]); + describe("shared ACPX engine runtime behavior", () => { it("persists ACP agent process identity before prompting and reuses it for the next warm heartbeat", async () => { const root = await makeTempRoot(); @@ -3208,15 +3250,33 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, ); - // Exactly one root span, and it is the bring-up root. + // Exactly one trace root, and it is the run root span. const roots = spans.filter((span) => span.parent === null); expect(roots).toHaveLength(1); - const rootSpan = roots[0]!; - expect(rootSpan.name).toBe("sandbox.startup"); - expect(rootSpan.ended).toBe(true); + const runRootSpan = roots[0]!; + expect(runRootSpan.name).toBe("task.run"); + expect(runRootSpan.ended).toBe(true); + + // The sandbox bring-up span parents to the run root span. + const startupSpan = spans.find((span) => span.name === "sandbox.startup"); + expect(startupSpan).toBeTruthy(); + expect(startupSpan!.parent).toBe(runRootSpan); + expect(startupSpan!.ended).toBe(true); + + // The agent turn span is a sibling of the bring-up span: it parents to the + // run root span, not to the bring-up span. + const turnSpan = spans.find((span) => span.name === "agent.turn"); + expect(turnSpan).toBeTruthy(); + expect(turnSpan!.parent).toBe(runRootSpan); + expect(turnSpan!.ended).toBe(true); // A codex bring-up over the remote sandbox lane crosses all 7 boundaries. - const childNames = spans.filter((span) => span !== rootSpan).map((span) => span.name).sort(); + // Each boundary span parents to the sandbox bring-up span, not to the run + // root or the turn span. + const childNames = spans + .filter((span) => span !== runRootSpan && span !== startupSpan && span !== turnSpan) + .map((span) => span.name) + .sort(); expect(childNames).toEqual( [ "acp.handshake", @@ -3229,14 +3289,340 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = ], ); - // Every child parents to the one root and ends. + // Every boundary span parents to the sandbox bring-up span and ends. for (const span of spans) { - if (span === rootSpan) continue; - expect(span.parent, `span "${span.name}" must parent to the root`).toBe(rootSpan); + if (span === runRootSpan || span === startupSpan || span === turnSpan) continue; + expect(span.parent, `span "${span.name}" must parent to the startup span`).toBe(startupSpan); expect(span.ended, `span "${span.name}" must end`).toBe(true); } }); + it("test_task_run_span_opens_and_ends_once_for_remote", 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(); + + // Run the executor with a fake remote-sandbox tracer. The engine opens one + // `task.run` root span and ends it once at the run return. + await runExecutor( + { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, + ); + + // Exactly one `task.run` span opens for a remote-sandbox run. + const runSpans = spans.filter((span) => span.name === "task.run"); + expect(runSpans).toHaveLength(1); + const runSpan = runSpans[0]!; + // It is the trace root: it opens with no parent-context token. + expect(runSpan.parent).toBeNull(); + expect(runSpan.parentContextArg).toBeUndefined(); + // It ends exactly once. A clean run sets no error status. + expect(runSpan.ended).toBe(true); + expect(runSpan.endCalls).toBe(1); + expect(runSpan.status).toBeNull(); + // The run id rides only as a non-reversible hash; the raw run id never rides + // the span. + expect(runSpan.attributes["paperclip.task.run.run_id"]).toMatch(/^[0-9a-f]{12}$/); + expect(String(runSpan.attributes["paperclip.task.run.run_id"])).not.toContain("run-"); + }); + + it("test_sandbox_startup_parents_to_task_run", 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(); + + // Run the executor startup path with a fake remote-sandbox tracer. The run + // root opens the `task.run` span first, then the startup root opens the + // `sandbox.startup` span as its child. + await runExecutor( + { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, + ); + + const runSpan = spans.find((span) => span.name === "task.run"); + expect(runSpan).toBeTruthy(); + const startupSpan = spans.find((span) => span.name === "sandbox.startup"); + expect(startupSpan).toBeTruthy(); + // The `sandbox.startup` `startSpan` call now receives the `task.run` parent + // context as its third argument. The recorder builds the token as + // `{ span }`, so the token carries the run span and the startup span parents + // to `task.run`. + expect(startupSpan!.parentContextArg).toEqual({ span: runSpan }); + expect(startupSpan!.parent).toBe(runSpan); + }); + + it("test_task_run_span_is_noop_for_local_target", async () => { + const root = await makeTempRoot(); + const stateDir = path.join(root, "state"); + const localCwd = path.join(root, "worktree"); + await fs.mkdir(localCwd, { recursive: true }); + const { traceContext, spans } = createRecordingStartupTrace(); + + // A local run has no sandbox, so the run root span stays a no-op even when a + // trace context is injected. No real `task.run` span opens. + const { result } = await runExecutor( + { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd }, + { authToken: "real-run-jwt", startupTraceContext: traceContext }, + ); + expect(result.exitCode).toBe(0); + expect(spans.some((span) => span.name === "task.run")).toBe(false); + expect(spans).toHaveLength(0); + }); + + it("test_agent_turn_span_parents_to_task_run", 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(); + + // Run the executor turn path with a fake remote-sandbox tracer. The engine + // opens one `agent.turn` span around the turn as a child of `task.run` and + // ends it once at the turn return. + await runExecutor( + { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, + ); + + const runSpan = spans.find((span) => span.name === "task.run"); + expect(runSpan).toBeTruthy(); + // Exactly one `agent.turn` span opens for a remote-sandbox run. + const turnSpans = spans.filter((span) => span.name === "agent.turn"); + expect(turnSpans).toHaveLength(1); + const turnSpan = turnSpans[0]!; + // The `agent.turn` `startSpan` call receives the `task.run` parent context + // as its third argument. The recorder builds the token as `{ span }`, so the + // turn span parents to `task.run`. + expect(turnSpan.parentContextArg).toEqual({ span: runSpan }); + expect(turnSpan.parent).toBe(runSpan); + // It ends exactly once. A clean turn sets no error status. + expect(turnSpan.ended).toBe(true); + expect(turnSpan.endCalls).toBe(1); + expect(turnSpan.status).toBeNull(); + }); + + it("test_agent_turn_span_is_noop_for_local_target", async () => { + const root = await makeTempRoot(); + const stateDir = path.join(root, "state"); + const localCwd = path.join(root, "worktree"); + await fs.mkdir(localCwd, { recursive: true }); + const { traceContext, spans } = createRecordingStartupTrace(); + + // A local run has no sandbox, so the turn span stays a no-op even when a + // trace context is injected. No real `agent.turn` span opens. + const { result } = await runExecutor( + { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd }, + { authToken: "real-run-jwt", startupTraceContext: traceContext }, + ); + expect(result.exitCode).toBe(0); + expect(spans.some((span) => span.name === "agent.turn")).toBe(false); + }); + + it("test_run_parent_getter_tracks_task_run_then_turn", 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(); + + // Sample `getRuntimeParentContext` at three points of the run: at runtime + // construction (startup), inside `startTurn` (turn), and after the executor + // resolves (post-turn). The run publishes the current-run parent token + // through `runtimeOptions.getRuntimeParentContext`, so a fake runtime reads + // it to prove the holder tracks `task.run`, then `agent.turn`, then + // `task.run` again. + let startupToken: unknown; + let turnToken: unknown; + let capturedGetter: (() => unknown) | undefined; + const execute = createAcpxEngineExecutor({ + createRuntime: (options) => { + const opts = options as unknown as { getRuntimeParentContext?: () => unknown }; + // Keep the getter for the post-turn sample after the run resolves. + capturedGetter = opts.getRuntimeParentContext; + // Startup phase: the holder is the `task.run` token here. + startupToken = opts.getRuntimeParentContext?.(); + const runtime = buildRuntime(); + return { + ...runtime, + startTurn: (input: Record) => { + // Turn phase: the holder is the `agent.turn` token here. + turnToken = opts.getRuntimeParentContext?.(); + return (runtime.startTurn as (input: unknown) => unknown)(input); + }, + } as never; + }, + }); + + const result = await execute({ + runId: "run-getter", + agent: { id: "agent-1", companyId: "company-1" }, + runtime: {}, + config: { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + context: {}, + authToken: "real-run-jwt", + executionTarget, + startupTraceContext: traceContext, + onLog: async () => {}, + onMeta: async () => {}, + onEvent: async () => {}, + } as never); + expect(result.exitCode).toBe(0); + + // Post-turn phase: the holder is the `task.run` token again. + const postToken = capturedGetter?.(); + + const taskRunSpan = spans.find((span) => span.name === "task.run"); + expect(taskRunSpan).toBeTruthy(); + const agentTurnSpan = spans.find((span) => span.name === "agent.turn"); + expect(agentTurnSpan).toBeTruthy(); + + // The recorder builds a parent-context token as `{ span }`. So the getter + // returns the `task.run` token during startup, the `agent.turn` token during + // the turn, and the `task.run` token after the turn. + expect(startupToken).toEqual({ span: taskRunSpan }); + expect(turnToken).toEqual({ span: agentTurnSpan }); + expect(postToken).toEqual({ span: taskRunSpan }); + }); + + it("test_root_region_exec_parents_to_sandbox_startup", 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(); + + // Issue one exec from the root region of the bring-up. `getServers()` runs + // once inside the bring-up, after the `sandbox.startup` span opens and + // outside every measured step, so it stands in for a startup-body exec that + // runs at the root region. The run publishes the `sandbox.startup` context to + // the runtime-parent store for the whole bring-up, so the exec reads that + // token here. + const runtimeMcp = { + getServers: () => { + issueSandboxExecFromStore(traceContext); + return []; + }, + }; + + await runExecutor( + { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + { + authToken: "real-run-jwt", + executionTarget, + startupTraceContext: traceContext, + runtimeMcp: runtimeMcp as never, + }, + ); + + const startupSpan = spans.find((span) => span.name === "sandbox.startup"); + expect(startupSpan).toBeTruthy(); + const execSpan = spans.find((span) => span.name === "sandbox.exec"); + expect(execSpan).toBeTruthy(); + // The root-region exec parents to `sandbox.startup`, not to a detached root. + // The third `startSpan` argument is the exact `sandbox.startup` child context + // that `contextWithSpan` built, so the exec span is a child of the bring-up. + expect(execSpan!.parentContextArg).toEqual({ span: startupSpan }); + expect(execSpan!.parent).toBe(startupSpan); + }); + + it("test_in_step_exec_still_parents_to_step_after_root_wrap", 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(); + + // Issue one exec from inside the `stage.sync` step body, under the same root + // wrap. `prepareRemoteManagedHome` runs inside the measured `stage.sync` + // step, so the step overrides the runtime-parent store with its own context + // there. The in-step exec must read the step context, not the root context. + await runExecutor( + { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + { + authToken: "real-run-jwt", + executionTarget, + startupTraceContext: traceContext, + prepareRemoteManagedHome: async (input) => { + issueSandboxExecFromStore(traceContext); + const stagedRuntime = await input.stage([]); + return { stagedRuntime }; + }, + }, + ); + + const stepSpan = spans.find((span) => span.name === "stage.sync"); + expect(stepSpan).toBeTruthy(); + const startupSpan = spans.find((span) => span.name === "sandbox.startup"); + expect(startupSpan).toBeTruthy(); + const execSpan = spans.find((span) => span.name === "sandbox.exec"); + expect(execSpan).toBeTruthy(); + // The in-step exec still parents to its step span. `measureStartupStep` + // overrides the store inside the wrap, so the step context wins over the + // root context for an exec that runs inside the step. + expect(execSpan!.parentContextArg).toEqual({ span: stepSpan }); + expect(execSpan!.parent).toBe(stepSpan); + // The in-step exec does not parent to `sandbox.startup`. + expect(execSpan!.parent).not.toBe(startupSpan); + }); + 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"); @@ -3261,7 +3647,7 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, ); - const rootSpan = spans.find((span) => span.name === "sandbox.startup" && span.parent === null); + const rootSpan = spans.find((span) => span.name === "sandbox.startup"); expect(rootSpan).toBeTruthy(); // The three timing numbers are present, finite, and non-negative. for (const key of [A.rootWallMs, A.rootWorkMs, A.rootDiffMs]) { @@ -3317,7 +3703,7 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = .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); + const rootSpan = spans.find((span) => span.name === "sandbox.startup"); expect(rootSpan).toBeTruthy(); expect(rootSpan!.attributes[A.rootWorkMs]).toBe(sumExceptReconcile); }); @@ -3335,7 +3721,7 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = { authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext }, ); - const rootSpan = spans.find((span) => span.name === "sandbox.startup" && span.parent === null); + const rootSpan = spans.find((span) => span.name === "sandbox.startup"); expect(rootSpan).toBeTruthy(); const paperclip = spans.find((span) => span.name === "bridge.paperclip"); const processSession = spans.find((span) => span.name === "bridge.process-session"); @@ -3385,9 +3771,17 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = expect(spans.length).toBeGreaterThan(0); for (const span of spans) { + // The run root span and the agent turn span each use their own closed + // allowlist; every other span uses the sandbox startup allowlist. + const allowed = + span.name === "task.run" + ? ALLOWED_RUN_SPAN_ATTRIBUTE_KEYS + : span.name === "agent.turn" + ? ALLOWED_TURN_SPAN_ATTRIBUTE_KEYS + : ALLOWED_STARTUP_SPAN_ATTRIBUTE_KEYS; for (const [key, value] of Object.entries(span.attributes)) { expect( - ALLOWED_STARTUP_SPAN_ATTRIBUTE_KEYS.has(key), + allowed.has(key), `span "${span.name}" set a non-allowlisted attribute "${key}"`, ).toBe(true); // No non-finite numeric attribute (no NaN, no Infinity). @@ -3437,7 +3831,7 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = } as never); expect(result.exitCode).toBe(1); - const rootSpan = spans.find((span) => span.name === "sandbox.startup" && span.parent === null); + const rootSpan = spans.find((span) => span.name === "sandbox.startup"); expect(rootSpan).toBeTruthy(); expect(rootSpan!.ended).toBe(true); // `2` is `SpanStatusCode.ERROR`. @@ -3498,6 +3892,261 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = expect(result.exitCode).toBe(0); expect(spans).toHaveLength(0); }); + + it("test_full_trace_tree_parents_correctly", 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(); + + // Drive one remote-sandbox run and issue an exec at four points of the run. + // Each exec issues through the same host-to-sandbox seam that the run uses, + // so the recorder captures the exact parent of each exec span. Each point + // fires exactly once, so the run records exactly four `sandbox.exec` spans. + let rootRegionExecFired = false; + let syncExecFired = false; + let turnExecFired = false; + + // A run-scoped getter holder. The engine publishes the current-run parent + // token through `runtimeOptions.getRuntimeParentContext`. A detached site + // reads it per unit of work and wraps the work in `runWithRuntimeParent`. + let getRuntimeParentContext: (() => unknown) | undefined; + + const execute = createAcpxEngineExecutor({ + prepareRemoteManagedHome: async (input) => { + // Point 2: an exec inside the measured `stage.sync` step body. The step + // overrides the runtime-parent store, so this exec parents to the sync + // step span, not to `sandbox.startup`. + if (!syncExecFired) { + syncExecFired = true; + issueSandboxExecFromStore(traceContext); + } + const stagedRuntime = await input.stage([]); + return { stagedRuntime }; + }, + createRuntime: (options) => { + const opts = options as unknown as { + getRuntimeParentContext?: () => unknown; + }; + getRuntimeParentContext = opts.getRuntimeParentContext; + const runtime = buildRuntime(); + return { + ...runtime, + startTurn: (input: Record) => { + // Point 3: a detached exec during the turn. The detached site reads + // the getter (the `agent.turn` token here) and wraps the work in + // `runWithRuntimeParent`, so the exec parents to `agent.turn`. + if (!turnExecFired) { + turnExecFired = true; + runWithRuntimeParent(opts.getRuntimeParentContext?.(), () => + issueSandboxExecFromStore(traceContext), + ); + } + return (runtime.startTurn as (input: unknown) => unknown)(input); + }, + } as never; + }, + }); + + const runtimeMcp = { + getServers: () => { + // Point 1: a root-region exec. `getServers` runs inside the bring-up, + // after `sandbox.startup` opens and outside every measured step, so the + // store holds the `sandbox.startup` context and this exec parents to it. + if (!rootRegionExecFired) { + rootRegionExecFired = true; + issueSandboxExecFromStore(traceContext); + } + return []; + }, + }; + + const result = await execute({ + runId: "run-e2e-tree", + agent: { id: "agent-1", companyId: "company-1" }, + runtime: {}, + config: { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + context: {}, + authToken: "real-run-jwt", + executionTarget, + runtimeMcp: runtimeMcp as never, + startupTraceContext: traceContext, + onLog: async () => {}, + onMeta: async () => {}, + onEvent: async () => {}, + } as never); + expect(result.exitCode).toBe(0); + + // Point 4: a detached exec after the turn. The getter returns the `task.run` + // token now, so an off-turn detached exec parents to `task.run`. + runWithRuntimeParent(getRuntimeParentContext?.(), () => + issueSandboxExecFromStore(traceContext), + ); + + // The four framing spans of the run. + const runSpan = spans.find((span) => span.name === "task.run"); + expect(runSpan).toBeTruthy(); + const startupSpan = spans.find((span) => span.name === "sandbox.startup"); + expect(startupSpan).toBeTruthy(); + const turnSpan = spans.find((span) => span.name === "agent.turn"); + expect(turnSpan).toBeTruthy(); + const syncStepSpan = spans.find((span) => span.name === "stage.sync"); + expect(syncStepSpan).toBeTruthy(); + + // `task.run` is the trace root. `sandbox.startup` and `agent.turn` are its + // direct children. + expect(runSpan!.parent).toBeNull(); + expect(startupSpan!.parent).toBe(runSpan); + expect(turnSpan!.parent).toBe(runSpan); + + // The run records exactly the four injected exec spans. + const execSpans = spans.filter((span) => span.name === "sandbox.exec"); + expect(execSpans).toHaveLength(4); + + // A root-region exec parents to `sandbox.startup`. + const rootRegionExec = execSpans.find((span) => span.parent === startupSpan); + expect(rootRegionExec, "a root-region exec must parent to sandbox.startup").toBeTruthy(); + + // A `stage.sync` body exec parents to the sync step, not to `sandbox.startup`. + const syncExec = execSpans.find((span) => span.parent === syncStepSpan); + expect(syncExec, "a stage.sync exec must parent to the sync step").toBeTruthy(); + expect(syncExec!.parent).not.toBe(startupSpan); + + // A turn detached exec parents to `agent.turn`. + const turnExec = execSpans.find((span) => span.parent === turnSpan); + expect(turnExec, "a turn detached exec must parent to agent.turn").toBeTruthy(); + + // An off-turn detached exec parents to `task.run`. + const offTurnExec = execSpans.find((span) => span.parent === runSpan); + expect(offTurnExec, "an off-turn detached exec must parent to task.run").toBeTruthy(); + + // The four execs are distinct spans with four distinct parents. + const execParents = new Set([rootRegionExec, syncExec, turnExec, offTurnExec]); + expect(execParents.size).toBe(4); + }); + + it("test_no_sandbox_exec_parents_to_http_root", 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(); + + // Open a top-level HTTP request span before the run. In production the run + // opens under the HTTP request span, and the buggy exec parented to it. The + // recorder resolves an explicit parent token to its `span`, and it resolves + // an `undefined` token to `null`. A `sandbox.exec` issued with an `undefined` + // token is exactly the exec that the real tracer would attach to the ambient + // HTTP request span. So the two negatives are: no exec names this request + // span, and no exec opens with an `undefined` token (the ambient root). + const httpRequestSpan = traceContext.tracer.startSpan("http.request", undefined, undefined); + + let rootRegionExecFired = false; + let syncExecFired = false; + let turnExecFired = false; + let getRuntimeParentContext: (() => unknown) | undefined; + + const execute = createAcpxEngineExecutor({ + prepareRemoteManagedHome: async (input) => { + if (!syncExecFired) { + syncExecFired = true; + issueSandboxExecFromStore(traceContext); + } + const stagedRuntime = await input.stage([]); + return { stagedRuntime }; + }, + createRuntime: (options) => { + const opts = options as unknown as { + getRuntimeParentContext?: () => unknown; + }; + getRuntimeParentContext = opts.getRuntimeParentContext; + const runtime = buildRuntime(); + return { + ...runtime, + startTurn: (input: Record) => { + // The detached site reads the getter and wraps the work. The getter + // never returns `undefined` inside a live run, so this exec never + // detaches to the HTTP request span. + if (!turnExecFired) { + turnExecFired = true; + runWithRuntimeParent(opts.getRuntimeParentContext?.(), () => + issueSandboxExecFromStore(traceContext), + ); + } + return (runtime.startTurn as (input: unknown) => unknown)(input); + }, + } as never; + }, + }); + + const runtimeMcp = { + getServers: () => { + if (!rootRegionExecFired) { + rootRegionExecFired = true; + issueSandboxExecFromStore(traceContext); + } + return []; + }, + }; + + const result = await execute({ + runId: "run-e2e-http", + agent: { id: "agent-1", companyId: "company-1" }, + runtime: {}, + config: { + agent: "codex", + agentCommand: "node ./fake-acp.js", + stateDir, + cwd: localCwd, + env: { CODEX_HOME: codexHome }, + }, + context: {}, + authToken: "real-run-jwt", + executionTarget, + runtimeMcp: runtimeMcp as never, + startupTraceContext: traceContext, + onLog: async () => {}, + onMeta: async () => {}, + onEvent: async () => {}, + } as never); + expect(result.exitCode).toBe(0); + + // The off-turn detached exec also reads the getter, so it also stays under a + // run span. + runWithRuntimeParent(getRuntimeParentContext?.(), () => + issueSandboxExecFromStore(traceContext), + ); + + const execSpans = spans.filter((span) => span.name === "sandbox.exec"); + // The run issues four exec spans, so there is something to scan. + expect(execSpans.length).toBeGreaterThan(0); + + for (const span of execSpans) { + // Negative 1: no exec parents to the top-level HTTP request span. + expect(span.parent, "a sandbox.exec must not parent to the HTTP request span").not.toBe( + httpRequestSpan, + ); + // Negative 2: no exec opens unparented inside the run. An `undefined` + // parent token is the ambient root that would attach to the HTTP request + // span in production, and a `null` parent is a detached span. + expect(span.parentContextArg, "a sandbox.exec must open with an explicit parent token") + .not.toBeUndefined(); + expect(span.parent, "a sandbox.exec must not open unparented inside the run").not.toBeNull(); + } + }); }); describe("ACPX engine per-step startup timing (run.startup.step events)", () => { diff --git a/packages/adapter-utils/src/acpx-engine/execute.ts b/packages/adapter-utils/src/acpx-engine/execute.ts index 71344f5d0d..868df3897f 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.ts @@ -88,6 +88,7 @@ import { measureStartupStep, NOOP_STARTUP_SPAN, NOOP_STARTUP_TRACE_CONTEXT, + runWithRuntimeParent, setSandboxRootSpanAttributes, type SandboxRootSpanContext, type StartupSpan, @@ -136,6 +137,11 @@ type AcpxAgentProcessIdentity = { pid: number; startedAt: string }; type PaperclipAcpRuntimeOptions = AcpRuntimeOptions & { onAgentSpawn?: (meta: AcpxAgentProcessIdentity) => Promise; + // Return the current-run parent-context token. It is the `task.run` token + // during startup and after the turn, and the `agent.turn` token during the + // turn. A detached exec reads this getter to parent to the live run span. The + // real `createAcpRuntime` ignores this optional field. + getRuntimeParentContext?: () => StartupSpanContext | undefined; }; type AcpxProcessIdentitySink = { @@ -1355,6 +1361,12 @@ async function buildRuntime(input: { // executor opens, and each step publishes its own child context for an inner // exec span to parent to. spanParent: Pick; + // Return the current-run parent-context token. `buildRuntime` threads it into + // the two remote bridge factories, so a run-time exec from a bridge parents to + // the live run span (`agent.turn` during the turn, `task.run` otherwise). The + // run closure passes the run-scoped getter here; when it is absent, each + // bridge site keeps its earlier unparented run-time behavior. + getRuntimeParentContext?: () => StartupSpanContext | undefined; }): Promise { const { runId, agent, config, context, authToken } = input.ctx; // Injectable monotonic clock for per-step startup timing. Hoisted above the @@ -1950,6 +1962,7 @@ async function buildRuntime(input: { timeoutSec, hostApiToken: env.PAPERCLIP_API_KEY, onLog: input.ctx.onLog, + getRuntimeParentContext: input.getRuntimeParentContext, }), concurrentBridgeStepMetrics, ); @@ -1980,6 +1993,7 @@ async function buildRuntime(input: { env: finalizeLaunchEnv, timeoutSec, onLog: input.ctx.onLog, + getRuntimeParentContext: input.getRuntimeParentContext, }), concurrentBridgeStepMetrics, ); @@ -2865,16 +2879,20 @@ 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: - * the engine forwards `parentContext` to each `measureStartupStep` call. The - * `end` closure runs at most once (bring-up complete OR a bring-up failure) and - * swallows every tracer error, so observability never changes startup control - * flow. With no injected trace context, the tracer is a no-op and the span is - * a no-op. + * token plus a guarded `end`. The span parents to the run root span through + * `runParentContext`, so `sandbox.startup` becomes a child of `task.run`. The + * span then parents every startup boundary span in turn: the engine forwards + * `parentContext` to each `measureStartupStep` call. The `end` closure runs at + * most once (bring-up complete OR a bring-up failure) and swallows every tracer + * error, so observability never changes startup control flow. With no injected + * trace context, the tracer is a no-op and the span is a no-op. */ function openStartupRootSpan( tracing: StartupTraceContext, nowMs: () => number, + // The run root span parent context. `sandbox.startup` opens as a child of it, + // so the whole bring-up parents to `task.run`. It is an opaque token here. + runParentContext: StartupSpanContext, // 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. @@ -2885,7 +2903,7 @@ function openStartupRootSpan( } { let span: StartupSpan; try { - span = tracing.tracer.startSpan(STARTUP_ROOT_SPAN_NAME); + span = tracing.tracer.startSpan(STARTUP_ROOT_SPAN_NAME, undefined, runParentContext); } catch { span = NOOP_STARTUP_SPAN; } @@ -2920,6 +2938,146 @@ function openStartupRootSpan( }; } +/** The stable name of the one root span for a whole run. It is a fixed + * low-cardinality constant, never derived from run or user data. */ +const RUN_ROOT_SPAN_NAME = "task.run"; + +/** The stable name of the one span for the agent turn. It is a fixed + * low-cardinality constant, never derived from run or user data. The turn span + * is a child of the run root span. */ +const TURN_SPAN_NAME = "agent.turn"; + +/** The attribute prefix for the run root span. It groups the run-level span + * attributes under one namespace, the same shape as the sandbox startup + * prefix. */ +const RUN_ROOT_SPAN_ATTR_PREFIX = "paperclip.task.run."; + +/** The attribute prefix for the agent turn span. It groups the turn-level span + * attributes under one namespace, the same shape as the run root prefix. */ +const TURN_SPAN_ATTR_PREFIX = "paperclip.agent.turn."; + +/** Map a run id to a non-reversible 12-hex hash for a span attribute. The raw + * run id never rides a span; only this hash does. This mirrors the id-hash rule + * that `clampSpanLabel` uses for the startup ids. */ +function hashRunId(runId: string): string { + return createHash("sha256").update(runId).digest("hex").slice(0, 12); +} + +/** + * Open the one root span for a whole run and return its parent-context token + * plus a guarded `end`. The run root span is the trace root: the sandbox + * bring-up span (`sandbox.startup`) parents to it, so the engine forwards + * `parentContext` into `openStartupRootSpan`. The `end` closure runs at most + * once and swallows every tracer error, so observability never changes run + * control flow. With no injected trace context the tracer is a no-op and the + * span is a no-op. + * + * The span carries only a bounded, non-reversible run-id hash and its own wall + * time. It never carries the prompt, the command, or any user text, so no raw + * run text rides the span. This follows the same allowlist rule as + * `openStartupRootSpan`. + */ +function openRunRootSpan( + tracing: StartupTraceContext, + nowMs: () => number, + runId: string, +): { + parentContext: StartupSpanContext; + end: (failed: boolean) => void; +} { + let span: StartupSpan; + try { + span = tracing.tracer.startSpan(RUN_ROOT_SPAN_NAME); + } catch { + span = NOOP_STARTUP_SPAN; + } + let parentContext: StartupSpanContext; + try { + parentContext = tracing.contextWithSpan(span); + } catch { + parentContext = undefined; + } + const startedAtMs = nowMs(); + let ended = false; + return { + parentContext, + end: (failed: boolean) => { + if (ended) return; + ended = true; + try { + // The run id rides only as a non-reversible short hash, never as the raw + // id. The wall time is a plain duration. No raw run text rides the span. + span.setAttribute(`${RUN_ROOT_SPAN_ATTR_PREFIX}run_id`, hashRunId(runId)); + span.setAttribute(`${RUN_ROOT_SPAN_ATTR_PREFIX}wall_ms`, nowMs() - startedAtMs); + // `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. + if (failed) span.setStatus({ code: 2 }); + span.end(); + } catch { + // Observability must not change run control flow. + } + }, + }; +} + +/** + * Open the one span for the agent turn and return its parent-context token plus + * a guarded `end`. The span parents to the run root span through + * `runParentContext`, so `agent.turn` becomes a child of `task.run`. The + * executor holds the returned `parentContext` for later exec parenting. The + * `end` closure runs at most once and swallows every tracer error, so + * observability never changes turn control flow. With no injected trace context + * the tracer is a no-op and the span is a no-op. + * + * The span carries only its own wall time. It never carries the prompt, the + * command, or any user text, so no raw run text rides the span. This follows the + * same allowlist rule as `openStartupRootSpan`. + */ +function openTurnSpan( + tracing: StartupTraceContext, + nowMs: () => number, + // The run root span parent context. `agent.turn` opens as a child of it, so + // the turn parents to `task.run`. It is an opaque token here. + runParentContext: StartupSpanContext, +): { + parentContext: StartupSpanContext; + end: (failed: boolean) => void; +} { + let span: StartupSpan; + try { + span = tracing.tracer.startSpan(TURN_SPAN_NAME, undefined, runParentContext); + } catch { + span = NOOP_STARTUP_SPAN; + } + let parentContext: StartupSpanContext; + try { + parentContext = tracing.contextWithSpan(span); + } catch { + parentContext = undefined; + } + const startedAtMs = nowMs(); + let ended = false; + return { + parentContext, + end: (failed: boolean) => { + if (ended) return; + ended = true; + try { + // The wall time is a plain duration. No raw run text rides the span. + span.setAttribute(`${TURN_SPAN_ATTR_PREFIX}wall_ms`, nowMs() - startedAtMs); + // `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. + if (failed) span.setStatus({ code: 2 }); + span.end(); + } catch { + // Observability must not change turn control flow. + } + }, + }; +} + export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { const createRuntime = deps.createRuntime ?? createAcpRuntime; const now = deps.now ?? (() => Date.now()); @@ -2941,20 +3099,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { billingType: billingIdentity?.billingType ?? ("unknown" as const), }; const warmIdleMs = asNumber(ctx.config.warmHandleIdleMs, DEFAULT_ACP_ENGINE_WARM_HANDLE_IDLE_MS); - // Evict idle staged runtimes BEFORE building the runtime, since buildRuntime - // consults the staged cache to decide whether a compatible resume may reuse - // an already-staged runtime — an expired entry must not be reused. - await cleanupIdleStagedRuntimes({ - handles: stagedRuntimes, - locks: stagingLocks, - now, - idleMs: warmIdleMs, - }); - // The `sandbox.startup` span names a sandbox bring-up. It must not cover a - // local or SSH run: those runs have no sandbox, so they stay out of sandbox - // telemetry. Open the real root span only when the target is a remote - // sandbox; every other target forces the no-op trace context, so the whole - // startup span path stays inert regardless of the injected context. + // The `task.run` and `sandbox.startup` spans must not cover a local or SSH + // run: those runs have no sandbox, so they stay out of sandbox telemetry. + // Open a real root span only when the target is a remote sandbox and the + // server injected a trace context; every other target forces the no-op + // trace context, so the whole span path stays inert. const startupExecutionTarget = readAdapterExecutionTarget({ executionTarget: ctx.executionTarget, legacyRemoteExecution: ctx.executionTransport?.remoteExecution, @@ -2964,583 +3113,640 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { ? 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 - // `measureStartupStep` call. With no injected trace context the whole path - // is a no-op. `endRootSpan` runs exactly once — at bring-up completion or on - // a bring-up failure. const tracing = targetsRemoteSandbox && ctx.startupTraceContext ? ctx.startupTraceContext : NOOP_STARTUP_TRACE_CONTEXT; - // 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; + // Open the one run root span at the engine first line, before any bring-up + // work. It is the trace root for the whole run: the sandbox bring-up and the + // agent turn parent to it. The engine forwards its parent context into the + // startup span. `runRootSpan.end` runs exactly once, in the `finally` below, + // on every return and on a throw. + const runRootSpan = openRunRootSpan(tracing, now, ctx.runId); + // Hold the current-run parent-context token for the whole run. It starts as + // the `task.run` token, switches to the `agent.turn` token during the turn, + // and switches back to the `task.run` token after the turn. It is never + // `undefined` while the run is live. The holder is a run-scoped local, so two + // concurrent runs in one host process keep separate tokens. A detached exec + // reads it through `getRuntimeParentContext` to parent to the live span. + let currentRunParentContext: StartupSpanContext | undefined = runRootSpan.parentContext; + const getRuntimeParentContext = (): StartupSpanContext | undefined => currentRunParentContext; + // `runFailed` marks the run root span status at end time. It stays `true` + // until the run reaches a clean completed turn, so every failure and every + // early exit closes the span with error status. + let runFailed = true; try { - prepared = await buildRuntime({ ctx, engine, deps, spanParent }); - } catch (err) { - rootSpan.end(true); - throw err; - } - // Per-project staging outcomes for the referenced (mentioned) projects, surfaced back to the - // server on the run result. A referenced project that failed to stage into the sandbox is a - // first-class, counted failure in the requested-vs-synced observability, not only a warning. The - // list is empty on a local target, on a transport that does not stage referenced projects, or - // when every staged referenced project succeeded, so the spread adds the field only when there - // is a failure to report. - const referencedProjectStagingFailures = ( - prepared.stagedRuntime?.additionalSourceFailures ?? [] - ).map((failure) => ({ projectId: failure.projectId })); - const referencedProjectStagingFailuresField = - referencedProjectStagingFailures.length > 0 ? { referencedProjectStagingFailures } : {}; - // State the effective wall-clock timeout and its source up front so a - // later timeout is diagnosable from the run log alone. Goes to stderr: - // the acpx stdout log stream carries JSON acpx.* event payloads and must - // stay machine-parseable line by line. - await ctx.onLog( - "stderr", - `[paperclip] ${formatAdapterExecutionTimeoutStartLogLine(prepared.timeoutResolution)}\n`, - ); - await cleanupIdleHandles({ handles: warmHandles, now: now(), idleMs: warmIdleMs }); - - const previousParams = parseObject(ctx.runtime.sessionParams); - const canResume = isCompatibleSession(previousParams, prepared); - const resumeSessionId = canResume ? asString(previousParams.acpSessionId, "") || undefined : undefined; - const cached = canResume ? warmHandles.get(prepared.sessionKey) : undefined; - const childStderrState = cached?.childStderrState ?? { logPath: null, pendingLiveLine: "" }; - const processIdentitySink = cached?.processIdentitySink ?? { - current: ctx.onSpawn, - latest: null, - }; - // ACPX runtimes can stay warm across heartbeat runs. Keep the callback - // target mutable so a later agent respawn records identity on the current - // heartbeat instead of the run that originally created the runtime. - processIdentitySink.current = ctx.onSpawn; - flushChildStderr(childStderrState); - childStderrState.logPath = prepared.childStderrLogPath; - const runtimeOptions: PaperclipAcpRuntimeOptions = { - cwd: prepared.cwd, - // Host-only spawn cwd for the relay proxy on the remote process-session - // lane; `undefined` elsewhere so acpx falls back to `cwd` (byte-identical). - // The advertised `session/new` cwd (`prepared.cwd` = `remoteCwd`) and the - // fingerprint / compat key are unaffected — this redirects ONLY the host - // `spawn()` `chdir`, not the in-sandbox data path. - spawnCwd: prepared.hostSpawnCwd, - sessionStore: createRuntimeStore({ stateDir: prepared.stateDir }), - agentRegistry: prepared.agentRegistry, - permissionMode: prepared.permissionMode, - nonInteractivePermissions: prepared.nonInteractivePermissions, - mcpServers: prepared.mcpServers, - timeoutMs: prepared.timeoutSec > 0 ? prepared.timeoutSec * 1000 : undefined, - // Scope ACPX runtime verbose logs to the claude agent only. Codex - // and custom agents already emit their own per-tool output and don't - // benefit from doubling the log volume. - verbose: prepared.acpxAgent === "claude", - onAgentStderr: prepared.childStderrLogPath - ? (chunk) => routeChildStderr(childStderrState, chunk) - : undefined, - onAgentSpawn: async (meta) => { - processIdentitySink.latest = meta; - await processIdentitySink.current?.({ - pid: meta.pid, - processGroupId: null, - startedAt: meta.startedAt, - }); - }, - }; - // Open Q2: split the ~7s `acp.handshake` into the two in-repo-observable - // sub-phases — the ACP runtime construction (`createRuntime`) vs the session - // establishment envelope (`ensureSession`). The patched spawn lifecycle - // hook records process identity, but the finer spawn/`initialize`/ - // `session/new` timing split still lives inside external `acpx`. - // `createRuntime` runs once and only on a cold start; a warm-handle hit - // reuses `cached.runtime`, so `createRuntimeMs` stays undefined and the - // 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 { - const createRuntimeStart = now(); - runtime = createRuntime(runtimeOptions); - createRuntimeMs = now() - createRuntimeStart; - } - if (cached) clearWarmHandleTimer(cached); - if (!canResume && asString(previousParams.runtimeSessionName, "")) { + // Evict idle staged runtimes BEFORE building the runtime, since buildRuntime + // consults the staged cache to decide whether a compatible resume may reuse + // an already-staged runtime — an expired entry must not be reused. + await cleanupIdleStagedRuntimes({ + handles: stagedRuntimes, + locks: stagingLocks, + now, + idleMs: warmIdleMs, + }); + // 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, runRootSpan.parentContext, () => ({ + 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 { + // Publish the `sandbox.startup` context to the runtime-parent store for + // the whole bring-up. A startup-body exec that runs outside a measured + // step reads this token and parents its span to `sandbox.startup`, not to + // a detached root. A measured step nests its own `activeStepContextStorage` + // run inside this wrap and overrides the store, so an in-step exec still + // parents to its step span. On a local or SSH target + // `spanParent.parentContext` is a no-op token, so the wrap is inert. + prepared = await runWithRuntimeParent(spanParent.parentContext, () => + buildRuntime({ ctx, engine, deps, spanParent, getRuntimeParentContext }), + ); + } catch (err) { + rootSpan.end(true); + throw err; + } + // Per-project staging outcomes for the referenced (mentioned) projects, surfaced back to the + // server on the run result. A referenced project that failed to stage into the sandbox is a + // first-class, counted failure in the requested-vs-synced observability, not only a warning. The + // list is empty on a local target, on a transport that does not stage referenced projects, or + // when every staged referenced project succeeded, so the spread adds the field only when there + // is a failure to report. + const referencedProjectStagingFailures = ( + prepared.stagedRuntime?.additionalSourceFailures ?? [] + ).map((failure) => ({ projectId: failure.projectId })); + const referencedProjectStagingFailuresField = + referencedProjectStagingFailures.length > 0 ? { referencedProjectStagingFailures } : {}; + // State the effective wall-clock timeout and its source up front so a + // later timeout is diagnosable from the run log alone. Goes to stderr: + // the acpx stdout log stream carries JSON acpx.* event payloads and must + // stay machine-parseable line by line. await ctx.onLog( - "stdout", - `[paperclip] ACPX session "${asString(previousParams.runtimeSessionName, "")}" does not match the current agent/cwd/mode/runtime identity; starting fresh in "${prepared.cwd}".\n`, + "stderr", + `[paperclip] ${formatAdapterExecutionTimeoutStartLogLine(prepared.timeoutResolution)}\n`, ); - } + await cleanupIdleHandles({ handles: warmHandles, now: now(), idleMs: warmIdleMs }); - let handle = cached?.handle ?? null; - let resumedSession = Boolean(handle ?? resumeSessionId); - let clearSession = false; - - try { - if (!handle) { - 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. 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(); - const established = await runtime.ensureSession({ - sessionKey: prepared.sessionKey, - agent: prepared.acpxAgent, - mode: prepared.mode, - cwd: prepared.cwd, - resumeSessionId, - sessionOptions: { env: prepared.env }, - }); - ensureSessionMs = now() - ensureSessionStart; - return established; - }, { - ...prepared.stepMetrics, - // The two sub-times ride the span as fixed, closed keys. - spanWallTimes: () => ({ - createRuntime: createRuntimeMs, - ensureSession: ensureSessionMs, - }), - }); - } catch (err) { - if (!resumeSessionId || !isResumeFailure(err)) throw err; - clearSession = true; - resumedSession = false; - await ctx.onLog( - "stdout", - `[paperclip] ACPX resume session "${resumeSessionId}" is unavailable; retrying with a fresh session.\n`, - ); - // Fresh-session retry: the runtime was already constructed on the - // first attempt (never re-created), so this event reports only its - // own `ensureSessionMs` — no `createRuntimeMs`. - let retryEnsureSessionMs: number | undefined; - handle = await measureStartupStep(ctx, now, "acp.handshake", async () => { - const ensureSessionStart = now(); - const established = await runtime.ensureSession({ - sessionKey: prepared.sessionKey, - agent: prepared.acpxAgent, - mode: prepared.mode, - cwd: prepared.cwd, - sessionOptions: { env: prepared.env }, - }); - retryEnsureSessionMs = now() - ensureSessionStart; - return established; - }, { - ...prepared.stepMetrics, - // 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 - // before the next prompt starts so every running heartbeat is adoptable. - if (handle && cached && processIdentitySink.latest && ctx.onSpawn) { - await ctx.onSpawn({ - pid: processIdentitySink.latest.pid, - processGroupId: null, - startedAt: processIdentitySink.latest.startedAt, - }); - } - } catch (err) { - // Bring-up failed at the handshake — close the root span with error status. - rootSpan.end(true); - const { classified, message } = await emitAcpxFailure({ - ctx, - prepared, - err, - phase: "ensure_session", - }); - await discardStagedRuntime({ handles: stagedRuntimes, prepared }); - await cleanupRemoteBridges(prepared); - return { - exitCode: 1, - signal: null, - timedOut: false, - errorMessage: message, - ...classified, - ...billingFields, - ...referencedProjectStagingFailuresField, - model: prepared.requestedModel || null, - clearSession, - resultJson: { phase: "ensure_session" }, - summary: message, + const previousParams = parseObject(ctx.runtime.sessionParams); + const canResume = isCompatibleSession(previousParams, prepared); + const resumeSessionId = canResume ? asString(previousParams.acpSessionId, "") || undefined : undefined; + const cached = canResume ? warmHandles.get(prepared.sessionKey) : undefined; + const childStderrState = cached?.childStderrState ?? { logPath: null, pendingLiveLine: "" }; + const processIdentitySink = cached?.processIdentitySink ?? { + current: ctx.onSpawn, + latest: null, }; - } - - if (!handle) { - // Bring-up produced no session handle — close the root span with error status. - rootSpan.end(true); - await discardStagedRuntime({ handles: stagedRuntimes, prepared }); - await cleanupRemoteBridges(prepared); - return { - exitCode: 1, - signal: null, - timedOut: false, - errorMessage: "ACPX did not return a runtime session handle.", - errorCode: "acpx_runtime_error", - ...billingFields, - ...referencedProjectStagingFailuresField, - model: prepared.requestedModel || null, - resultJson: { phase: "ensure_session" }, - summary: "ACPX did not return a runtime session handle.", - }; - } - // Bring-up is complete: the session handle is established. Close the root - // span here, so it covers `buildRuntime` through `acp.handshake` and no - // further. The agent turn runs after and is out of the startup root's scope. - rootSpan.end(false); - const sessionHandle = handle; - try { - await applySessionConfigOptions({ - runtime, - handle: sessionHandle, - prepared, - onLog: ctx.onLog, - }); - } catch (err) { - const { classified, message } = await emitAcpxFailure({ - ctx, - prepared, - err, - phase: "configure_session", - }); - await runtime.close({ - handle: sessionHandle, - reason: "paperclip config cleanup", - discardPersistentState: false, - }).catch(() => {}); - const existing = warmHandles.get(prepared.sessionKey); - if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { - clearWarmHandleTimer(existing); - warmHandles.delete(prepared.sessionKey); - } - await discardStagedRuntime({ handles: stagedRuntimes, prepared }); - await cleanupRemoteBridges(prepared); - return { - exitCode: 1, - signal: null, - timedOut: false, - errorMessage: message, - ...classified, - ...billingFields, - ...referencedProjectStagingFailuresField, - model: prepared.requestedModel || null, - clearSession, - resultJson: { - phase: "configure_session", - agent: prepared.acpxAgent, - requestedModel: prepared.requestedModel || null, - requestedThinkingEffort: prepared.requestedThinkingEffort || null, - fastMode: prepared.fastMode, - }, - summary: message, - }; - } - const { prompt, promptMetrics, commandNotes } = await buildPrompt(ctx, resumedSession, prepared.env); - const runPrompt = joinPromptSections([prepared.skillPromptInstructions, prompt]); - await emitAcpxLog(ctx, { - type: "acpx.session", - agent: prepared.acpxAgent, - sessionId: sessionHandle.backendSessionId, - acpSessionId: sessionHandle.backendSessionId, - agentSessionId: sessionHandle.agentSessionId, - runtimeSessionName: sessionHandle.runtimeSessionName, - mode: prepared.mode, - permissionMode: prepared.permissionMode, - model: prepared.requestedModel || null, - thinkingEffort: prepared.requestedThinkingEffort || null, - fastMode: prepared.fastMode, - }); - if (ctx.onMeta) { - await ctx.onMeta({ - adapterType: engine.adapterType, - command: prepared.agentCommand ?? prepared.acpxAgent, + // ACPX runtimes can stay warm across heartbeat runs. Keep the callback + // target mutable so a later agent respawn records identity on the current + // heartbeat instead of the run that originally created the runtime. + processIdentitySink.current = ctx.onSpawn; + flushChildStderr(childStderrState); + childStderrState.logPath = prepared.childStderrLogPath; + const runtimeOptions: PaperclipAcpRuntimeOptions = { cwd: prepared.cwd, - commandNotes: [ - `ACPX runtime embedded in Paperclip with ${prepared.mode} session mode.`, - `Effective ACPX permission mode: ${prepared.permissionMode}.`, - ...(prepared.requestedModel - ? [ - prepared.acpxAgent === "claude" - ? `Requested ACPX model: ${prepared.requestedModel} (set via ANTHROPIC_MODEL env at startup).` - : prepared.acpxAgent === "codex" - ? `Requested ACPX model: ${prepared.requestedModel} (set via CODEX_CONFIG at startup).` - : `Requested ACPX model: ${prepared.requestedModel}.`, - ] - : []), - ...(prepared.requestedThinkingEffort ? [`Requested ACPX thinking effort: ${prepared.requestedThinkingEffort}.`] : []), - ...(prepared.fastMode ? ["Requested ACPX Codex fast mode."] : []), - ...(Array.isArray(prepared.skillsIdentity.commandNotes) - ? prepared.skillsIdentity.commandNotes.filter((note): note is string => typeof note === "string") - : []), - ...commandNotes, - ], - env: prepared.loggedEnv, - prompt: runPrompt, - promptMetrics, - context: ctx.context, - }); - } - - let cancelActiveTurn: ((reason: string) => Promise) | null = null; - let controller: AbortController | null = null; - let timeout: NodeJS.Timeout | null = null; - let timedOut = false; - const textParts: string[] = []; - let eventBreakdown: AcpRuntimeUsageBreakdown | null = null; - let eventCostUsd: number | null = null; - try { - // Snapshot pre-turn usage so cumulative agent-reported cost can be - // attributed to this run alone. - const preTurnStatus = await readRuntimeStatus(runtime, sessionHandle); - const timeoutMs = prepared.timeoutSec > 0 ? prepared.timeoutSec * 1000 : undefined; - controller = new AbortController(); - if (timeoutMs) { - timeout = setTimeout(() => { - timedOut = true; - controller?.abort(); - void cancelActiveTurn?.(formatAdapterExecutionTimeoutErrorMessage(prepared.timeoutResolution)).catch(() => {}); - }, timeoutMs); - } - const turn = runtime.startTurn({ - handle: sessionHandle, - text: runPrompt, - mode: "prompt", - requestId: ctx.runId, - timeoutMs, - signal: controller?.signal, - }); - cancelActiveTurn = async (reason: string) => { - await turn.cancel({ reason }); - }; - const toolTitles = new Map(); - for await (const event of turn.events) { - if (event.type === "text_delta") textParts.push(event.text); - if (event.type === "status" && event.tag === "usage_update") { - eventBreakdown = event.breakdown ?? eventBreakdown; - eventCostUsd = usdCostAmount(event.cost) ?? eventCostUsd; - } - await emitRuntimeEvent(ctx, event, toolTitles); - } - const terminal = await turn.result; - if (timeout) clearTimeout(timeout); - // Read usage before the close/warm-handle paths below can discard state. - const postTurnStatus = await readRuntimeStatus(runtime, sessionHandle); - const turnUsage = summarizeAcpxTurnUsage({ - preStatus: preTurnStatus, - postStatus: postTurnStatus, - eventBreakdown, - eventCostUsd, - }); - if (terminal.status === "failed" || terminal.status === "cancelled" || timedOut) { - const existing = warmHandles.get(prepared.sessionKey); - if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { - await closeWarmHandle({ - handles: warmHandles, - key: prepared.sessionKey, - entry: existing, - reason: timedOut ? "paperclip timeout cleanup" : `paperclip turn ${terminal.status}`, - discardPersistentState: terminal.status === "cancelled" || timedOut, + // Host-only spawn cwd for the relay proxy on the remote process-session + // lane; `undefined` elsewhere so acpx falls back to `cwd` (byte-identical). + // The advertised `session/new` cwd (`prepared.cwd` = `remoteCwd`) and the + // fingerprint / compat key are unaffected — this redirects ONLY the host + // `spawn()` `chdir`, not the in-sandbox data path. + spawnCwd: prepared.hostSpawnCwd, + sessionStore: createRuntimeStore({ stateDir: prepared.stateDir }), + agentRegistry: prepared.agentRegistry, + permissionMode: prepared.permissionMode, + nonInteractivePermissions: prepared.nonInteractivePermissions, + mcpServers: prepared.mcpServers, + timeoutMs: prepared.timeoutSec > 0 ? prepared.timeoutSec * 1000 : undefined, + // Scope ACPX runtime verbose logs to the claude agent only. Codex + // and custom agents already emit their own per-tool output and don't + // benefit from doubling the log volume. + verbose: prepared.acpxAgent === "claude", + onAgentStderr: prepared.childStderrLogPath + ? (chunk) => routeChildStderr(childStderrState, chunk) + : undefined, + onAgentSpawn: async (meta) => { + processIdentitySink.latest = meta; + await processIdentitySink.current?.({ + pid: meta.pid, + processGroupId: null, + startedAt: meta.startedAt, }); - } else { - await runtime.close({ - handle: sessionHandle, - reason: timedOut ? "paperclip timeout cleanup" : `paperclip turn ${terminal.status}`, - discardPersistentState: terminal.status === "cancelled" || timedOut, - }).catch(() => {}); - } - } else if (prepared.mode === "persistent" && warmIdleMs > 0 && !prepared.processSessionBridge) { - const existing = warmHandles.get(prepared.sessionKey); - if (existing && !warmHandleMatches(existing, runtime, sessionHandle)) { - await runtime.close({ - handle: sessionHandle, - reason: "paperclip duplicate warm handle cleanup", - discardPersistentState: false, - }).catch(() => {}); - } else { - const entry: RuntimeCacheEntry = { - runtime, - handle: sessionHandle, - childStderrState, - processIdentitySink, - fingerprint: prepared.fingerprint, - lastUsedAt: now(), - }; - warmHandles.set(prepared.sessionKey, entry); - scheduleIdleHandleCleanup({ - handles: warmHandles, - key: prepared.sessionKey, - entry, - idleMs: warmIdleMs, - now, - }); - } - } else { - const existing = warmHandles.get(prepared.sessionKey); - if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { - await closeWarmHandle({ - handles: warmHandles, - key: prepared.sessionKey, - entry: existing, - reason: "paperclip completed turn cleanup", - }); - } else { - await runtime.close({ - handle: sessionHandle, - reason: "paperclip completed turn cleanup", - discardPersistentState: false, - }).catch(() => {}); - } - } - - // PR 3: keep the staged runtime warm for the next compatible resume only - // after a clean turn; a failed/cancelled/timed-out turn discards it so the - // next run stages fresh instead of reusing a torn-down session's staged - // credentials. Copy-back still fires for every outcome via - // `cleanupRemoteBridges` below (unchanged from PR 2). - if (terminal.status === "completed" && !timedOut) { - saveStagedRuntimeAfterCleanTurn({ handles: stagedRuntimes, prepared, now: now() }); - } else { - await discardStagedRuntime({ handles: stagedRuntimes, prepared }); - } - - const errorMessage = timedOut - ? formatAdapterExecutionTimeoutErrorMessage(prepared.timeoutResolution) - : resultErrorMessage(terminal); - const terminalStopReason = terminal.status === "failed" ? terminal.error.message : terminal.stopReason; - await emitAcpxLog(ctx, { - type: terminal.status === "completed" ? "acpx.result" : "acpx.error", - summary: terminal.status, - stopReason: terminalStopReason, - message: errorMessage, - }); - await cleanupRemoteBridges(prepared); - flushChildStderr(childStderrState); - return { - exitCode: terminal.status === "completed" ? 0 : 1, - signal: timedOut ? "SIGTERM" : null, - timedOut, - errorMessage, - errorCode: terminal.status === "failed" ? "acpx_turn_failed" : timedOut ? "acpx_timeout" : null, - sessionId: sessionHandle.backendSessionId ?? sessionHandle.runtimeSessionName, - sessionParams: buildSessionParams({ prepared, handle: sessionHandle }), - sessionDisplayId: sessionHandle.agentSessionId ?? sessionHandle.backendSessionId ?? sessionHandle.runtimeSessionName, - ...billingFields, - ...referencedProjectStagingFailuresField, - model: prepared.requestedModel || null, - ...(turnUsage.usage ? { usage: turnUsage.usage, usageBasis: "per_run" as const } : {}), - costUsd: turnUsage.costUsd, - resultJson: { - status: terminal.status, - stopReason: terminalStopReason, - permissionMode: prepared.permissionMode, - mode: prepared.mode, - requestedModel: prepared.requestedModel || null, - requestedThinkingEffort: prepared.requestedThinkingEffort || null, - fastMode: prepared.fastMode, - ...(turnUsage.usageDetail ? { usage: turnUsage.usageDetail } : {}), - ...(turnUsage.cumulativeCostUsd != null - ? { cumulativeCostUsd: turnUsage.cumulativeCostUsd } - : {}), }, - summary: textParts.join("").trim() || terminalStopReason || terminal.status, - clearSession, + getRuntimeParentContext, }; - } catch (err) { - if (timeout) clearTimeout(timeout); - const messageOverride = timedOut - ? formatAdapterExecutionTimeoutErrorMessage(prepared.timeoutResolution) - : undefined; - const cancel = cancelActiveTurn as ((reason: string) => Promise) | null; - const preEmitMessage = - messageOverride ?? (err instanceof Error ? err.message : String(err)); - if (cancel) await cancel(preEmitMessage).catch(() => {}); - await runtime.close({ - handle: sessionHandle, - reason: timedOut ? "paperclip timeout cleanup" : "paperclip error cleanup", - discardPersistentState: timedOut, - }).catch(() => {}); - const existing = warmHandles.get(prepared.sessionKey); - if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { - clearWarmHandleTimer(existing); - warmHandles.delete(prepared.sessionKey); + // Open Q2: split the ~7s `acp.handshake` into the two in-repo-observable + // sub-phases — the ACP runtime construction (`createRuntime`) vs the session + // establishment envelope (`ensureSession`). The patched spawn lifecycle + // hook records process identity, but the finer spawn/`initialize`/ + // `session/new` timing split still lives inside external `acpx`. + // `createRuntime` runs once and only on a cold start; a warm-handle hit + // reuses `cached.runtime`, so `createRuntimeMs` stays undefined and the + // 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 { + const createRuntimeStart = now(); + runtime = createRuntime(runtimeOptions); + createRuntimeMs = now() - createRuntimeStart; } - await discardStagedRuntime({ handles: stagedRuntimes, prepared }); - const { classified, message } = await emitAcpxFailure({ - ctx, - prepared, - err, - phase: "turn", - messageOverride, - }); - await cleanupRemoteBridges(prepared); - flushChildStderr(childStderrState); - return { - exitCode: 1, - signal: timedOut ? "SIGTERM" : null, - timedOut, - errorMessage: message, - errorCode: timedOut ? "acpx_timeout" : classified.errorCode, - errorMeta: classified.errorMeta, - ...billingFields, - ...referencedProjectStagingFailuresField, + if (cached) clearWarmHandleTimer(cached); + if (!canResume && asString(previousParams.runtimeSessionName, "")) { + await ctx.onLog( + "stdout", + `[paperclip] ACPX session "${asString(previousParams.runtimeSessionName, "")}" does not match the current agent/cwd/mode/runtime identity; starting fresh in "${prepared.cwd}".\n`, + ); + } + + let handle = cached?.handle ?? null; + let resumedSession = Boolean(handle ?? resumeSessionId); + let clearSession = false; + + try { + if (!handle) { + 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. 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(); + const established = await runtime.ensureSession({ + sessionKey: prepared.sessionKey, + agent: prepared.acpxAgent, + mode: prepared.mode, + cwd: prepared.cwd, + resumeSessionId, + sessionOptions: { env: prepared.env }, + }); + ensureSessionMs = now() - ensureSessionStart; + return established; + }, { + ...prepared.stepMetrics, + // The two sub-times ride the span as fixed, closed keys. + spanWallTimes: () => ({ + createRuntime: createRuntimeMs, + ensureSession: ensureSessionMs, + }), + }); + } catch (err) { + if (!resumeSessionId || !isResumeFailure(err)) throw err; + clearSession = true; + resumedSession = false; + await ctx.onLog( + "stdout", + `[paperclip] ACPX resume session "${resumeSessionId}" is unavailable; retrying with a fresh session.\n`, + ); + // Fresh-session retry: the runtime was already constructed on the + // first attempt (never re-created), so this event reports only its + // own `ensureSessionMs` — no `createRuntimeMs`. + let retryEnsureSessionMs: number | undefined; + handle = await measureStartupStep(ctx, now, "acp.handshake", async () => { + const ensureSessionStart = now(); + const established = await runtime.ensureSession({ + sessionKey: prepared.sessionKey, + agent: prepared.acpxAgent, + mode: prepared.mode, + cwd: prepared.cwd, + sessionOptions: { env: prepared.env }, + }); + retryEnsureSessionMs = now() - ensureSessionStart; + return established; + }, { + ...prepared.stepMetrics, + // 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 + // before the next prompt starts so every running heartbeat is adoptable. + if (handle && cached && processIdentitySink.latest && ctx.onSpawn) { + await ctx.onSpawn({ + pid: processIdentitySink.latest.pid, + processGroupId: null, + startedAt: processIdentitySink.latest.startedAt, + }); + } + } catch (err) { + // Bring-up failed at the handshake — close the root span with error status. + rootSpan.end(true); + const { classified, message } = await emitAcpxFailure({ + ctx, + prepared, + err, + phase: "ensure_session", + }); + await discardStagedRuntime({ handles: stagedRuntimes, prepared }); + await cleanupRemoteBridges(prepared); + return { + exitCode: 1, + signal: null, + timedOut: false, + errorMessage: message, + ...classified, + ...billingFields, + ...referencedProjectStagingFailuresField, + model: prepared.requestedModel || null, + clearSession, + resultJson: { phase: "ensure_session" }, + summary: message, + }; + } + + if (!handle) { + // Bring-up produced no session handle — close the root span with error status. + rootSpan.end(true); + await discardStagedRuntime({ handles: stagedRuntimes, prepared }); + await cleanupRemoteBridges(prepared); + return { + exitCode: 1, + signal: null, + timedOut: false, + errorMessage: "ACPX did not return a runtime session handle.", + errorCode: "acpx_runtime_error", + ...billingFields, + ...referencedProjectStagingFailuresField, + model: prepared.requestedModel || null, + resultJson: { phase: "ensure_session" }, + summary: "ACPX did not return a runtime session handle.", + }; + } + // Bring-up is complete: the session handle is established. Close the root + // span here, so it covers `buildRuntime` through `acp.handshake` and no + // further. The agent turn runs after and is out of the startup root's scope. + rootSpan.end(false); + const sessionHandle = handle; + try { + await applySessionConfigOptions({ + runtime, + handle: sessionHandle, + prepared, + onLog: ctx.onLog, + }); + } catch (err) { + const { classified, message } = await emitAcpxFailure({ + ctx, + prepared, + err, + phase: "configure_session", + }); + await runtime.close({ + handle: sessionHandle, + reason: "paperclip config cleanup", + discardPersistentState: false, + }).catch(() => {}); + const existing = warmHandles.get(prepared.sessionKey); + if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { + clearWarmHandleTimer(existing); + warmHandles.delete(prepared.sessionKey); + } + await discardStagedRuntime({ handles: stagedRuntimes, prepared }); + await cleanupRemoteBridges(prepared); + return { + exitCode: 1, + signal: null, + timedOut: false, + errorMessage: message, + ...classified, + ...billingFields, + ...referencedProjectStagingFailuresField, + model: prepared.requestedModel || null, + clearSession, + resultJson: { + phase: "configure_session", + agent: prepared.acpxAgent, + requestedModel: prepared.requestedModel || null, + requestedThinkingEffort: prepared.requestedThinkingEffort || null, + fastMode: prepared.fastMode, + }, + summary: message, + }; + } + const { prompt, promptMetrics, commandNotes } = await buildPrompt(ctx, resumedSession, prepared.env); + const runPrompt = joinPromptSections([prepared.skillPromptInstructions, prompt]); + await emitAcpxLog(ctx, { + type: "acpx.session", + agent: prepared.acpxAgent, + sessionId: sessionHandle.backendSessionId, + acpSessionId: sessionHandle.backendSessionId, + agentSessionId: sessionHandle.agentSessionId, + runtimeSessionName: sessionHandle.runtimeSessionName, + mode: prepared.mode, + permissionMode: prepared.permissionMode, model: prepared.requestedModel || null, - clearSession: clearSession || timedOut, - resultJson: { phase: "turn" }, - summary: message, - }; + thinkingEffort: prepared.requestedThinkingEffort || null, + fastMode: prepared.fastMode, + }); + if (ctx.onMeta) { + await ctx.onMeta({ + adapterType: engine.adapterType, + command: prepared.agentCommand ?? prepared.acpxAgent, + cwd: prepared.cwd, + commandNotes: [ + `ACPX runtime embedded in Paperclip with ${prepared.mode} session mode.`, + `Effective ACPX permission mode: ${prepared.permissionMode}.`, + ...(prepared.requestedModel + ? [ + prepared.acpxAgent === "claude" + ? `Requested ACPX model: ${prepared.requestedModel} (set via ANTHROPIC_MODEL env at startup).` + : prepared.acpxAgent === "codex" + ? `Requested ACPX model: ${prepared.requestedModel} (set via CODEX_CONFIG at startup).` + : `Requested ACPX model: ${prepared.requestedModel}.`, + ] + : []), + ...(prepared.requestedThinkingEffort ? [`Requested ACPX thinking effort: ${prepared.requestedThinkingEffort}.`] : []), + ...(prepared.fastMode ? ["Requested ACPX Codex fast mode."] : []), + ...(Array.isArray(prepared.skillsIdentity.commandNotes) + ? prepared.skillsIdentity.commandNotes.filter((note): note is string => typeof note === "string") + : []), + ...commandNotes, + ], + env: prepared.loggedEnv, + prompt: runPrompt, + promptMetrics, + context: ctx.context, + }); + } + + let cancelActiveTurn: ((reason: string) => Promise) | null = null; + let controller: AbortController | null = null; + let timeout: NodeJS.Timeout | null = null; + let timedOut = false; + const textParts: string[] = []; + let eventBreakdown: AcpRuntimeUsageBreakdown | null = null; + let eventCostUsd: number | null = null; + // Open the agent turn span as a child of the run root span. It wraps the + // whole turn: the executor holds `turnSpan.parentContext` for later exec + // parenting, and the `finally` below ends the span once on every path. The + // span is declared before the `try` so the `finally` can reach it. + const turnSpan = openTurnSpan(tracing, now, runRootSpan.parentContext); + // Switch the current-run holder to the `agent.turn` token for the turn, so + // a detached exec during the turn parents to `agent.turn`. The turn + // `finally` resets the holder to the `task.run` token. + currentRunParentContext = turnSpan.parentContext; + try { + // Snapshot pre-turn usage so cumulative agent-reported cost can be + // attributed to this run alone. + const preTurnStatus = await readRuntimeStatus(runtime, sessionHandle); + const timeoutMs = prepared.timeoutSec > 0 ? prepared.timeoutSec * 1000 : undefined; + controller = new AbortController(); + if (timeoutMs) { + timeout = setTimeout(() => { + timedOut = true; + controller?.abort(); + void cancelActiveTurn?.(formatAdapterExecutionTimeoutErrorMessage(prepared.timeoutResolution)).catch(() => {}); + }, timeoutMs); + } + const turn = runtime.startTurn({ + handle: sessionHandle, + text: runPrompt, + mode: "prompt", + requestId: ctx.runId, + timeoutMs, + signal: controller?.signal, + }); + cancelActiveTurn = async (reason: string) => { + await turn.cancel({ reason }); + }; + const toolTitles = new Map(); + for await (const event of turn.events) { + if (event.type === "text_delta") textParts.push(event.text); + if (event.type === "status" && event.tag === "usage_update") { + eventBreakdown = event.breakdown ?? eventBreakdown; + eventCostUsd = usdCostAmount(event.cost) ?? eventCostUsd; + } + await emitRuntimeEvent(ctx, event, toolTitles); + } + const terminal = await turn.result; + if (timeout) clearTimeout(timeout); + // Read usage before the close/warm-handle paths below can discard state. + const postTurnStatus = await readRuntimeStatus(runtime, sessionHandle); + const turnUsage = summarizeAcpxTurnUsage({ + preStatus: preTurnStatus, + postStatus: postTurnStatus, + eventBreakdown, + eventCostUsd, + }); + if (terminal.status === "failed" || terminal.status === "cancelled" || timedOut) { + const existing = warmHandles.get(prepared.sessionKey); + if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { + await closeWarmHandle({ + handles: warmHandles, + key: prepared.sessionKey, + entry: existing, + reason: timedOut ? "paperclip timeout cleanup" : `paperclip turn ${terminal.status}`, + discardPersistentState: terminal.status === "cancelled" || timedOut, + }); + } else { + await runtime.close({ + handle: sessionHandle, + reason: timedOut ? "paperclip timeout cleanup" : `paperclip turn ${terminal.status}`, + discardPersistentState: terminal.status === "cancelled" || timedOut, + }).catch(() => {}); + } + } else if (prepared.mode === "persistent" && warmIdleMs > 0 && !prepared.processSessionBridge) { + const existing = warmHandles.get(prepared.sessionKey); + if (existing && !warmHandleMatches(existing, runtime, sessionHandle)) { + await runtime.close({ + handle: sessionHandle, + reason: "paperclip duplicate warm handle cleanup", + discardPersistentState: false, + }).catch(() => {}); + } else { + const entry: RuntimeCacheEntry = { + runtime, + handle: sessionHandle, + childStderrState, + processIdentitySink, + fingerprint: prepared.fingerprint, + lastUsedAt: now(), + }; + warmHandles.set(prepared.sessionKey, entry); + scheduleIdleHandleCleanup({ + handles: warmHandles, + key: prepared.sessionKey, + entry, + idleMs: warmIdleMs, + now, + }); + } + } else { + const existing = warmHandles.get(prepared.sessionKey); + if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { + await closeWarmHandle({ + handles: warmHandles, + key: prepared.sessionKey, + entry: existing, + reason: "paperclip completed turn cleanup", + }); + } else { + await runtime.close({ + handle: sessionHandle, + reason: "paperclip completed turn cleanup", + discardPersistentState: false, + }).catch(() => {}); + } + } + + // PR 3: keep the staged runtime warm for the next compatible resume only + // after a clean turn; a failed/cancelled/timed-out turn discards it so the + // next run stages fresh instead of reusing a torn-down session's staged + // credentials. Copy-back still fires for every outcome via + // `cleanupRemoteBridges` below (unchanged from PR 2). + if (terminal.status === "completed" && !timedOut) { + saveStagedRuntimeAfterCleanTurn({ handles: stagedRuntimes, prepared, now: now() }); + } else { + await discardStagedRuntime({ handles: stagedRuntimes, prepared }); + } + + const errorMessage = timedOut + ? formatAdapterExecutionTimeoutErrorMessage(prepared.timeoutResolution) + : resultErrorMessage(terminal); + const terminalStopReason = terminal.status === "failed" ? terminal.error.message : terminal.stopReason; + await emitAcpxLog(ctx, { + type: terminal.status === "completed" ? "acpx.result" : "acpx.error", + summary: terminal.status, + stopReason: terminalStopReason, + message: errorMessage, + }); + await cleanupRemoteBridges(prepared); + flushChildStderr(childStderrState); + // The one clean-completion path clears the run failure flag; every other + // path keeps it set, so the run root span closes with error status. + runFailed = terminal.status === "completed" && !timedOut ? false : true; + return { + exitCode: terminal.status === "completed" ? 0 : 1, + signal: timedOut ? "SIGTERM" : null, + timedOut, + errorMessage, + errorCode: terminal.status === "failed" ? "acpx_turn_failed" : timedOut ? "acpx_timeout" : null, + sessionId: sessionHandle.backendSessionId ?? sessionHandle.runtimeSessionName, + sessionParams: buildSessionParams({ prepared, handle: sessionHandle }), + sessionDisplayId: sessionHandle.agentSessionId ?? sessionHandle.backendSessionId ?? sessionHandle.runtimeSessionName, + ...billingFields, + ...referencedProjectStagingFailuresField, + model: prepared.requestedModel || null, + ...(turnUsage.usage ? { usage: turnUsage.usage, usageBasis: "per_run" as const } : {}), + costUsd: turnUsage.costUsd, + resultJson: { + status: terminal.status, + stopReason: terminalStopReason, + permissionMode: prepared.permissionMode, + mode: prepared.mode, + requestedModel: prepared.requestedModel || null, + requestedThinkingEffort: prepared.requestedThinkingEffort || null, + fastMode: prepared.fastMode, + ...(turnUsage.usageDetail ? { usage: turnUsage.usageDetail } : {}), + ...(turnUsage.cumulativeCostUsd != null + ? { cumulativeCostUsd: turnUsage.cumulativeCostUsd } + : {}), + }, + summary: textParts.join("").trim() || terminalStopReason || terminal.status, + clearSession, + }; + } catch (err) { + if (timeout) clearTimeout(timeout); + const messageOverride = timedOut + ? formatAdapterExecutionTimeoutErrorMessage(prepared.timeoutResolution) + : undefined; + const cancel = cancelActiveTurn as ((reason: string) => Promise) | null; + const preEmitMessage = + messageOverride ?? (err instanceof Error ? err.message : String(err)); + if (cancel) await cancel(preEmitMessage).catch(() => {}); + await runtime.close({ + handle: sessionHandle, + reason: timedOut ? "paperclip timeout cleanup" : "paperclip error cleanup", + discardPersistentState: timedOut, + }).catch(() => {}); + const existing = warmHandles.get(prepared.sessionKey); + if (warmHandleMatches(existing, runtime, sessionHandle) && existing) { + clearWarmHandleTimer(existing); + warmHandles.delete(prepared.sessionKey); + } + await discardStagedRuntime({ handles: stagedRuntimes, prepared }); + const { classified, message } = await emitAcpxFailure({ + ctx, + prepared, + err, + phase: "turn", + messageOverride, + }); + await cleanupRemoteBridges(prepared); + flushChildStderr(childStderrState); + return { + exitCode: 1, + signal: timedOut ? "SIGTERM" : null, + timedOut, + errorMessage: message, + errorCode: timedOut ? "acpx_timeout" : classified.errorCode, + errorMeta: classified.errorMeta, + ...billingFields, + ...referencedProjectStagingFailuresField, + model: prepared.requestedModel || null, + clearSession: clearSession || timedOut, + resultJson: { phase: "turn" }, + summary: message, + }; + } finally { + // End the agent turn span exactly once, on every return and on a throw. + // `runFailed` is `false` only on a completed, non-timed-out turn, so the + // span status is correct for success, error, and timeout. + turnSpan.end(runFailed); + // Reset the current-run holder to the `task.run` token after the turn. + // The run stays live here, so the holder is never `undefined`. A detached + // exec after the turn parents to `task.run`. + currentRunParentContext = runRootSpan.parentContext; + } + } finally { + // End the run root span exactly once, on every return and on a throw. + runRootSpan.end(runFailed); } }; } 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 fa07faff41..1678282143 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.test.ts @@ -6,8 +6,10 @@ import { emitSkippedStartupStep, getActiveStepContext, measureStartupStep, + NOOP_STARTUP_SPAN, normalizeProviderFamily, runWithoutActiveStep, + runWithRuntimeParent, SANDBOX_STARTUP_SPAN_ATTR_PREFIX, SANDBOX_STARTUP_SPAN_ATTRS, setSandboxRootSpanAttributes, @@ -578,6 +580,41 @@ describe("getActiveStepContext", () => { }); }); +describe("runWithRuntimeParent", () => { + it("sets the parent context so inner code parents to the given token", () => { + // The server builds an opaque parent-context token from a run-time span. The + // helper publishes it, so inner code reads it through the getter and parents + // a child span to that token. Model the token as a plain object; the helper + // forwards it opaque. + const token = { span: "runtime-parent" }; + const seen = runWithRuntimeParent(token, () => getActiveStepContext()); + + expect(seen).not.toBeNull(); + // The published parent token is the given token, unchanged. + expect(seen!.parentContext).toBe(token); + // The helper stores the no-op span, not a real step span. + expect(seen!.span).toBe(NOOP_STARTUP_SPAN); + // A run-time exec is not on the startup critical path. + expect(seen!.criticalPath).toBe(false); + // The context clears once the work settles. + expect(getActiveStepContext()).toBeNull(); + }); + + it("empties the store when the token is undefined, like runWithoutActiveStep", () => { + // A missing token means no run-time parent. The helper then empties the + // store, so inner code reads no active step and opens an unparented span. + const seen = runWithRuntimeParent(undefined, () => getActiveStepContext()); + + expect(seen).toBeNull(); + expect(getActiveStepContext()).toBeNull(); + }); + + it("returns the work result", () => { + const value = runWithRuntimeParent({ span: "runtime-parent" }, () => "value"); + expect(value).toBe("value"); + }); +}); + describe("clampSpanLabel", () => { it("returns a known command label unchanged and maps an unknown command to `other`", () => { expect(clampSpanLabel("command", "sh")).toBe("sh"); diff --git a/packages/adapter-utils/src/acpx-engine/startup-timing.ts b/packages/adapter-utils/src/acpx-engine/startup-timing.ts index d13ba73659..f49f3ccfd6 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.ts @@ -364,6 +364,44 @@ export function runWithoutActiveStep(work: () => T): T { return activeStepContextStorage.run(undefined, work); } +/** + * Build the minimal active step context that the store publishes. The step path + * and `runWithRuntimeParent` share this builder, so both write the same shape. + */ +function buildActiveStepContext( + span: StartupSpan, + parentContext: StartupSpanContext, + criticalPath: boolean, +): ActiveStepContext { + return { span, parentContext, criticalPath }; +} + +/** + * Run `work` under a given parent-context token, then restore the previous + * store. A run-time exec that reads `getActiveStepContext()` inside `work` + * parents its span to `parentContext`, not to a startup step. The store carries + * the no-op span, because there is no open step span at run time. It sets + * `criticalPath` to `false`, because a run-time exec is not on the startup + * critical path. + * + * When `parentContext` is `undefined`, the helper empties the store, exactly + * like `runWithoutActiveStep`. Inner code then reads `null` and opens an + * unparented span. + * + * The helper forwards only the opaque token, so this package stays free of + * `@opentelemetry/api`. + */ +export function runWithRuntimeParent( + parentContext: StartupSpanContext, + work: () => T, +): T { + if (parentContext === undefined) { + return activeStepContextStorage.run(undefined, work); + } + const activeStep = buildActiveStepContext(NOOP_SPAN, parentContext, false); + return activeStepContextStorage.run(activeStep, work); +} + /** * 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, @@ -519,11 +557,11 @@ export async function measureStartupStep( } catch { stepChildContext = undefined; } - const activeStep: ActiveStepContext = { + const activeStep = buildActiveStepContext( span, - parentContext: stepChildContext, - criticalPath: options.criticalPath ?? true, - }; + stepChildContext, + options.criticalPath ?? true, + ); let stepFailed = false; try { diff --git a/packages/adapter-utils/src/execution-target-sandbox.test.ts b/packages/adapter-utils/src/execution-target-sandbox.test.ts index 8f939c6540..321e88cb15 100644 --- a/packages/adapter-utils/src/execution-target-sandbox.test.ts +++ b/packages/adapter-utils/src/execution-target-sandbox.test.ts @@ -23,6 +23,7 @@ import { startAdapterExecutionTargetPaperclipBridge, type AdapterSandboxExecutionTarget, } from "./execution-target.js"; +import { getActiveStepContext } from "./acpx-engine/startup-timing.js"; import { createSandboxRunLogTailFactory } from "./sandbox-run-log-stream.js"; import { runChildProcess } from "./server-utils.js"; import { shellQuote } from "./ssh.js"; @@ -248,6 +249,238 @@ describe("sandbox adapter execution targets", () => { } }); + it("test_process_session_poll_exec_parents_to_run_context", async () => { + // The poll timer runs run-time execs for the whole run. Its `sandbox.exec` + // span must parent to the live run span, not to the ended startup step. The + // bridge reads `getRuntimeParentContext` per tick and runs the poll under + // that token. This test drives the bridge with a getter that returns a known + // token, lets the first poll tick fire, and proves the poll exec reads that + // token from the active step store. + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-poll-parent-")); + cleanupDirs.push(rootDir); + const childPath = path.join(rootDir, "noop-acp-child.mjs"); + await writeFile(childPath, "process.stdin.on('data', () => {});\n", "utf8"); + + const runParentToken = { marker: "process-session-run-parent" }; + let bridgeStarted = false; + let pollStep: ReturnType | "unset" = "unset"; + let resolvePoll: () => void = () => {}; + const pollObserved = new Promise((resolve) => { + resolvePoll = resolve; + }); + + const delegate = createLocalSandboxRunner(); + const runner = { + execute: async (input: Parameters[0]) => { + // Record the active step for the first exec that runs after the bridge + // start resolves. The setup execs run during the measured start; the + // poll timer fires later, under the run parent context. + if (bridgeStarted && pollStep === "unset") { + pollStep = getActiveStepContext(); + resolvePoll(); + } + return delegate.execute(input); + }, + }; + const target: AdapterSandboxExecutionTarget = { + kind: "remote", + transport: "sandbox", + providerKey: "local-test", + remoteCwd: rootDir, + timeoutMs: 30_000, + runner, + }; + + const bridge = await startAdapterExecutionTargetProcessSessionBridge({ + runId: "run-process-session-poll-parent", + target, + runtimeRootDir: path.posix.join(rootDir, ".paperclip-runtime", "acpx"), + adapterKey: "acpx", + command: process.execPath, + args: [childPath], + cwd: rootDir, + env: {}, + timeoutSec: 5, + onLog: async () => {}, + getRuntimeParentContext: () => runParentToken, + }); + expect(bridge).not.toBeNull(); + bridgeStarted = true; + + try { + await pollObserved; + // The poll exec ran under the run parent context, so its exec span parents + // to the run token, not to a detached root or an ended startup step. + expect(pollStep).not.toBe("unset"); + expect(pollStep).not.toBeNull(); + expect((pollStep as { parentContext?: unknown }).parentContext).toBe(runParentToken); + expect((pollStep as { criticalPath?: boolean }).criticalPath).toBe(false); + } finally { + await bridge?.stop(); + } + }); + + it("test_process_session_poll_exec_stays_unparented_without_getter", async () => { + // With no `getRuntimeParentContext`, the poll tick runs with an empty active + // step store, exactly like the earlier `runWithoutActiveStep` behavior. So a + // poll `sandbox.exec` span opens unparented with no stale startup flag. + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-poll-nogetter-")); + cleanupDirs.push(rootDir); + const childPath = path.join(rootDir, "noop-acp-child.mjs"); + await writeFile(childPath, "process.stdin.on('data', () => {});\n", "utf8"); + + let bridgeStarted = false; + let pollStep: ReturnType | "unset" = "unset"; + let resolvePoll: () => void = () => {}; + const pollObserved = new Promise((resolve) => { + resolvePoll = resolve; + }); + + const delegate = createLocalSandboxRunner(); + const runner = { + execute: async (input: Parameters[0]) => { + if (bridgeStarted && pollStep === "unset") { + pollStep = getActiveStepContext(); + resolvePoll(); + } + return delegate.execute(input); + }, + }; + const target: AdapterSandboxExecutionTarget = { + kind: "remote", + transport: "sandbox", + providerKey: "local-test", + remoteCwd: rootDir, + timeoutMs: 30_000, + runner, + }; + + const bridge = await startAdapterExecutionTargetProcessSessionBridge({ + runId: "run-process-session-poll-nogetter", + target, + runtimeRootDir: path.posix.join(rootDir, ".paperclip-runtime", "acpx"), + adapterKey: "acpx", + command: process.execPath, + args: [childPath], + cwd: rootDir, + env: {}, + timeoutSec: 5, + onLog: async () => {}, + }); + expect(bridge).not.toBeNull(); + bridgeStarted = true; + + try { + await pollObserved; + expect(pollStep).toBeNull(); + } finally { + await bridge?.stop(); + } + }); + + it("test_process_session_stdin_exec_reads_send_time_run_parent", async () => { + // A persistent socket can open under one run parent and receive stdin later, + // under a different parent. The stdin-write `sandbox.exec` span must parent + // to the parent that is live at send time, not to the parent that was live + // when the socket opened. The bridge reads `getRuntimeParentContext` per + // message in the `data` handler, not once at connect time. This test opens a + // socket while `connectParent` is live, switches the getter to `turnParent`, + // sends one stdin line, and proves the stdin write ran under `turnParent`. + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-stdin-parent-")); + cleanupDirs.push(rootDir); + const childPath = path.join(rootDir, "noop-acp-child.mjs"); + await writeFile(childPath, "process.stdin.on('data', () => {});\n", "utf8"); + + const connectParent = { marker: "process-session-connect-parent" }; + const turnParent = { marker: "process-session-turn-parent" }; + let currentParent: unknown = connectParent; + + let stdinWriteStep: ReturnType | "unset" = "unset"; + let resolveStdinWrite: () => void = () => {}; + const stdinWriteObserved = new Promise((resolve) => { + resolveStdinWrite = resolve; + }); + + const delegate = createLocalSandboxRunner(); + const runner = { + execute: async (input: Parameters[0]) => { + // Record the active step for the first exec that writes the stdin file. + // The `.paperclip-upload` temp path under the `stdin` directory is unique + // to the stdin-write path; the poll loop reads the `events` directory. + const script = (input.args ?? []).join("\n"); + if (stdinWriteStep === "unset" && /\/stdin\/[^\s']*paperclip-upload/.test(script)) { + stdinWriteStep = getActiveStepContext(); + resolveStdinWrite(); + } + return delegate.execute(input); + }, + }; + const target: AdapterSandboxExecutionTarget = { + kind: "remote", + transport: "sandbox", + providerKey: "local-test", + remoteCwd: rootDir, + timeoutMs: 30_000, + runner, + }; + + const bridge = await startAdapterExecutionTargetProcessSessionBridge({ + runId: "run-process-session-stdin-parent", + target, + runtimeRootDir: path.posix.join(rootDir, ".paperclip-runtime", "acpx"), + adapterKey: "acpx", + command: process.execPath, + args: [childPath], + cwd: rootDir, + env: {}, + timeoutSec: 5, + onLog: async () => {}, + getRuntimeParentContext: () => currentParent as never, + }); + expect(bridge).not.toBeNull(); + + let peer: net.Socket | null = null; + try { + const proxySource = await readFile(bridge!.agentCommand, "utf8"); + const port = Number(/port: (\d+)/.exec(proxySource)?.[1] ?? Number.NaN); + const tokenLiteral = /const token = (".*?");/.exec(proxySource)?.[1]; + expect(Number.isFinite(port)).toBe(true); + expect(typeof tokenLiteral).toBe("string"); + const token = JSON.parse(tokenLiteral as string) as string; + + // Open the socket while `connectParent` is the live run parent. + const peerSocket = net.createConnection({ host: "127.0.0.1", port }); + peer = peerSocket; + peerSocket.on("error", () => undefined); + await new Promise((resolve, reject) => { + peerSocket.once("connect", () => resolve()); + peerSocket.once("error", reject); + }); + // Let the server accept the connection and register the `data` handler + // under the connect-time parent before the getter switches. + await new Promise((resolve) => setImmediate(resolve)); + + // The run enters an agent turn: the live run parent switches. + currentParent = turnParent; + + // Send one stdin line. The first token-bearing message authenticates and + // writes the stdin file. That write must read `turnParent` at send time. + peerSocket.write(`${JSON.stringify({ token, type: "stdin", data: Buffer.from("hi").toString("base64") })}\n`); + + await stdinWriteObserved; + // The stdin write ran under the send-time parent, not the connect-time + // parent captured when the socket opened. + expect(stdinWriteStep).not.toBe("unset"); + expect(stdinWriteStep).not.toBeNull(); + expect((stdinWriteStep as { parentContext?: unknown }).parentContext).toBe(turnParent); + expect((stdinWriteStep as { parentContext?: unknown }).parentContext).not.toBe(connectParent); + expect((stdinWriteStep as { criticalPath?: boolean }).criticalPath).toBe(false); + } finally { + peer?.destroy(); + await bridge?.stop(); + } + }); + it("bridges bidirectional sandbox process sessions through a local ACPX-spawnable proxy", async () => { const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-")); cleanupDirs.push(rootDir); diff --git a/packages/adapter-utils/src/execution-target.ts b/packages/adapter-utils/src/execution-target.ts index 2ee9c0f049..0eb776e8cd 100644 --- a/packages/adapter-utils/src/execution-target.ts +++ b/packages/adapter-utils/src/execution-target.ts @@ -46,7 +46,10 @@ import { } from "./server-utils.js"; import { sanitizeRemoteExecutionEnv } from "./remote-execution-env.js"; import { preferredShellForSandbox, shellCommandArgs } from "./sandbox-shell.js"; -import { runWithoutActiveStep } from "./acpx-engine/startup-timing.js"; +import { + runWithRuntimeParent, + type StartupSpanContext, +} from "./acpx-engine/startup-timing.js"; import type { RuntimeProgressSink, RuntimeStatusSink } from "./runtime-progress.js"; import type { LocalProcessSandboxOptions } from "./local-process-sandbox.js"; @@ -1367,6 +1370,12 @@ export async function startAdapterExecutionTargetProcessSessionBridge(input: { env: Record | (() => Promise>); timeoutSec?: number | null; onLog?: (stream: "stdout" | "stderr", chunk: string) => Promise; + // Return the current-run parent-context token. The socket handlers and the + // poll timer read it per unit of work and run under it, so their run-time + // `sandbox.exec` spans parent to the live run span (`agent.turn` during the + // turn, `task.run` otherwise). When it is absent, the work runs with an empty + // store, exactly like the earlier `runWithoutActiveStep` behavior. + getRuntimeParentContext?: () => StartupSpanContext | undefined; }): Promise { if (!input.target || input.target.kind !== "remote" || input.target.transport !== "sandbox") { return null; @@ -1489,10 +1498,14 @@ export async function startAdapterExecutionTargetProcessSessionBridge(input: { }; const liveSockets = new Set(); - // Register the per-connection socket handlers outside the measured bridge step - // store. A stdin write from a socket handler is a run-time exec, not startup - // work, so its `sandbox.exec` span must not parent to the ended bridge step. - const server = net.createServer((nextSocket) => runWithoutActiveStep(() => { + // Register the per-connection socket handlers with no run parent context. + // A stdin write from a socket handler is a run-time exec, not startup work. + // The connection can open under `task.run` and receive stdin later, during an + // `agent.turn`. So the handler must read the current-run parent at send time, + // not at connect time. A connect-time read captures the parent that was live + // when the socket opened, and every later exec span parents to that stale + // parent. The `data` handler below reads the getter per message instead. + const server = net.createServer((nextSocket) => { liveSockets.add(nextSocket); nextSocket.setEncoding("utf8"); nextSocket.on("error", () => undefined); @@ -1535,23 +1548,29 @@ export async function startAdapterExecutionTargetProcessSessionBridge(input: { socket = nextSocket; flushPendingRemoteEvents(); } - void (async () => { - if (message.type === "stdin" && typeof message.data === "string") { - stdinSeq += 1; - const name = `${String(stdinSeq).padStart(12, "0")}.json`; - await client.writeTextFile(path.posix.join(stdinDir, name), jsonLine({ type: "stdin", data: message.data })); - } else if (message.type === "stdinEnd") { - stdinSeq += 1; - const name = `${String(stdinSeq).padStart(12, "0")}.json`; - await client.writeTextFile(path.posix.join(stdinDir, name), jsonLine({ type: "stdinEnd" })); - } - })().catch((error) => { - nextSocket.write(jsonLine({ type: "error", message: error instanceof Error ? error.message : String(error) })); - nextSocket.destroy(); + // Read the current-run parent now, at send time. The live parent + // switches to `agent.turn` during the turn and back to `task.run` + // after it. With no getter the store stays empty, exactly like the + // earlier unparented behavior. + runWithRuntimeParent(input.getRuntimeParentContext?.(), () => { + void (async () => { + if (message.type === "stdin" && typeof message.data === "string") { + stdinSeq += 1; + const name = `${String(stdinSeq).padStart(12, "0")}.json`; + await client.writeTextFile(path.posix.join(stdinDir, name), jsonLine({ type: "stdin", data: message.data })); + } else if (message.type === "stdinEnd") { + stdinSeq += 1; + const name = `${String(stdinSeq).padStart(12, "0")}.json`; + await client.writeTextFile(path.posix.join(stdinDir, name), jsonLine({ type: "stdinEnd" })); + } + })().catch((error) => { + nextSocket.write(jsonLine({ type: "error", message: error instanceof Error ? error.message : String(error) })); + nextSocket.destroy(); + }); }); } }); - })); + }); const poll = async () => { if (stopping) return; @@ -1581,13 +1600,15 @@ export async function startAdapterExecutionTargetProcessSessionBridge(input: { } }; - // Schedule the long-lived poll timer outside the measured bridge step store. + // Schedule the long-lived poll timer under the current-run parent context. // The poll loop reads remote event files with run-time execs, not startup - // work, so a poll `sandbox.exec` span must not parent to the ended bridge step. - // `runWithoutActiveStep` also empties the store for the re-arm timer that the - // poll body schedules, so every later tick stays unparented too. + // work, so a poll `sandbox.exec` span parents to the live run span, not to the + // ended bridge step. Read the getter per tick, because the re-arm timer that + // the poll body schedules reads it again: the live parent switches to + // `agent.turn` during the turn and back to `task.run` after it. With no getter + // the store stays empty, exactly like the earlier unparented behavior. const schedulePoll = () => { - pollTimer = setTimeout(() => runWithoutActiveStep(() => void poll()), 100); + pollTimer = setTimeout(() => runWithRuntimeParent(input.getRuntimeParentContext?.(), () => void poll()), 100); pollTimer.unref?.(); }; @@ -1738,6 +1759,11 @@ export async function startAdapterExecutionTargetPaperclipBridge(input: { hostApiUrl?: string | null; onLog?: (stream: "stdout" | "stderr", chunk: string) => Promise; maxBodyBytes?: number | null; + // Return the current-run parent-context token. The factory threads it into the + // callback bridge worker, which reads it per request so each request + // `sandbox.exec` span parents to the live run span. When it is absent, the + // request work runs with an empty store, exactly like the earlier behavior. + getRuntimeParentContext?: () => StartupSpanContext | undefined; }): Promise { if (!adapterExecutionTargetUsesPaperclipBridge(input.target)) { return null; @@ -1800,14 +1826,15 @@ export async function startAdapterExecutionTargetPaperclipBridge(input: { // environments. const bridgeDebugEnabled = isBridgeDebugEnabled(process.env); // `startSandboxCallbackBridgeWorker` keeps its awaited queue-directory - // setup on the active `bridge.paperclip` step, and resets the store only - // for its long-lived poll loop (see `runWithoutActiveStep` inside that - // function). So the startup `mkdir` execs stay parented and every later - // loop `sandbox.exec` span stays unparented with no stale `criticalPath`. + // setup on the active `bridge.paperclip` step, and runs each request under + // the run parent context (see `runWithRuntimeParent` inside that function). + // So the startup `mkdir` execs stay parented to the step, and every later + // request `sandbox.exec` span parents to the live run span. worker = await startSandboxCallbackBridgeWorker({ client, queueDir, maxBodyBytes, + getRuntimeParentContext: input.getRuntimeParentContext, handleRequest: async (request) => { const method = request.method.trim().toUpperCase() || "GET"; if (bridgeDebugEnabled) { diff --git a/packages/adapter-utils/src/sandbox-callback-bridge.test.ts b/packages/adapter-utils/src/sandbox-callback-bridge.test.ts index 5bd5f0626e..85a361f431 100644 --- a/packages/adapter-utils/src/sandbox-callback-bridge.test.ts +++ b/packages/adapter-utils/src/sandbox-callback-bridge.test.ts @@ -539,6 +539,127 @@ describe("sandbox callback bridge", () => { expect(loopStep).toBeNull(); }); + it("test_paperclip_loop_exec_parents_to_run_context", async () => { + // The worker starts inside the measured `bridge.paperclip` step. Its awaited + // queue-directory setup is startup work and keeps the active step. The poll + // loop shell stays outside that store. But a per-request unit of work is + // run-time work, so the worker runs each request under the current-run + // parent context. A request `sandbox.exec` span then parents to the live run + // span, not to the ended startup step. This test drives the worker with a + // `getRuntimeParentContext` that returns a known token, queues one request, + // and proves the request work reads that token from the active step store. + const runParentToken = { marker: "run-parent-token" }; + let setupStep: ReturnType | "unset" = "unset"; + let requestStep: ReturnType | "unset" = "unset"; + let served = false; + let resolveServed: () => void = () => {}; + const requestServed = new Promise((resolve) => { + resolveServed = resolve; + }); + + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-bridge-run-parent-")); + cleanupDirs.push(rootDir); + const queueDir = path.posix.join(rootDir, "queue"); + + const worker = await measureStartupStep( + {}, + () => 0, + "bridge.paperclip", + () => + startSandboxCallbackBridgeWorker({ + client: { + makeDir: async () => { + setupStep = getActiveStepContext(); + }, + makeDirs: async () => { + setupStep = getActiveStepContext(); + }, + // Return one request on the first poll, then nothing. + listJsonFiles: async () => (served ? [] : ["000000000001.json"]), + readTextFile: async () => + JSON.stringify({ id: "req-1", method: "GET", path: "/", query: "", headers: {}, body: "" }), + writeTextFile: async () => {}, + rename: async () => {}, + remove: async () => {}, + }, + queueDir, + authorizeRequest: async () => null, + handleRequest: async () => { + requestStep = getActiveStepContext(); + served = true; + resolveServed(); + return { status: 200, body: "ok" }; + }, + getRuntimeParentContext: () => runParentToken, + }), + { criticalPath: false }, + ); + + await requestServed; + await worker.stop(); + + // The setup ran on the active step, so its exec span parents to the step. + expect(setupStep).not.toBe("unset"); + expect(setupStep).not.toBeNull(); + + // The request work ran under the run parent context. Its exec span parents + // to the run token, not to the ended startup step, and it carries no + // startup `criticalPath` flag. + expect(requestStep).not.toBe("unset"); + expect(requestStep).not.toBeNull(); + expect((requestStep as { parentContext?: unknown }).parentContext).toBe(runParentToken); + expect((requestStep as { criticalPath?: boolean }).criticalPath).toBe(false); + }); + + it("test_paperclip_loop_exec_stays_unparented_without_getter", async () => { + // With no `getRuntimeParentContext`, a request runs with an empty active + // step store, exactly like the earlier `runWithoutActiveStep` behavior. So a + // request `sandbox.exec` span opens unparented with no stale startup flag. + let requestStep: ReturnType | "unset" = "unset"; + let served = false; + let resolveServed: () => void = () => {}; + const requestServed = new Promise((resolve) => { + resolveServed = resolve; + }); + + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-bridge-no-getter-")); + cleanupDirs.push(rootDir); + const queueDir = path.posix.join(rootDir, "queue"); + + const worker = await measureStartupStep( + {}, + () => 0, + "bridge.paperclip", + () => + startSandboxCallbackBridgeWorker({ + client: { + makeDir: async () => {}, + makeDirs: async () => {}, + listJsonFiles: async () => (served ? [] : ["000000000001.json"]), + readTextFile: async () => + JSON.stringify({ id: "req-1", method: "GET", path: "/", query: "", headers: {}, body: "" }), + writeTextFile: async () => {}, + rename: async () => {}, + remove: async () => {}, + }, + queueDir, + authorizeRequest: async () => null, + handleRequest: async () => { + requestStep = getActiveStepContext(); + served = true; + resolveServed(); + return { status: 200, body: "ok" }; + }, + }), + { criticalPath: false }, + ); + + await requestServed; + await worker.stop(); + + expect(requestStep).toBeNull(); + }); + it("serializes remote response writes so stop does not recreate a late orphaned response", async () => { const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-bridge-response-lock-")); cleanupDirs.push(rootDir); diff --git a/packages/adapter-utils/src/sandbox-callback-bridge.ts b/packages/adapter-utils/src/sandbox-callback-bridge.ts index 3014f1ed6d..48f64211d7 100644 --- a/packages/adapter-utils/src/sandbox-callback-bridge.ts +++ b/packages/adapter-utils/src/sandbox-callback-bridge.ts @@ -3,7 +3,11 @@ import { promises as fs } from "node:fs"; import os from "node:os"; import path from "node:path"; -import { runWithoutActiveStep } from "./acpx-engine/startup-timing.js"; +import { + runWithoutActiveStep, + runWithRuntimeParent, + type StartupSpanContext, +} from "./acpx-engine/startup-timing.js"; import type { CommandManagedRuntimeRunner } from "./command-managed-runtime.js"; import { preferredShellForSandbox, shellCommandArgs } from "./sandbox-shell.js"; import type { RunProcessResult } from "./server-utils.js"; @@ -620,6 +624,12 @@ export async function startSandboxCallbackBridgeWorker(input: { body?: string; }>; maxBodyBytes?: number | null; + // Return the current-run parent-context token. The worker reads it per request + // and runs the request work under it, so the request `sandbox.exec` span + // parents to the live run span (`agent.turn` during the turn, `task.run` + // otherwise). When it is absent, the request work runs with an empty store, + // exactly like the earlier `runWithoutActiveStep` behavior. + getRuntimeParentContext?: () => StartupSpanContext | undefined; }): Promise { const pollIntervalMs = normalizeTimeoutMs(input.pollIntervalMs, DEFAULT_BRIDGE_POLL_INTERVAL_MS); const maxBodyBytes = normalizeTimeoutMs(input.maxBodyBytes, DEFAULT_BRIDGE_MAX_BODY_BYTES); @@ -767,7 +777,15 @@ export async function startSandboxCallbackBridgeWorker(input: { if (stopping && Date.now() >= stopDeadline) break; inFlight += 1; try { - await processRequestFile(fileName); + // A request is run-time work, not startup work. Read the run parent + // context now and run the request under it, so the request + // `sandbox.exec` span parents to the live run span. Read the getter + // per request: the live parent switches to `agent.turn` during the + // turn and back to `task.run` after it. With no getter the store + // stays empty, exactly like the earlier unparented behavior. + await runWithRuntimeParent(input.getRuntimeParentContext?.(), () => + processRequestFile(fileName), + ); } finally { inFlight -= 1; } diff --git a/server/src/__tests__/environment-execution-target.test.ts b/server/src/__tests__/environment-execution-target.test.ts index c49557dc71..558621fb9a 100644 --- a/server/src/__tests__/environment-execution-target.test.ts +++ b/server/src/__tests__/environment-execution-target.test.ts @@ -59,6 +59,42 @@ function createRecordingTrace() { return { tracer, contextWithSpan, spans }; } +// A fake tracer that records the third `startSpan` argument — the parent-context +// token — for each span, keyed by the span name. `contextWithSpan` wraps a span +// in a token and keeps that token, so a test asserts the exact token identity, +// not a rebuilt copy. The exec seam reads the parent-context token from the +// active step store and passes it as the third `startSpan` argument. This helper +// holds the parent assertion in one place for reuse. +function recordParentContext() { + const calls: Array<{ name: string; parentContext: unknown; span: unknown }> = []; + const tokens = new Map(); + const tracer = { + startSpan(name: string, _options?: unknown, parentContext?: unknown) { + const span = { + name, + setAttribute(_key: string, _value: unknown) {}, + setStatus(_status: { code: number; message?: string }) {}, + end() {}, + }; + calls.push({ name, parentContext, span }); + return span; + }, + }; + const contextWithSpan = (span: unknown) => { + const token = { span }; + tokens.set(span, token); + return token; + }; + // The span object recorded for a given span name. + const spanNamed = (name: string) => calls.find((call) => call.name === name)?.span; + // The parent-context token that `startSpan` received for a given span name. + const parentContextFor = (name: string) => + calls.find((call) => call.name === name)?.parentContext; + // The parent-context token that `contextWithSpan` returned for a given span. + const tokenForSpan = (span: unknown) => tokens.get(span); + return { tracer, contextWithSpan, calls, spanNamed, parentContextFor, tokenForSpan }; +} + describe("resolveEnvironmentExecutionTarget", () => { beforeEach(() => { mockResolveEnvironmentDriverConfigForRuntime.mockReset(); @@ -756,6 +792,68 @@ describe("resolveEnvironmentExecutionTarget", () => { expect(execSpan!.parent).toBeNull(); }); + // The three baseline tests below record the third `startSpan` argument — the + // parent-context token — and assert its identity. They pin the current exec + // parenting so a later phase that re-points the exec parent has a fixed + // reference point. + it("test_exec_inside_measured_step_parents_to_step_context", async () => { + const rec = recordParentContext(); + const runner = await runnerFor({ + provider: "daytona", + execResult: { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" }, + tracer: rec.tracer, + }); + + // Run the seam `execute` inside one measured step. The step publishes its + // child context to the active step store, so the seam reads it and passes it + // as the third `startSpan` argument for the exec span. + await measureStartupStep({}, () => 0, "stage.sync", () => runner.execute({ command: "echo" }), { + tracer: rec.tracer, + contextWithSpan: rec.contextWithSpan, + }); + + const stepSpan = rec.spanNamed("stage.sync"); + expect(stepSpan).toBeTruthy(); + // The exec span parents to the step span. The third `startSpan` argument is + // the exact parent-context token that `contextWithSpan` built for the step + // span, not a rebuilt copy. + expect(rec.parentContextFor("sandbox.exec")).toBe(rec.tokenForSpan(stepSpan)); + }); + + it("test_exec_in_root_region_is_unparented_today", async () => { + const rec = recordParentContext(); + const runner = await runnerFor({ + provider: "daytona", + execResult: { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" }, + tracer: rec.tracer, + }); + + // No measured step wraps the exec, so the active step store is empty. The + // seam reads no parent and passes `undefined` as the third `startSpan` + // argument. The exec span opens unparented today. + await runner.execute({ command: "echo" }); + + expect(rec.spanNamed("sandbox.exec")).toBeTruthy(); + expect(rec.parentContextFor("sandbox.exec")).toBeUndefined(); + }); + + it("test_exec_on_runWithoutActiveStep_is_unparented_today", async () => { + const rec = recordParentContext(); + const runner = await runnerFor({ + provider: "daytona", + execResult: { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" }, + tracer: rec.tracer, + }); + + // `runWithoutActiveStep` empties the active step store for the wrapped work. + // The seam reads no parent and passes `undefined` as the third `startSpan` + // argument. The exec span opens unparented today. + await runWithoutActiveStep(() => runner.execute({ command: "echo" })); + + expect(rec.spanNamed("sandbox.exec")).toBeTruthy(); + expect(rec.parentContextFor("sandbox.exec")).toBeUndefined(); + }); + 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