feat(observability): add granular OpenTelemetry spans for sandbox startup and execution (#10758)
## Thinking Path > - Paperclip coordinates AI agent work and records execution data. > - The sandbox startup path and the host-to-sandbox execution path need clearer OpenTelemetry spans. > - The trace data now shows wait time, critical path data, and bounded labels. > - This pull request adds bounded spans and closed attribute helpers for sandbox startup and execution. > - The result is better trace data with low cardinality and no secret leakage. ## Linked Issues or Issue Description - No public GitHub issue exists for this branch. - Related PR: #10536 - This PR extends the sandbox OpenTelemetry work with exec spans, root timing, and bounded labels. ## What Changed - Added a closed span-attribute contract for sandbox startup data. - Added a bounded label helper for command and region values. - Threaded the active step context into the execution path. - Added a `sandbox.exec` span with true timestamps and bounded attributes. - Added skipped-step and root-span timing data with low-cardinality context. - Moved handshake sub-times and bridge batch data onto spans. ## Verification - `pnpm --filter @paperclipai/adapter-utils run typecheck` - `pnpm --filter @paperclipai/server run typecheck` - `pnpm --filter @paperclipai/adapter-utils exec vitest run` - `pnpm --filter @paperclipai/server exec vitest run environment-execution-target` - `git log --oneline origin/master..origin/feat/sandbox-startup-otel-spans` - `git diff origin/master...origin/feat/sandbox-startup-otel-spans --stat` ## Risks - Span attribute rules could still miss a future field if new code skips the shared helper. - Low-cardinality labels may hide some detail, but that is the intended tradeoff. - Tracing stays fail-open, so a missing tracer still hides data rather than stopping work. ## Model Used - OpenAI Codex, GPT-5, tool use enabled. The runtime did not expose the context window size. ## 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 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] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge The current head still has one failing required check: `e2e`. The PR stays unready for board handoff until that check passes. --------- Co-authored-by: Paperclip <noreply@paperclip.ing>
This commit is contained in:
Nicky Leach
GitHub
parent
bc5c392331
commit
c09ea7112b
|
|
@ -35,6 +35,7 @@ import {
|
|||
type AcpxEngineExecutorOptions,
|
||||
} from "./execute.js";
|
||||
import { runChildProcess } from "../server-utils.js";
|
||||
import { SANDBOX_STARTUP_SPAN_ATTRS } from "./startup-timing.js";
|
||||
|
||||
|
||||
const tempRoots: string[] = [];
|
||||
|
|
@ -278,15 +279,29 @@ function createRecordingStartupTrace() {
|
|||
return { traceContext, spans };
|
||||
}
|
||||
|
||||
// The closed span-attribute allowlist for a sandbox-start span (Phase 2 + 3).
|
||||
// A test asserts every recorded attribute key is in this set, so a command,
|
||||
// path, id, or error-text key can never ride a span.
|
||||
const ALLOWED_STARTUP_SPAN_ATTRIBUTE_KEYS = new Set([
|
||||
"step",
|
||||
"provider",
|
||||
"roundTrips",
|
||||
"providerExecMs",
|
||||
"providerGetMs",
|
||||
// The closed span-attribute allowlist for a sandbox-start span. A test asserts
|
||||
// every recorded attribute key is in this set, so a command, path, id, or
|
||||
// error-text key can never ride a span. Every key uses the closed
|
||||
// `paperclip.sandbox.startup.` prefix from the attribute contract.
|
||||
const A = SANDBOX_STARTUP_SPAN_ATTRS;
|
||||
const ALLOWED_STARTUP_SPAN_ATTRIBUTE_KEYS = new Set<string>([
|
||||
// Step-span keys.
|
||||
A.provider,
|
||||
A.stepWallMs,
|
||||
A.outcome,
|
||||
// Root-span keys.
|
||||
A.rootWallMs,
|
||||
A.rootWorkMs,
|
||||
A.rootDiffMs,
|
||||
A.coldStart,
|
||||
A.region,
|
||||
A.imageId,
|
||||
A.sandboxId,
|
||||
A.leaseId,
|
||||
// Handshake sub-times and the parallel-batch tag.
|
||||
A.handshakeCreateRuntimeWallMs,
|
||||
A.handshakeEnsureSessionWallMs,
|
||||
A.batch,
|
||||
]);
|
||||
|
||||
describe("shared ACPX engine runtime behavior", () => {
|
||||
|
|
@ -3233,6 +3248,91 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () =
|
|||
}
|
||||
});
|
||||
|
||||
it("records root wall / work / diff times and the bounded context on the root span", async () => {
|
||||
const root = await makeTempRoot();
|
||||
const stateDir = path.join(root, "state");
|
||||
const localCwd = path.join(root, "worktree");
|
||||
const remoteCwd = path.join(root, "remote-workspace");
|
||||
await fs.mkdir(localCwd, { recursive: true });
|
||||
await fs.mkdir(remoteCwd, { recursive: true });
|
||||
// A plugin-backed target with a lease id. The provider clamps to `plugin`
|
||||
// and the lease id rides only as a hash.
|
||||
const executionTarget = {
|
||||
kind: "remote",
|
||||
transport: "sandbox",
|
||||
providerKey: "fake-plugin",
|
||||
leaseId: "lease-super-secret-internal-id",
|
||||
remoteCwd,
|
||||
runner: createLocalSandboxRunner(),
|
||||
};
|
||||
const { traceContext, spans } = createRecordingStartupTrace();
|
||||
|
||||
await runExecutor(
|
||||
{ agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd },
|
||||
{ authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext },
|
||||
);
|
||||
|
||||
const rootSpan = spans.find((span) => span.name === "sandbox.startup" && span.parent === null);
|
||||
expect(rootSpan).toBeTruthy();
|
||||
// The three timing numbers are present, finite, and non-negative.
|
||||
for (const key of [A.rootWallMs, A.rootWorkMs, A.rootDiffMs]) {
|
||||
expect(typeof rootSpan!.attributes[key], `attribute ${key}`).toBe("number");
|
||||
expect(Number.isFinite(rootSpan!.attributes[key] as number)).toBe(true);
|
||||
}
|
||||
expect(rootSpan!.attributes[A.rootWorkMs] as number).toBeGreaterThanOrEqual(0);
|
||||
// A cold start (no warm handle) and the clamped provider family.
|
||||
expect(rootSpan!.attributes[A.coldStart]).toBe(true);
|
||||
expect(rootSpan!.attributes[A.provider]).toBe("plugin");
|
||||
// The lease id rides only as a non-reversible hash, never the raw value.
|
||||
expect(rootSpan!.attributes[A.leaseId]).toMatch(/^[0-9a-f]{12}$/);
|
||||
expect(String(rootSpan!.attributes[A.leaseId])).not.toContain("secret");
|
||||
// The absent region, image id, and sandbox id set no attribute (fail open).
|
||||
expect(rootSpan!.attributes).not.toHaveProperty(A.region);
|
||||
expect(rootSpan!.attributes).not.toHaveProperty(A.imageId);
|
||||
expect(rootSpan!.attributes).not.toHaveProperty(A.sandboxId);
|
||||
});
|
||||
|
||||
it("excludes the nested skills.reconcile wall time from the root work sum (no double count)", async () => {
|
||||
const root = await makeTempRoot();
|
||||
const stateDir = path.join(root, "state");
|
||||
const localCwd = path.join(root, "worktree");
|
||||
const codexHome = path.join(root, "codex-home");
|
||||
await fs.mkdir(localCwd, { recursive: true });
|
||||
await fs.mkdir(codexHome, { recursive: true });
|
||||
const executionTarget = await remoteSandboxTarget(root);
|
||||
const { traceContext, spans } = createRecordingStartupTrace();
|
||||
|
||||
// A codex bring-up runs the codex-home.seed step, which nests skills.reconcile.
|
||||
const { events } = await runExecutor(
|
||||
{
|
||||
agent: "codex",
|
||||
agentCommand: "node ./fake-acp.js",
|
||||
stateDir,
|
||||
cwd: localCwd,
|
||||
env: { CODEX_HOME: codexHome },
|
||||
},
|
||||
{ authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext },
|
||||
);
|
||||
|
||||
const stepEvents = events.filter((event) => event.eventType === "run.startup.step");
|
||||
// The nested skills.reconcile step still emits its own boundary event.
|
||||
const reconcile = stepEvents.find((event) => event.payload?.step === "skills.reconcile");
|
||||
expect(reconcile, "skills.reconcile must still emit its own step event").toBeTruthy();
|
||||
|
||||
// The root work sum is the sum of the top-level step walls only. The nested
|
||||
// skills.reconcile wall sits inside the codex-home.seed wall, so it must not
|
||||
// ride the sum a second time. The sum of every step wall except
|
||||
// skills.reconcile equals the recorded root work sum exactly; each step
|
||||
// reports the same duration to the event and to the root accumulator.
|
||||
const sumExceptReconcile = stepEvents
|
||||
.filter((event) => event.payload?.step !== "skills.reconcile")
|
||||
.reduce((total, event) => total + (event.payload?.durationMs as number), 0);
|
||||
|
||||
const rootSpan = spans.find((span) => span.name === "sandbox.startup" && span.parent === null);
|
||||
expect(rootSpan).toBeTruthy();
|
||||
expect(rootSpan!.attributes[A.rootWorkMs]).toBe(sumExceptReconcile);
|
||||
});
|
||||
|
||||
it("parents both concurrent bridge spans to the root (neither orphans)", async () => {
|
||||
const root = await makeTempRoot();
|
||||
const stateDir = path.join(root, "state");
|
||||
|
|
@ -3252,6 +3352,33 @@ describe("ACPX engine sandbox-start spans (opt-in root + child parenting)", () =
|
|||
const processSession = spans.find((span) => span.name === "bridge.process-session");
|
||||
expect(paperclip?.parent).toBe(rootSpan);
|
||||
expect(processSession?.parent).toBe(rootSpan);
|
||||
// Both bridge spans carry the same batch tag, so the trace marks them as one
|
||||
// parallel batch.
|
||||
expect(paperclip?.attributes[A.batch]).toBe("bridge");
|
||||
expect(processSession?.attributes[A.batch]).toBe("bridge");
|
||||
expect(paperclip?.attributes[A.batch]).toBe(processSession?.attributes[A.batch]);
|
||||
});
|
||||
|
||||
it("records the handshake create-runtime and ensure-session sub-times on the acp.handshake span", async () => {
|
||||
const root = await makeTempRoot();
|
||||
const stateDir = path.join(root, "state");
|
||||
const localCwd = path.join(root, "worktree");
|
||||
await fs.mkdir(localCwd, { recursive: true });
|
||||
const executionTarget = await remoteSandboxTarget(root);
|
||||
const { traceContext, spans } = createRecordingStartupTrace();
|
||||
|
||||
await runExecutor(
|
||||
{ agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd },
|
||||
{ authToken: "real-run-jwt", executionTarget, startupTraceContext: traceContext },
|
||||
);
|
||||
|
||||
const handshake = spans.find((span) => span.name === "acp.handshake");
|
||||
expect(handshake).toBeTruthy();
|
||||
// A cold start records both sub-times as finite float ms on the span.
|
||||
expect(typeof handshake!.attributes[A.handshakeCreateRuntimeWallMs]).toBe("number");
|
||||
expect(handshake!.attributes[A.handshakeCreateRuntimeWallMs] as number).toBeGreaterThanOrEqual(0);
|
||||
expect(typeof handshake!.attributes[A.handshakeEnsureSessionWallMs]).toBe("number");
|
||||
expect(handshake!.attributes[A.handshakeEnsureSessionWallMs] as number).toBeGreaterThanOrEqual(0);
|
||||
});
|
||||
|
||||
it("keeps every span attribute inside the closed allowlist (no command/path/id keys)", async () => {
|
||||
|
|
@ -3560,7 +3687,7 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () =>
|
|||
expect(handshake!.payload?.ensureSessionMs as number).toBeGreaterThanOrEqual(0);
|
||||
});
|
||||
|
||||
it("emits no acp.handshake event when a warm-handle hit skips the handshake", async () => {
|
||||
it("emits a skipped acp.handshake event when a warm-handle hit skips the handshake", async () => {
|
||||
const root = await makeTempRoot();
|
||||
const stateDir = path.join(root, "state");
|
||||
const warmHandles = new Map();
|
||||
|
|
@ -3586,8 +3713,9 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () =>
|
|||
onMeta: async () => {},
|
||||
onEvent: async () => {},
|
||||
} as never);
|
||||
// The second run reuses the warm handle, so the whole handshake block is
|
||||
// skipped — it must emit NO acp.handshake event (not a zero-duration one).
|
||||
// The second run reuses the warm handle, so the handshake does no work. It
|
||||
// must emit exactly one acp.handshake event with outcome = skipped and a
|
||||
// zero wall time, not a misleading zero-work `ok` event.
|
||||
await execute({
|
||||
runId: "run-warm-2",
|
||||
agent: { id: "agent-1", companyId: "company-1" },
|
||||
|
|
@ -3601,10 +3729,12 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () =>
|
|||
},
|
||||
} as never);
|
||||
|
||||
const handshakeEmitted = secondEvents.some(
|
||||
const handshakeEvents = secondEvents.filter(
|
||||
(event) => event.eventType === "run.startup.step" && event.payload?.step === "acp.handshake",
|
||||
);
|
||||
expect(handshakeEmitted).toBe(false);
|
||||
expect(handshakeEvents).toHaveLength(1);
|
||||
expect(handshakeEvents[0]!.payload?.outcome).toBe("skipped");
|
||||
expect(handshakeEvents[0]!.payload?.durationMs).toBe(0);
|
||||
});
|
||||
|
||||
it("does not emit startup-step events on a local (non-sandbox) run except workspace.resolve", async () => {
|
||||
|
|
|
|||
|
|
@ -84,9 +84,12 @@ import {
|
|||
DEFAULT_ACP_ENGINE_WARM_HANDLE_IDLE_MS,
|
||||
} from "./constants.js";
|
||||
import {
|
||||
emitSkippedStartupStep,
|
||||
measureStartupStep,
|
||||
NOOP_STARTUP_SPAN,
|
||||
NOOP_STARTUP_TRACE_CONTEXT,
|
||||
setSandboxRootSpanAttributes,
|
||||
type SandboxRootSpanContext,
|
||||
type StartupSpan,
|
||||
type StartupSpanContext,
|
||||
type StartupStepMeasureOptions,
|
||||
|
|
@ -972,7 +975,15 @@ async function prepareCodexSkillRuntime(input: {
|
|||
const skillsHome = path.join(effectiveCodexHome, "skills");
|
||||
await fs.mkdir(skillsHome, { recursive: true });
|
||||
// Step 3 — skills.reconcile: nested inside the codex-home seed (step 2), so it
|
||||
// emits its own boundary event at this call-site.
|
||||
// emits its own boundary event and span at this call-site. It must NOT add its
|
||||
// wall time to the root work sum. The enclosing step 2 wall already covers this
|
||||
// interval, so a second `onWallMs` call would count the same milliseconds
|
||||
// twice. Drop `onWallMs` for the nested step; keep every other attribution
|
||||
// field.
|
||||
const nestedStepMetrics: StartupStepMeasureOptions = {
|
||||
...(input.stepMetrics ?? {}),
|
||||
onWallMs: undefined,
|
||||
};
|
||||
await measureStartupStep({ onEvent: input.onEvent }, now, "skills.reconcile", () =>
|
||||
reconcileManagedCodexSkills({
|
||||
skillsHome,
|
||||
|
|
@ -980,7 +991,7 @@ async function prepareCodexSkillRuntime(input: {
|
|||
selectedSkills,
|
||||
onLog: input.onLog,
|
||||
}),
|
||||
input.stepMetrics ?? {},
|
||||
nestedStepMetrics,
|
||||
);
|
||||
|
||||
for (const entry of selectedSkills) {
|
||||
|
|
@ -1355,10 +1366,12 @@ async function buildRuntime(input: {
|
|||
ctx: AdapterExecutionContext;
|
||||
engine: AcpxEngineSettings;
|
||||
deps: AcpxEngineExecutorOptions;
|
||||
// The injected tracer plus the root-span parent-context token. Merged into
|
||||
// every startup-step option set, so each boundary span parents to the one
|
||||
// root span (`sandbox.startup`) that the executor opens.
|
||||
spanParent: Pick<StartupStepMeasureOptions, "tracer" | "parentContext">;
|
||||
// The injected tracer, the root-span parent-context token, and the
|
||||
// context-builder. Merged into every startup-step option set, so each
|
||||
// boundary span parents to the one root span (`sandbox.startup`) that the
|
||||
// executor opens, and each step publishes its own child context for an inner
|
||||
// exec span to parent to.
|
||||
spanParent: Pick<StartupStepMeasureOptions, "tracer" | "parentContext" | "contextWithSpan">;
|
||||
}): Promise<AcpxPreparedRuntime> {
|
||||
const { runId, agent, config, context, authToken } = input.ctx;
|
||||
// Injectable monotonic clock for per-step startup timing. Hoisted above the
|
||||
|
|
@ -1458,8 +1471,14 @@ async function buildRuntime(input: {
|
|||
// would double-count each other if we sampled them here. Keep the shared
|
||||
// counter attribution on the sequential startup phases only; the concurrent
|
||||
// bridge steps still emit duration telemetry (and a span), just not
|
||||
// misleading per-step round-trip/provider deltas.
|
||||
const concurrentBridgeStepMetrics: StartupStepMeasureOptions = { ...input.spanParent };
|
||||
// misleading per-step round-trip/provider deltas. A shared `batch` tag marks
|
||||
// the two spans as one parallel batch, and `criticalPath: false` keeps their
|
||||
// inner exec spans off the critical path (their wall time overlaps).
|
||||
const concurrentBridgeStepMetrics: StartupStepMeasureOptions = {
|
||||
...input.spanParent,
|
||||
batch: STARTUP_BRIDGE_BATCH,
|
||||
criticalPath: false,
|
||||
};
|
||||
const shapedWorkspaceEnv = shapePaperclipWorkspaceEnvForExecution({
|
||||
workspaceCwd: effectiveWorkspaceCwd,
|
||||
workspaceWorktreePath,
|
||||
|
|
@ -2873,6 +2892,11 @@ function warmHandleMatches(
|
|||
* low-cardinality constant, never derived from run/user data. */
|
||||
const STARTUP_ROOT_SPAN_NAME = "sandbox.startup";
|
||||
|
||||
/** The shared batch tag for the two parallel bridge steps. It is a fixed
|
||||
* low-cardinality literal, so it marks the two spans as one batch without
|
||||
* carrying run or user data. */
|
||||
const STARTUP_BRIDGE_BATCH = "bridge";
|
||||
|
||||
/**
|
||||
* Open the one root span for a sandbox bring-up and return its parent-context
|
||||
* token plus a guarded `end`. The span parents every startup boundary span:
|
||||
|
|
@ -2882,7 +2906,14 @@ const STARTUP_ROOT_SPAN_NAME = "sandbox.startup";
|
|||
* flow. With no injected trace context, the tracer is a no-op and the span is
|
||||
* a no-op.
|
||||
*/
|
||||
function openStartupRootSpan(tracing: StartupTraceContext): {
|
||||
function openStartupRootSpan(
|
||||
tracing: StartupTraceContext,
|
||||
nowMs: () => number,
|
||||
// Return the final root-span numbers and context at end time. The work sum
|
||||
// and the cold-start flag are known only after the bring-up runs, so the
|
||||
// caller reads them lazily here.
|
||||
finalize: () => { workMs: number; context: SandboxRootSpanContext },
|
||||
): {
|
||||
parentContext: StartupSpanContext;
|
||||
end: (failed: boolean) => void;
|
||||
} {
|
||||
|
|
@ -2898,6 +2929,7 @@ function openStartupRootSpan(tracing: StartupTraceContext): {
|
|||
} catch {
|
||||
parentContext = undefined;
|
||||
}
|
||||
const startedAtMs = nowMs();
|
||||
let ended = false;
|
||||
return {
|
||||
parentContext,
|
||||
|
|
@ -2905,6 +2937,11 @@ function openStartupRootSpan(tracing: StartupTraceContext): {
|
|||
if (ended) return;
|
||||
ended = true;
|
||||
try {
|
||||
// The root span records its own wall time, the step-work sum, and the
|
||||
// bounded context. `setSandboxRootSpanAttributes` sets only the closed
|
||||
// allowlist, so no raw id or image reference rides the span.
|
||||
const { workMs, context } = finalize();
|
||||
setSandboxRootSpanAttributes(span, { wallMs: nowMs() - startedAtMs, workMs }, context);
|
||||
// `2` is `SpanStatusCode.ERROR`. `adapter-utils` stays OTel-free, so it
|
||||
// uses the numeric value that a real injected span reads as the error
|
||||
// status.
|
||||
|
|
@ -2956,8 +2993,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
executionTarget: ctx.executionTarget,
|
||||
legacyRemoteExecution: ctx.executionTransport?.remoteExecution,
|
||||
});
|
||||
const targetsRemoteSandbox =
|
||||
startupExecutionTarget?.kind === "remote" && startupExecutionTarget.transport === "sandbox";
|
||||
const sandboxTarget =
|
||||
startupExecutionTarget?.kind === "remote" && startupExecutionTarget.transport === "sandbox"
|
||||
? startupExecutionTarget
|
||||
: null;
|
||||
const targetsRemoteSandbox = sandboxTarget !== null;
|
||||
// Open the one root span for this bring-up. It spans `buildRuntime` through
|
||||
// `acp.handshake`, so every startup boundary span parents to it. `spanParent`
|
||||
// carries the injected tracer + the root parent-context token into each
|
||||
|
|
@ -2968,10 +3008,40 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
targetsRemoteSandbox && ctx.startupTraceContext
|
||||
? ctx.startupTraceContext
|
||||
: NOOP_STARTUP_TRACE_CONTEXT;
|
||||
const rootSpan = openStartupRootSpan(tracing);
|
||||
const spanParent: Pick<StartupStepMeasureOptions, "tracer" | "parentContext"> = {
|
||||
// The sum of the step wall times. The root span records it as `root.work_ms`
|
||||
// and the difference from its own wall time as `root.diff_ms` (the overlap
|
||||
// the parallel steps saved). Every step reports its wall time through
|
||||
// `onWallMs`; a skipped step adds zero.
|
||||
let stepWallSumMs = 0;
|
||||
// Whether this bring-up is a cold start (no warm handle). Set once the warm-
|
||||
// handle lookup runs below; it stays undefined on an early build failure, so
|
||||
// the root span omits the attribute (fail open).
|
||||
let coldStart: boolean | undefined;
|
||||
const rootSpan = openStartupRootSpan(tracing, now, () => ({
|
||||
workMs: stepWallSumMs,
|
||||
context: {
|
||||
coldStart,
|
||||
// The provider key and the lease id are the only low-cardinality
|
||||
// context values this provider-agnostic layer holds. The region, the
|
||||
// image id, and the sandbox id are not threaded here, so the root span
|
||||
// omits them (fail open). The lease id rides only as a hash.
|
||||
provider: sandboxTarget?.providerKey ?? undefined,
|
||||
leaseId: sandboxTarget?.leaseId ?? undefined,
|
||||
},
|
||||
}));
|
||||
const spanParent: Pick<
|
||||
StartupStepMeasureOptions,
|
||||
"tracer" | "parentContext" | "contextWithSpan" | "onWallMs"
|
||||
> = {
|
||||
tracer: tracing.tracer,
|
||||
parentContext: rootSpan.parentContext,
|
||||
// Each step uses this to publish its own child context, so an inner exec
|
||||
// span parents to the step span, not to the root.
|
||||
contextWithSpan: (span) => tracing.contextWithSpan(span),
|
||||
// Accumulate each step wall time into the root work sum.
|
||||
onWallMs: (wallMs) => {
|
||||
stepWallSumMs += wallMs;
|
||||
},
|
||||
};
|
||||
let prepared: AcpxPreparedRuntime;
|
||||
try {
|
||||
|
|
@ -3056,6 +3126,9 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
// split reports nothing for it.
|
||||
let createRuntimeMs: number | undefined;
|
||||
let runtime: AcpRuntime;
|
||||
// A warm handle reuses the running ACP runtime; a miss constructs one. The
|
||||
// root span records this as `cold_start`.
|
||||
coldStart = !cached?.runtime;
|
||||
if (cached?.runtime) {
|
||||
runtime = cached.runtime;
|
||||
} else {
|
||||
|
|
@ -3102,6 +3175,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
...(createRuntimeMs !== undefined ? { createRuntimeMs } : {}),
|
||||
...(ensureSessionMs !== undefined ? { ensureSessionMs } : {}),
|
||||
}),
|
||||
// The same two sub-times ride the span as fixed, closed keys.
|
||||
spanWallTimes: () => ({
|
||||
createRuntime: createRuntimeMs,
|
||||
ensureSession: ensureSessionMs,
|
||||
}),
|
||||
});
|
||||
} catch (err) {
|
||||
if (!resumeSessionId || !isResumeFailure(err)) throw err;
|
||||
|
|
@ -3131,8 +3209,21 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
extra: () => ({
|
||||
...(retryEnsureSessionMs !== undefined ? { ensureSessionMs: retryEnsureSessionMs } : {}),
|
||||
}),
|
||||
// The retry reuses the runtime from the first attempt, so it reports
|
||||
// only its own ensure-session sub-time on the span.
|
||||
spanWallTimes: () => ({ ensureSession: retryEnsureSessionMs }),
|
||||
});
|
||||
}
|
||||
} else {
|
||||
// Warm-handle hit: a compatible cached handle reuses the running ACP
|
||||
// agent, so the `acp.handshake` step does no work. Emit a step span and
|
||||
// event with `outcome = skipped` and a zero wall time, so the trace and
|
||||
// the run log show the skip as a distinct outcome, never a misleading
|
||||
// zero-work `ok` step.
|
||||
await emitSkippedStartupStep(ctx, "acp.handshake", {
|
||||
tracer: prepared.stepMetrics.tracer,
|
||||
parentContext: prepared.stepMetrics.parentContext,
|
||||
});
|
||||
}
|
||||
// A compatible warm handle reuses the already-running ACP agent and does
|
||||
// not emit another spawn event. Persist its known identity on this run
|
||||
|
|
|
|||
|
|
@ -1,7 +1,18 @@
|
|||
import { describe, expect, it, vi } from "vitest";
|
||||
import type { AdapterRuntimeEvent } from "../types.js";
|
||||
import type { StartupSpan, StartupTracer } from "./startup-timing.js";
|
||||
import { measureStartupStep, normalizeProviderFamily } from "./startup-timing.js";
|
||||
import {
|
||||
clampSpanLabel,
|
||||
emitSkippedStartupStep,
|
||||
getActiveStepContext,
|
||||
measureStartupStep,
|
||||
normalizeProviderFamily,
|
||||
SANDBOX_STARTUP_SPAN_ATTR_PREFIX,
|
||||
SANDBOX_STARTUP_SPAN_ATTRS,
|
||||
setSandboxRootSpanAttributes,
|
||||
} from "./startup-timing.js";
|
||||
|
||||
const A = SANDBOX_STARTUP_SPAN_ATTRS;
|
||||
|
||||
/**
|
||||
* A recording span for the mock tracer. It captures the attribute set, the
|
||||
|
|
@ -247,7 +258,10 @@ describe("measureStartupStep", () => {
|
|||
|
||||
expect(spans).toHaveLength(1);
|
||||
expect(spans[0]!.name).toBe("stage.sync");
|
||||
expect(spans[0]!.attributes.step).toBe("stage.sync");
|
||||
// The span name carries the step; no redundant `step` attribute rides it.
|
||||
expect(spans[0]!.attributes).not.toHaveProperty("step");
|
||||
// The step wall time rides the closed, type-suffixed attribute key.
|
||||
expect(spans[0]!.attributes[A.stepWallMs]).toBe(0);
|
||||
expect(spans[0]!.endCount).toBe(1);
|
||||
});
|
||||
|
||||
|
|
@ -268,7 +282,7 @@ describe("measureStartupStep", () => {
|
|||
expect(spans[0]!.status?.code).toBe(2);
|
||||
});
|
||||
|
||||
it("sets the same roundTrips / providerExecMs / providerGetMs deltas on the payload and the span", async () => {
|
||||
it("keeps the roundTrips / providerExecMs / providerGetMs deltas on the payload but off the span", async () => {
|
||||
let t = 0;
|
||||
const now = () => t;
|
||||
let execCount = 5;
|
||||
|
|
@ -293,14 +307,16 @@ describe("measureStartupStep", () => {
|
|||
providerGetMs: () => getMs,
|
||||
});
|
||||
|
||||
// The counter deltas still ride the event payload.
|
||||
const payload = events[0]!.payload as Record<string, unknown>;
|
||||
expect(payload.roundTrips).toBe(3);
|
||||
expect(payload.providerExecMs).toBe(600);
|
||||
expect(payload.providerGetMs).toBe(15);
|
||||
// The span carries the identical deltas — one build block feeds both.
|
||||
expect(spans[0]!.attributes.roundTrips).toBe(3);
|
||||
expect(spans[0]!.attributes.providerExecMs).toBe(600);
|
||||
expect(spans[0]!.attributes.providerGetMs).toBe(15);
|
||||
// The per-execution `sandbox.exec` spans now carry the round-trip detail, so
|
||||
// the step span no longer duplicates it.
|
||||
expect(spans[0]!.attributes).not.toHaveProperty(A.roundTripsCount);
|
||||
expect(spans[0]!.attributes).not.toHaveProperty(A.providerExecSumMs);
|
||||
expect(spans[0]!.attributes).not.toHaveProperty(A.providerGetSumMs);
|
||||
});
|
||||
|
||||
it("sets no span attribute (and no payload field) when a reader returns undefined", async () => {
|
||||
|
|
@ -318,8 +334,8 @@ describe("measureStartupStep", () => {
|
|||
providerExecMs: () => undefined as unknown as number,
|
||||
});
|
||||
|
||||
expect(spans[0]!.attributes).not.toHaveProperty("roundTrips");
|
||||
expect(spans[0]!.attributes).not.toHaveProperty("providerExecMs");
|
||||
expect(spans[0]!.attributes).not.toHaveProperty(A.roundTripsCount);
|
||||
expect(spans[0]!.attributes).not.toHaveProperty(A.providerExecSumMs);
|
||||
expect(Object.values(spans[0]!.attributes).some((v) => Number.isNaN(v))).toBe(false);
|
||||
const payload = events[0]!.payload as Record<string, unknown>;
|
||||
expect(payload).not.toHaveProperty("roundTrips");
|
||||
|
|
@ -334,14 +350,14 @@ describe("measureStartupStep", () => {
|
|||
tracer: custom.tracer,
|
||||
provider: "acme-cloud-runner",
|
||||
});
|
||||
expect(custom.spans[0]!.attributes.provider).toBe("plugin");
|
||||
expect(custom.spans[0]!.attributes[A.provider]).toBe("plugin");
|
||||
|
||||
const builtIn = makeMockTracer();
|
||||
await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", {
|
||||
tracer: builtIn.tracer,
|
||||
provider: "daytona",
|
||||
});
|
||||
expect(builtIn.spans[0]!.attributes.provider).toBe("daytona");
|
||||
expect(builtIn.spans[0]!.attributes[A.provider]).toBe("daytona");
|
||||
});
|
||||
|
||||
it("normalizeProviderFamily maps every non-built-in key to plugin", () => {
|
||||
|
|
@ -369,16 +385,21 @@ describe("measureStartupStep", () => {
|
|||
});
|
||||
|
||||
expect(Object.keys(spans[0]!.attributes).sort()).toEqual(
|
||||
["provider", "providerExecMs", "providerGetMs", "roundTrips", "step"],
|
||||
[A.provider, A.stepWallMs, A.outcome].sort(),
|
||||
);
|
||||
// extra() keys stay off the span.
|
||||
expect(spans[0]!.attributes).not.toHaveProperty("createRuntimeMs");
|
||||
expect(spans[0]!.attributes).not.toHaveProperty("ensureSessionMs");
|
||||
// No free-form identifier / command / path key leaks in. The pattern uses
|
||||
// no `i` flag, so the camelCase `Id` matches `runId` / `userId` but not the
|
||||
// "id" inside the allowlisted `provider`.
|
||||
// Every key uses the closed prefix, so no free-form command / path / id key
|
||||
// can ride the span.
|
||||
for (const key of Object.keys(spans[0]!.attributes)) {
|
||||
expect(key).not.toMatch(/command|args|env|stdout|stderr|path|url|repo|ref|branch|Id|_id|error|message/);
|
||||
expect(key.startsWith(SANDBOX_STARTUP_SPAN_ATTR_PREFIX)).toBe(true);
|
||||
}
|
||||
// No forbidden segment (command / arg / env / output / path / raw id) rides
|
||||
// the span key set, even after the prefix.
|
||||
for (const key of Object.keys(spans[0]!.attributes)) {
|
||||
const suffix = key.slice(SANDBOX_STARTUP_SPAN_ATTR_PREFIX.length);
|
||||
expect(suffix).not.toMatch(/command|args|env|stdout|stderr|path|url|repo|ref|branch|error|message/);
|
||||
}
|
||||
});
|
||||
|
||||
|
|
@ -397,4 +418,230 @@ describe("measureStartupStep", () => {
|
|||
expect(result).toBe("ok");
|
||||
expect(events[0]!.payload).toMatchObject({ step: "stage.sync" });
|
||||
});
|
||||
|
||||
it("sets a batch tag on the span from the batch option", async () => {
|
||||
const { tracer, spans } = makeMockTracer();
|
||||
await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "bridge.paperclip", async () => "ok", {
|
||||
tracer,
|
||||
batch: "bridge",
|
||||
});
|
||||
expect(spans[0]!.attributes[A.batch]).toBe("bridge");
|
||||
});
|
||||
|
||||
it("maps handshake sub-times to fixed span keys and skips a non-finite one", async () => {
|
||||
const { tracer, spans } = makeMockTracer();
|
||||
await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "acp.handshake", async () => "ok", {
|
||||
tracer,
|
||||
spanWallTimes: () => ({ createRuntime: 12, ensureSession: 6988 }),
|
||||
});
|
||||
expect(spans[0]!.attributes[A.handshakeCreateRuntimeWallMs]).toBe(12);
|
||||
expect(spans[0]!.attributes[A.handshakeEnsureSessionWallMs]).toBe(6988);
|
||||
|
||||
// A retry reports only its own ensure-session sub-time; the absent create-
|
||||
// runtime value sets no attribute.
|
||||
const retry = makeMockTracer();
|
||||
await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "acp.handshake", async () => "ok", {
|
||||
tracer: retry.tracer,
|
||||
spanWallTimes: () => ({ ensureSession: 40 }),
|
||||
});
|
||||
expect(retry.spans[0]!.attributes[A.handshakeEnsureSessionWallMs]).toBe(40);
|
||||
expect(retry.spans[0]!.attributes).not.toHaveProperty(A.handshakeCreateRuntimeWallMs);
|
||||
});
|
||||
|
||||
it("sets outcome = ok on a settled step and outcome = failed on a throwing step", async () => {
|
||||
const okEvents: AdapterRuntimeEvent[] = [];
|
||||
const ok = makeMockTracer();
|
||||
await measureStartupStep({ onEvent: vi.fn(async (e: AdapterRuntimeEvent) => { okEvents.push(e); }) },
|
||||
() => 0, "stage.sync", async () => "ok", { tracer: ok.tracer });
|
||||
expect(ok.spans[0]!.attributes[A.outcome]).toBe("ok");
|
||||
expect((okEvents[0]!.payload as Record<string, unknown>).outcome).toBe("ok");
|
||||
|
||||
const failEvents: AdapterRuntimeEvent[] = [];
|
||||
const fail = makeMockTracer();
|
||||
await expect(
|
||||
measureStartupStep({ onEvent: vi.fn(async (e: AdapterRuntimeEvent) => { failEvents.push(e); }) },
|
||||
() => 0, "acp.handshake", async () => { throw new Error("boom"); }, { tracer: fail.tracer }),
|
||||
).rejects.toThrow("boom");
|
||||
expect(fail.spans[0]!.attributes[A.outcome]).toBe("failed");
|
||||
expect((failEvents[0]!.payload as Record<string, unknown>).outcome).toBe("failed");
|
||||
});
|
||||
|
||||
it("sets each step-span attribute key with the closed prefix and a type suffix", async () => {
|
||||
const { tracer, spans } = makeMockTracer();
|
||||
await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "stage.sync", async () => "ok", {
|
||||
tracer,
|
||||
provider: "daytona",
|
||||
roundTrips: () => 3,
|
||||
providerExecMs: () => 600,
|
||||
providerGetMs: () => 15,
|
||||
});
|
||||
|
||||
const keys = Object.keys(spans[0]!.attributes);
|
||||
expect(keys.length).toBeGreaterThan(0);
|
||||
for (const key of keys) {
|
||||
expect(key.startsWith(SANDBOX_STARTUP_SPAN_ATTR_PREFIX)).toBe(true);
|
||||
}
|
||||
// The step wall time and the counters use their type suffixes.
|
||||
expect(keys).toContain(A.stepWallMs);
|
||||
expect(A.stepWallMs.endsWith(".wall_ms")).toBe(true);
|
||||
expect(A.roundTripsCount.endsWith(".count")).toBe(true);
|
||||
expect(A.providerExecSumMs.endsWith(".sum_ms")).toBe(true);
|
||||
expect(A.providerGetSumMs.endsWith(".sum_ms")).toBe(true);
|
||||
});
|
||||
});
|
||||
|
||||
describe("setSandboxRootSpanAttributes", () => {
|
||||
it("records wall / work / diff and bounds the context, hashing ids and image", () => {
|
||||
const span = new MockSpan("sandbox.startup", undefined);
|
||||
setSandboxRootSpanAttributes(span, { wallMs: 800, workMs: 1000 }, {
|
||||
coldStart: true,
|
||||
provider: "acme-custom-runner",
|
||||
region: "us-east-1",
|
||||
imageId: "registry.internal/team/secret-codename:sha-1234",
|
||||
sandboxId: "sbx-secret-internal-id",
|
||||
leaseId: "lease-secret-internal-id",
|
||||
});
|
||||
|
||||
expect(span.attributes[A.rootWallMs]).toBe(800);
|
||||
expect(span.attributes[A.rootWorkMs]).toBe(1000);
|
||||
expect(span.attributes[A.rootDiffMs]).toBe(200);
|
||||
expect(span.attributes[A.coldStart]).toBe(true);
|
||||
// Provider clamps to the bounded family; region stays a known value.
|
||||
expect(span.attributes[A.provider]).toBe("plugin");
|
||||
expect(span.attributes[A.region]).toBe("us-east-1");
|
||||
// The image id and both ids ride only as non-reversible hashes.
|
||||
for (const key of [A.imageId, A.sandboxId, A.leaseId]) {
|
||||
expect(String(span.attributes[key])).toMatch(/^[0-9a-f]{12}$/);
|
||||
}
|
||||
for (const value of Object.values(span.attributes).map(String)) {
|
||||
expect(value).not.toContain("secret");
|
||||
expect(value).not.toContain("codename");
|
||||
expect(value).not.toContain("registry.internal");
|
||||
}
|
||||
});
|
||||
|
||||
it("maps an unknown region to `unknown` and omits every absent context value", () => {
|
||||
const span = new MockSpan("sandbox.startup", undefined);
|
||||
setSandboxRootSpanAttributes(span, { wallMs: 5, workMs: 5 }, { region: "moon-base-1" });
|
||||
expect(span.attributes[A.region]).toBe("unknown");
|
||||
expect(span.attributes).not.toHaveProperty(A.coldStart);
|
||||
expect(span.attributes).not.toHaveProperty(A.provider);
|
||||
expect(span.attributes).not.toHaveProperty(A.imageId);
|
||||
expect(span.attributes).not.toHaveProperty(A.sandboxId);
|
||||
expect(span.attributes).not.toHaveProperty(A.leaseId);
|
||||
});
|
||||
});
|
||||
|
||||
describe("emitSkippedStartupStep", () => {
|
||||
it("emits a span and event with outcome = skipped and a zero wall time", async () => {
|
||||
const { tracer, spans } = makeMockTracer();
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => {
|
||||
events.push(event);
|
||||
});
|
||||
|
||||
await emitSkippedStartupStep({ onEvent }, "acp.handshake", { tracer });
|
||||
|
||||
expect(spans).toHaveLength(1);
|
||||
expect(spans[0]!.name).toBe("acp.handshake");
|
||||
expect(spans[0]!.attributes[A.stepWallMs]).toBe(0);
|
||||
expect(spans[0]!.attributes[A.outcome]).toBe("skipped");
|
||||
expect(spans[0]!.endCount).toBe(1);
|
||||
|
||||
expect(events).toHaveLength(1);
|
||||
expect(events[0]!.payload).toMatchObject({
|
||||
step: "acp.handshake",
|
||||
durationMs: 0,
|
||||
outcome: "skipped",
|
||||
});
|
||||
});
|
||||
|
||||
it("emits the event with no injected tracer and does not throw", async () => {
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
await emitSkippedStartupStep(
|
||||
{ onEvent: vi.fn(async (e: AdapterRuntimeEvent) => { events.push(e); }) },
|
||||
"acp.handshake",
|
||||
);
|
||||
expect(events[0]!.payload).toMatchObject({ step: "acp.handshake", outcome: "skipped" });
|
||||
});
|
||||
});
|
||||
|
||||
describe("getActiveStepContext", () => {
|
||||
it("returns null when no measured step runs", () => {
|
||||
expect(getActiveStepContext()).toBeNull();
|
||||
});
|
||||
|
||||
it("exposes the active step context to inner code while fn runs, then clears it", async () => {
|
||||
const { tracer, spans } = makeMockTracer();
|
||||
let seen: ReturnType<typeof getActiveStepContext> = null;
|
||||
|
||||
await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "stage.sync", async () => {
|
||||
// Inner code reads the active step context through the getter.
|
||||
seen = getActiveStepContext();
|
||||
return "ok";
|
||||
}, {
|
||||
tracer,
|
||||
// The server builds a child-context token whose active span is the step
|
||||
// span. Model it as `{ span }`, the same shape the recording tracer reads.
|
||||
contextWithSpan: (span) => ({ span }),
|
||||
});
|
||||
|
||||
expect(seen).not.toBeNull();
|
||||
// The published span is the one open step span.
|
||||
expect(seen!.span).toBe(spans[0]);
|
||||
// The parent token points at the step span, so an inner exec span parents
|
||||
// to it.
|
||||
expect(seen!.parentContext).toEqual({ span: spans[0] });
|
||||
// A regular step is on the critical path by default.
|
||||
expect(seen!.criticalPath).toBe(true);
|
||||
// The context clears once the step body settles.
|
||||
expect(getActiveStepContext()).toBeNull();
|
||||
});
|
||||
|
||||
it("carries criticalPath = false when the step opts out (parallel steps)", async () => {
|
||||
let seen: ReturnType<typeof getActiveStepContext> = null;
|
||||
await measureStartupStep({ onEvent: vi.fn(async () => {}) }, () => 0, "bridge.paperclip", async () => {
|
||||
seen = getActiveStepContext();
|
||||
}, { criticalPath: false });
|
||||
expect(seen!.criticalPath).toBe(false);
|
||||
});
|
||||
});
|
||||
|
||||
describe("clampSpanLabel", () => {
|
||||
it("returns a known command label unchanged and maps an unknown command to `other`", () => {
|
||||
expect(clampSpanLabel("command", "sh")).toBe("sh");
|
||||
expect(clampSpanLabel("command", "git")).toBe("git");
|
||||
// A full command line, a path, or a secret-like argument is not a known
|
||||
// basename, so it maps to the bounded fallback and never leaks.
|
||||
expect(clampSpanLabel("command", "bash -lc 'rm -rf /secret/path'")).toBe("other");
|
||||
expect(clampSpanLabel("command", "/usr/local/bin/node")).toBe("other");
|
||||
expect(clampSpanLabel("command", undefined)).toBe("other");
|
||||
});
|
||||
|
||||
it("returns a known region unchanged and maps an unknown region to `unknown`", () => {
|
||||
expect(clampSpanLabel("region", "us-east-1")).toBe("us-east-1");
|
||||
expect(clampSpanLabel("region", "moon-base-1")).toBe("unknown");
|
||||
expect(clampSpanLabel("region", undefined)).toBe("unknown");
|
||||
});
|
||||
|
||||
it("hashes an id or image label to a non-reversible short digest and never returns the raw value", () => {
|
||||
const raw = "lease-super-secret-internal-codename";
|
||||
for (const label of ["image_id", "sandbox_id", "lease_id"]) {
|
||||
const clamped = clampSpanLabel(label, raw);
|
||||
expect(clamped).toBeTruthy();
|
||||
expect(clamped).not.toBe(raw);
|
||||
expect(clamped).not.toContain("secret");
|
||||
expect(clamped).not.toContain("codename");
|
||||
// A stable 12-hex-character digest prefix.
|
||||
expect(clamped).toMatch(/^[0-9a-f]{12}$/);
|
||||
}
|
||||
// A missing id yields no attribute (fail open — never a raw value).
|
||||
expect(clampSpanLabel("sandbox_id", undefined)).toBeUndefined();
|
||||
expect(clampSpanLabel("sandbox_id", "")).toBeUndefined();
|
||||
});
|
||||
|
||||
it("drops an unknown label name so the caller sets no attribute for it", () => {
|
||||
expect(clampSpanLabel("nonsense", "anything")).toBeUndefined();
|
||||
expect(clampSpanLabel("stdout", "secret output")).toBeUndefined();
|
||||
});
|
||||
});
|
||||
|
|
|
|||
|
|
@ -1,3 +1,5 @@
|
|||
import { AsyncLocalStorage } from "node:async_hooks";
|
||||
import { createHash } from "node:crypto";
|
||||
import type { AdapterExecutionContext, AdapterRuntimeEvent } from "../types.js";
|
||||
|
||||
/**
|
||||
|
|
@ -39,6 +41,183 @@ export function normalizeProviderFamily(key: string | undefined): string {
|
|||
return PLUGIN_PROVIDER_FAMILY;
|
||||
}
|
||||
|
||||
/**
|
||||
* The common prefix for every sandbox-startup span attribute. One prefix keeps
|
||||
* the attribute namespace closed and easy to find in the telemetry backend.
|
||||
*/
|
||||
export const SANDBOX_STARTUP_SPAN_ATTR_PREFIX = "paperclip.sandbox.startup.";
|
||||
|
||||
/**
|
||||
* The closed attribute-name contract for every sandbox-startup span. This is
|
||||
* the single source of truth for the harness span attributes. Each name uses
|
||||
* the `paperclip.sandbox.startup.` prefix and a type suffix:
|
||||
*
|
||||
* - `*.wall_ms` — one wall-clock time in float milliseconds.
|
||||
* - `*.sum_ms` — a sum of wall-clock times in float milliseconds.
|
||||
* - `*.count` — a count.
|
||||
*
|
||||
* The producer sets only these keys. It never sets a free-form key, so a
|
||||
* command, a path, an argument, or an environment value can never ride a span.
|
||||
*/
|
||||
export const SANDBOX_STARTUP_SPAN_ATTRS = {
|
||||
/** The low-cardinality provider family (through `normalizeProviderFamily`). */
|
||||
provider: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}provider`,
|
||||
/** The step or execution outcome: `ok`, `skipped`, or `failed`. */
|
||||
outcome: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}outcome`,
|
||||
/** The wall-clock time of one measured step. */
|
||||
stepWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}step.wall_ms`,
|
||||
/** The number of host-to-sandbox round trips a step made. */
|
||||
roundTripsCount: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}round_trips.count`,
|
||||
/** The sum of provider `executeCommand` wall time a step made. */
|
||||
providerExecSumMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}provider_exec.sum_ms`,
|
||||
/** The sum of provider handle-refetch wall time a step made. */
|
||||
providerGetSumMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}provider_get.sum_ms`,
|
||||
/** The clamped `argv[0]` command label of one execution. */
|
||||
execCommand: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.command`,
|
||||
/** The numeric process exit code of one execution. */
|
||||
execExitCode: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.exit_code`,
|
||||
/** The host-measured wall time of one execution. */
|
||||
execWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.wall_ms`,
|
||||
/** The provider handle-fetch wait before one execution ran. */
|
||||
execWaitBeforeMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.wait_before_ms`,
|
||||
/** The in-sandbox run time of one execution. */
|
||||
execSandboxMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.sandbox_ms`,
|
||||
/** The transport time the host adds around one execution. */
|
||||
execNetworkMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.network_ms`,
|
||||
/** Whether one execution sits on the startup critical path. */
|
||||
execCriticalPath: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}exec.critical_path`,
|
||||
/** The root-span wall time of the whole bring-up. */
|
||||
rootWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}root.wall_ms`,
|
||||
/** The sum of the step wall times of the whole bring-up. */
|
||||
rootWorkMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}root.work_ms`,
|
||||
/** The difference between the work sum and the wall time (overlap). */
|
||||
rootDiffMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}root.diff_ms`,
|
||||
/** Whether this bring-up is a cold start (no warm handle). */
|
||||
coldStart: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}cold_start`,
|
||||
/** The clamped region label (through `clampSpanLabel`). */
|
||||
region: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}region`,
|
||||
/** The hashed image-id label (through `clampSpanLabel`). */
|
||||
imageId: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}image_id`,
|
||||
/** The hashed sandbox-id label (through `clampSpanLabel`). */
|
||||
sandboxId: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}sandbox_id`,
|
||||
/** The hashed lease-id label (through `clampSpanLabel`). */
|
||||
leaseId: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}lease_id`,
|
||||
/** The create-runtime sub-time of the `acp.handshake` step. */
|
||||
handshakeCreateRuntimeWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}handshake.create_runtime.wall_ms`,
|
||||
/** The ensure-session sub-time of the `acp.handshake` step. */
|
||||
handshakeEnsureSessionWallMs: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}handshake.ensure_session.wall_ms`,
|
||||
/** A shared low-cardinality tag that marks two steps as one parallel batch. */
|
||||
batch: `${SANDBOX_STARTUP_SPAN_ATTR_PREFIX}batch`,
|
||||
} as const;
|
||||
|
||||
/** The closed value set for the `outcome` attribute. */
|
||||
export const SANDBOX_STARTUP_OUTCOME = {
|
||||
ok: "ok",
|
||||
skipped: "skipped",
|
||||
failed: "failed",
|
||||
} as const;
|
||||
|
||||
export type SandboxStartupOutcome =
|
||||
(typeof SANDBOX_STARTUP_OUTCOME)[keyof typeof SANDBOX_STARTUP_OUTCOME];
|
||||
|
||||
/**
|
||||
* The known command labels. A raw `argv[0]` outside this set maps to `other`,
|
||||
* so a full command line, a path, or an argument never rides a span. Keep this
|
||||
* list closed and small; a new command that is safe to name adds one entry.
|
||||
*/
|
||||
const KNOWN_COMMAND_LABELS: ReadonlySet<string> = new Set([
|
||||
"sh",
|
||||
"bash",
|
||||
"env",
|
||||
"mkdir",
|
||||
"rm",
|
||||
"mv",
|
||||
"cp",
|
||||
"ln",
|
||||
"cat",
|
||||
"echo",
|
||||
"printf",
|
||||
"test",
|
||||
"chmod",
|
||||
"true",
|
||||
"tar",
|
||||
"git",
|
||||
"node",
|
||||
"npm",
|
||||
"pnpm",
|
||||
"sudo",
|
||||
"bwrap",
|
||||
]);
|
||||
|
||||
/**
|
||||
* The known region labels. A raw region outside this set maps to `unknown`, so
|
||||
* a free-form region string never widens the attribute cardinality. Keep this
|
||||
* list closed; a new supported region adds one entry.
|
||||
*/
|
||||
const KNOWN_REGION_LABELS: ReadonlySet<string> = new Set([
|
||||
"us-east-1",
|
||||
"us-east-2",
|
||||
"us-west-1",
|
||||
"us-west-2",
|
||||
"eu-west-1",
|
||||
"eu-central-1",
|
||||
"ap-southeast-1",
|
||||
"ap-southeast-2",
|
||||
"ap-northeast-1",
|
||||
]);
|
||||
|
||||
/** The fallback value for a raw command outside the known-command allowlist. */
|
||||
const OTHER_COMMAND_LABEL = "other";
|
||||
/** The fallback value for a raw region outside the known-region allowlist. */
|
||||
const UNKNOWN_REGION_LABEL = "unknown";
|
||||
|
||||
/**
|
||||
* Map a raw label value to a non-reversible short hash. An id or an image
|
||||
* reference can hold an internal codename or a secret-like string, so the span
|
||||
* carries a hash, never the raw value. The hash is a stable 12-hex-character
|
||||
* prefix of the SHA-256 digest; it is not reversible and it is low-collision
|
||||
* for correlation.
|
||||
*/
|
||||
function hashLabelValue(value: string): string {
|
||||
return createHash("sha256").update(value).digest("hex").slice(0, 12);
|
||||
}
|
||||
|
||||
/**
|
||||
* Bound a span label value to a closed, low-cardinality set. This is the one
|
||||
* boundary function for every free-form label. It is a hard-coded per-label
|
||||
* map, the same pattern as `normalizeProviderFamily`:
|
||||
*
|
||||
* - `command` — a known command basename maps to itself; any other value maps
|
||||
* to `other`, so a full command line, a path, or an argument never leaks.
|
||||
* - `region` — a known region maps to itself; any other value maps to
|
||||
* `unknown`.
|
||||
* - `image_id` / `sandbox_id` / `lease_id` — the raw value maps to a
|
||||
* non-reversible short hash, because it can hold an internal codename or a
|
||||
* secret-like string, and the telemetry backend may index it.
|
||||
*
|
||||
* An unknown label name returns `undefined`, so the caller drops it. A missing
|
||||
* value for a hashed label returns `undefined` too (fail open — never a raw
|
||||
* value, never an empty attribute).
|
||||
*/
|
||||
export function clampSpanLabel(name: string, value: string | undefined): string | undefined {
|
||||
switch (name) {
|
||||
case "command":
|
||||
return value !== undefined && KNOWN_COMMAND_LABELS.has(value)
|
||||
? value
|
||||
: OTHER_COMMAND_LABEL;
|
||||
case "region":
|
||||
return value !== undefined && KNOWN_REGION_LABELS.has(value)
|
||||
? value
|
||||
: UNKNOWN_REGION_LABEL;
|
||||
case "image_id":
|
||||
case "sandbox_id":
|
||||
case "lease_id":
|
||||
return value && value.length > 0 ? hashLabelValue(value) : undefined;
|
||||
default:
|
||||
return undefined;
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* The value of `SpanStatusCode.ERROR` in `@opentelemetry/api`. `adapter-utils`
|
||||
* stays OTel-free, so the timing helper uses the numeric value directly. A real
|
||||
|
|
@ -127,6 +306,43 @@ export const NOOP_STARTUP_TRACE_CONTEXT: StartupTraceContext = {
|
|||
contextWithSpan: () => undefined,
|
||||
};
|
||||
|
||||
/**
|
||||
* The active step context that `measureStartupStep` publishes while it runs the
|
||||
* step body `fn`. Inner code (for example the host→sandbox exec seam) reads it
|
||||
* through `getActiveStepContext()` to parent a child span to the step span.
|
||||
*
|
||||
* - `span` — the open step span. A child span may set its status or read it.
|
||||
* - `parentContext` — a parent-context token whose active span is the step span.
|
||||
* A child span opened with this token parents to the step span. It is opaque
|
||||
* to `adapter-utils`; the server builds it through `contextWithSpan`.
|
||||
* - `criticalPath` — whether the step sits on the startup critical path. Two
|
||||
* overlapping steps (the parallel bridges) set it `false`; every other step
|
||||
* is `true`.
|
||||
*/
|
||||
export interface ActiveStepContext {
|
||||
readonly span: StartupSpan;
|
||||
readonly parentContext: StartupSpanContext;
|
||||
readonly criticalPath: boolean;
|
||||
}
|
||||
|
||||
/**
|
||||
* The one storage for the active step context. `measureStartupStep` runs the
|
||||
* step body inside it; inner code reads it with `getActiveStepContext()`. It is
|
||||
* a module-level singleton, so the value propagates across `await` boundaries
|
||||
* and across package boundaries that share this module.
|
||||
*/
|
||||
const activeStepContextStorage = new AsyncLocalStorage<ActiveStepContext>();
|
||||
|
||||
/**
|
||||
* Return the active step context, or `null` when no measured step is running.
|
||||
* Inner code parents a child span to the step span through
|
||||
* `getActiveStepContext()?.parentContext`. A `null` result is a no-op: the
|
||||
* caller opens no child span or opens an unparented span.
|
||||
*/
|
||||
export function getActiveStepContext(): ActiveStepContext | null {
|
||||
return activeStepContextStorage.getStore() ?? null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Set a numeric span attribute only when the value is a finite number. A reader
|
||||
* that returns `undefined` (the counter is unavailable) yields no attribute,
|
||||
|
|
@ -180,8 +396,11 @@ function finiteDelta(
|
|||
* attributes, so a free-form key cannot widen the closed span allowlist.
|
||||
* - `tracer` — an injected structural tracer. It defaults to a no-op, so the
|
||||
* span path changes no runtime behavior until the server injects a real
|
||||
* tracer. The span carries only the closed attribute allowlist (`step`, the
|
||||
* normalized `provider`, and the finite counter deltas).
|
||||
* tracer. The span carries only the closed attribute allowlist from
|
||||
* `SANDBOX_STARTUP_SPAN_ATTRS`: the normalized `provider`, the step wall time,
|
||||
* and the outcome. The step name rides the span name, not an attribute. The
|
||||
* round-trip and provider-duration detail stays on the payload and on the
|
||||
* per-execution `sandbox.exec` child spans.
|
||||
* - `parentContext` — an opaque parent-context token from the root span. When
|
||||
* set, the step's span parents to that root. `measureStartupStep` forwards it
|
||||
* to `startSpan` and never inspects it, so parenting stays explicit and does
|
||||
|
|
@ -198,6 +417,42 @@ export interface StartupStepMeasureOptions {
|
|||
tracer?: StartupTracer;
|
||||
parentContext?: StartupSpanContext;
|
||||
provider?: string;
|
||||
/**
|
||||
* Build a parent-context token whose active span is a given span. The server
|
||||
* binds it to `@opentelemetry/api`. `measureStartupStep` uses it once, after
|
||||
* it opens the step span, to publish the step's child context on the active
|
||||
* step context. Inner code reads that context to parent an exec span to the
|
||||
* step span. When absent, the active step context carries no parent token, so
|
||||
* an inner exec span opens unparented (a no-op when tracing is off).
|
||||
*/
|
||||
contextWithSpan?: (span: StartupSpan) => StartupSpanContext;
|
||||
/**
|
||||
* Whether the step sits on the startup critical path. It rides the active
|
||||
* step context, so an inner exec span records it. Two overlapping steps (the
|
||||
* parallel bridges) pass `false`; every other step defaults to `true`.
|
||||
*/
|
||||
criticalPath?: boolean;
|
||||
/**
|
||||
* Report the step wall time (float ms) once the step settles. The executor
|
||||
* accumulates it into the root-span work sum. A throwing reporter never
|
||||
* changes startup control flow.
|
||||
*/
|
||||
onWallMs?: (wallMs: number) => void;
|
||||
/**
|
||||
* A shared low-cardinality batch tag. Two steps that run in parallel (the
|
||||
* bridges) pass the same value, so the trace marks them as one batch. It
|
||||
* rides the span as the closed `…batch` attribute. Pass only a fixed literal,
|
||||
* never run or user data.
|
||||
*/
|
||||
batch?: string;
|
||||
/**
|
||||
* Named wall-time sub-splits (float ms) that ride the step span as fixed,
|
||||
* closed attribute keys. Only `acp.handshake` uses it today, for the
|
||||
* create-runtime and ensure-session sub-times. The helper maps each value to
|
||||
* a hard-coded attribute key, so a free-form key can never widen the closed
|
||||
* span allowlist. A non-finite value sets no attribute.
|
||||
*/
|
||||
spanWallTimes?: () => Partial<Record<"createRuntime" | "ensureSession", number>>;
|
||||
}
|
||||
|
||||
function buildStepEvent(payload: Record<string, unknown>): AdapterRuntimeEvent {
|
||||
|
|
@ -223,11 +478,11 @@ function buildStepEvent(payload: Record<string, unknown>): AdapterRuntimeEvent {
|
|||
* calls this helper, so it emits no event (never a zero).
|
||||
*
|
||||
* When `options.tracer` is injected, the helper also opens one span at `start`
|
||||
* and ends it in the `finally`. The span carries a closed attribute allowlist:
|
||||
* `step`, the normalized `provider`, and the finite counter deltas
|
||||
* (`roundTrips` / `providerExecMs` / `providerGetMs`). A throwing `fn` sets the
|
||||
* span error status before the span ends. The span build reuses the same delta
|
||||
* values as the event payload, so the two paths never drift. The tracer
|
||||
* and ends it in the `finally`. The span carries a closed attribute allowlist
|
||||
* from `SANDBOX_STARTUP_SPAN_ATTRS`: the normalized `provider`, the step wall
|
||||
* time, and the outcome (`ok` or `failed`). The step name rides the span name.
|
||||
* A throwing `fn` sets the span error status before the span ends and the
|
||||
* outcome is `failed`. The counter deltas stay on the event payload. The tracer
|
||||
* defaults to a no-op, so a caller with no tracer changes nothing. Every span
|
||||
* call sits inside the same error swallow as the event sink, so a throwing
|
||||
* tracer never changes startup control flow.
|
||||
|
|
@ -245,11 +500,15 @@ export async function measureStartupStep<T>(
|
|||
const providerGetStart = options.providerGetMs?.();
|
||||
|
||||
// Open the span with only the low-cardinality allowlisted attributes known at
|
||||
// the start: the step name and the normalized provider family.
|
||||
// the start: the normalized provider family. The span name already carries
|
||||
// the step name, so no redundant `step` attribute rides the span.
|
||||
const tracer = options.tracer ?? NOOP_TRACER;
|
||||
const startAttributes: Record<string, string> = { step };
|
||||
const startAttributes: Record<string, string> = {};
|
||||
if (options.provider !== undefined) {
|
||||
startAttributes.provider = normalizeProviderFamily(options.provider);
|
||||
startAttributes[SANDBOX_STARTUP_SPAN_ATTRS.provider] = normalizeProviderFamily(options.provider);
|
||||
}
|
||||
if (options.batch !== undefined) {
|
||||
startAttributes[SANDBOX_STARTUP_SPAN_ATTRS.batch] = options.batch;
|
||||
}
|
||||
let span: StartupSpan;
|
||||
try {
|
||||
|
|
@ -259,9 +518,28 @@ export async function measureStartupStep<T>(
|
|||
span = NOOP_SPAN;
|
||||
}
|
||||
|
||||
// Publish the active step context while `fn` runs. Inner code (the host→
|
||||
// sandbox exec seam) reads it to parent an exec span to this step span. The
|
||||
// parent token is the step span's own child context; a missing
|
||||
// `contextWithSpan` (no injected trace context) yields `undefined`, so an
|
||||
// inner exec span opens unparented — a no-op when tracing is off. The
|
||||
// `contextWithSpan` call is guarded, so a throwing helper never changes
|
||||
// startup control flow.
|
||||
let stepChildContext: StartupSpanContext;
|
||||
try {
|
||||
stepChildContext = options.contextWithSpan?.(span);
|
||||
} catch {
|
||||
stepChildContext = undefined;
|
||||
}
|
||||
const activeStep: ActiveStepContext = {
|
||||
span,
|
||||
parentContext: stepChildContext,
|
||||
criticalPath: options.criticalPath ?? true,
|
||||
};
|
||||
|
||||
let stepFailed = false;
|
||||
try {
|
||||
return await fn();
|
||||
return await activeStepContextStorage.run(activeStep, fn);
|
||||
} catch (err) {
|
||||
stepFailed = true;
|
||||
throw err;
|
||||
|
|
@ -275,7 +553,13 @@ export async function measureStartupStep<T>(
|
|||
const providerExecMs = finiteDelta(options.providerExecMs, providerExecStart);
|
||||
const providerGetMs = finiteDelta(options.providerGetMs, providerGetStart);
|
||||
|
||||
const payload: Record<string, unknown> = { step, durationMs };
|
||||
// The step outcome. A throwing `fn` is `failed`; a settled `fn` is `ok`. A
|
||||
// step that a warm cache skips uses `emitSkippedStartupStep` instead.
|
||||
const outcome: SandboxStartupOutcome = stepFailed
|
||||
? SANDBOX_STARTUP_OUTCOME.failed
|
||||
: SANDBOX_STARTUP_OUTCOME.ok;
|
||||
|
||||
const payload: Record<string, unknown> = { step, durationMs, outcome };
|
||||
if (roundTrips !== undefined) payload.roundTrips = roundTrips;
|
||||
if (providerExecMs !== undefined) payload.providerExecMs = providerExecMs;
|
||||
if (providerGetMs !== undefined) payload.providerGetMs = providerGetMs;
|
||||
|
|
@ -287,14 +571,29 @@ export async function measureStartupStep<T>(
|
|||
|
||||
try {
|
||||
if (stepFailed) span.setStatus({ code: SPAN_STATUS_CODE_ERROR });
|
||||
setFiniteNumberAttr(span, "roundTrips", roundTrips);
|
||||
setFiniteNumberAttr(span, "providerExecMs", providerExecMs);
|
||||
setFiniteNumberAttr(span, "providerGetMs", providerGetMs);
|
||||
// The step span carries only the step wall time and the outcome. The
|
||||
// per-execution `sandbox.exec` child spans now carry the round-trip and
|
||||
// provider-duration detail, so the step span no longer duplicates them.
|
||||
setFiniteNumberAttr(span, SANDBOX_STARTUP_SPAN_ATTRS.stepWallMs, durationMs);
|
||||
span.setAttribute(SANDBOX_STARTUP_SPAN_ATTRS.outcome, outcome);
|
||||
if (options.spanWallTimes) {
|
||||
// Map each named sub-time to a hard-coded, closed attribute key, so a
|
||||
// caller cannot widen the span allowlist with a free-form key.
|
||||
const sub = options.spanWallTimes();
|
||||
setFiniteNumberAttr(span, SANDBOX_STARTUP_SPAN_ATTRS.handshakeCreateRuntimeWallMs, sub.createRuntime);
|
||||
setFiniteNumberAttr(span, SANDBOX_STARTUP_SPAN_ATTRS.handshakeEnsureSessionWallMs, sub.ensureSession);
|
||||
}
|
||||
span.end();
|
||||
} catch {
|
||||
// Observability must not change startup control flow.
|
||||
}
|
||||
|
||||
try {
|
||||
options.onWallMs?.(durationMs);
|
||||
} catch {
|
||||
// Observability must not change startup control flow.
|
||||
}
|
||||
|
||||
try {
|
||||
await ctx.onEvent?.(buildStepEvent(payload));
|
||||
} catch {
|
||||
|
|
@ -302,3 +601,114 @@ export async function measureStartupStep<T>(
|
|||
}
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* The two root-span timing numbers. `wallMs` is the root span's own wall time.
|
||||
* `workMs` is the sum of the step wall times. The difference (`workMs − wallMs`)
|
||||
* is the overlap the parallel steps saved.
|
||||
*/
|
||||
export interface SandboxRootSpanTimings {
|
||||
wallMs: number;
|
||||
workMs: number;
|
||||
}
|
||||
|
||||
/**
|
||||
* The low-cardinality root-span context. Each field is optional and omitted
|
||||
* when absent (fail open — never an invented value). The helper below bounds
|
||||
* each value: `provider` through `normalizeProviderFamily`, `region` through a
|
||||
* small allowlist, and each id or image through a non-reversible hash.
|
||||
*/
|
||||
export interface SandboxRootSpanContext {
|
||||
coldStart?: boolean;
|
||||
provider?: string;
|
||||
region?: string;
|
||||
imageId?: string;
|
||||
sandboxId?: string;
|
||||
leaseId?: string;
|
||||
}
|
||||
|
||||
/**
|
||||
* Assemble every root-span (`sandbox.startup`) attribute in one place. This is
|
||||
* the single producer-side boundary for the root span: it sets only the closed
|
||||
* `paperclip.sandbox.startup.` allowlist. It records the wall, work, and diff
|
||||
* times, and the bounded context. A raw id, an image reference, or a region
|
||||
* never rides the span un-bounded, and an absent value sets no attribute.
|
||||
*/
|
||||
export function setSandboxRootSpanAttributes(
|
||||
span: StartupSpan,
|
||||
timings: SandboxRootSpanTimings,
|
||||
context: SandboxRootSpanContext,
|
||||
): void {
|
||||
const A = SANDBOX_STARTUP_SPAN_ATTRS;
|
||||
setFiniteNumberAttr(span, A.rootWallMs, timings.wallMs);
|
||||
setFiniteNumberAttr(span, A.rootWorkMs, timings.workMs);
|
||||
setFiniteNumberAttr(span, A.rootDiffMs, timings.workMs - timings.wallMs);
|
||||
if (context.coldStart !== undefined) span.setAttribute(A.coldStart, context.coldStart);
|
||||
if (context.provider !== undefined) {
|
||||
span.setAttribute(A.provider, normalizeProviderFamily(context.provider));
|
||||
}
|
||||
// A region rides only when a value is present; an unknown region maps to
|
||||
// `unknown`, never a free-form string.
|
||||
if (context.region !== undefined) {
|
||||
const region = clampSpanLabel("region", context.region);
|
||||
if (region !== undefined) span.setAttribute(A.region, region);
|
||||
}
|
||||
// The image id and the ids ride only as non-reversible hashes.
|
||||
const imageId = clampSpanLabel("image_id", context.imageId);
|
||||
if (imageId !== undefined) span.setAttribute(A.imageId, imageId);
|
||||
const sandboxId = clampSpanLabel("sandbox_id", context.sandboxId);
|
||||
if (sandboxId !== undefined) span.setAttribute(A.sandboxId, sandboxId);
|
||||
const leaseId = clampSpanLabel("lease_id", context.leaseId);
|
||||
if (leaseId !== undefined) span.setAttribute(A.leaseId, leaseId);
|
||||
}
|
||||
|
||||
/** The options a skipped step reuses from a measured step: the tracer, the root
|
||||
* parent-context token, and the raw provider key. */
|
||||
export type SkippedStartupStepOptions = Pick<
|
||||
StartupStepMeasureOptions,
|
||||
"tracer" | "parentContext" | "provider"
|
||||
>;
|
||||
|
||||
/**
|
||||
* Emit one `run.startup.step` span and event for a step that a warm cache
|
||||
* skips, with `outcome = skipped` and a zero wall time. A skipped step runs no
|
||||
* work, so this helper opens and ends the span without a body. It shows the
|
||||
* skip as a real, distinct outcome, never a misleading zero-work `ok` step.
|
||||
*
|
||||
* The span and the event carry the closed allowlist: the step name (the span
|
||||
* name), the normalized `provider` (when given), `step.wall_ms = 0`, and
|
||||
* `outcome = skipped`. Every tracer and sink call sits inside an error swallow,
|
||||
* so a throwing tracer or sink never changes startup control flow. The tracer
|
||||
* defaults to a no-op, so a caller with no tracer only emits the event.
|
||||
*/
|
||||
export async function emitSkippedStartupStep(
|
||||
ctx: Pick<AdapterExecutionContext, "onEvent">,
|
||||
step: string,
|
||||
options: SkippedStartupStepOptions = {},
|
||||
): Promise<void> {
|
||||
const tracer = options.tracer ?? NOOP_TRACER;
|
||||
const startAttributes: Record<string, string> = {};
|
||||
if (options.provider !== undefined) {
|
||||
startAttributes[SANDBOX_STARTUP_SPAN_ATTRS.provider] = normalizeProviderFamily(options.provider);
|
||||
}
|
||||
let span: StartupSpan;
|
||||
try {
|
||||
span = tracer.startSpan(step, { attributes: startAttributes }, options.parentContext);
|
||||
} catch {
|
||||
span = NOOP_SPAN;
|
||||
}
|
||||
try {
|
||||
span.setAttribute(SANDBOX_STARTUP_SPAN_ATTRS.stepWallMs, 0);
|
||||
span.setAttribute(SANDBOX_STARTUP_SPAN_ATTRS.outcome, SANDBOX_STARTUP_OUTCOME.skipped);
|
||||
span.end();
|
||||
} catch {
|
||||
// Observability must not change startup control flow.
|
||||
}
|
||||
try {
|
||||
await ctx.onEvent?.(
|
||||
buildStepEvent({ step, durationMs: 0, outcome: SANDBOX_STARTUP_OUTCOME.skipped }),
|
||||
);
|
||||
} catch {
|
||||
// Observability must not change startup control flow.
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -23,6 +23,12 @@ export interface RunProcessResult {
|
|||
stderr: string;
|
||||
pid: number | null;
|
||||
startedAt: string | null;
|
||||
// The stop timestamp and the measured wall time of one execution. Both are
|
||||
// optional and additive: a producer that does not measure them leaves them
|
||||
// absent, so the many existing `RunProcessResult` producers stay unchanged.
|
||||
// The sandbox runner sets them, so the exec span records a true wall time.
|
||||
finishedAt?: string | null;
|
||||
durationMs?: number | null;
|
||||
terminalResultCleanup?: TerminalResultCleanupEvidence | null;
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -67,10 +67,19 @@ configured. With no endpoint the whole span path is a no-op. Paperclip opens the
|
|||
spans only for a run that targets a remote sandbox. A local run and an SSH run
|
||||
stay out of these spans.
|
||||
|
||||
Span attributes use a closed allowlist. A command, an argument, an environment
|
||||
value, a file path, an identifier, or program output never rides a span. It rides
|
||||
neither as an attribute nor as an event. Each numeric attribute is finite.
|
||||
Paperclip omits an attribute when its value is absent.
|
||||
Every span attribute uses the closed `paperclip.sandbox.startup.` prefix and
|
||||
rides a fixed allowlist. A command line, an argument, an environment value, a
|
||||
file path, program output, or a raw identifier never rides a span. It rides
|
||||
neither as an attribute nor as an event. The producer bounds each free-form
|
||||
value:
|
||||
|
||||
- A command basename maps to a small known set. Any other value maps to `other`.
|
||||
- A region maps to a small known set. Any other value maps to `unknown`.
|
||||
- An image id, a sandbox id, and a lease id ride only as a non-reversible short
|
||||
hash.
|
||||
|
||||
Each numeric attribute is finite. Paperclip omits an attribute when its value is
|
||||
absent, never a misleading `0`.
|
||||
|
||||
### Spans
|
||||
|
||||
|
|
@ -84,38 +93,76 @@ Paperclip omits an attribute when its value is absent.
|
|||
| `bridge.paperclip` | Paperclip bridge start step. | `sandbox.startup` |
|
||||
| `bridge.process-session` | Process-session bridge start step. | `sandbox.startup` |
|
||||
| `acp.handshake` | ACP session handshake step. | `sandbox.startup` |
|
||||
| `provider.execute` | One host-to-sandbox provider exec call. | none |
|
||||
| `sandbox.exec` | One host-to-sandbox execution. | the active step span |
|
||||
|
||||
A step span name is the step name. The `sandbox.exec` span parents to the step
|
||||
span that runs the execution, so each execution nests under its step. With no
|
||||
active trace context the exec span opens unparented.
|
||||
|
||||
The root span sets the error status when the bring-up fails. Each step span sets
|
||||
the error status when its step fails.
|
||||
the error status when its step fails. The `sandbox.exec` span sets the error
|
||||
status when the exit code is non-zero or the execution throws.
|
||||
|
||||
### Startup span attributes
|
||||
### Outcome values
|
||||
|
||||
The bring-up step spans use this closed attribute allowlist.
|
||||
The `paperclip.sandbox.startup.outcome` attribute uses a closed value set:
|
||||
|
||||
- `ok` — the step or the execution settled with a success result.
|
||||
- `skipped` — a warm cache skipped the step; the step ran no work.
|
||||
- `failed` — the step or the execution threw, or the exit code was non-zero.
|
||||
|
||||
### Root span attributes
|
||||
|
||||
The `sandbox.startup` root span uses this closed attribute allowlist.
|
||||
|
||||
| Attribute | Type | Optional | Meaning |
|
||||
| --- | --- | --- | --- |
|
||||
| `step` | string | no | The bring-up step name. |
|
||||
| `provider` | string | yes | The normalized provider family. |
|
||||
| `roundTrips` | number | yes | Host-to-sandbox round trips for the step. |
|
||||
| `providerExecMs` | number | yes | Provider-reported exec time for the step, in milliseconds. |
|
||||
| `providerGetMs` | number | yes | Provider-reported fetch time for the step, in milliseconds. |
|
||||
| `paperclip.sandbox.startup.root.wall_ms` | number | no | The root-span wall time of the whole bring-up. |
|
||||
| `paperclip.sandbox.startup.root.work_ms` | number | no | The sum of the step wall times. |
|
||||
| `paperclip.sandbox.startup.root.diff_ms` | number | no | `work_ms − wall_ms`; the overlap the parallel steps saved. |
|
||||
| `paperclip.sandbox.startup.provider` | string | yes | The normalized provider family. |
|
||||
| `paperclip.sandbox.startup.cold_start` | boolean | yes | Whether the bring-up is a cold start. |
|
||||
| `paperclip.sandbox.startup.region` | string | yes | The clamped region label. |
|
||||
| `paperclip.sandbox.startup.image_id` | string | yes | The hashed image id. |
|
||||
| `paperclip.sandbox.startup.sandbox_id` | string | yes | The hashed sandbox id. |
|
||||
| `paperclip.sandbox.startup.lease_id` | string | yes | The hashed lease id. |
|
||||
|
||||
### Provider exec span attributes
|
||||
### Step span attributes
|
||||
|
||||
The `provider.execute` span uses this closed attribute allowlist. Paperclip omits
|
||||
a duration attribute when the provider does not report the value.
|
||||
Each bring-up step span uses this closed attribute allowlist. The step name
|
||||
rides the span name, so no `step` attribute repeats it.
|
||||
|
||||
| Attribute | Type | Optional | Meaning |
|
||||
| --- | --- | --- | --- |
|
||||
| `provider` | string | no | The normalized provider family. |
|
||||
| `exit` | string | no | `ok` when the exit code is 0, else `error`. |
|
||||
| `provider.exec.duration_ms` | number | yes | Provider-reported exec wall time, in milliseconds. |
|
||||
| `provider.get.duration_ms` | number | yes | Provider-reported fetch wall time, in milliseconds. |
|
||||
| `paperclip.sandbox.startup.step.wall_ms` | number | no | The wall time of the step. |
|
||||
| `paperclip.sandbox.startup.outcome` | string | no | The step outcome (`ok`, `skipped`, or `failed`). |
|
||||
| `paperclip.sandbox.startup.provider` | string | yes | The normalized provider family. |
|
||||
| `paperclip.sandbox.startup.batch` | string | yes | A shared tag that marks two parallel steps as one batch. |
|
||||
| `paperclip.sandbox.startup.handshake.create_runtime.wall_ms` | number | yes | The create-runtime sub-time of the `acp.handshake` step. |
|
||||
| `paperclip.sandbox.startup.handshake.ensure_session.wall_ms` | number | yes | The ensure-session sub-time of the `acp.handshake` step. |
|
||||
|
||||
To add a startup span attribute or a provider span attribute, extend the
|
||||
allowlist in the code first. Keep the attribute low-cardinality and free of user
|
||||
content.
|
||||
The round-trip count and the provider durations no longer ride a step span. The
|
||||
per-execution `sandbox.exec` child spans carry that detail.
|
||||
|
||||
### `sandbox.exec` span attributes
|
||||
|
||||
The `sandbox.exec` span uses this closed attribute allowlist. Paperclip omits a
|
||||
numeric attribute when the provider does not report the value.
|
||||
|
||||
| Attribute | Type | Optional | Meaning |
|
||||
| --- | --- | --- | --- |
|
||||
| `paperclip.sandbox.startup.provider` | string | no | The normalized provider family. |
|
||||
| `paperclip.sandbox.startup.exec.command` | string | no | The clamped `argv[0]` command label. |
|
||||
| `paperclip.sandbox.startup.exec.exit_code` | number | yes | The numeric process exit code. |
|
||||
| `paperclip.sandbox.startup.exec.wall_ms` | number | no | The host-measured wall time of the execution. |
|
||||
| `paperclip.sandbox.startup.exec.wait_before_ms` | number | yes | The provider handle-fetch wait before the execution ran. |
|
||||
| `paperclip.sandbox.startup.exec.sandbox_ms` | number | yes | The in-sandbox run time of the execution. |
|
||||
| `paperclip.sandbox.startup.exec.network_ms` | number | yes | The transport time the host adds; `wall_ms − wait_before_ms − sandbox_ms`. |
|
||||
| `paperclip.sandbox.startup.exec.critical_path` | boolean | no | Whether the execution sits on the startup critical path. |
|
||||
| `paperclip.sandbox.startup.outcome` | string | no | The execution outcome (`ok` or `failed`). |
|
||||
|
||||
To add a span attribute, extend the `SANDBOX_STARTUP_SPAN_ATTRS` allowlist in
|
||||
the code first. Keep the attribute low-cardinality and free of user content.
|
||||
|
||||
## Dimension Values
|
||||
|
||||
|
|
|
|||
|
|
@ -8,11 +8,56 @@ vi.mock("../services/environment-config.js", () => ({
|
|||
resolveEnvironmentDriverConfigForRuntime: mockResolveEnvironmentDriverConfigForRuntime,
|
||||
}));
|
||||
|
||||
import {
|
||||
measureStartupStep,
|
||||
SANDBOX_STARTUP_SPAN_ATTRS,
|
||||
} from "@paperclipai/adapter-utils/acpx-engine/startup-timing";
|
||||
import {
|
||||
DEFAULT_SANDBOX_REMOTE_CWD,
|
||||
resolveEnvironmentExecutionTarget,
|
||||
} from "../services/environment-execution-target.js";
|
||||
|
||||
const A = SANDBOX_STARTUP_SPAN_ATTRS;
|
||||
|
||||
// A recording trace context that models the OTel parenting contract:
|
||||
// `startSpan(name, options, context)` reads the parent from the explicit
|
||||
// `context` token that `contextWithSpan` built. A test asserts the exact parent
|
||||
// of each child span without an OTel package.
|
||||
function createRecordingTrace() {
|
||||
const spans: Array<{
|
||||
name: string;
|
||||
attributes: Record<string, unknown>;
|
||||
parent: unknown;
|
||||
ended: boolean;
|
||||
setAttribute(key: string, value: unknown): void;
|
||||
end(): void;
|
||||
}> = [];
|
||||
const tracer = {
|
||||
startSpan(name: string, _options?: unknown, context?: unknown) {
|
||||
const parent =
|
||||
context && typeof context === "object" && "span" in context
|
||||
? (context as { span: unknown }).span
|
||||
: null;
|
||||
const span = {
|
||||
name,
|
||||
attributes: {} as Record<string, unknown>,
|
||||
parent,
|
||||
ended: false,
|
||||
setAttribute(key: string, value: unknown) {
|
||||
span.attributes[key] = value;
|
||||
},
|
||||
end() {
|
||||
span.ended = true;
|
||||
},
|
||||
};
|
||||
spans.push(span);
|
||||
return span;
|
||||
},
|
||||
};
|
||||
const contextWithSpan = (span: unknown) => ({ span });
|
||||
return { tracer, contextWithSpan, spans };
|
||||
}
|
||||
|
||||
describe("resolveEnvironmentExecutionTarget", () => {
|
||||
beforeEach(() => {
|
||||
mockResolveEnvironmentDriverConfigForRuntime.mockReset();
|
||||
|
|
@ -424,16 +469,25 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
// A recording tracer that captures each provider-exec span's name, attribute
|
||||
// map, and end. It satisfies the structural tracer the seam calls.
|
||||
function createRecordingExecTracer() {
|
||||
const spans: Array<{ name: string; attributes: Record<string, unknown>; ended: boolean }> = [];
|
||||
const spans: Array<{
|
||||
name: string;
|
||||
attributes: Record<string, unknown>;
|
||||
status: { code: number; message?: string } | null;
|
||||
ended: boolean;
|
||||
}> = [];
|
||||
const tracer = {
|
||||
startSpan(name: string) {
|
||||
const span = {
|
||||
name,
|
||||
attributes: {} as Record<string, unknown>,
|
||||
status: null as { code: number; message?: string } | null,
|
||||
ended: false,
|
||||
setAttribute(key: string, value: unknown) {
|
||||
span.attributes[key] = value;
|
||||
},
|
||||
setStatus(status: { code: number; message?: string }) {
|
||||
span.status = status;
|
||||
},
|
||||
end() {
|
||||
span.ended = true;
|
||||
},
|
||||
|
|
@ -445,25 +499,50 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
return { tracer, spans };
|
||||
}
|
||||
|
||||
// The closed span-attribute allowlist for a provider-exec span (Phase 4).
|
||||
const ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS = new Set([
|
||||
"provider",
|
||||
"exit",
|
||||
"provider.exec.duration_ms",
|
||||
"provider.get.duration_ms",
|
||||
// The value of `SpanStatusCode.ERROR` in `@opentelemetry/api`. A failed exec
|
||||
// span must carry this native status, not only the `failed` outcome attribute.
|
||||
const SPAN_STATUS_CODE_ERROR = 2;
|
||||
|
||||
// The closed span-attribute allowlist for a `sandbox.exec` span. A test
|
||||
// asserts every recorded key is in this set, so a command, an argument, a
|
||||
// path, an id, or an error-text key can never ride the span.
|
||||
const ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS = new Set<string>([
|
||||
A.provider,
|
||||
A.execCommand,
|
||||
A.execExitCode,
|
||||
A.execWallMs,
|
||||
A.execWaitBeforeMs,
|
||||
A.execSandboxMs,
|
||||
A.execNetworkMs,
|
||||
A.execCriticalPath,
|
||||
A.outcome,
|
||||
]);
|
||||
|
||||
async function runnerFor(input: {
|
||||
provider: string;
|
||||
execResult: Record<string, unknown>;
|
||||
tracer: unknown;
|
||||
}) {
|
||||
return runnerWithExecute({
|
||||
provider: input.provider,
|
||||
tracer: input.tracer,
|
||||
execute: vi.fn().mockResolvedValue(input.execResult),
|
||||
});
|
||||
}
|
||||
|
||||
// Build the sandbox runner with a custom provider-exec implementation, so a
|
||||
// test can drive a thrown execution or assert the span order around the await.
|
||||
async function runnerWithExecute(input: {
|
||||
provider: string;
|
||||
tracer: unknown;
|
||||
execute: (...args: unknown[]) => Promise<unknown>;
|
||||
}) {
|
||||
mockResolveEnvironmentDriverConfigForRuntime.mockResolvedValue({
|
||||
driver: "sandbox",
|
||||
config: { provider: input.provider, reuseLease: false, timeoutMs: 30_000 },
|
||||
});
|
||||
const environmentRuntime = {
|
||||
execute: vi.fn().mockResolvedValue(input.execResult),
|
||||
execute: input.execute,
|
||||
supportsSync: vi.fn().mockReturnValue(false),
|
||||
};
|
||||
const target = await resolveEnvironmentExecutionTarget({
|
||||
|
|
@ -501,12 +580,22 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
|
||||
expect(spans).toHaveLength(1);
|
||||
const span = spans[0]!;
|
||||
expect(span.name).toBe("provider.execute");
|
||||
expect(span.name).toBe("sandbox.exec");
|
||||
expect(span.ended).toBe(true);
|
||||
expect(span.attributes["provider.exec.duration_ms"]).toBe(600);
|
||||
expect(span.attributes["provider.get.duration_ms"]).toBe(15);
|
||||
expect(span.attributes.provider).toBe("daytona");
|
||||
expect(span.attributes.exit).toBe("ok");
|
||||
// `sandbox_ms` = provider in-sandbox run; `wait_before_ms` = handle-fetch.
|
||||
expect(span.attributes[A.execSandboxMs]).toBe(600);
|
||||
expect(span.attributes[A.execWaitBeforeMs]).toBe(15);
|
||||
expect(span.attributes[A.provider]).toBe("daytona");
|
||||
// `echo` is a known command basename, so it rides as a clamped label.
|
||||
expect(span.attributes[A.execCommand]).toBe("echo");
|
||||
expect(span.attributes[A.execExitCode]).toBe(0);
|
||||
expect(span.attributes[A.outcome]).toBe("ok");
|
||||
// A successful exec leaves the native span status unset (default OTel status).
|
||||
expect(span.status).toBeNull();
|
||||
expect(span.attributes[A.execCriticalPath]).toBe(true);
|
||||
// The wall time is a real, finite, non-negative number.
|
||||
expect(typeof span.attributes[A.execWallMs]).toBe("number");
|
||||
expect(span.attributes[A.execWallMs] as number).toBeGreaterThanOrEqual(0);
|
||||
});
|
||||
|
||||
it("omits each duration attribute when a provider returns no timing (does not throw, keeps provider)", async () => {
|
||||
|
|
@ -521,10 +610,12 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
|
||||
expect(spans).toHaveLength(1);
|
||||
const span = spans[0]!;
|
||||
expect("provider.exec.duration_ms" in span.attributes).toBe(false);
|
||||
expect("provider.get.duration_ms" in span.attributes).toBe(false);
|
||||
expect(A.execSandboxMs in span.attributes).toBe(false);
|
||||
expect(A.execWaitBeforeMs in span.attributes).toBe(false);
|
||||
// With no provider durations, the derived network time is also omitted.
|
||||
expect(A.execNetworkMs in span.attributes).toBe(false);
|
||||
// The provider attribute is always present so a trace shows which provider ran.
|
||||
expect(span.attributes.provider).toBe("kubernetes");
|
||||
expect(span.attributes[A.provider]).toBe("kubernetes");
|
||||
});
|
||||
|
||||
it("never emits a `0` duration attribute for a Daytona timeout that omits durationMs", async () => {
|
||||
|
|
@ -546,12 +637,18 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
await runner.execute({ command: "sleep", args: ["999"] });
|
||||
|
||||
const span = spans[0]!;
|
||||
expect("provider.exec.duration_ms" in span.attributes).toBe(false);
|
||||
expect(span.attributes["provider.get.duration_ms"]).toBe(20);
|
||||
expect(span.attributes.exit).toBe("error");
|
||||
expect(A.execSandboxMs in span.attributes).toBe(false);
|
||||
expect(span.attributes[A.execWaitBeforeMs]).toBe(20);
|
||||
// A non-zero exit yields `failed`; the exit code rides as a number.
|
||||
expect(span.attributes[A.outcome]).toBe("failed");
|
||||
// A failed exec also sets the native span status to ERROR.
|
||||
expect(span.status).toEqual({ code: SPAN_STATUS_CODE_ERROR });
|
||||
expect(span.attributes[A.execExitCode]).toBe(124);
|
||||
// `sleep` is not in the known-command allowlist, so it clamps to `other`.
|
||||
expect(span.attributes[A.execCommand]).toBe("other");
|
||||
});
|
||||
|
||||
it("never sets a command, arg, or non-allowlisted key as an indexed span attribute", async () => {
|
||||
it("never sets a command, arg, env, cwd, or stream text as a span attribute, even with secret-like input", async () => {
|
||||
const { tracer, spans } = createRecordingExecTracer();
|
||||
const runner = await runnerFor({
|
||||
provider: "daytona",
|
||||
|
|
@ -559,22 +656,48 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
exitCode: 0,
|
||||
signal: null,
|
||||
timedOut: false,
|
||||
stdout: "",
|
||||
stderr: "",
|
||||
// Secret-like standard-stream text must never ride the span.
|
||||
stdout: "AKIAIOSFODNN7EXAMPLE token=s3cr3t-stdout",
|
||||
stderr: "error at /home/agent/.ssh/id_rsa: s3cr3t-stderr",
|
||||
metadata: { durationMs: 5, getDurationMs: 1 },
|
||||
},
|
||||
tracer,
|
||||
});
|
||||
|
||||
await runner.execute({ command: "bash -lc 'rm -rf /secret/path'", args: ["--token", "s3cr3t"] });
|
||||
await runner.execute({
|
||||
// A full command line, a secret-like argument, a secret-like env value, a
|
||||
// stdin blob, and a path-like cwd — none may ride the span.
|
||||
command: "bash -lc 'rm -rf /secret/path'",
|
||||
args: ["--token", "s3cr3t-arg", "--password", "hunter2"],
|
||||
env: { AWS_SECRET_ACCESS_KEY: "s3cr3t-env", HOME: "/home/agent" },
|
||||
cwd: "/home/agent/secret-workspace/.git",
|
||||
stdin: "s3cr3t-stdin-blob",
|
||||
});
|
||||
|
||||
const span = spans[0]!;
|
||||
for (const key of Object.keys(span.attributes)) {
|
||||
expect(ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS.has(key), `non-allowlisted key "${key}"`).toBe(true);
|
||||
}
|
||||
// The command clamps to the bounded `other` fallback (not a known basename).
|
||||
expect(span.attributes[A.execCommand]).toBe("other");
|
||||
// No forbidden substring rides any attribute value.
|
||||
const values = Object.values(span.attributes).map(String);
|
||||
expect(values.some((value) => value.includes("rm -rf"))).toBe(false);
|
||||
expect(values.some((value) => value.includes("s3cr3t"))).toBe(false);
|
||||
for (const forbidden of [
|
||||
"rm -rf",
|
||||
"s3cr3t",
|
||||
"hunter2",
|
||||
"AKIA",
|
||||
"id_rsa",
|
||||
"/secret/path",
|
||||
"/home/agent",
|
||||
"secret-workspace",
|
||||
"stdin",
|
||||
]) {
|
||||
expect(
|
||||
values.some((value) => value.includes(forbidden)),
|
||||
`attribute value leaked "${forbidden}"`,
|
||||
).toBe(false);
|
||||
}
|
||||
});
|
||||
|
||||
it("normalizes a plugin-backed provider key to `plugin` and keeps a built-in family as-is", async () => {
|
||||
|
|
@ -585,7 +708,7 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
tracer: plugin.tracer,
|
||||
});
|
||||
await pluginRunner.execute({ command: "echo" });
|
||||
expect(plugin.spans[0]!.attributes.provider).toBe("plugin");
|
||||
expect(plugin.spans[0]!.attributes[A.provider]).toBe("plugin");
|
||||
|
||||
const builtIn = createRecordingExecTracer();
|
||||
const builtInRunner = await runnerFor({
|
||||
|
|
@ -594,6 +717,139 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
tracer: builtIn.tracer,
|
||||
});
|
||||
await builtInRunner.execute({ command: "echo" });
|
||||
expect(builtIn.spans[0]!.attributes.provider).toBe("e2b");
|
||||
expect(builtIn.spans[0]!.attributes[A.provider]).toBe("e2b");
|
||||
});
|
||||
|
||||
it("parents the exec span to the active step span when the exec runs inside a measured step", async () => {
|
||||
const { tracer, contextWithSpan, spans } = createRecordingTrace();
|
||||
const runner = await runnerFor({
|
||||
provider: "daytona",
|
||||
execResult: { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" },
|
||||
tracer,
|
||||
});
|
||||
|
||||
// The exec seam reads the active step context through `getActiveStepContext`.
|
||||
// Wrap the exec in one measured step and assert the exec span parents to the
|
||||
// step span, not to nothing.
|
||||
await measureStartupStep({}, () => 0, "stage.sync", () => runner.execute({ command: "echo" }), {
|
||||
tracer,
|
||||
contextWithSpan,
|
||||
});
|
||||
|
||||
const stepSpan = spans.find((span) => span.name === "stage.sync");
|
||||
const execSpan = spans.find((span) => span.name === "sandbox.exec");
|
||||
expect(stepSpan).toBeTruthy();
|
||||
expect(execSpan).toBeTruthy();
|
||||
expect(execSpan!.parent).toBe(stepSpan);
|
||||
});
|
||||
|
||||
it("opens an unparented exec span when the exec runs outside any measured step", async () => {
|
||||
const { tracer, spans } = createRecordingTrace();
|
||||
const runner = await runnerFor({
|
||||
provider: "daytona",
|
||||
execResult: { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" },
|
||||
tracer,
|
||||
});
|
||||
|
||||
// No measured step wraps the exec, so the active step context is null and
|
||||
// the exec span opens unparented (a no-op when tracing is off).
|
||||
await runner.execute({ command: "echo" });
|
||||
|
||||
const execSpan = spans.find((span) => span.name === "sandbox.exec");
|
||||
expect(execSpan).toBeTruthy();
|
||||
expect(execSpan!.parent).toBeNull();
|
||||
});
|
||||
|
||||
it("opens the exec span before the provider await so the span wraps the execution", async () => {
|
||||
const { tracer, spans } = createRecordingExecTracer();
|
||||
// Assert the span is already open (started, not ended) while the provider
|
||||
// runs. If the seam opened the span after the await, no open span would
|
||||
// exist here and the native span duration would be near zero.
|
||||
const runner = await runnerWithExecute({
|
||||
provider: "daytona",
|
||||
tracer,
|
||||
execute: vi.fn().mockImplementation(async () => {
|
||||
const open = spans.find((span) => span.name === "sandbox.exec");
|
||||
expect(open, "the exec span must be open during the provider await").toBeTruthy();
|
||||
expect(open!.ended).toBe(false);
|
||||
return { exitCode: 0, signal: null, timedOut: false, stdout: "", stderr: "" };
|
||||
}),
|
||||
});
|
||||
|
||||
await runner.execute({ command: "echo" });
|
||||
|
||||
const span = spans.find((s) => s.name === "sandbox.exec");
|
||||
expect(span!.ended).toBe(true);
|
||||
expect(span!.attributes[A.outcome]).toBe("ok");
|
||||
});
|
||||
|
||||
it("records a failed exec span and rethrows when the provider execution throws", async () => {
|
||||
const { tracer, spans } = createRecordingExecTracer();
|
||||
const runner = await runnerWithExecute({
|
||||
provider: "daytona",
|
||||
tracer,
|
||||
execute: vi.fn().mockRejectedValue(new Error("provider transport failed")),
|
||||
});
|
||||
|
||||
// The original error rides through unchanged; observability never swallows it.
|
||||
await expect(runner.execute({ command: "echo" })).rejects.toThrow("provider transport failed");
|
||||
|
||||
// A thrown execution still produces one ended span with the `failed` outcome,
|
||||
// instead of no span at all.
|
||||
const span = spans.find((s) => s.name === "sandbox.exec");
|
||||
expect(span).toBeTruthy();
|
||||
expect(span!.ended).toBe(true);
|
||||
expect(span!.attributes[A.outcome]).toBe("failed");
|
||||
// A thrown execution also sets the native span status to ERROR.
|
||||
expect(span!.status).toEqual({ code: SPAN_STATUS_CODE_ERROR });
|
||||
expect(span!.attributes[A.provider]).toBe("daytona");
|
||||
// `echo` is a known basename, so the clamped command rides the span.
|
||||
expect(span!.attributes[A.execCommand]).toBe("echo");
|
||||
// No exec result exists, so the exit code never rides the span.
|
||||
expect(A.execExitCode in span!.attributes).toBe(false);
|
||||
// The wall time is a real, finite, non-negative number.
|
||||
expect(typeof span!.attributes[A.execWallMs]).toBe("number");
|
||||
expect(span!.attributes[A.execWallMs] as number).toBeGreaterThanOrEqual(0);
|
||||
// Only allowlisted keys ride the failed span.
|
||||
for (const key of Object.keys(span!.attributes)) {
|
||||
expect(ALLOWED_EXEC_SPAN_ATTRIBUTE_KEYS.has(key), `non-allowlisted key "${key}"`).toBe(true);
|
||||
}
|
||||
});
|
||||
|
||||
it("keeps the exec span outcome `ok` when the execution succeeds but a log callback rejects", async () => {
|
||||
const { tracer, spans } = createRecordingExecTracer();
|
||||
// The provider execution succeeds and returns stdout, so the seam invokes
|
||||
// the log callback. The callback rejects, which models a downstream log-sink
|
||||
// failure. The rejection must reach the caller, but it must never reclassify
|
||||
// the successful execution as a failed span.
|
||||
const runner = await runnerWithExecute({
|
||||
provider: "daytona",
|
||||
tracer,
|
||||
execute: vi.fn().mockResolvedValue({
|
||||
exitCode: 0,
|
||||
signal: null,
|
||||
timedOut: false,
|
||||
stdout: "hello",
|
||||
stderr: "",
|
||||
}),
|
||||
});
|
||||
|
||||
const onLog = vi.fn().mockRejectedValue(new Error("log sink rejected"));
|
||||
// The rejection rides through unchanged; observability never swallows it.
|
||||
await expect(
|
||||
(runner as { execute(input: unknown): Promise<unknown> }).execute({ command: "echo", onLog }),
|
||||
).rejects.toThrow("log sink rejected");
|
||||
|
||||
// The span ended with the successful outcome from the command result, not
|
||||
// the failed outcome. A log failure never marks the execution failed.
|
||||
const span = spans.find((s) => s.name === "sandbox.exec");
|
||||
expect(span).toBeTruthy();
|
||||
expect(span!.ended).toBe(true);
|
||||
expect(span!.attributes[A.outcome]).toBe("ok");
|
||||
// A log-callback rejection never marks the span as ERROR; the status stays unset.
|
||||
expect(span!.status).toBeNull();
|
||||
expect(span!.attributes[A.execExitCode]).toBe(0);
|
||||
// The seam reached the log callback exactly once (the stdout delivery).
|
||||
expect(onLog).toHaveBeenCalledTimes(1);
|
||||
});
|
||||
});
|
||||
|
|
|
|||
|
|
@ -43,6 +43,11 @@ interface StartupTracerHandle {
|
|||
startSpan(
|
||||
name: string,
|
||||
options?: unknown,
|
||||
// The optional explicit parent-context token. A real OTel
|
||||
// `startSpan(name, options, context)` parents the new span to the span that
|
||||
// `context` carries. The no-op tracer ignores it. The exec seam passes the
|
||||
// active step context here, so an exec span parents to its step span.
|
||||
context?: unknown,
|
||||
): {
|
||||
setAttribute(key: string, value: unknown): void;
|
||||
setStatus(status: { code: number; message?: string }): void;
|
||||
|
|
|
|||
|
|
@ -5,7 +5,13 @@ import {
|
|||
adapterExecutionTargetToRemoteSpec,
|
||||
type AdapterExecutionTarget,
|
||||
} from "@paperclipai/adapter-utils/execution-target";
|
||||
import { normalizeProviderFamily } from "@paperclipai/adapter-utils/acpx-engine/startup-timing";
|
||||
import {
|
||||
clampSpanLabel,
|
||||
getActiveStepContext,
|
||||
normalizeProviderFamily,
|
||||
SANDBOX_STARTUP_OUTCOME,
|
||||
SANDBOX_STARTUP_SPAN_ATTRS,
|
||||
} from "@paperclipai/adapter-utils/acpx-engine/startup-timing";
|
||||
import { parseObject } from "../adapters/utils.js";
|
||||
import { getStartupTracer } from "../instrumentation.js";
|
||||
import { resolveEnvironmentDriverConfigForRuntime } from "./environment-config.js";
|
||||
|
|
@ -17,12 +23,25 @@ export const DEFAULT_SANDBOX_REMOTE_CWD = "/tmp";
|
|||
* span satisfies it; the no-op tracer's span satisfies it too. */
|
||||
type ExecSpan = {
|
||||
setAttribute(key: string, value: string | number | boolean): void;
|
||||
setStatus(status: { code: number; message?: string }): void;
|
||||
end(): void;
|
||||
};
|
||||
|
||||
/**
|
||||
* The value of `SpanStatusCode.ERROR` in `@opentelemetry/api`. The server injects
|
||||
* a real OTel span, but this module stays OTel-free, so it uses the numeric value
|
||||
* directly. A failed exec span sets this status, so a trace UI counts and filters
|
||||
* the failure through the native span status, not only the `outcome` attribute.
|
||||
*/
|
||||
const SPAN_STATUS_CODE_ERROR = 2;
|
||||
|
||||
/** The minimal tracer surface the provider-exec seam calls. `getStartupTracer`
|
||||
* returns a real or no-op implementation that satisfies it. */
|
||||
type ExecTracer = { startSpan(name: string): ExecSpan };
|
||||
* returns a real or no-op implementation that satisfies it. The optional third
|
||||
* argument is the explicit parent-context token: the seam passes the active
|
||||
* step context, so the exec span parents to its step span. */
|
||||
type ExecTracer = {
|
||||
startSpan(name: string, options?: unknown, context?: unknown): ExecSpan;
|
||||
};
|
||||
|
||||
/**
|
||||
* Set a numeric span attribute only when the value is a finite number. A value
|
||||
|
|
@ -36,6 +55,96 @@ function setFiniteNumberAttr(span: ExecSpan, key: string, value: unknown): void
|
|||
}
|
||||
}
|
||||
|
||||
/** Read a free-form metadata value as a finite number, or `undefined`. The
|
||||
* provider durations ride the exec result's untyped `metadata`, so a provider
|
||||
* that omits or mistypes one yields no attribute — never a misleading `0`. */
|
||||
function toFiniteNumber(value: unknown): number | undefined {
|
||||
return typeof value === "number" && Number.isFinite(value) ? value : undefined;
|
||||
}
|
||||
|
||||
/**
|
||||
* The closed input for one `sandbox.exec` span. The seam builds it from the
|
||||
* exec result and the active step context. Every field is already bounded or
|
||||
* numeric; the raw command clamps inside the helper below.
|
||||
*/
|
||||
interface SandboxExecSpanInput {
|
||||
/** The low-cardinality provider family (already through `normalizeProviderFamily`). */
|
||||
provider: string;
|
||||
/** The raw `argv[0]`. The helper clamps it; the raw value never rides the span. */
|
||||
command: string;
|
||||
/** The numeric process exit code, or `null`. */
|
||||
exitCode: number | null;
|
||||
/** The host-measured wall time of the execution. */
|
||||
wallMs: number;
|
||||
/** The provider handle-fetch wait before the execution ran. */
|
||||
waitBeforeMs: number | undefined;
|
||||
/** The in-sandbox run time of the execution. */
|
||||
sandboxMs: number | undefined;
|
||||
/** Whether the execution sits on the startup critical path. */
|
||||
criticalPath: boolean;
|
||||
}
|
||||
|
||||
/**
|
||||
* Assemble every `sandbox.exec` span attribute in one place. This is the single
|
||||
* producer-side boundary for the exec span: it sets only the closed
|
||||
* `paperclip.sandbox.startup.exec.*` allowlist. The command rides only as a
|
||||
* clamped label, so a full command line, an argument, a path, an environment
|
||||
* value, or any standard-stream text can never ride the span. A non-finite
|
||||
* numeric input yields no attribute (fail open — never `NaN`, never a
|
||||
* misleading `0`).
|
||||
*/
|
||||
function setSandboxExecSpanAttributes(span: ExecSpan, input: SandboxExecSpanInput): void {
|
||||
const A = SANDBOX_STARTUP_SPAN_ATTRS;
|
||||
span.setAttribute(A.provider, input.provider);
|
||||
const command = clampSpanLabel("command", input.command);
|
||||
if (command !== undefined) span.setAttribute(A.execCommand, command);
|
||||
if (typeof input.exitCode === "number" && Number.isFinite(input.exitCode)) {
|
||||
span.setAttribute(A.execExitCode, input.exitCode);
|
||||
}
|
||||
setFiniteNumberAttr(span, A.execWallMs, input.wallMs);
|
||||
setFiniteNumberAttr(span, A.execWaitBeforeMs, input.waitBeforeMs);
|
||||
setFiniteNumberAttr(span, A.execSandboxMs, input.sandboxMs);
|
||||
// The transport time the host adds around the provider work: wall minus the
|
||||
// handle-fetch wait minus the in-sandbox run. Set it only when both parts are
|
||||
// present, so a provider that reports no durations yields no derived value.
|
||||
if (input.waitBeforeMs !== undefined && input.sandboxMs !== undefined) {
|
||||
setFiniteNumberAttr(span, A.execNetworkMs, input.wallMs - input.waitBeforeMs - input.sandboxMs);
|
||||
}
|
||||
span.setAttribute(A.execCriticalPath, input.criticalPath);
|
||||
const failed = input.exitCode !== 0;
|
||||
span.setAttribute(
|
||||
A.outcome,
|
||||
failed ? SANDBOX_STARTUP_OUTCOME.failed : SANDBOX_STARTUP_OUTCOME.ok,
|
||||
);
|
||||
// A non-zero exit code is a failed execution, so set the native span status to
|
||||
// ERROR too. The success path leaves the status unset, so a successful exec
|
||||
// keeps the default OTel status. A `null` exit code counts as failed here.
|
||||
if (failed) span.setStatus({ code: SPAN_STATUS_CODE_ERROR });
|
||||
}
|
||||
|
||||
/**
|
||||
* Record a failed `sandbox.exec` span when the provider execution throws. There
|
||||
* is no exec result, so only the bounded provider family, the clamped command
|
||||
* label, the measured wall time, the critical-path flag, and the `failed`
|
||||
* outcome ride the span. The raw command never rides the span. A thrown
|
||||
* execution now still produces a span, instead of no span at all.
|
||||
*/
|
||||
function setSandboxExecSpanFailure(
|
||||
span: ExecSpan,
|
||||
input: { provider: string; command: string; wallMs: number; criticalPath: boolean },
|
||||
): void {
|
||||
const A = SANDBOX_STARTUP_SPAN_ATTRS;
|
||||
span.setAttribute(A.provider, input.provider);
|
||||
const command = clampSpanLabel("command", input.command);
|
||||
if (command !== undefined) span.setAttribute(A.execCommand, command);
|
||||
setFiniteNumberAttr(span, A.execWallMs, input.wallMs);
|
||||
span.setAttribute(A.execCriticalPath, input.criticalPath);
|
||||
span.setAttribute(A.outcome, SANDBOX_STARTUP_OUTCOME.failed);
|
||||
// A thrown execution is a failed execution, so set the native span status to
|
||||
// ERROR too, not only the `outcome` attribute.
|
||||
span.setStatus({ code: SPAN_STATUS_CODE_ERROR });
|
||||
}
|
||||
|
||||
export async function resolveEnvironmentExecutionTarget(input: {
|
||||
db: Db;
|
||||
companyId: string;
|
||||
|
|
@ -141,49 +250,112 @@ export async function resolveEnvironmentExecutionTarget(input: {
|
|||
providerGetMs: () => providerGetMs,
|
||||
execute: async (commandInput) => {
|
||||
execCount += 1;
|
||||
const startedAt = new Date().toISOString();
|
||||
const result = await input.environmentRuntime!.execute({
|
||||
environment: input.environment as Environment,
|
||||
lease: input.lease!,
|
||||
command: commandInput.command,
|
||||
args: commandInput.args,
|
||||
cwd: commandInput.cwd ?? remoteCwd,
|
||||
env: commandInput.env,
|
||||
stdin: commandInput.stdin,
|
||||
timeoutMs: commandInput.timeoutMs,
|
||||
});
|
||||
accumulateProviderDurations(result.metadata);
|
||||
// Emit one span for this host→sandbox exec (opt-in; a no-op tracer
|
||||
// when tracing is off). It carries ONLY closed-allowlist,
|
||||
// low-cardinality attributes: the normalized provider family, the
|
||||
// exit status (a two-value enum), and the host-received provider
|
||||
// durations (per field, only when finite). The full command, args,
|
||||
// env, stdout, and stderr never ride a span — not as an attribute
|
||||
// and not as an event. The span name is the fixed operation label.
|
||||
// Record true start and stop timestamps around the provider await,
|
||||
// so the exec span and the result carry a real wall time.
|
||||
const startedAtMs = Date.now();
|
||||
const startedAt = new Date(startedAtMs).toISOString();
|
||||
// Open one `sandbox.exec` span BEFORE the provider await, so the
|
||||
// native span duration covers the whole execution and a thrown
|
||||
// execution still produces a span. The span parents to the active
|
||||
// step span. `startSpan` sits inside a guard; observability must
|
||||
// never change execution control flow, and a no-op tracer
|
||||
// (tracing off) makes the whole block inert.
|
||||
const activeStep = getActiveStepContext();
|
||||
const criticalPath = activeStep?.criticalPath ?? true;
|
||||
let span: ExecSpan | null = null;
|
||||
try {
|
||||
const span = tracer.startSpan("provider.execute");
|
||||
try {
|
||||
span.setAttribute("provider", providerFamily);
|
||||
span.setAttribute("exit", result.exitCode === 0 ? "ok" : "error");
|
||||
setFiniteNumberAttr(span, "provider.exec.duration_ms", result.metadata?.durationMs);
|
||||
setFiniteNumberAttr(span, "provider.get.duration_ms", result.metadata?.getDurationMs);
|
||||
} finally {
|
||||
span.end();
|
||||
}
|
||||
span = tracer.startSpan("sandbox.exec", undefined, activeStep?.parentContext);
|
||||
} catch {
|
||||
// Observability must not change execution control flow.
|
||||
span = null;
|
||||
}
|
||||
try {
|
||||
// Classify the span outcome from the provider execution ONLY.
|
||||
// The inner try/catch wraps just the provider await, so a thrown
|
||||
// provider execution marks the span failed. A later log-callback
|
||||
// rejection sits outside this block and never flips a successful
|
||||
// execution to failed.
|
||||
let result;
|
||||
try {
|
||||
result = await input.environmentRuntime!.execute({
|
||||
environment: input.environment as Environment,
|
||||
lease: input.lease!,
|
||||
command: commandInput.command,
|
||||
args: commandInput.args,
|
||||
cwd: commandInput.cwd ?? remoteCwd,
|
||||
env: commandInput.env,
|
||||
stdin: commandInput.stdin,
|
||||
timeoutMs: commandInput.timeoutMs,
|
||||
});
|
||||
} catch (error) {
|
||||
// The provider execution threw. Mark the span failed with the
|
||||
// measured wall time, then rethrow the original error unchanged.
|
||||
if (span) {
|
||||
try {
|
||||
setSandboxExecSpanFailure(span, {
|
||||
provider: providerFamily,
|
||||
command: commandInput.command,
|
||||
wallMs: Date.now() - startedAtMs,
|
||||
criticalPath,
|
||||
});
|
||||
} catch {
|
||||
// Observability must not change execution control flow.
|
||||
}
|
||||
}
|
||||
throw error;
|
||||
}
|
||||
// The provider execution succeeded. The span timing and outcome
|
||||
// come from the command result, not from the log callbacks below.
|
||||
const finishedAtMs = Date.now();
|
||||
const finishedAt = new Date(finishedAtMs).toISOString();
|
||||
const durationMs = finishedAtMs - startedAtMs;
|
||||
accumulateProviderDurations(result.metadata);
|
||||
// `setSandboxExecSpanAttributes` sets ONLY the closed
|
||||
// `paperclip.sandbox.startup.exec.*` allowlist: the normalized
|
||||
// provider family, the clamped command label, the numeric exit
|
||||
// code, the wall / wait-before / sandbox / network times, the
|
||||
// critical-path flag, and the outcome. The full command, args,
|
||||
// env, stdout, and stderr never ride the span.
|
||||
if (span) {
|
||||
try {
|
||||
setSandboxExecSpanAttributes(span, {
|
||||
provider: providerFamily,
|
||||
command: commandInput.command,
|
||||
exitCode: result.exitCode,
|
||||
wallMs: durationMs,
|
||||
waitBeforeMs: toFiniteNumber(result.metadata?.getDurationMs),
|
||||
sandboxMs: toFiniteNumber(result.metadata?.durationMs),
|
||||
criticalPath,
|
||||
});
|
||||
} catch {
|
||||
// Observability must not change execution control flow.
|
||||
}
|
||||
}
|
||||
// Deliver the captured output. A rejected `onLog` still
|
||||
// propagates to the caller (control flow is unchanged), but the
|
||||
// span already carries the successful outcome, so a log failure
|
||||
// never marks the execution failed.
|
||||
if (result.stdout) await commandInput.onLog?.("stdout", result.stdout);
|
||||
if (result.stderr) await commandInput.onLog?.("stderr", result.stderr);
|
||||
return {
|
||||
exitCode: result.exitCode,
|
||||
signal: result.signal ?? null,
|
||||
timedOut: result.timedOut,
|
||||
stdout: result.stdout,
|
||||
stderr: result.stderr,
|
||||
pid: null,
|
||||
startedAt,
|
||||
finishedAt,
|
||||
durationMs,
|
||||
};
|
||||
} finally {
|
||||
if (span) {
|
||||
try {
|
||||
span.end();
|
||||
} catch {
|
||||
// Observability must not change execution control flow.
|
||||
}
|
||||
}
|
||||
}
|
||||
if (result.stdout) await commandInput.onLog?.("stdout", result.stdout);
|
||||
if (result.stderr) await commandInput.onLog?.("stderr", result.stderr);
|
||||
return {
|
||||
exitCode: result.exitCode,
|
||||
signal: result.signal ?? null,
|
||||
timedOut: result.timedOut,
|
||||
stdout: result.stdout,
|
||||
stderr: result.stderr,
|
||||
pid: null,
|
||||
startedAt,
|
||||
};
|
||||
},
|
||||
// Expose the native file-sync capability only when the provider's
|
||||
// worker advertises BOTH sync verbs; otherwise leave syncIn/syncOut
|
||||
|
|
|
|||
Loading…
Reference in New Issue