diff --git a/doc/observability.md b/doc/observability.md index a96ae96058b..abadb0e6538 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -1900,6 +1900,49 @@ name to `sandbox.daytona.`. The host maps any other value to daytona provider emits these spans today, so the segment is the literal `daytona`. +### Daytona lease acquisition and resume + +The worker invocation carries nested, monotonic timing receipts for lease work. +The host also admits the following fixed `lease.*` names and prefixes them with +`sandbox.daytona.`. These use the existing opt-in endpoint and host-owned parent +context; they do not create an exporter or first-party Telemetry events. + +```text +execution.plugin_dispatch +└── plugin.worker + ├── sandbox.daytona.lease.wait_for_teardown (only when teardown blocks resume) + ├── sandbox.daytona.lease.lookup + ├── sandbox.daytona.lease.refresh (missing-container confirmation) + ├── sandbox.daytona.lease.channel_cleanup (before restart) + ├── sandbox.daytona.lease.start (or lease.recover) + └── sandbox.daytona.lease.verify + ├── sandbox.daytona.lease.workspace + ├── sandbox.daytona.lease.sentinel + └── sandbox.daytona.lease.shell +``` + +`lease.lookup` includes cached-handle lookup and any required provider refresh. +`lease.start` and `lease.recover` measure the actual SDK operation, including its +internal readiness wait. They also cover starts triggered by execution or sync. +They do not separate SDK-internal requests or provider-side queue time. +Their `paperclip.sandbox.startup.state` attribute records the state before the +call: `started`, `stopped`, `archived`, `error`, or `other`. Both the plugin and +host restrict this value; no provider error text or resource identity is sent. + +Fresh acquisition emits `lease.create`, `lease.workspace`, `lease.shell`, +`lease.expiry`, and `lease.sentinel`. `lease.create` covers the existing creation +helper, including qualification-only snapshot resolution and creation-failure +cleanup. Setup-failure deletion is a separate `lease.cleanup` sibling, so it +does not inherit a failed workspace or verification phase. Existing deadlines, +ownership, cleanup and retry behavior are unchanged. Failed awaited steps close +with error status; the receipt contains no exception message. + +Children nest beneath the current `plugin.worker` receipt and verification +children nest beneath `lease.verify`. Never add parent and child durations. +Receipt budgets and clock validation still apply. Older workers without +`tracer.withSpan` keep the original behavior without these detail spans. Tracing +failures preserve the operation's result or error and never repeat it. + The `sandbox.daytona.*` spans use this closed attribute allowlist. The host drops every other key, so a command, an argument, a path, an id, a standard output, or a standard error never rides a provider span. The host records only @@ -1908,6 +1951,7 @@ the attributes that the producer sends for one span. | Attribute | Type | Optional | Meaning | | ------------------------------------------------ | ------ | -------- | --------------------------------------------------------------------------------------------------------- | | `paperclip.sandbox.startup.provider` | string | no | The normalized provider family. | +| `paperclip.sandbox.startup.state` | string | yes | State before start/recovery: `started`, `stopped`, `archived`, `error`, or `other`. | | `paperclip.sandbox.startup.outcome` | string | yes | The step outcome (`ok`, `skipped`, or `failed`). | | `paperclip.sandbox.startup.pack.wall_ms` | number | yes | The host-local wall time of the pack step. It rides the `sandbox.daytona.pack` span. | | `paperclip.sandbox.startup.transfer.wall_ms` | number | yes | The wall time of the transfer step. It rides the `sandbox.daytona.transfer` span. | diff --git a/packages/adapter-utils/src/acpx-engine/startup-timing.ts b/packages/adapter-utils/src/acpx-engine/startup-timing.ts index 74f1977c5c3..5ce26855ef2 100644 --- a/packages/adapter-utils/src/acpx-engine/startup-timing.ts +++ b/packages/adapter-utils/src/acpx-engine/startup-timing.ts @@ -67,6 +67,8 @@ export const EXECUTION_PREPARATION_SPAN_ATTRS = { * command, a path, an argument, or an environment value can never ride a span. */ export const SANDBOX_STARTUP_SPAN_ATTRS = { + /** Provider state before a lease start or recovery; the host clamps values. */ + state: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}state`, /** The low-cardinality provider family (through `normalizeProviderFamily`). */ provider: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}provider`, /** The step or execution outcome: `ok`, `skipped`, or `failed`. */ diff --git a/packages/plugins/sandbox-providers/daytona/src/lease-tracing.test.ts b/packages/plugins/sandbox-providers/daytona/src/lease-tracing.test.ts new file mode 100644 index 00000000000..dbb8b9eac18 --- /dev/null +++ b/packages/plugins/sandbox-providers/daytona/src/lease-tracing.test.ts @@ -0,0 +1,273 @@ +import { createInterface } from "node:readline"; +import { PassThrough } from "node:stream"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { NOOP_PLUGIN_TRACER, startWorkerRpcHost, type PluginInvocationContext, type PluginTracer } from "@paperclipai/plugin-sdk"; +import plugin, { __resetDaytonaSandboxHandleCacheForTest, __setDaytonaPluginContextForTest } from "./plugin.js"; +import manifest from "./manifest.js"; +import { leaseStateAttributes, withLeaseSpan } from "./lease-tracing.js"; + +const { get, create } = vi.hoisted(() => ({ get: vi.fn(), create: vi.fn() })); +vi.mock("@daytonaio/sdk", () => ({ + Daytona: class { get = get; create = create; }, + DaytonaNotFoundError: class extends Error {}, + DaytonaTimeoutError: class extends Error {}, +})); + +type Receipt = { + name: string; + startTimeMs: number; + endTimeMs: number; + attributes?: Record; + status?: { code: number }; + children: Receipt[]; +}; + +function sandbox(id = "fixture-sandbox", state = "archived") { + return { + id, state, target: "us", recoverable: true, errorReason: null as string | null, + start: vi.fn().mockResolvedValue(undefined), + stop: vi.fn().mockResolvedValue(undefined), + refreshData: vi.fn().mockResolvedValue(undefined), + recover: vi.fn().mockResolvedValue(undefined), + delete: vi.fn().mockResolvedValue(undefined), + getWorkDir: vi.fn().mockResolvedValue("/home/daytona"), + fs: { createFolder: vi.fn().mockResolvedValue(undefined), uploadFile: vi.fn().mockResolvedValue(undefined) }, + process: { executeCommand: vi.fn(async (command: string) => ({ + exitCode: 0, result: command.startsWith("cat ") ? '{"token":"private-token"}' : "bash", + })) }, + }; +} + +const params = { + driverKey: "daytona", companyId: "fixture-company", environmentId: "fixture-environment", + providerLeaseId: "fixture-sandbox", config: { apiKey: "private-api-key", timeoutMs: 300000, reuseLease: true }, + leaseMetadata: { workspaceSentinel: { token: "private-token", result: "written" } }, +}; + +function workerHarness() { + const stdin = new PassThrough(), stdout = new PassThrough(); + const lines = createInterface({ input: stdout }); + const pending = new Map(); + const receipts: Array<{ invocationId: string; span: Receipt }> = []; + let sequence = 0; + lines.on("line", line => { + const message = JSON.parse(line); + if (message.method) { + if (message.method === "span.record") receipts.push({ invocationId: message.paperclipInvocationId, span: message.params }); + if (message.id !== undefined) stdin.write(JSON.stringify({ jsonrpc: "2.0", id: message.id, result: null }) + "\n"); + } else { + const waiter = pending.get(message.id); + pending.delete(message.id); + if (message.error) waiter?.reject(new Error(message.error.message)); + else waiter?.resolve(message.result); + } + }); + const worker = startWorkerRpcHost({ plugin, stdin, stdout }); + function call(method: string, input: unknown, invocation?: PluginInvocationContext): Promise { + const id = String(++sequence); + return new Promise((resolve, reject) => { + pending.set(id, { resolve, reject }); + stdin.write(JSON.stringify({ jsonrpc: "2.0", id, method, params: input, + ...(invocation ? { paperclipInvocation: invocation } : {}) }) + "\n"); + }); + } + return { + call, receipts, + initialize: () => call("initialize", { manifest, config: {}, apiVersion: 1, + instanceInfo: { instanceId: "fixture", hostVersion: "0.0.0" } }), + close() { worker.stop(); lines.close(); stdin.destroy(); stdout.destroy(); }, + }; +} + +function invocation(id: string, enabled = true): PluginInvocationContext { + return { id, scope: { companyId: "fixture-company" }, + ...(enabled ? { traceparent: "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01" } : {}) }; +} + +describe("Daytona lease worker tracing", () => { + beforeEach(() => { get.mockReset(); create.mockReset(); __resetDaytonaSandboxHandleCacheForTest(); }); + afterEach(() => { __setDaytonaPluginContextForTest(null); __resetDaytonaSandboxHandleCacheForTest(); }); + + it.each([true, false])("records the archived start and nested verification only with trace context: %s", async enabled => { + const resource = sandbox(); get.mockResolvedValue(resource); + const worker = workerHarness(); + try { + await worker.initialize(); + expect(await worker.call("environmentResumeLease", params, invocation("resume", enabled))) + .toMatchObject({ providerLeaseId: resource.id, metadata: { resumedFromState: "archived" } }); + expect(resource.start).toHaveBeenCalledExactlyOnceWith(300); + expect(get).toHaveBeenCalledExactlyOnceWith(resource.id); + if (!enabled) { expect(worker.receipts).toEqual([]); return; } + expect(worker.receipts).toHaveLength(1); + const root = worker.receipts[0].span; + expect(root.name).toBe("plugin.worker"); + expect(root.children.map(span => span.name)).toEqual(["lease.lookup", "lease.channel_cleanup", "lease.start", "lease.verify"]); + expect(root.children[2].attributes).toMatchObject({ "paperclip.sandbox.startup.state": "archived" }); + expect(root.children[3].children.map(span => span.name)).toEqual(["lease.workspace", "lease.sentinel", "lease.shell"]); + function checkBounds(parent: Receipt) { + for (const child of parent.children) { + expect(child.startTimeMs).toBeGreaterThanOrEqual(parent.startTimeMs); + expect(child.endTimeMs).toBeGreaterThanOrEqual(child.startTimeMs); + expect(child.endTimeMs).toBeLessThanOrEqual(parent.endTimeMs); + checkBounds(child); + } + } + checkBounds(root); + expect(JSON.stringify(root)).not.toMatch(/private-|fixture-sandbox|fixture-company|\/home\//); + } finally { worker.close(); } + }); + + it("keeps simultaneous resume receipts separate and closes failed starts", async () => { + const slow = sandbox(), failed = sandbox("failed-sandbox", "stopped"); + let release!: () => void, started!: () => void; + const waiting = new Promise(resolve => { release = resolve; }); + const entered = new Promise(resolve => { started = resolve; }); + slow.start.mockImplementation(async () => { started(); await waiting; }); + failed.start.mockRejectedValue(new Error("private-provider-error")); + get.mockImplementation(async id => id === slow.id ? slow : failed); + const worker = workerHarness(); + try { + await worker.initialize(); + const first = worker.call("environmentResumeLease", params, invocation("slow")); + await entered; + await expect(worker.call("environmentResumeLease", { ...params, providerLeaseId: failed.id }, invocation("failed"))) + .rejects.toThrow("private-provider-error"); + release(); await first; + expect(worker.receipts.map(record => record.invocationId)).toEqual(["failed", "slow"]); + const failure = worker.receipts[0].span; + expect(failure.status).toEqual({ code: 2 }); + expect(failure.children.find(span => span.name === "lease.start")?.status).toEqual({ code: 2 }); + expect(failure.children.some(span => span.name === "lease.verify")).toBe(false); + expect(JSON.stringify(worker.receipts)).not.toContain("private-provider-error"); + expect(slow.start).toHaveBeenCalledTimes(1); + expect(failed.start).toHaveBeenCalledTimes(1); + } finally { release(); worker.close(); } + }); + + it("waits for a pending teardown and records the wait under the resume worker", async () => { + const resource = sandbox("fixture-sandbox", "started"); get.mockResolvedValue(resource); + let release!: () => void, stopping!: () => void; + const waiting = new Promise(resolve => { release = resolve; }); + const entered = new Promise(resolve => { stopping = resolve; }); + resource.stop.mockImplementation(async () => { stopping(); await waiting; resource.state = "stopped"; }); + const worker = workerHarness(); + try { + await worker.initialize(); + const teardown = worker.call("environmentReleaseLease", params, invocation("release")); + await entered; + let settled = false; + const resume = worker.call("environmentResumeLease", params, invocation("resume")) + .then(result => { settled = true; return result; }); + // Process the resume request while the actual provider stop is held open. + await new Promise(resolve => setImmediate(resolve)); + expect(settled).toBe(false); + expect(get).toHaveBeenCalledTimes(1); + expect(resource.start).not.toHaveBeenCalled(); + release(); + await teardown; + expect(await resume).toMatchObject({ providerLeaseId: resource.id }); + const root = worker.receipts.find(receipt => receipt.invocationId === "resume")!.span; + expect(root.name).toBe("plugin.worker"); + expect(root.children.filter(span => span.name === "lease.wait_for_teardown")).toHaveLength(1); + expect(root.children[0].name).toBe("lease.wait_for_teardown"); + expect(root.children[0].endTimeMs).toBeLessThanOrEqual(root.children[1].startTimeMs); + expect(get).toHaveBeenCalledTimes(2); + expect(resource.start).toHaveBeenCalledTimes(1); + } finally { release(); worker.close(); } + }); + + it.each([false, true])("records missing-container confirmation and preserves refresh failures: %s", async fails => { + const resource = sandbox("fixture-sandbox", "error"); + resource.recoverable = false; + resource.errorReason = `not found: failed to inspect sandbox container ${resource.id}: Error response from daemon: No such container: ${resource.id}`; + get.mockResolvedValue(resource); + resource.refreshData.mockImplementation(async () => { + if (fails) throw new Error("private-refresh-failure"); + resource.state = "started"; + }); + const worker = workerHarness(); + try { + await worker.initialize(); + const result = worker.call("environmentResumeLease", params, invocation("resume")); + if (fails) await expect(result).rejects.toThrow("private-refresh-failure"); + else expect(await result).toMatchObject({ providerLeaseId: resource.id }); + expect(resource.refreshData).toHaveBeenCalledTimes(1); + const root = worker.receipts[0].span; + expect(root.children.map(span => span.name)).toEqual(fails + ? ["lease.lookup", "lease.refresh"] : ["lease.lookup", "lease.refresh", "lease.verify"]); + expect(root.children[1].status).toEqual(fails ? { code: 2 } : undefined); + expect(resource.start).not.toHaveBeenCalled(); + expect(resource.delete).not.toHaveBeenCalled(); + expect(create).not.toHaveBeenCalled(); + expect(JSON.stringify(worker.receipts)).not.toContain("private-refresh-failure"); + } finally { worker.close(); } + }); + + it.each(["started", "error"])("traces a %s sandbox without adding a provider start", async state => { + const resource = sandbox("fixture-sandbox", state); get.mockResolvedValue(resource); + const worker = workerHarness(); + try { + await worker.initialize(); + await worker.call("environmentResumeLease", params, invocation("resume")); + expect(resource.start).not.toHaveBeenCalled(); + expect(resource.recover).toHaveBeenCalledTimes(state === "error" ? 1 : 0); + const phases = worker.receipts[0].span.children; + expect(phases.some(span => span.name === "lease.start")).toBe(false); + expect(phases.some(span => span.name === "lease.recover")).toBe(state === "error"); + } finally { worker.close(); } + }); + + it("closes the verification group and failing workspace child", async () => { + const resource = sandbox(); get.mockResolvedValue(resource); + resource.getWorkDir.mockRejectedValue(new Error("private-workspace-error")); + const worker = workerHarness(); + try { + await worker.initialize(); + await expect(worker.call("environmentResumeLease", params, invocation("resume"))) + .rejects.toThrow("private-workspace-error"); + const verify = worker.receipts[0].span.children.find(span => span.name === "lease.verify")!; + expect(verify.status).toEqual({ code: 2 }); + expect(verify.children.map(span => span.name)).toEqual(["lease.workspace"]); + expect(verify.children[0].status).toEqual({ code: 2 }); + expect(resource.delete).not.toHaveBeenCalled(); + } finally { worker.close(); } + }); + + it("records setup failure and compensating cleanup as siblings", async () => { + const resource = sandbox(); create.mockResolvedValue(resource); + resource.getWorkDir.mockRejectedValue(new Error("private-workspace-error")); + const worker = workerHarness(); + try { + await worker.initialize(); + await expect(worker.call("environmentAcquireLease", { ...params, runId: "fixture-run" }, invocation("acquire"))) + .rejects.toThrow("private-workspace-error"); + expect(resource.delete).toHaveBeenCalledTimes(1); + const root = worker.receipts[0].span; + expect(root.children.map(span => span.name)).toEqual(["lease.create", "lease.workspace", "lease.cleanup"]); + expect(root.children[1].status).toEqual({ code: 2 }); + expect(root.children[2].status).toBeUndefined(); + } finally { worker.close(); } + }); +}); + +describe("lease tracing cannot change provider work", () => { + it.each(["missing", "before", "after", "during"])("preserves the result and error with a %s tracer failure", async mode => { + const tracer: PluginTracer = { ...NOOP_PLUGIN_TRACER, + ...(mode === "missing" ? {} : { async withSpan(_name: string, work: () => T | Promise): Promise { + if (mode === "before") throw new Error("trace failure"); + const result = work(); + if (mode === "during") throw new Error("trace failure"); + await result; + throw new Error("trace failure"); + } }), + }; + const success = vi.fn(async () => 42), error = new Error("provider failure"), failure = vi.fn(async () => { throw error; }); + expect(await withLeaseSpan(tracer, "lease.lookup", success)).toBe(42); + await expect(withLeaseSpan(tracer, "lease.lookup", failure)).rejects.toBe(error); + expect(success).toHaveBeenCalledTimes(1); expect(failure).toHaveBeenCalledTimes(1); + }); + + it("normalizes unknown provider states before recording", () => { + expect(leaseStateAttributes("provider-private-state")).toEqual({ "paperclip.sandbox.startup.state": "other" }); + }); +}); diff --git a/packages/plugins/sandbox-providers/daytona/src/lease-tracing.ts b/packages/plugins/sandbox-providers/daytona/src/lease-tracing.ts new file mode 100644 index 00000000000..8ad09499f64 --- /dev/null +++ b/packages/plugins/sandbox-providers/daytona/src/lease-tracing.ts @@ -0,0 +1,49 @@ +import type { PluginTracer } from "@paperclipai/plugin-sdk"; + +export type LeaseSpanName = + | "lease.wait_for_teardown" + | "lease.lookup" + | "lease.refresh" + | "lease.channel_cleanup" + | "lease.start" + | "lease.recover" + | "lease.verify" + | "lease.workspace" + | "lease.sentinel" + | "lease.shell" + | "lease.create" + | "lease.expiry" + | "lease.cleanup"; + +/** Keep provider state useful without exporting a new SDK value as free text. */ +export function leaseStateAttributes(state: unknown): Record { + return { + "paperclip.sandbox.startup.state": + state === "started" || state === "stopped" || state === "archived" || state === "error" + ? state : "other", + }; +} + +/** Use the invocation's async parent, while keeping tracer faults out of work. */ +export async function withLeaseSpan( + tracer: PluginTracer, + name: LeaseSpanName, + work: () => Promise, + attributes?: Record, +): Promise { + let result: Promise | undefined; + // A tracer can fail before or after invoking work. Preserve its exact result + // or error and never repeat provider operations in either case. + const runOnce = () => result ??= Promise.resolve().then(work); + try { + if (tracer.withSpan) { + await tracer.withSpan(name, runOnce, { + "paperclip.sandbox.startup.provider": "daytona", + ...attributes, + }); + } + } catch { + // The operation's error is still held by result and is rethrown below. + } + return runOnce(); +} diff --git a/packages/plugins/sandbox-providers/daytona/src/plugin.ts b/packages/plugins/sandbox-providers/daytona/src/plugin.ts index 74dd8029c15..55f1aa8eaf0 100644 --- a/packages/plugins/sandbox-providers/daytona/src/plugin.ts +++ b/packages/plugins/sandbox-providers/daytona/src/plugin.ts @@ -50,6 +50,7 @@ import type { } from "@paperclipai/plugin-sdk"; import { performSyncIn, performSyncOut, withProviderSpan } from "./file-sync.js"; import { DEFAULT_DAYTONA_OPERATION_TIMEOUT_MS } from "./manifest.js"; +import { withLeaseSpan, leaseStateAttributes, type LeaseSpanName } from "./lease-tracing.js"; import { observeSessionStreamExit } from "./session-stream-exit.js"; import { DaytonaIdleActivity, trackDaytonaHooks, type DaytonaIdleProof } from "./idle-activity.js"; @@ -126,6 +127,10 @@ export function getPluginTracer(): PluginTracer { return pluginContext?.tracer ?? NOOP_PLUGIN_TRACER; } +function traceLeaseStep(name: LeaseSpanName, work: () => Promise, attributes?: Record): Promise { + return withLeaseSpan(getPluginTracer(), name, work, attributes); +} + /** * Test seam: set the module-level plugin context, and return a restore function. * `plugin.test.ts` uses it to inject a recording tracer without running `setup`. @@ -528,12 +533,16 @@ async function ensureSandboxStarted(sandbox: Sandbox, timeoutSeconds: number): P const startBoundMs = timeoutSeconds * 1_000 + LIVENESS_START_TIMEOUT_MARGIN_MS; if (sandbox.state === "error") { if (sandbox.recoverable) { - await withLivenessTimeout("sandbox.recover", startBoundMs, () => sandbox.recover(timeoutSeconds)); + await traceLeaseStep("lease.recover", () => + withLivenessTimeout("sandbox.recover", startBoundMs, () => sandbox.recover(timeoutSeconds)), + leaseStateAttributes(sandbox.state)); return; } throw new Error(`Daytona sandbox ${sandbox.id} is in an unrecoverable error state: ${sandbox.errorReason ?? "unknown error"}`); } - await withLivenessTimeout("sandbox.start", startBoundMs, () => sandbox.start(timeoutSeconds)); + await traceLeaseStep("lease.start", () => + withLivenessTimeout("sandbox.start", startBoundMs, () => sandbox.start(timeoutSeconds)), + leaseStateAttributes(sandbox.state)); } function hasMissingSandboxContainer(sandbox: Sandbox): boolean { @@ -1362,6 +1371,7 @@ const sandboxHandleActivityGates = (() => { type SandboxLeaseAdmissionOptions = { allowClosed?: boolean; + traceLeaseWait?: boolean; }; const sandboxHandleLeaseAdmissionStates = (() => { @@ -1402,7 +1412,8 @@ async function withSandboxActivityGate( const teardownGate = sandboxHandleTeardownGates.current(scope); if (teardownGate) { - await teardownGate.promise; + if (options.traceLeaseWait) await traceLeaseStep("lease.wait_for_teardown", () => teardownGate.promise); + else await teardownGate.promise; if (!options.allowClosed && sandboxHandleLeaseAdmissionStates.isClosed(scope)) { throw new Error(`Daytona sandbox lease ${scope.providerLeaseId} is no longer active.`); } @@ -2682,39 +2693,39 @@ const plugin = definePlugin(trackDaytonaHooks({ return timeoutFailure(); }; const acquire = async (): Promise => { - const sandbox = await createSandbox(params, config, { + const sandbox = await traceLeaseStep("lease.create", () => createSandbox(params, config, { onCreateAttempt: (attempt) => { assertActive(); cleanup = attempt; }, onCreateFailure: observeFailure, onSnapshotIdentity: identity => { snapshotIdentity = identity; }, - }); + })); try { assertActive(); if (cleanup) cleanup.observedProviderLeaseId = sandbox.id; phase = "workspace"; - const remoteCwd = await resolveSandboxWorkingDirectory(sandbox); + const remoteCwd = await traceLeaseStep("lease.workspace", () => resolveSandboxWorkingDirectory(sandbox)); assertActive(); phase = "shell"; - const shellCommand = await detectSandboxShellCommand(sandbox, toTimeoutSeconds(Math.max(1, deadline - Date.now()))); + const shellCommand = await traceLeaseStep("lease.shell", () => detectSandboxShellCommand(sandbox, toTimeoutSeconds(Math.max(1, deadline - Date.now())))); assertActive(); // Configure a provider-side destroy time at or before a caller deadline, so // an abandoned sandbox self-destroys even if Paperclip is down. The lease // carries the real provider expiry (or none) as evidence of the bound. phase = "expiry"; - const expiresAt = await configureSandboxExpiry({ + const expiresAt = await traceLeaseStep("lease.expiry", () => configureSandboxExpiry({ sandbox, requestedExpiresAt: params.requestedExpiresAt, nowMs: Date.now(), preserveCreationExpiry: config.ttlMinutes != null, - }); + })); assertActive(); phase = "sentinel"; - const workspaceSentinel = await writeWorkspaceSentinel({ + const workspaceSentinel = await traceLeaseStep("lease.sentinel", () => writeWorkspaceSentinel({ sandbox, remoteCwd, params, config, timeoutSeconds: toTimeoutSeconds(Math.max(1, deadline - Date.now())), - }); + })); assertActive(); sandboxHandleLeaseAdmissionStates.open({ driverKey: params.driverKey, @@ -2757,7 +2768,7 @@ const plugin = definePlugin(trackDaytonaHooks({ cleanupInProgress = true; try { const proof = idleActivity.proof(providerActivityKey(params, config, sandbox.id)); - await sandbox.delete(toTimeoutSeconds(Math.max(1, deadline - Date.now())), true); + await traceLeaseStep("lease.cleanup", () => sandbox.delete(toTimeoutSeconds(Math.max(1, deadline - Date.now())), true)); idleActivity.confirm(proof); } catch (cleanupError) { if (cleanup) { @@ -2821,7 +2832,7 @@ const plugin = definePlugin(trackDaytonaHooks({ throw new Error("The stopped Daytona sandbox is still settling cancelled work. Retry shortly."); } return await withSandboxActivityGate(scope, async () => { - const sandbox = await getSandboxOrNull(scope, { bypassTeardownGate: true }); + const sandbox = await traceLeaseStep("lease.lookup", () => getSandboxOrNull(scope, { bypassTeardownGate: true })); if (!sandbox) { return { providerLeaseId: null, metadata: { expired: true } }; } @@ -2831,7 +2842,7 @@ const plugin = definePlugin(trackDaytonaHooks({ // backup-guarded replacement path. Unknown errors preserve the lease. if (hasMissingSandboxContainer(sandbox)) { try { - await withLivenessTimeout("sandbox.refreshData", config.livenessTimeoutMs, () => sandbox.refreshData()); + await traceLeaseStep("lease.refresh", () => withLivenessTimeout("sandbox.refreshData", config.livenessTimeoutMs, () => sandbox.refreshData())); assertHandleMatchesLease(sandbox, params.providerLeaseId); } catch (error) { evictSandboxHandle(scope); @@ -2859,48 +2870,50 @@ const plugin = definePlugin(trackDaytonaHooks({ // A stopped sandbox loses its pseudo-terminals, so a stored duplex channel // is dead after a real restart. Close and drop every channel on this lease // before the restart, so no stale channel id survives the resume. - await closeDaytonaDuplexChannelsForLease(params.providerLeaseId); + await traceLeaseStep("lease.channel_cleanup", () => closeDaytonaDuplexChannelsForLease(params.providerLeaseId)); } const resumedFromState = sandbox.state ?? null; await ensureSandboxStarted(sandbox, toTimeoutSeconds(config.timeoutMs)); try { - const remoteCwd = await resolveSandboxWorkingDirectory(sandbox, false); - // C3: a resumed lease must clear the workspace sentinel before it is - // trusted, even when the handle came from the cache. On any non-match we - // evict the cached handle and expire the lease so a stale/foreign sandbox - // is never reused on the subsequent (sentinel-skipping) exec path. - const workspaceSentinel = await verifyWorkspaceSentinel({ - sandbox, - remoteCwd, - leaseMetadata: params.leaseMetadata, - timeoutSeconds: toTimeoutSeconds(config.timeoutMs), - }); - if (workspaceSentinel.result !== "matched") { - evictSandboxHandle(scope); - return { - providerLeaseId: null, - metadata: { expired: true, workspaceSentinel }, - }; - } - const shellCommand = await detectSandboxShellCommand( - sandbox, - toTimeoutSeconds(config.timeoutMs), - ); - sandboxHandleCache.markFresh(scope); - sandboxHandleLeaseAdmissionStates.open(scope); - return { - providerLeaseId: sandbox.id, - metadata: leaseMetadata({ - config, + return await traceLeaseStep("lease.verify", async () => { + const remoteCwd = await traceLeaseStep("lease.workspace", () => resolveSandboxWorkingDirectory(sandbox, false)); + // C3: a resumed lease must clear the workspace sentinel before it is + // trusted, even when the handle came from the cache. On any non-match we + // evict the cached handle and expire the lease so a stale/foreign sandbox + // is never reused on the subsequent (sentinel-skipping) exec path. + const workspaceSentinel = await traceLeaseStep("lease.sentinel", () => verifyWorkspaceSentinel({ sandbox, - shellCommand, - remoteCwd: requestedCwd ?? remoteCwd, - resumedLease: true, - resumedFromState, - sandboxState: "started", - workspaceSentinel, - }), - }; + remoteCwd, + leaseMetadata: params.leaseMetadata, + timeoutSeconds: toTimeoutSeconds(config.timeoutMs), + })); + if (workspaceSentinel.result !== "matched") { + evictSandboxHandle(scope); + return { + providerLeaseId: null, + metadata: { expired: true, workspaceSentinel }, + }; + } + const shellCommand = await traceLeaseStep("lease.shell", () => detectSandboxShellCommand( + sandbox, + toTimeoutSeconds(config.timeoutMs), + )); + sandboxHandleCache.markFresh(scope); + sandboxHandleLeaseAdmissionStates.open(scope); + return { + providerLeaseId: sandbox.id, + metadata: leaseMetadata({ + config, + sandbox, + shellCommand, + remoteCwd: requestedCwd ?? remoteCwd, + resumedLease: true, + resumedFromState, + sandboxState: "started", + workspaceSentinel, + }), + }; + }); } catch (error) { evictSandboxHandle(scope); // A timeout, rate limit, or provider 5xx does not prove this sandbox is @@ -2910,7 +2923,7 @@ const plugin = definePlugin(trackDaytonaHooks({ throw error; } }, - { allowClosed: true }, + { allowClosed: true, traceLeaseWait: true }, ); }, diff --git a/server/src/__tests__/plugin-host-services-span.test.ts b/server/src/__tests__/plugin-host-services-span.test.ts index 01b7eb06c7a..a91e6c4e626 100644 --- a/server/src/__tests__/plugin-host-services-span.test.ts +++ b/server/src/__tests__/plugin-host-services-span.test.ts @@ -332,6 +332,36 @@ describe("clampProviderSpanAttributes", () => { }); describe("nested worker timing receipts",()=>{ + it("keeps lease verification beneath its worker and clamps provider state", () => { + mockRecordSpan.mockReset(); + const rootParent = { traceId: "0af7651916cd43dd8448eb211c80319c", spanId: "1111111111111111", traceFlags: 1 }; + const verifyParent = { ...rootParent, spanId: "2222222222222222" }; + mockRecordSpan.mockReturnValueOnce(rootParent).mockReturnValueOnce(verifyParent); + const now = Date.now(); + recordWorkerProviderSpan({ name: "plugin.worker", startTimeMs: now - 100, endTimeMs: now, children: [ + { name: "lease.verify", startTimeMs: now - 90, endTimeMs: now - 10, children: [ + { name: "lease.sentinel", startTimeMs: now - 80, endTimeMs: now - 20, + attributes: { "paperclip.sandbox.startup.state": "archived", token: "private-token" } }, + ] }, + ] }, { traceparent: VALID_TRACEPARENT }); + expect(mockRecordSpan.mock.calls[1][0]).toMatchObject({ name: "sandbox.daytona.lease.verify", parent: rootParent }); + expect(mockRecordSpan.mock.calls[2][0]).toMatchObject({ name: "sandbox.daytona.lease.sentinel", parent: verifyParent, + startTimeMs: now - 80, endTimeMs: now - 20, attributes: { "paperclip.sandbox.startup.state": "archived" } }); + expect(JSON.stringify(mockRecordSpan.mock.calls)).not.toContain("private-token"); + expect(clampProviderSpanAttributes({ "paperclip.sandbox.startup.state": "private-state" })).toEqual({}); + }); + + it("admits every closed lease phase and rejects dynamic phase names", () => { + mockRecordSpan.mockReset(); + const names = ["lease.wait_for_teardown", "lease.lookup", "lease.refresh", "lease.channel_cleanup", + "lease.start", "lease.recover", "lease.verify", "lease.workspace", "lease.sentinel", "lease.shell", + "lease.create", "lease.expiry", "lease.cleanup", "lease.private-resource-id"]; + for (const name of names) recordWorkerProviderSpan({ name }, { traceparent: VALID_TRACEPARENT }); + expect(mockRecordSpan.mock.calls.map(call => call[0].name)).toEqual([ + ...names.slice(0, -1).map(name => `sandbox.daytona.${name}`), "sandbox.daytona.other", + ]); + }); + it("uses host-generated parents, clamps content and bounds child clocks",()=>{ mockRecordSpan.mockReset(); const childParent={traceId:"0af7651916cd43dd8448eb211c80319c",spanId:"1111111111111111",traceFlags:1}; diff --git a/server/src/services/plugin-host-services.ts b/server/src/services/plugin-host-services.ts index 2a9a845d01a..eeff010abbe 100644 --- a/server/src/services/plugin-host-services.ts +++ b/server/src/services/plugin-host-services.ts @@ -537,6 +537,9 @@ const KNOWN_PROVIDER_SPAN_NAMES: ReadonlySet = new Set([ "postUploadCommand", "session.open", "session.close", + "lease.wait_for_teardown", "lease.lookup", "lease.refresh", "lease.channel_cleanup", + "lease.start", "lease.recover", "lease.verify", "lease.workspace", "lease.sentinel", + "lease.shell", "lease.create", "lease.expiry", "lease.cleanup", "plugin.worker", "plugin.host.identity.read", "plugin.host.config.read", "plugin.host.progress.read", "plugin.host.progress.write", "plugin.workspace.prepare", "plugin.storage.queue", "plugin.storage.execute", "plugin.runtime.queue", "plugin.runtime.prepare", "plugin.runtime.reconcile", "plugin.runtime.verify", @@ -564,6 +567,7 @@ const PROVIDER_SPAN_ATTR_ALLOWLIST: ReadonlySet = new Set([ SPAN_ATTRS.transferWallMs, SPAN_ATTRS.transferGuardCount, SPAN_ATTRS.transferDirection, + SPAN_ATTRS.state, "plugin.operation", "plugin.reused", "plugin.item_count", "plugin.bytes", "plugin.call_count", ]); @@ -595,6 +599,10 @@ export function clampProviderSpanAttributes( if (!raw) return clamped; for (const [key, value] of Object.entries(raw)) { if (!PROVIDER_SPAN_ATTR_ALLOWLIST.has(key)) continue; + if (key === SPAN_ATTRS.state) { + if (typeof value === "string" && ["started", "stopped", "archived", "error", "other"].includes(value)) clamped[key] = value; + continue; + } if (key === "plugin.operation") { if (typeof value === "string" && ["request", "queue.wait", "launch.wait", "mount.refresh", "guest.setup", "process.execute", "script.workspace", "script.git", "script.settings", "script.publication", "cleanup", "process.start", "hello", "checkpoint.load"].includes(value)) clamped[key] = value; continue;