From b9e94b85a69bf679818eeef9ecf4655554a89c6b Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Mon, 2 Nov 2026 11:32:03 -0600 Subject: [PATCH] feat(observability): trace Daytona lease acquisition and resume (#18626) ## Thinking Path > - Paperclip manages work performed by AI agents. > - The server prepares a remote execution environment before the agent can respond. > - OpenTelemetry traces show the time spent in each preparation phase. > - A retained Daytona sandbox can take minutes to resume from an archive. > - The provider worker previously exposed no child timings for this operation. > - This pull request adds bounded lease phase spans under the existing worker trace. > - Operators can separate provider startup from lookup, teardown waits, and workspace verification. ## Linked Issues or Issue Description **What existing behavior does this improve?** Daytona environment acquisition and resume tracing. A long worker invocation currently hides the operation that consumed its time. Related tracing foundation: #10999. No duplicate open PR was found. **Subsystem affected** The Daytona sandbox provider and the server's existing plugin span validation boundary. **Proposed behavior** Show lookup, start or recovery, teardown waits, workspace verification, and fresh acquisition setup as timed child spans. Group verification steps beneath one parent. Record the bounded provider state before start, including archived. **Reason and benefit** An operator can identify which step delayed the first agent response. SDK startup includes its internal readiness wait; this change does not claim to measure provider queue time separately. **Breaking changes** The opt-in trace schema gains fixed span names and one closed state attribute. Execution, authorization, resource ownership, deadlines, and retry policies keep their existing contracts. ## What Changed - Add lease phase spans through the existing invocation tracer. - Add the fixed span names and state values to host validation. Define the state key in the shared startup attribute contract. - Preserve the exact work result or error if tracing fails. Never repeat work through the tracing wrapper. - Test worker receipts for archived and warm resume, recovery, concurrency, failure, disabled tracing, and cleanup. - Document the waterfall and its attribution limits. ## Verification - Daytona plugin suite: 525 passed, 7 skipped. The expanded tracing suite separately passes all 12 cases. - Host span validation and instrumentation tests: 46 passed, 3 skipped. - Standalone Daytona TypeScript check passes. - Module boundary and whitespace checks pass. - Full recursive typecheck and full build pass. - The full local Vitest attempt at b007a8e64f20f9fdadb457cc3ce1940208359d65 stopped in chat shard 1: 337 passed, 2 failed, 1478 skipped. One retry-notice case exceeded 15 seconds. The next case then reported that fake timers were no longer installed. A focused rerun of all four retry-notice cases passed. This is not a full local suite pass. - Final head 8e1f81523b3869b9877b44d22c2cb7c938abf014 passes CI and Greptile 5/5, with no unresolved review threads. The CI chat shards pass despite the preserved local timeout attempt. - The expanded lease tracing suite passes 15 tests; host/shared tracing suites pass 66 tests. Disabling the wait flag makes the new teardown test fail, and restoring it passes. Standalone plugin typecheck passes. - The tests drive the real plugin worker RPC and invocation tracer with a controlled provider fixture. They validate receipts and host parent IDs. They do not establish deployment or Honeycomb ingestion. Inspect a new deployed run to verify the exported waterfall. ## Risks - A new provider phase must be added to the closed host allowlist or it appears as other. - SDK-internal start and readiness work remains one measured operation. - Older workers without withSpan run normally without these new detail spans. - Receipt budgets and clock validation can omit detail from very large or invalid receipts. ## Model Used OpenAI Codex, GPT-6, with repository tools and code execution. The exact runtime model ID and context window were not exposed in this session. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [x] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge --------- Co-authored-by: Paperclip --- doc/observability.md | 44 +++ .../src/acpx-engine/startup-timing.ts | 2 + .../daytona/src/lease-tracing.test.ts | 273 ++++++++++++++++++ .../daytona/src/lease-tracing.ts | 49 ++++ .../sandbox-providers/daytona/src/plugin.ts | 117 ++++---- .../plugin-host-services-span.test.ts | 30 ++ server/src/services/plugin-host-services.ts | 8 + 7 files changed, 471 insertions(+), 52 deletions(-) create mode 100644 packages/plugins/sandbox-providers/daytona/src/lease-tracing.test.ts create mode 100644 packages/plugins/sandbox-providers/daytona/src/lease-tracing.ts 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;