From 04bf7a6ab595913dc42ed543db4013d449f0c2a7 Mon Sep 17 00:00:00 2001 From: Nicky Leach Date: Wed, 12 Aug 2026 16:06:05 -0700 Subject: [PATCH] feat(observability): instrument stage.sync host steps and home the agent process span (#11301) ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work. > - It runs each agent in a remote sandbox and emits OpenTelemetry spans for the sandbox bring-up and the run. > - A real trace showed two gaps. `stage.sync` had about 3 seconds of unattributed host work before its `pack` span. The persistent agent process showed a `sandbox.exec` span that outlived its parent by about 50 seconds. > - The gaps hide real cost and make the trace read as a sequencing bug, so an operator cannot see where startup time goes. > - This pull request wraps the two pre-`pack` host steps in their own spans. It also homes the long-lived process in a run-scoped `sandbox.agentProcess` span. > - The benefit is that startup time is fully attributed and the process reads as a resource that overlaps the turn, not a child that outlives its parent. ## Linked Issues or Issue Description No public issue exists. This is an enhancement to existing telemetry. It is described inline below, following `.github/ISSUE_TEMPLATE/enhancement.yml`. Prior related work: the merged PR #10999 added the run-time wrapper spans and the telemetry data-contract section this PR extends. **What existing behavior does this improve?** The sandbox bring-up and run OpenTelemetry trace. It closes two attribution gaps in that trace. **Subsystem affected** Observability for sandbox execution. The code lives in `packages/adapter-utils`. The span contract lives in `packages/shared/src/telemetry`. **Current behavior** `stage.sync` opens a `pack` span, but the git enumeration and the baseline content-hash walk that run before `pack` have no span, so about 3 seconds read as a gap. On the streamed process-session path the agent process launches fire-and-forget inside the ~2.3 second `bridge.process-session` bring-up step, so its `sandbox.exec` span parents to that step and then runs about 50 seconds. The child dangles past its parent and overlaps `agent.turn`. **Proposed behavior** Wrap the two pre-`pack` host operations in `snapshot.git` and `snapshot.baseline` spans under `stage.sync`. Wrap the streamed launch in a run-scoped `sandbox.agentProcess` span that parents to the live run root (`task.run` at launch). **Reason and benefit** Startup time is fully attributed. The long-lived process reads as a resource that overlaps the sibling `agent.turn`, not a mis-parented child. **Breaking changes** None. The spans are opt-in and export only when an OTLP endpoint is configured. The span seam is a no-op when no runner is injected. No first-party telemetry event changes. ## What Changed - `sandbox-managed-runtime.ts`: add `snapshot.git` and `snapshot.baseline` spans around the git enumeration and the baseline content-hash walk, nested under `stage.sync`, through a shared `runStepSpan` helper that `pack` now also uses. - `execution-target.ts`: wrap the fire-and-forget streamed launch in a run-rooted `sandbox.agentProcess` span, so it parents to the live run root and holds the inner `sandbox.exec`. The `.then`/`.catch` chain became try/catch inside the span callback, with identical frame-ingestion behavior. - `packages/shared/src/telemetry/README.md`: update the span table and the parenting prose. Add `snapshot.git`, `snapshot.baseline`, `pack`, and `sandbox.agentProcess`, and document the intended `sandbox.agentProcess` / `agent.turn` overlap. - Tests: update the executor span-tree test (`childNames` and parent assertions), update the `sandbox-managed-runtime` span-set and nesting tests, and add two `execution-target-sandbox` tests (the launch opens `sandbox.agentProcess`; it parents to the run root, not the bring-up step). ## Verification - Run `npx vitest run` on the three affected test files. Result: 174 tests pass. This includes the updated executor span-tree test and the new `sandbox.agentProcess` open and parenting tests. - Run `tsc --noEmit` in `packages/adapter-utils`. Result: no errors in the changed source or test files. - The full 37-test streamed process-session suite passes unchanged. This confirms the try/catch restructure preserves frame delivery and exit/error behavior. - Pre-existing and unrelated to this PR (present on `master`): `tsc` errors in `execute.ts` / `execute.test.ts` / `remote-spawn-smoke.test.ts` (`onAgentStderr` / `spawnCwd`), and a `check:forbidden-tokens` failure from internal `PAP-###` ids in `ui/src/components/IssueRecoveryActionCard.test.tsx`. This PR does not touch those files, and its own diff is token-clean. ## Risks Low. The change adds instrumentation on the opt-in span path and does not change control flow on the default path. The one production restructure is the streamed launch, which stays fire-and-forget, so bring-up does not block on it. Only the streamed path gains `sandbox.agentProcess`; the legacy poll path launches the process detached and has no host-side long-lived span to home. ## Model Used Anthropic Claude Opus 4.8 (`claude-opus-4-8`), about 200K-token context, agentic tool use through Claude Code. The trace was reviewed through the Honeycomb MCP. The code was written and tested with the model. ## 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 - [x] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge --------- Co-authored-by: Claude Opus 4.8 --- .../src/acpx-engine/execute.test.ts | 25 +- .../src/execution-target-sandbox.test.ts | 225 +++++++++++++++++- .../adapter-utils/src/execution-target.ts | 96 +++++--- .../src/sandbox-managed-runtime.test.ts | 16 +- .../src/sandbox-managed-runtime.ts | 30 ++- packages/shared/src/telemetry/README.md | 28 ++- 6 files changed, 368 insertions(+), 52 deletions(-) diff --git a/packages/adapter-utils/src/acpx-engine/execute.test.ts b/packages/adapter-utils/src/acpx-engine/execute.test.ts index 242ca77995..d2786120d1 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.test.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.test.ts @@ -3272,8 +3272,10 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = // A codex bring-up over the remote sandbox lane crosses all 7 boundaries. // Each boundary span parents to the sandbox bring-up span, not to the run - // root or the turn span. The `stage.sync` step also opens one host `pack` - // span around the workspace tarball build, so it nests one level deeper. + // root or the turn span. The `stage.sync` step also opens three host + // sub-step spans — `snapshot.git`, `snapshot.baseline`, and `pack` — around + // its git enumeration, baseline content-hash walk, and workspace tarball + // build, so those nest one level deeper. const childNames = spans .filter((span) => span !== runRootSpan && span !== startupSpan && span !== turnSpan) .map((span) => span.name) @@ -3286,26 +3288,35 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () = "codex-home.seed", "pack", "skills.reconcile", + "snapshot.baseline", + "snapshot.git", "stage.sync", "workspace.resolve", ], ); - // The host `pack` span nests under the `stage.sync` step span (the host - // tarball build runs inside that step), not directly under the bring-up - // span. + // The three host sub-step spans nest under the `stage.sync` step span (that + // host work runs inside the step), not directly under the bring-up span. const stageSyncSpan = spans.find((span) => span.name === "stage.sync"); const packSpan = spans.find((span) => span.name === "pack"); + const snapshotGitSpan = spans.find((span) => span.name === "snapshot.git"); + const snapshotBaselineSpan = spans.find((span) => span.name === "snapshot.baseline"); expect(stageSyncSpan).toBeTruthy(); expect(packSpan).toBeTruthy(); + expect(snapshotGitSpan).toBeTruthy(); + expect(snapshotBaselineSpan).toBeTruthy(); expect(packSpan!.parent).toBe(stageSyncSpan); + expect(snapshotGitSpan!.parent).toBe(stageSyncSpan); + expect(snapshotBaselineSpan!.parent).toBe(stageSyncSpan); expect(packSpan!.ended).toBe(true); // Every boundary step span parents to the sandbox bring-up span and ends. - // The `pack` span is the one exception: it parents to `stage.sync` above. + // The three `stage.sync` sub-step spans are the exceptions: they parent to + // `stage.sync` above. + const stageSyncChildren = new Set([packSpan, snapshotGitSpan, snapshotBaselineSpan]); for (const span of spans) { if (span === runRootSpan || span === startupSpan || span === turnSpan) continue; - if (span === packSpan) continue; + if (stageSyncChildren.has(span)) 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); } diff --git a/packages/adapter-utils/src/execution-target-sandbox.test.ts b/packages/adapter-utils/src/execution-target-sandbox.test.ts index db7eeeda20..e6e4dc69a5 100644 --- a/packages/adapter-utils/src/execution-target-sandbox.test.ts +++ b/packages/adapter-utils/src/execution-target-sandbox.test.ts @@ -23,13 +23,55 @@ import { startAdapterExecutionTargetPaperclipBridge, type AdapterSandboxExecutionTarget, } from "./execution-target.js"; -import { getActiveStepContext } from "./acpx-engine/startup-timing.js"; +import { + createRuntimeSpanRunner, + getActiveStepContext, + type StartupSpan, + type StartupTraceContext, + type StartupTracer, +} 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"; const execFileAsync = promisify(execFile); +type RecordedSpan = { name: string; parentName: string | null; ended: boolean }; + +/** + * A structural tracer that records each opened span's name, parent, and end + * state, so a test can assert the trace shape a runtime span runner produces. + * Mirrors the recorder used for the `pack`/`stage.sync` nesting tests. + */ +function createRecordingTraceContext(): { + traceContext: StartupTraceContext; + spans: RecordedSpan[]; +} { + const spans: RecordedSpan[] = []; + const byHandle = new WeakMap(); + const tracer: StartupTracer = { + startSpan(name, _options, context) { + const parent = context as RecordedSpan | undefined; + const record: RecordedSpan = { name, parentName: parent?.name ?? null, ended: false }; + spans.push(record); + const handle: StartupSpan = { + setAttribute() {}, + setStatus() {}, + end() { + record.ended = true; + }, + }; + byHandle.set(handle, record); + return handle; + }, + }; + const traceContext: StartupTraceContext = { + tracer, + contextWithSpan: (span) => byHandle.get(span), + }; + return { traceContext, spans }; +} + describe("sandbox adapter execution targets", () => { const cleanupDirs: string[] = []; @@ -950,6 +992,187 @@ describe("sandbox adapter execution targets", () => { } }); + it("wraps the long-lived streamed launch in a sandbox.agentProcess span", async () => { + // The streamed launch is fire-and-forget and lives for the whole run, so + // its span must open under the live run root (not the ephemeral bring-up + // step) and stay open around the launch. Record the opened span names and + // prove `sandbox.agentProcess` is among them, and that a normal exchange + // still works through the wrap. + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-stream-span-")); + cleanupDirs.push(rootDir); + const childPath = path.join(rootDir, "echo-acp-child.mjs"); + await writeFile( + childPath, + [ + "process.stdin.on('data', (chunk) => {", + " process.stdout.write('out:' + chunk.toString());", + "});", + ].join("\n"), + "utf8", + ); + const target: AdapterSandboxExecutionTarget = { + kind: "remote", + transport: "sandbox", + providerKey: "local-test", + remoteCwd: rootDir, + timeoutMs: 30_000, + runner: createLocalSandboxRunner(), + }; + + const spanNames: string[] = []; + const bridge = await startAdapterExecutionTargetProcessSessionBridge({ + runId: "run-stream-span", + target, + runtimeRootDir: path.posix.join(rootDir, ".paperclip-runtime", "acpx"), + adapterKey: "acpx", + command: process.execPath, + args: [childPath], + cwd: rootDir, + env: {}, + timeoutSec: 5, + onLog: async () => {}, + streamOutputViaSession: true, + // Record each wrapper span name, then run the wrapped work. + runtimeSpan: async (name, work) => { + spanNames.push(name); + return work(); + }, + }); + expect(bridge).not.toBeNull(); + + try { + // The launch span opens synchronously as the bridge starts, before any + // frame flows, so it is observable as soon as the handle resolves. + expect(spanNames).toContain("sandbox.agentProcess"); + const result = await runProxyWithInput(bridge!.agentCommand, "hello\n"); + expect(result.code).toBe(0); + expect(result.stdout).toBe("out:hello\n"); + } finally { + await bridge?.stop(); + } + }); + + it("parents the sandbox.agentProcess span to the live run root, not the bring-up step", async () => { + // The launch runs for the whole run, so its span must parent to the live + // run root (here a stand-in `task.run`) rather than the ephemeral + // `bridge.process-session` bring-up step — otherwise it dangles past its + // parent and overlaps `agent.turn`. Build the real run-rooted runner from a + // recording trace context and assert the recorded parent. + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-stream-parent-")); + cleanupDirs.push(rootDir); + const childPath = path.join(rootDir, "noop-acp-child.mjs"); + await writeFile(childPath, "process.stdin.on('data', () => {});\n", "utf8"); + const target: AdapterSandboxExecutionTarget = { + kind: "remote", + transport: "sandbox", + providerKey: "local-test", + remoteCwd: rootDir, + timeoutMs: 30_000, + runner: createLocalSandboxRunner(), + }; + + const { traceContext, spans } = createRecordingTraceContext(); + // The run root stands in for `task.run` — the parent the run-rooted runner + // resolves at launch time, since no turn has started yet. + const runRoot = traceContext.tracer.startSpan("task.run", undefined, undefined); + const runRootContext = traceContext.contextWithSpan(runRoot); + const runtimeSpan = createRuntimeSpanRunner(traceContext, () => runRootContext); + + const bridge = await startAdapterExecutionTargetProcessSessionBridge({ + runId: "run-stream-parent", + target, + runtimeRootDir: path.posix.join(rootDir, ".paperclip-runtime", "acpx"), + adapterKey: "acpx", + command: process.execPath, + args: [childPath], + cwd: rootDir, + env: {}, + timeoutSec: 5, + onLog: async () => {}, + streamOutputViaSession: true, + runtimeSpan, + }); + expect(bridge).not.toBeNull(); + + try { + const agentProcess = spans.find((span) => span.name === "sandbox.agentProcess"); + expect(agentProcess).toBeDefined(); + expect(agentProcess!.parentName).toBe("task.run"); + } finally { + await bridge?.stop(); + } + }); + + it("ends the sandbox.agentProcess span at stop() even when the process lingers", async () => { + // The span must not outlive the run root. When the remote process lingers + // past bridge teardown (`execute` has no cancel), the span still has to end + // at `stop()`, which the caller awaits before it ends `task.run`. Use a + // child that ignores stdin and never exits on its own, so the launch + // command stays pending across `stop()`, and prove the span ends anyway. + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-stream-linger-")); + cleanupDirs.push(rootDir); + const childPath = path.join(rootDir, "linger-acp-child.mjs"); + await writeFile( + childPath, + [ + "process.stdin.on('data', () => {});", + // Stay alive well past the assertions, then self-exit so the test + // leaves no lingering process. + "setTimeout(() => process.exit(0), 3000);", + ].join("\n"), + "utf8", + ); + const target: AdapterSandboxExecutionTarget = { + kind: "remote", + transport: "sandbox", + providerKey: "local-test", + remoteCwd: rootDir, + timeoutMs: 30_000, + runner: createLocalSandboxRunner(), + }; + + // Track when each wrapper span's work settles (i.e. when its span ends). + const spanRecords: Array<{ name: string; ended: boolean }> = []; + const bridge = await startAdapterExecutionTargetProcessSessionBridge({ + runId: "run-stream-linger", + target, + runtimeRootDir: path.posix.join(rootDir, ".paperclip-runtime", "acpx"), + adapterKey: "acpx", + command: process.execPath, + args: [childPath], + cwd: rootDir, + env: {}, + timeoutSec: 10, + onLog: async () => {}, + streamOutputViaSession: true, + runtimeSpan: (name, work) => { + const record = { name, ended: false }; + spanRecords.push(record); + const promise = work(); + void promise.then( + () => { + record.ended = true; + }, + () => { + record.ended = true; + }, + ); + return promise; + }, + }); + expect(bridge).not.toBeNull(); + + const record = spanRecords.find((span) => span.name === "sandbox.agentProcess"); + expect(record).toBeDefined(); + // The launch command is still running, so the span is still open. + expect(record!.ended).toBe(false); + + // Teardown ends the span promptly, without waiting for the lingering command. + await bridge!.stop(); + await new Promise((resolve) => setTimeout(resolve, 50)); + expect(record!.ended).toBe(true); + }); + it("buffers streamed output until the local proxy connects", async () => { const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-process-session-stream-buffer-")); cleanupDirs.push(rootDir); diff --git a/packages/adapter-utils/src/execution-target.ts b/packages/adapter-utils/src/execution-target.ts index 614131cd0c..fd4a158651 100644 --- a/packages/adapter-utils/src/execution-target.ts +++ b/packages/adapter-utils/src/execution-target.ts @@ -1514,6 +1514,13 @@ export async function startAdapterExecutionTargetProcessSessionBridge(input: { let socket: net.Socket | null = null; let stopping = false; + // Resolves when `stop()` tears the bridge down. The streamed `sandbox.agentProcess` + // span races its work against this, so the span ends at teardown at the latest + // even when the remote process lingers, and never outlives the run root span. + let signalStopped: () => void = () => {}; + const stopped = new Promise((resolve) => { + signalStopped = resolve; + }); let stdinSeq = 0; let pollTimer: NodeJS.Timeout | null = null; const pendingRemoteEvents: Array<{ @@ -1742,39 +1749,63 @@ export async function startAdapterExecutionTargetProcessSessionBridge(input: { // persistent session so the provider streams the wrapper stdout back through // `onLog`. On resolve, the terminal re-parse fills any frames the live stream // missed; on reject, deliver one error frame so the local proxy fails loud. - void runner - .execute({ - command: shellCommand, - args: shellCommandArgs(`node ${shellQuote(remoteScriptPath)}`), - cwd: target.remoteCwd, - env: { - PAPERCLIP_PROCESS_SESSION_DIR: sessionDir, - PAPERCLIP_PROCESS_SESSION_COMMAND_B64: streamCommandPayload, - PAPERCLIP_SANDBOX_EXEC_CHANNEL: "bridge", - }, - timeoutMs, - useSession: true, - onLog: async (stream, chunk) => { - if (stream === "stdout") ingestStreamChunk(chunk); - }, - }) - .then((result) => { - ingestFinalText(result.stdout); - if (!sawTerminal && !stopping) { - deliverRemoteEvent({ - type: "exit", - code: typeof result.exitCode === "number" ? result.exitCode : null, + // + // Wrap the launch in a `sandbox.agentProcess` span. `runRuntimeWork` parents + // it to the LIVE RUN root (`task.run` at launch time — no turn has started + // yet), not to the ephemeral `bridge.process-session` bring-up step, and it + // stays open for the whole process lifetime. The inner `sandbox.exec` nests + // under it. Without the wrapper the raw exec's span inherits the ~2.28s + // bring-up step as its parent and then dangles ~50s past it, overlapping + // `agent.turn` — a child outliving its parent. As a run-scoped span it reads + // instead as a resource that OVERLAPS the sibling `agent.turn`, which is the + // correct shape (the persistent process hosts the turn; it is not a child of + // it, and on multi-turn runs one process spans several turns). `runRuntimeWork` + // is voided, not awaited, so bring-up never blocks on the long-lived command, + // and it defaults to a no-op parent when no span runner is injected. + // + // The span is bounded to the bridge lifecycle: it ends when the command + // settles OR when `stop()` runs, whichever comes first. `stop()` runs during + // run teardown, before the caller ends the `task.run` root span, so the span + // never outlives the run root even if the remote process lingers past + // teardown (`execute` has no cancel, so a lingering process cannot be forced + // to resolve). The command promise keeps running after the span ends so its + // frame handlers still deliver; they no-op once `stopping` is set. + void runRuntimeWork("sandbox.agentProcess", async () => { + const commandSettled = (async () => { + try { + const result = await runner.execute({ + command: shellCommand, + args: shellCommandArgs(`node ${shellQuote(remoteScriptPath)}`), + cwd: target.remoteCwd, + env: { + PAPERCLIP_PROCESS_SESSION_DIR: sessionDir, + PAPERCLIP_PROCESS_SESSION_COMMAND_B64: streamCommandPayload, + PAPERCLIP_SANDBOX_EXEC_CHANNEL: "bridge", + }, + timeoutMs, + useSession: true, + onLog: async (stream, chunk) => { + if (stream === "stdout") ingestStreamChunk(chunk); + }, }); + ingestFinalText(result.stdout); + if (!sawTerminal && !stopping) { + deliverRemoteEvent({ + type: "exit", + code: typeof result.exitCode === "number" ? result.exitCode : null, + }); + } + } catch (error) { + if (!stopping) { + deliverRemoteEvent({ + type: "error", + message: error instanceof Error ? error.message : String(error), + }); + } } - }) - .catch((error) => { - if (!stopping) { - deliverRemoteEvent({ - type: "error", - message: error instanceof Error ? error.message : String(error), - }); - } - }); + })(); + await Promise.race([commandSettled, stopped]); + }); } else { schedulePoll(); } @@ -1783,6 +1814,9 @@ export async function startAdapterExecutionTargetProcessSessionBridge(input: { agentCommand, stop: async () => { stopping = true; + // End the `sandbox.agentProcess` span now, before the caller ends the run + // root span, even if the remote command has not resolved yet. + signalStopped(); if (pollTimer) clearTimeout(pollTimer); for (const liveSocket of liveSockets) liveSocket.destroy(); await new Promise((resolve) => server.close(() => resolve())).catch(() => undefined); diff --git a/packages/adapter-utils/src/sandbox-managed-runtime.test.ts b/packages/adapter-utils/src/sandbox-managed-runtime.test.ts index 52c3cb65db..e736385609 100644 --- a/packages/adapter-utils/src/sandbox-managed-runtime.test.ts +++ b/packages/adapter-utils/src/sandbox-managed-runtime.test.ts @@ -2029,8 +2029,9 @@ describe("sandbox managed runtime", () => { await writeFile(path.join(localWorkspaceDir, "README.md"), "workspace body\n", "utf8"); // Record every span name the runner opens and run the wrapped work, so the - // test proves the host opens exactly one `pack` span around the tarball - // build for the usual (plain) workspace sync. + // test proves the host opens a span around each host-side staging sub-step + // for the usual (plain) workspace sync: the git enumeration, the baseline + // content-hash walk, and the tarball build, in that order. const openedSpans: string[] = []; const runtimeSpan: RuntimeSpanRunner = async (name, work) => { openedSpans.push(name); @@ -2052,7 +2053,7 @@ describe("sandbox managed runtime", () => { runtimeSpan, }); - expect(openedSpans).toEqual(["pack"]); + expect(openedSpans).toEqual(["snapshot.git", "snapshot.baseline", "pack"]); // The tarball build still lands the workspace inside the span, so the wrap // changes no staging behavior. await expect(readFile(path.join(remoteWorkspaceDir, "README.md"), "utf8")).resolves.toBe("workspace body\n"); @@ -2120,5 +2121,14 @@ describe("sandbox managed runtime", () => { // The `pack` span parents to `stage.sync`, not to the root span, so it nests // under the step in a real trace. expect(packSpan!.parentName).toBe("stage.sync"); + + // The two pre-`pack` staging sub-steps nest under `stage.sync` the same way, + // so the previously hidden gap at the head of the step is now attributed. + for (const name of ["snapshot.git", "snapshot.baseline"]) { + const span = spans.find((candidate) => candidate.name === name); + expect(span, name).toBeDefined(); + expect(span!.ended).toBe(true); + expect(span!.parentName).toBe("stage.sync"); + } }); }); diff --git a/packages/adapter-utils/src/sandbox-managed-runtime.ts b/packages/adapter-utils/src/sandbox-managed-runtime.ts index 4169ced4a7..3ded18487b 100644 --- a/packages/adapter-utils/src/sandbox-managed-runtime.ts +++ b/packages/adapter-utils/src/sandbox-managed-runtime.ts @@ -714,7 +714,23 @@ export async function prepareSandboxManagedRuntime(input: { const workspaceRemoteDir = input.workspaceRemoteDir ?? input.spec.remoteCwd; const runtimeRootDir = path.posix.join(workspaceRemoteDir, ".paperclip-runtime", input.adapterKey); const syncWorkspace = input.syncWorkspace !== false; - const gitSnapshot = syncWorkspace ? await readGitWorkspaceSnapshot(input.workspaceLocalDir) : null; + + // Wrap a host-side staging sub-step in its own span when the caller injects a + // runtime span runner. Mirrors the `pack` span below: the runner defaults to a + // no-op, so a caller with no injected runner keeps the current control flow, + // and a throwing runner never changes it (see `createRuntimeSpanRunner`). Each + // span parents under the `stage.sync` step, so the two pre-`pack` operations — + // the git enumeration and the baseline content-hash walk — stop showing up as + // a hidden gap at the head of the step. + const runStepSpan = (name: string, work: () => Promise): Promise => + input.runtimeSpan ? input.runtimeSpan(name, work) : work(); + + // The git enumeration (`git status --ignored`, the HEAD diffs, `ls-files`). + // It reads git's own bookkeeping to decide what to include/exclude, so it is + // usually fast, but on a large working tree the `--ignored` walk is not free. + const gitSnapshot = syncWorkspace + ? await runStepSpan("snapshot.git", () => readGitWorkspaceSnapshot(input.workspaceLocalDir)) + : null; const gitIgnoredExcludes = gitSnapshot?.ignoredPaths; const workspaceArchiveExclude = mergeExcludes( SANDBOX_WORKSPACE_HEAVY_DIR_EXCLUDES, @@ -730,8 +746,14 @@ export async function prepareSandboxManagedRuntime(input: { input.workspaceExclude, gitIgnoredExcludes, ); + // The baseline "before" snapshot: a recursive walk of the whole workspace that + // `lstat`s every entry and SHA-256-hashes every file's bytes. This is the + // dominant cost in the pre-`pack` window — it reads the content of every + // non-excluded file, serially — so it earns its own span. const baselineSnapshot = syncWorkspace - ? await captureDirectorySnapshot(input.workspaceLocalDir, { exclude: restoreExclude }) + ? await runStepSpan("snapshot.baseline", () => + captureDirectorySnapshot(input.workspaceLocalDir, { exclude: restoreExclude }), + ) : null; // Every inbound staging step delegates to the provider through `client.syncIn`: @@ -849,9 +871,7 @@ export async function prepareSandboxManagedRuntime(input: { // span, so `pack` measures only the host tar-build cost. The runner // defaults to a no-op, so a caller with no injected runner keeps the // current behavior and control flow. - const runPackSpan = (work: () => Promise): Promise => - input.runtimeSpan ? input.runtimeSpan("pack", work) : work(); - await runPackSpan(async () => { + await runStepSpan("pack", async () => { // 1. git-history tar (git-backed workspace only). Both tar targets live under // `runtimeRootDir` (`.paperclip-runtime/`). The git extract // wipes the target tree EXCEPT `.paperclip-runtime`, so the overlay tar, diff --git a/packages/shared/src/telemetry/README.md b/packages/shared/src/telemetry/README.md index 79ae3e2581..409f654662 100644 --- a/packages/shared/src/telemetry/README.md +++ b/packages/shared/src/telemetry/README.md @@ -90,21 +90,39 @@ absent, never a misleading `0`. | `codex-home.seed` | Managed-home seed step. | `sandbox.startup` | | `skills.reconcile` | Skills reconcile step. | `sandbox.startup` | | `stage.sync` | Workspace stage-sync step. | `sandbox.startup` | +| `snapshot.git` | Host-side git workspace enumeration inside `stage.sync` (`git status --ignored`, the HEAD diffs, `ls-files`). | `stage.sync` | +| `snapshot.baseline` | Host-side baseline workspace content-hash walk inside `stage.sync`, kept for restore. | `stage.sync` | +| `pack` | Host-side workspace tarball build inside `stage.sync`. | `stage.sync` | | `bridge.paperclip` | Paperclip bridge start step. | `sandbox.startup` | | `bridge.process-session` | Process-session bridge start step. | `sandbox.startup` | | `acp.handshake` | ACP session handshake step. | `sandbox.startup` | | `sandbox.agentSession.sendInput` | One outbound ACP message to the agent — the socket handler's one `writeTextFile` exec. | the active run span | | `sandbox.agentSession.pollOutput` | One 100 ms poll tick — `list`, then `read`+`remove` per file found (`1 + 2n` execs). | the active run span | | `sandbox.callbackBridge.relayRequest` | One Paperclip-API callback request — read the request, write the response, remove it. | the active run span | +| `sandbox.agentProcess` | The persistent streamed agent process the process-session bridge launches; open until the process settles or the bridge tears down, whichever comes first. | the active run span | | `sandbox.exec` | One host-to-sandbox execution. | the active step or wrapper span | A step span name is the step name. The `sandbox.exec` span parents to the step -span that runs the execution, so each execution nests under its step. A run-time +span that runs the execution, so each execution nests under its step. Within +`stage.sync`, the host-side sub-steps `snapshot.git`, `snapshot.baseline`, and +`pack` open as child spans of the step, so the host work at the head of the step +is attributed rather than showing as a gap. A run-time `sandbox.exec` span parents instead to the run-time wrapper span that runs it -(`sandbox.agentSession.sendInput`, `sandbox.agentSession.pollOutput`, or -`sandbox.callbackBridge.relayRequest`). Each run-time wrapper span parents to the -live run span (`agent.turn` during the turn, `task.run` otherwise). With no -active trace context the exec span opens unparented. +(`sandbox.agentSession.sendInput`, `sandbox.agentSession.pollOutput`, +`sandbox.callbackBridge.relayRequest`, or `sandbox.agentProcess`). Each run-time +wrapper span parents to the live run span (`agent.turn` during the turn, +`task.run` otherwise). With no active trace context the exec span opens +unparented. + +`sandbox.agentProcess` wraps the persistent streamed agent process. The +process-session bridge launches it during `bridge.process-session`, so it opens +under `task.run` — no turn has started yet. It therefore overlaps the sibling +`agent.turn` rather than nesting under it or dangling off the short-lived bring-up +step. The span ends when the process settles or when the bridge tears down, +whichever comes first. The bridge tears down before the run root span ends, so +the span never outlives `task.run` even when the process lingers past teardown +(the sandbox `execute` has no cancel, so a lingering process cannot be forced to +resolve). The root span sets the error status when the bring-up fails. Each step span sets the error status when its step fails. The `sandbox.exec` span sets the error