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 } : {}), }); }