From d114c4925e168174895c458218674054d0ef2cc6 Mon Sep 17 00:00:00 2001 From: Nicky Leach Date: Tue, 4 Aug 2026 19:52:15 -0700 Subject: [PATCH] feat(observability): give sandbox sync spans true wall-clock width (#10864) ## Thinking Path > - Paperclip keeps company work visible and governed. > - Sandbox agents run serial sync work across worker and host boundaries. > - The current span path hid real wall-clock time for that sync work. > - The host needs safe timestamps if it wants true span width. > - This pull request carries worker timestamps, validates them, and records the real duration. > - The benefit is clearer operator visibility for sandbox sync work. ## Linked Issues or Issue Description **Subsystem affected** Cross-cutting. This touches `packages/plugins`, `server`, and the Daytona plugin test surface. **Problem or motivation** Sandbox sync spans opened and closed in one host call. The native width stayed near zero, so the real time spent in serial round trips was hard to see. **Proposed solution** Carry worker start and end times across the span record protocol. Validate the pair at the host boundary. Record the host span with the true duration when the pair is safe. **Alternatives considered** Keep the numeric duration only. That keeps the data, but it does not widen the span and it does not show the real wall-clock time. **Roadmap alignment** This fits the `Cloud / Sandbox agents` and `Artifacts & Work Products` areas in `ROADMAP.md`. I found no other roadmap item that covers this span-width gap. **Additional context** The host allowlist stays narrow. Unknown names still map to `sandbox.provider.other`. Invalid timestamp pairs still fall back to the synchronous path. Related public PRs: none found. ## What Changed - Added optional `startTimeMs` and `endTimeMs` fields to the `span.record` protocol. - Captured start and end times in the worker tracer and sent them to the host. - Validated host timestamps with finite, ordered, bounded checks before span reconstruction. - Extended the host allowlist to the sandbox sync command names. - Wrapped each inbound sync round trip in its own named span. - Added tests for the worker path, host boundary, host recorder, and Daytona sync flow. ## Verification - `pnpm --filter @paperclipai/plugins-sdk test` - `pnpm --filter @paperclipai/server test` - `pnpm --filter @paperclipai/daytona-plugin test` - `pnpm --filter @paperclipai/server tsc --noEmit` still shows pre-existing `drizzle-orm` duplicate-declaration errors in this sandbox. The changed files do not touch those lines. - GitHub checks are green. - Greptile review is 5/5. - No open review threads remain. ## Risks - A bad timestamp pair can fall back to the synchronous path. - The host clock gate can reject spans if the pair is stale, reversed, or too large. - The new worker fields change the wire protocol, but the public plugin tracer contract stays the same. ## Model Used OpenAI GPT-5, tool-enabled. ## 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 linked existing issues with `Fixes: #` / `Closes #` / `Refs #` or described the issue in-PR following the relevant issue template - [x] I have not referenced internal or instance-local Paperclip issues or links - [x] My branch name describes the change 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: Paperclip --- .../daytona/src/file-sync.ts | 132 +++++++++------ .../daytona/src/plugin.test.ts | 156 ++++++++++++++++++ packages/plugins/sdk/src/protocol.ts | 9 + packages/plugins/sdk/src/worker-rpc-host.ts | 8 + .../plugins/sdk/tests/worker-rpc-host.test.ts | 16 ++ server/src/__tests__/instrumentation.test.ts | 82 +++++++++ .../plugin-host-services-span.test.ts | 94 +++++++++++ server/src/instrumentation.ts | 26 ++- server/src/services/plugin-host-services.ts | 75 ++++++++- 9 files changed, 539 insertions(+), 59 deletions(-) diff --git a/packages/plugins/sandbox-providers/daytona/src/file-sync.ts b/packages/plugins/sandbox-providers/daytona/src/file-sync.ts index b1e1bcbfe7..3b91438138 100644 --- a/packages/plugins/sandbox-providers/daytona/src/file-sync.ts +++ b/packages/plugins/sandbox-providers/daytona/src/file-sync.ts @@ -31,15 +31,21 @@ const SPAN_ATTR = { const SPAN_STATUS_CODE_ERROR = 2; /** - * Run one span-wrapped step through the plugin tracer. The pack step and the - * transfer step share this helper. It seeds the provider family, runs the step, - * sets the wall time, marks a thrown step failed, and always ends the span. The - * tracer is a no-op until the host injects a live tracer, so the span never - * changes the sync control flow. + * Run one span-wrapped step through the plugin tracer. The pack step, the + * transfer step, and each command round trip share this helper. It seeds the + * provider family, runs the step, marks a thrown step failed, and always ends + * the span. The host records the span with its true wall-clock width from the + * worker timestamps, so the span shows real time in the trace. The tracer is a + * no-op until the host injects a live tracer, so the span never changes the sync + * control flow. + * + * `wallMsAttr` is optional. The `pack` and `transfer` spans pass it to keep + * their existing `*.wall_ms` attribute. A per-round-trip span omits it, so it + * carries no `*.wall_ms` attribute and relies on the native span width. */ async function withProviderSpan(input: { name: string; - wallMsAttr: string; + wallMsAttr?: string; attributes?: Record; run: () => Promise; }): Promise { @@ -53,7 +59,7 @@ async function withProviderSpan(input: { span.setStatus({ code: SPAN_STATUS_CODE_ERROR }); throw error; } finally { - span.setAttribute(input.wallMsAttr, Date.now() - startedAtMs); + if (input.wallMsAttr) span.setAttribute(input.wallMsAttr, Date.now() - startedAtMs); span.end(); } } @@ -454,19 +460,26 @@ async function syncInFileMappings(input: { // Ensure every target directory exists before the bulk upload writes its temp. const mkdirCommand = [...parentDirs].map((dir) => `mkdir -p ${shellQuote(dir)}`).join(" && "); - await assertSandboxCommandOk(sandbox, mkdirCommand, timeoutSeconds, "syncIn mkdir"); + await withProviderSpan({ + name: "mkdir", + run: () => assertSandboxCommandOk(sandbox, mkdirCommand, timeoutSeconds, "syncIn mkdir"), + }); guardRoundTrips += 1; // Defense-in-depth beyond the lexical `assertConfinedSandboxPath`: a sandbox // can replace a target parent with a symlink to `/etc` so the string check // passes but the upload + `mv -f` resolve through it. Canonicalize every parent // dir (now materialized) and fail closed if any escapes, BEFORE any bytes land. - await assertSandboxPathsConfined({ - sandbox, - remoteDir, - paths: [...parentDirs], - timeoutSeconds, - label: "inbound symlink-escape guard", + await withProviderSpan({ + name: "guard", + run: () => + assertSandboxPathsConfined({ + sandbox, + remoteDir, + paths: [...parentDirs], + timeoutSeconds, + label: "inbound symlink-escape guard", + }), }); guardRoundTrips += 1; @@ -521,12 +534,16 @@ async function syncInFileMappings(input: { `exec 8>&-;`, ); } - await assertSandboxCommandOk( - sandbox, - `sh -c ${shellQuote(renameScript.join("\n"))}`, - timeoutSeconds, - "syncIn rename", - ); + await withProviderSpan({ + name: "rename", + run: () => + assertSandboxCommandOk( + sandbox, + `sh -c ${shellQuote(renameScript.join("\n"))}`, + timeoutSeconds, + "syncIn rename", + ), + }); } catch (error) { await removeSandboxScratch(sandbox, renames.map((rename) => rename.temp), timeoutSeconds); throw error; @@ -568,19 +585,27 @@ async function syncInDirectoryMapping(input: { // components, then confirm it (and any existing parent) canonicalizes inside // the remote dir — `tar -C` would otherwise follow a sandbox-planted symlink // and extract our archive outside the workspace root. - await assertSandboxCommandOk( - sandbox, - `mkdir -p ${shellQuote(mapping.targetPath)}`, - timeoutSeconds, - "syncIn mkdir", - ); + await withProviderSpan({ + name: "mkdir", + run: () => + assertSandboxCommandOk( + sandbox, + `mkdir -p ${shellQuote(mapping.targetPath)}`, + timeoutSeconds, + "syncIn mkdir", + ), + }); guardRoundTrips += 1; - await assertSandboxPathsConfined({ - sandbox, - remoteDir, - paths: [mapping.targetPath], - timeoutSeconds, - label: "inbound symlink-escape guard", + await withProviderSpan({ + name: "guard", + run: () => + assertSandboxPathsConfined({ + sandbox, + remoteDir, + paths: [mapping.targetPath], + timeoutSeconds, + label: "inbound symlink-escape guard", + }), }); guardRoundTrips += 1; await withProviderSpan({ @@ -616,12 +641,16 @@ async function syncInDirectoryMapping(input: { `exec 9>&-;`, `rm -f ${shellQuote(remoteTar)};`, ].join("\n"); - await assertSandboxCommandOk( - sandbox, - `sh -c ${shellQuote(extractScript)}`, - timeoutSeconds, - "syncIn extract", - ); + await withProviderSpan({ + name: "extract", + run: () => + assertSandboxCommandOk( + sandbox, + `sh -c ${shellQuote(extractScript)}`, + timeoutSeconds, + "syncIn extract", + ), + }); const filesTransferred = await countHostFiles(mapping.sourcePath, mapping.exclude); return { filesTransferred, bytesTransferred }; }); @@ -658,12 +687,16 @@ async function runPostUploadCommands(input: { let cwd = remoteDir; if (command.cwd != null) { assertConfinedSandboxPath(remoteDir, command.cwd, "post-upload command cwd"); - await assertSandboxPathsConfined({ - sandbox, - remoteDir, - paths: [command.cwd], - timeoutSeconds, - label: "post-upload command cwd symlink-escape guard", + await withProviderSpan({ + name: "guard", + run: () => + assertSandboxPathsConfined({ + sandbox, + remoteDir, + paths: [command.cwd as string], + timeoutSeconds, + label: "post-upload command cwd symlink-escape guard", + }), }); cwd = command.cwd; } @@ -671,12 +704,11 @@ async function runPostUploadCommands(input: { // C4: first non-zero exit or timeout throws and aborts the remaining commands. const commandTimeoutSeconds = command.timeoutMs != null ? toTimeoutSeconds(command.timeoutMs) : timeoutSeconds; - const result = await sandbox.process.executeCommand( - command.command, - cwd, - undefined, - commandTimeoutSeconds, - ); + const result = await withProviderSpan({ + name: "provision", + run: () => + sandbox.process.executeCommand(command.command, cwd, undefined, commandTimeoutSeconds), + }); if ((result.exitCode ?? 1) !== 0) { const detail = (result.result ?? result.artifacts?.stdout ?? "").toString().trim(); throw new Error( diff --git a/packages/plugins/sandbox-providers/daytona/src/plugin.test.ts b/packages/plugins/sandbox-providers/daytona/src/plugin.test.ts index 8b726e1949..d5588335e9 100644 --- a/packages/plugins/sandbox-providers/daytona/src/plugin.test.ts +++ b/packages/plugins/sandbox-providers/daytona/src/plugin.test.ts @@ -2777,6 +2777,162 @@ describe("daytona native file-sync hooks", () => { expect(transfer!.attributes["paperclip.sandbox.startup.transfer.guard.count"]).toBe(2); }); + it("opens mkdir, guard, transfer, rename spans in call order for a file-mapping sync", async () => { + const hostDir = await makeHostDir(); + const source = path.join(hostDir, "config.txt"); + await fs.writeFile(source, "plain"); + const sandbox = createMockSandbox(); + mockGet.mockResolvedValue(sandbox); + + const { tracer, spans } = createRecordingPluginTracer(); + const restore = __setDaytonaPluginContextForTest({ tracer } as unknown as PluginContext); + try { + await plugin.definition.onEnvironmentSyncIn?.({ + driverKey: "daytona", + companyId: "company-1", + environmentId: "env-1", + config: { timeoutMs: 300000, reuseLease: false }, + lease: syncLease(), + operations: [ + { + operationId: "sync-op-order", + files: [{ sourcePath: source, targetPath: `${REMOTE_DIR}/config.txt`, kind: "file" }], + }, + ], + }); + } finally { + restore(); + } + + expect(spans.map((span) => span.name)).toEqual(["mkdir", "guard", "transfer", "rename"]); + for (const span of spans) { + expect(span.ended).toBe(true); + expect(span.attributes["paperclip.sandbox.startup.provider"]).toBe("daytona"); + // A per-round-trip span carries no `*.wall_ms` attribute; the native span + // width carries its time. Only `pack` and `transfer` keep a wall_ms value. + if (span.name !== "transfer") { + expect(span.attributes["paperclip.sandbox.startup.mkdir.wall_ms"]).toBeUndefined(); + expect(span.attributes["paperclip.sandbox.startup.rename.wall_ms"]).toBeUndefined(); + expect(span.attributes["paperclip.sandbox.startup.guard.wall_ms"]).toBeUndefined(); + } + } + }); + + it("opens pack, mkdir, guard, transfer, extract spans in call order for a directory-mapping sync", async () => { + const hostDir = await makeHostDir(); + const sourceDir = path.join(hostDir, "assets"); + await fs.mkdir(sourceDir, { recursive: true }); + await fs.writeFile(path.join(sourceDir, "a.txt"), "alpha"); + const sandbox = createMockSandbox(); + mockGet.mockResolvedValue(sandbox); + + const { tracer, spans } = createRecordingPluginTracer(); + const restore = __setDaytonaPluginContextForTest({ tracer } as unknown as PluginContext); + try { + await plugin.definition.onEnvironmentSyncIn?.({ + driverKey: "daytona", + companyId: "company-1", + environmentId: "env-1", + config: { timeoutMs: 300000, reuseLease: false }, + lease: syncLease(), + operations: [ + { + operationId: "sync-op-dir-order", + files: [ + { sourcePath: sourceDir, targetPath: `${REMOTE_DIR}/.paperclip-runtime/assets`, kind: "directory" }, + ], + }, + ], + }); + } finally { + restore(); + } + + expect(spans.map((span) => span.name)).toEqual(["pack", "mkdir", "guard", "transfer", "extract"]); + for (const span of spans) { + expect(span.attributes["paperclip.sandbox.startup.provider"]).toBe("daytona"); + } + }); + + it("records a pack span for a traced directory mapping", async () => { + const hostDir = await makeHostDir(); + const sourceDir = path.join(hostDir, "assets"); + await fs.mkdir(sourceDir, { recursive: true }); + await fs.writeFile(path.join(sourceDir, "a.txt"), "alpha"); + const sandbox = createMockSandbox(); + mockGet.mockResolvedValue(sandbox); + + const { tracer, spans } = createRecordingPluginTracer(); + const restore = __setDaytonaPluginContextForTest({ tracer } as unknown as PluginContext); + try { + await plugin.definition.onEnvironmentSyncIn?.({ + driverKey: "daytona", + companyId: "company-1", + environmentId: "env-1", + config: { timeoutMs: 300000, reuseLease: false }, + lease: syncLease(), + operations: [ + { + operationId: "sync-op-pack", + files: [ + { sourcePath: sourceDir, targetPath: `${REMOTE_DIR}/.paperclip-runtime/assets`, kind: "directory" }, + ], + }, + ], + }); + } finally { + restore(); + } + + const pack = spans.find((span) => span.name === "pack"); + expect(pack).toBeDefined(); + expect(pack!.ended).toBe(true); + expect(pack!.attributes["paperclip.sandbox.startup.provider"]).toBe("daytona"); + }); + + it("opens a guard span and a provision span in call order for a post-upload command with a working directory", async () => { + const hostDir = await makeHostDir(); + const source = path.join(hostDir, "config.txt"); + await fs.writeFile(source, "plain"); + const sandbox = createMockSandbox(); + mockGet.mockResolvedValue(sandbox); + + const { tracer, spans } = createRecordingPluginTracer(); + const restore = __setDaytonaPluginContextForTest({ tracer } as unknown as PluginContext); + try { + await plugin.definition.onEnvironmentSyncIn?.({ + driverKey: "daytona", + companyId: "company-1", + environmentId: "env-1", + config: { timeoutMs: 300000, reuseLease: false }, + lease: syncLease(), + operations: [ + { + operationId: "sync-op-post", + files: [{ sourcePath: source, targetPath: `${REMOTE_DIR}/config.txt`, kind: "file" }], + postUploadCommands: [{ command: "run-me", cwd: `${REMOTE_DIR}/sub` }], + }, + ], + }); + } finally { + restore(); + } + + // The full order: the file mapping opens mkdir, guard, transfer, rename; the + // post-upload command then opens its own cwd guard and the provision span. + expect(spans.map((span) => span.name)).toEqual([ + "mkdir", + "guard", + "transfer", + "rename", + "guard", + "provision", + ]); + const provision = spans.find((span) => span.name === "provision"); + expect(provision!.ended).toBe(true); + expect(provision!.attributes["paperclip.sandbox.startup.provider"]).toBe("daytona"); + }); + it("syncIn tars a directory mapping host-side honoring excludes and the followSymlinks flag, then extracts it in-sandbox via a single quoted tar command", async () => { const hostDir = await makeHostDir(); const sourceDir = path.join(hostDir, "assets"); diff --git a/packages/plugins/sdk/src/protocol.ts b/packages/plugins/sdk/src/protocol.ts index 83e22a16b5..7e299764e1 100644 --- a/packages/plugins/sdk/src/protocol.ts +++ b/packages/plugins/sdk/src/protocol.ts @@ -1303,6 +1303,15 @@ export interface WorkerToHostMethods { attributes?: Record; /** The optional span status. */ status?: { code: number; message?: string }; + /** The optional span start time as epoch milliseconds (`Date.now()`). + * The worker captures it when it opens the span. The host validates the + * pair and records the span with its true native width. An omitted value + * makes the host fall back to a synchronous open-and-end. */ + startTimeMs?: number; + /** The optional span end time as epoch milliseconds (`Date.now()`). The + * worker captures it when it ends the span. The host uses it as the span + * end time when the pair passes the clock-safety check. */ + endTimeMs?: number; }, result: void, ]; diff --git a/packages/plugins/sdk/src/worker-rpc-host.ts b/packages/plugins/sdk/src/worker-rpc-host.ts index 12739cf3d8..8b56a48972 100644 --- a/packages/plugins/sdk/src/worker-rpc-host.ts +++ b/packages/plugins/sdk/src/worker-rpc-host.ts @@ -1406,6 +1406,9 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost const attributes: Record = { ...(options?.attributes ?? {}), }; + // Capture the real start time once when the span opens. The host uses + // it as the span start time, so the span shows its true native width. + const startTimeMs = Date.now(); let status: { code: number; message?: string } | undefined; let ended = false; return { @@ -1419,6 +1422,9 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost if (ended) return; ended = true; if (!hasTraceContext) return; + // Capture the real end time once at the first end call. The host + // uses the pair to record the span with its true wall-clock width. + const endTimeMs = Date.now(); // Send the finished span to the host once. The host re-clamps the // name and the attributes, mints the parentage from its own // invocation record, and records the span through the real tracer. @@ -1427,6 +1433,8 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost name, attributes, ...(status ? { status } : {}), + startTimeMs, + endTimeMs, }).catch(() => undefined); }, }; diff --git a/packages/plugins/sdk/tests/worker-rpc-host.test.ts b/packages/plugins/sdk/tests/worker-rpc-host.test.ts index e34ca4de3c..e88833671b 100644 --- a/packages/plugins/sdk/tests/worker-rpc-host.test.ts +++ b/packages/plugins/sdk/tests/worker-rpc-host.test.ts @@ -606,6 +606,22 @@ describe("worker provider tracer", () => { }); }); + it("sends a finite startTimeMs and endTimeMs with endTimeMs >= startTimeMs", async () => { + const spanRecords = await runSpanProbe({ + id: "invocation-a", + scope: { companyId: "company-a" }, + traceparent: "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01", + }); + expect(spanRecords).toHaveLength(1); + const params = spanRecords[0]!.params as { + startTimeMs?: number; + endTimeMs?: number; + }; + expect(Number.isFinite(params.startTimeMs)).toBe(true); + expect(Number.isFinite(params.endTimeMs)).toBe(true); + expect(params.endTimeMs!).toBeGreaterThanOrEqual(params.startTimeMs!); + }); + it("emits no span.record when the invocation carries no traceparent (tracing off)", async () => { const spanRecords = await runSpanProbe({ id: "invocation-a", diff --git a/server/src/__tests__/instrumentation.test.ts b/server/src/__tests__/instrumentation.test.ts index 41c8407906..b0b94e07a3 100644 --- a/server/src/__tests__/instrumentation.test.ts +++ b/server/src/__tests__/instrumentation.test.ts @@ -1,4 +1,5 @@ import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { createRequire } from "node:module"; /** * Tests for the opt-in OpenTelemetry bootstrap. The @opentelemetry/* packages @@ -146,3 +147,84 @@ describe("shutdownInstrumentation", () => { await expect(shutdownInstrumentation()).resolves.toBeUndefined(); }); }); + +// The `@opentelemetry/*` packages are optional. When they are absent, +// `recordProviderPluginSpan` is a no-op by contract, so a native-duration test +// cannot run. Resolve the SDK first and skip the test when it is not installed. +const otelSdk = (() => { + try { + const require = createRequire(import.meta.url); + return { + api: require("@opentelemetry/api") as typeof import("@opentelemetry/api"), + sdk: require("@opentelemetry/sdk-trace-base") as typeof import("@opentelemetry/sdk-trace-base"), + }; + } catch { + return null; + } +})(); + +const hrTimeToMs = (time: [number, number]): number => time[0] * 1000 + time[1] / 1e6; + +describe.skipIf(!otelSdk)("recordProviderPluginSpan native duration", () => { + it("opens the span at the true start time and ends it at the true end time", async () => { + const { api, sdk } = otelSdk!; + const exporter = new sdk.InMemorySpanExporter(); + const provider = new sdk.BasicTracerProvider({ + spanProcessors: [new sdk.SimpleSpanProcessor(exporter)], + }); + api.trace.setGlobalTracerProvider(provider); + try { + const { recordProviderPluginSpan } = await import("../instrumentation.js"); + const startTimeMs = Date.now() - 4500; + const endTimeMs = startTimeMs + 4500; + recordProviderPluginSpan({ + name: "sandbox.provider.mkdir", + parent: { + traceId: "0af7651916cd43dd8448eb211c80319c", + spanId: "b7ad6b7169203331", + traceFlags: 1, + }, + attributes: { provider: "daytona" }, + startTimeMs, + endTimeMs, + }); + const finished = exporter.getFinishedSpans(); + expect(finished).toHaveLength(1); + const span = finished[0]!; + expect(span.name).toBe("sandbox.provider.mkdir"); + expect(Math.round(hrTimeToMs(span.startTime as [number, number]))).toBe(startTimeMs); + expect(Math.round(hrTimeToMs(span.endTime as [number, number]))).toBe(endTimeMs); + // The native width equals the true wall-clock difference, not near zero. + expect(Math.round(hrTimeToMs(span.duration as [number, number]))).toBe(4500); + } finally { + api.trace.disable(); + } + }); + + it("opens and ends the span now when the timestamp pair is absent", async () => { + const { api, sdk } = otelSdk!; + const exporter = new sdk.InMemorySpanExporter(); + const provider = new sdk.BasicTracerProvider({ + spanProcessors: [new sdk.SimpleSpanProcessor(exporter)], + }); + api.trace.setGlobalTracerProvider(provider); + try { + const { recordProviderPluginSpan } = await import("../instrumentation.js"); + recordProviderPluginSpan({ + name: "sandbox.provider.pack", + parent: { + traceId: "0af7651916cd43dd8448eb211c80319c", + spanId: "b7ad6b7169203331", + traceFlags: 1, + }, + attributes: { provider: "daytona" }, + }); + const finished = exporter.getFinishedSpans(); + expect(finished).toHaveLength(1); + // The synchronous open-and-end path yields a near-zero native width. + expect(hrTimeToMs(finished[0]!.duration as [number, number])).toBeLessThan(1000); + } finally { + api.trace.disable(); + } + }); +}); diff --git a/server/src/__tests__/plugin-host-services-span.test.ts b/server/src/__tests__/plugin-host-services-span.test.ts index ea9e688e24..abc4ea058f 100644 --- a/server/src/__tests__/plugin-host-services-span.test.ts +++ b/server/src/__tests__/plugin-host-services-span.test.ts @@ -125,6 +125,100 @@ describe("plugin provider span host handler", () => { ); }); + it("admits each per-round-trip span name to sandbox.provider.", async () => { + const services = servicesFor(); + for (const name of ["mkdir", "guard", "rename", "extract", "provision"]) { + await services.tracer.record( + { name }, + { traceparent: VALID_TRACEPARENT } as WorkerHostCallContext, + ); + } + const recorded = mockRecordSpan.mock.calls.map((c) => (c[0] as { name: string }).name); + expect(recorded).toEqual([ + "sandbox.provider.mkdir", + "sandbox.provider.guard", + "sandbox.provider.rename", + "sandbox.provider.extract", + "sandbox.provider.provision", + ]); + }); + + it("forwards a valid start-time and end-time pair to the recorder", async () => { + const services = servicesFor(); + const startTimeMs = Date.now() - 4500; + const endTimeMs = startTimeMs + 4500; + await services.tracer.record( + { name: "mkdir", startTimeMs, endTimeMs }, + { traceparent: VALID_TRACEPARENT } as WorkerHostCallContext, + ); + const call = mockRecordSpan.mock.calls[0]![0] as { + startTimeMs?: number; + endTimeMs?: number; + }; + expect(call.startTimeMs).toBe(startTimeMs); + expect(call.endTimeMs).toBe(endTimeMs); + }); + + it("accepts a pair whose end is a small skew ahead of the host clock", async () => { + const services = servicesFor(); + // The worker clock leads the host clock by a few seconds. This small skew + // is within the allowed bound, so the host keeps the native width. + const startTimeMs = Date.now() + 5000; + const endTimeMs = startTimeMs + 1000; + await services.tracer.record( + { name: "mkdir", startTimeMs, endTimeMs }, + { traceparent: VALID_TRACEPARENT } as WorkerHostCallContext, + ); + const call = mockRecordSpan.mock.calls[0]![0] as { + startTimeMs?: number; + endTimeMs?: number; + }; + expect(call.startTimeMs).toBe(startTimeMs); + expect(call.endTimeMs).toBe(endTimeMs); + }); + + it("drops an invalid timestamp pair so the synchronous path runs", async () => { + const services = servicesFor(); + const now = Date.now(); + const invalidPairs: Array<{ startTimeMs?: unknown; endTimeMs?: unknown; why: string }> = [ + { startTimeMs: now, endTimeMs: now - 1000, why: "reversed order" }, + { startTimeMs: Number.NaN, endTimeMs: now, why: "non-finite start" }, + { startTimeMs: now, endTimeMs: Number.POSITIVE_INFINITY, why: "non-finite end" }, + { startTimeMs: now, endTimeMs: now + 11 * 60 * 1000, why: "over-ceiling duration" }, + { startTimeMs: now - 2 * 60 * 60 * 1000, endTimeMs: now - 2 * 60 * 60 * 1000 + 10, why: "over-age start" }, + { startTimeMs: now, endTimeMs: now + 2 * 60 * 1000, why: "end far in the future" }, + { startTimeMs: now + 5 * 60 * 1000, endTimeMs: now + 5 * 60 * 1000 + 10, why: "start and end in the future" }, + ]; + for (const pair of invalidPairs) { + mockRecordSpan.mockReset(); + await services.tracer.record( + { name: "mkdir", startTimeMs: pair.startTimeMs, endTimeMs: pair.endTimeMs } as never, + { traceparent: VALID_TRACEPARENT } as WorkerHostCallContext, + ); + // The span still records (the synchronous path), but without a timestamp. + const call = mockRecordSpan.mock.calls[0]![0] as { + startTimeMs?: number; + endTimeMs?: number; + }; + expect(call.startTimeMs, pair.why).toBeUndefined(); + expect(call.endTimeMs, pair.why).toBeUndefined(); + } + }); + + it("records the synchronous path when the timestamp pair is absent", async () => { + const services = servicesFor(); + await services.tracer.record( + { name: "pack" }, + { traceparent: VALID_TRACEPARENT } as WorkerHostCallContext, + ); + const call = mockRecordSpan.mock.calls[0]![0] as { + startTimeMs?: number; + endTimeMs?: number; + }; + expect(call.startTimeMs).toBeUndefined(); + expect(call.endTimeMs).toBeUndefined(); + }); + it("rejects a malformed traceparent — no span is recorded", async () => { const services = servicesFor(); for (const bad of [ diff --git a/server/src/instrumentation.ts b/server/src/instrumentation.ts index 246908ab00..c1524c815d 100644 --- a/server/src/instrumentation.ts +++ b/server/src/instrumentation.ts @@ -51,7 +51,10 @@ interface StartupTracerHandle { ): { setAttribute(key: string, value: unknown): void; setStatus(status: { code: number; message?: string }): void; - end(): void; + // The optional explicit end time as an epoch-millisecond number. A real OTel + // `span.end(endTime)` uses it as the span end time, so the span shows its + // true wall-clock width. The no-op span ignores it. + end(endTime?: unknown): void; }; } @@ -222,6 +225,12 @@ export function recordProviderPluginSpan(input: { parent: ParsedTraceparent; attributes: Record; status?: { code: number; message?: string }; + /** The optional span start time as an epoch-millisecond number. When present + * with `endTimeMs`, the span shows its true wall-clock width. When absent, the + * span opens and ends synchronously, so its native width is near zero. */ + startTimeMs?: number; + /** The optional span end time as an epoch-millisecond number. */ + endTimeMs?: number; }): void { try { const require = createRequire(import.meta.url); @@ -243,9 +252,20 @@ export function recordProviderPluginSpan(input: { }; const parentContext = trace.setSpanContext(context.active(), remoteSpanContext); const tracer = trace.getTracer("paperclip.startup"); - const span = tracer.startSpan(input.name, { attributes: input.attributes }, parentContext); + // Pass the true start time as the OpenTelemetry `startTime` option, so the + // span opens at its real wall-clock start. An epoch-millisecond number is a + // valid OpenTelemetry `TimeInput`. + const startSpanOptions = + input.startTimeMs !== undefined + ? { attributes: input.attributes, startTime: input.startTimeMs } + : { attributes: input.attributes }; + const span = tracer.startSpan(input.name, startSpanOptions, parentContext); if (input.status) span.setStatus(input.status); - span.end(); + // Pass the true end time to `span.end`, so the span ends at its real + // wall-clock end and shows its true native width. When the end time is + // absent, the span ends now, so its native width is near zero. + if (input.endTimeMs !== undefined) span.end(input.endTimeMs); + else span.end(); } catch { // Observability must not change control flow. } diff --git a/server/src/services/plugin-host-services.ts b/server/src/services/plugin-host-services.ts index a156c02bc7..bf490c69a7 100644 --- a/server/src/services/plugin-host-services.ts +++ b/server/src/services/plugin-host-services.ts @@ -507,8 +507,19 @@ const SESSION_EVENT_SUBSCRIPTION_TIMEOUT_MS = 30 * 60 * 1_000; // 30 minutes const SPAN_ATTRS = SANDBOX_STARTUP_SPAN_ATTRS; -/** The closed set of provider span names a plugin may emit. */ -const KNOWN_PROVIDER_SPAN_NAMES: ReadonlySet = new Set(["pack", "transfer"]); +/** The closed set of provider span names a plugin may emit. `pack` and + * `transfer` are the host-local build and the byte upload. `mkdir`, `guard`, + * `rename`, `extract`, and `provision` are the per-round-trip command spans in + * the inbound sync path. */ +const KNOWN_PROVIDER_SPAN_NAMES: ReadonlySet = new Set([ + "pack", + "transfer", + "mkdir", + "guard", + "rename", + "extract", + "provision", +]); /** Clamp the span name to a closed, namespaced set. A known name maps to * `sandbox.provider.`; any other value maps to `sandbox.provider.other`, @@ -593,24 +604,76 @@ function clampSpanStatus( return { code: status.code }; } +/** The largest span duration the host accepts as a real wall-clock width. A + * larger difference means a skewed or wrong clock, so the host drops the pair. */ +const MAX_PROVIDER_SPAN_DURATION_MS = 10 * 60 * 1000; // 10 minutes + +/** The largest age the host accepts for a span start time relative to its own + * clock. An older start means a stale or wrong clock, so the host drops the + * pair. A small negative skew (a start slightly ahead of the host clock) is + * allowed, because the host and the worker clocks can differ. */ +const MAX_PROVIDER_SPAN_START_AGE_MS = 60 * 60 * 1000; // 1 hour + +/** The largest amount by which the end time may be ahead of the host clock. A + * larger lead means a wrong or skewed clock, so the host drops the pair. This + * upper bound rejects a timestamp pair that is far in the future. It still + * allows a small clock skew between the host and the worker. */ +const MAX_PROVIDER_SPAN_END_SKEW_MS = 60 * 1000; // 1 minute + +/** + * Validate the worker-sent start-time and end-time pair at the trust boundary. + * Return the pair only when it passes the clock-safety policy: + * - both values are finite numbers; + * - the start time is less than or equal to the end time; + * - the duration is not larger than a bounded ceiling; + * - the start time is not older than a bounded age relative to the host clock; + * - the end time is not ahead of the host clock by more than a bounded skew. + * Return `undefined` when any check fails, so the host falls back to the + * synchronous open-and-end path. + */ +function validateProviderSpanTimes( + startTimeMs: unknown, + endTimeMs: unknown, +): { startTimeMs: number; endTimeMs: number } | undefined { + if (typeof startTimeMs !== "number" || !Number.isFinite(startTimeMs)) return undefined; + if (typeof endTimeMs !== "number" || !Number.isFinite(endTimeMs)) return undefined; + if (startTimeMs > endTimeMs) return undefined; + if (endTimeMs - startTimeMs > MAX_PROVIDER_SPAN_DURATION_MS) return undefined; + if (Date.now() - startTimeMs > MAX_PROVIDER_SPAN_START_AGE_MS) return undefined; + if (endTimeMs - Date.now() > MAX_PROVIDER_SPAN_END_SKEW_MS) return undefined; + return { startTimeMs, endTimeMs }; +} + /** * Record a worker-sent provider span through the real tracer. This is the host * trust boundary: it validates the host-minted `traceparent`, re-clamps the span * name and every attribute, mints the parentage host-side, and drops a status - * message. It rejects a span with a missing or malformed `traceparent`. It never - * throws — observability must not change control flow. + * message. It validates the optional start-time and end-time pair with a + * clock-safety policy; a valid pair gives the span its true native width, and an + * absent or invalid pair falls back to the synchronous open-and-end path. It + * rejects a span with a missing or malformed `traceparent`. It never throws — + * observability must not change control flow. */ export function recordWorkerProviderSpan( - params: { name: string; attributes?: Record; status?: { code?: unknown; message?: unknown } }, + params: { + name: string; + attributes?: Record; + status?: { code?: unknown; message?: unknown }; + startTimeMs?: unknown; + endTimeMs?: unknown; + }, context: WorkerHostCallContext | undefined, ): void { const parent = parseTraceparent(context?.traceparent); if (!parent) return; // reject a missing or malformed traceparent + const times = validateProviderSpanTimes(params.startTimeMs, params.endTimeMs); + const status = clampSpanStatus(params.status); recordProviderPluginSpan({ name: clampProviderSpanName(params.name), parent, attributes: clampProviderSpanAttributes(params.attributes), - ...(clampSpanStatus(params.status) ? { status: clampSpanStatus(params.status) } : {}), + ...(status ? { status } : {}), + ...(times ? { startTimeMs: times.startTimeMs, endTimeMs: times.endTimeMs } : {}), }); }