refactor(observability): stop writing detailed per-step timing to the run log (#10776)
## Thinking Path > - Paperclip tracks agent work for the team. > - The startup timing path already emits detailed spans. > - The run log repeats the same detailed timing. > - That makes the event larger than it needs to be. > - This pull request removes the redundant per-step timing fields from the run-log payload. > - The benefit is a smaller log with the same detail still available in traces. ## Linked Issues or Issue Description No public GitHub issue or open pull request matches this change. I described the enhancement below. **What existing behavior does this improve?** `run.startup.step` event output. **Subsystem affected** Cross-cutting (multiple of the above) **Current behavior** `run.startup.step` writes `roundTrips`, `providerExecMs`, `providerGetMs`, `createRuntimeMs`, and `ensureSessionMs`. The same detail already exists in the spans. **Proposed behavior** `run.startup.step` keeps only `step`, `durationMs`, and `outcome`. The heartbeat lifecycle timestamps stay unchanged. **Reason and benefit** This change removes redundant data from the run log. It keeps the useful detail in trace spans. It also makes the payload smaller and easier to read. The revert path stays clear because the removed data has one producer chain. **Breaking changes** Yes. Consumers that read the removed fields must switch to span data or the remaining event fields. The heartbeat lifecycle timestamps do not change. **Additional context** I searched GitHub for related open PRs and issues. I found no match. ## What Changed - Removed the redundant per-step timing fields from the run-log payload. - Removed the now-dead producer chain that fed those fields. - Kept the span-level timing data and the heartbeat lifecycle timestamps. ## Verification - `adapter-utils` typecheck clean - `server` typecheck clean - `startup-timing` suite: 30 passed - `adapter-utils` `execute` suite: 99 passed - `server` `environment-execution-target` suite: 21 passed ## Risks - Consumers that still read the removed fields will need a code change. - This is a one-way-door data removal for the run log. ## Model Used OpenAI Codex, GPT-5, tool use enabled. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (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] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge --------- Co-authored-by: Paperclip <noreply@paperclip.ing>
This commit is contained in:
Nicky Leach
GitHub
parent
18f391ef02
commit
6a69a3d6b0
|
|
@ -92,16 +92,7 @@ function createLocalSandboxRunner(
|
|||
}) => void,
|
||||
) {
|
||||
let counter = 0;
|
||||
// Synthetic provider-duration accumulators so per-step payload assertions can
|
||||
// verify the `providerExecMs`/`providerGetMs` threading end-to-end (the real
|
||||
// sandbox runner sources these from the Daytona plugin's result metadata; this
|
||||
// double stands in for that with a fixed per-exec cost).
|
||||
let providerExecMs = 0;
|
||||
let providerGetMs = 0;
|
||||
return {
|
||||
execCount: () => counter,
|
||||
providerExecMs: () => providerExecMs,
|
||||
providerGetMs: () => providerGetMs,
|
||||
execute: async (input: {
|
||||
command: string;
|
||||
args?: string[];
|
||||
|
|
@ -113,8 +104,6 @@ function createLocalSandboxRunner(
|
|||
onSpawn?: (meta: { pid: number; startedAt: string }) => Promise<void>;
|
||||
}) => {
|
||||
counter += 1;
|
||||
providerExecMs += 600;
|
||||
providerGetMs += 15;
|
||||
onExecute?.(input);
|
||||
const command = input.command === "bash" ? "/bin/bash" : input.command;
|
||||
return await runChildProcess(`acpx-sandbox-run-${counter}`, command, input.args ?? [], {
|
||||
|
|
@ -3605,7 +3594,7 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () =>
|
|||
}
|
||||
});
|
||||
|
||||
it("carries roundTrips + provider durations for sequential startup steps and keeps concurrent bridge steps duration-only", async () => {
|
||||
it("emits only the high-level fields on every startup-step payload, never the detailed timing or counts", async () => {
|
||||
const root = await makeTempRoot();
|
||||
const stateDir = path.join(root, "state");
|
||||
const localCwd = path.join(root, "worktree");
|
||||
|
|
@ -3626,65 +3615,20 @@ describe("ACPX engine per-step startup timing (run.startup.step events)", () =>
|
|||
);
|
||||
|
||||
const steps = stepEvents(events);
|
||||
const seen = new Map(steps.map((event) => [String(event.payload?.step), event]));
|
||||
expect(steps.length).toBeGreaterThan(0);
|
||||
|
||||
// Every timed boundary still records duration.
|
||||
// Every timed boundary still records the high-level duration and outcome.
|
||||
// The detailed per-step round-trip and provider-duration numbers ride the
|
||||
// OTel spans now, so no payload carries them.
|
||||
for (const event of steps) {
|
||||
expect(typeof event.payload?.durationMs).toBe("number");
|
||||
const payload = event.payload ?? {};
|
||||
expect(typeof payload.durationMs).toBe("number");
|
||||
expect(payload).not.toHaveProperty("roundTrips");
|
||||
expect(payload).not.toHaveProperty("providerExecMs");
|
||||
expect(payload).not.toHaveProperty("providerGetMs");
|
||||
expect(payload).not.toHaveProperty("createRuntimeMs");
|
||||
expect(payload).not.toHaveProperty("ensureSessionMs");
|
||||
}
|
||||
// Sequential boundaries retain runner-counter attribution.
|
||||
for (const step of ["workspace.resolve", "stage.sync", "acp.handshake"]) {
|
||||
expect(typeof seen.get(step)?.payload?.roundTrips).toBe("number");
|
||||
}
|
||||
// workspace.resolve is host-only → zero host→sandbox execs.
|
||||
expect(seen.get("workspace.resolve")?.payload?.roundTrips).toBe(0);
|
||||
// stage.sync ships the workspace over the exec seam → at least one round-trip,
|
||||
// and the accumulated provider durations scale with it.
|
||||
const stageSync = seen.get("stage.sync");
|
||||
expect(stageSync?.payload?.roundTrips as number).toBeGreaterThan(0);
|
||||
expect(stageSync?.payload?.providerExecMs).toBe(
|
||||
(stageSync?.payload?.roundTrips as number) * 600,
|
||||
);
|
||||
expect(stageSync?.payload?.providerGetMs).toBe(
|
||||
(stageSync?.payload?.roundTrips as number) * 15,
|
||||
);
|
||||
// Concurrent bridge steps are duration-only so they do not double-count
|
||||
// shared runner counters while their lifecycles overlap.
|
||||
for (const step of ["bridge.paperclip", "bridge.process-session"]) {
|
||||
expect(seen.get(step)?.payload?.roundTrips).toBeUndefined();
|
||||
expect(seen.get(step)?.payload?.providerExecMs).toBeUndefined();
|
||||
expect(seen.get(step)?.payload?.providerGetMs).toBeUndefined();
|
||||
}
|
||||
// The external ACP client crosses no host exec seam.
|
||||
expect(seen.get("acp.handshake")?.payload?.roundTrips).toBe(0);
|
||||
});
|
||||
|
||||
it("splits acp.handshake into createRuntimeMs and ensureSessionMs sub-phases", 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 });
|
||||
const executionTarget = {
|
||||
kind: "remote",
|
||||
transport: "sandbox",
|
||||
providerKey: "fake-plugin",
|
||||
remoteCwd,
|
||||
runner: createLocalSandboxRunner(),
|
||||
};
|
||||
|
||||
const { events } = await runExecutor(
|
||||
{ agent: "custom", agentCommand: "node ./fake-acp.js", stateDir, cwd: localCwd },
|
||||
{ authToken: "real-run-jwt", executionTarget },
|
||||
);
|
||||
|
||||
const handshake = stepEvents(events).find((event) => event.payload?.step === "acp.handshake");
|
||||
expect(handshake).toBeTruthy();
|
||||
expect(typeof handshake!.payload?.createRuntimeMs).toBe("number");
|
||||
expect(handshake!.payload?.createRuntimeMs as number).toBeGreaterThanOrEqual(0);
|
||||
expect(typeof handshake!.payload?.ensureSessionMs).toBe("number");
|
||||
expect(handshake!.payload?.ensureSessionMs as number).toBeGreaterThanOrEqual(0);
|
||||
});
|
||||
|
||||
it("emits a skipped acp.handshake event when a warm-handle hit skips the handshake", async () => {
|
||||
|
|
|
|||
|
|
@ -95,7 +95,6 @@ import {
|
|||
type StartupStepMeasureOptions,
|
||||
type StartupTraceContext,
|
||||
} from "./startup-timing.js";
|
||||
import type { CommandManagedRuntimeRunner } from "../command-managed-runtime.js";
|
||||
|
||||
const defaultModuleDir = path.dirname(fileURLToPath(import.meta.url));
|
||||
const PAPERCLIP_MANAGED_CODEX_SKILLS_MANIFEST = ".paperclip-managed-skills.json";
|
||||
|
|
@ -1346,22 +1345,6 @@ async function stageAcpRemoteRuntime(input: {
|
|||
});
|
||||
}
|
||||
|
||||
// Bind a startup-step round-trip/provider-duration reader set to a runner's
|
||||
// cumulative counters (Open Q1). Only the sandbox runner instruments the exec
|
||||
// seam, so a runner without `execCount` (SSH, or none) yields an empty option
|
||||
// set and the affected steps omit the fields entirely. Reader closures are
|
||||
// passed — not the runner — so `measureStartupStep` stays runner-agnostic.
|
||||
function buildStartupStepMetrics(
|
||||
runner: CommandManagedRuntimeRunner | undefined,
|
||||
): StartupStepMeasureOptions {
|
||||
if (!runner) return {};
|
||||
return {
|
||||
...(runner.execCount ? { roundTrips: () => runner.execCount!() } : {}),
|
||||
...(runner.providerExecMs ? { providerExecMs: () => runner.providerExecMs!() } : {}),
|
||||
...(runner.providerGetMs ? { providerGetMs: () => runner.providerGetMs!() } : {}),
|
||||
};
|
||||
}
|
||||
|
||||
async function buildRuntime(input: {
|
||||
ctx: AdapterExecutionContext;
|
||||
engine: AcpxEngineSettings;
|
||||
|
|
@ -1450,28 +1433,13 @@ async function buildRuntime(input: {
|
|||
? remoteExecutionIdentity.remoteCwd
|
||||
: cwd;
|
||||
const executionTargetIsRemote = remoteExecutionIdentity !== null;
|
||||
// Round-trip / provider-duration readers for per-step attribution (Open Q1),
|
||||
// sourced from the sandbox runner's cumulative counters. `measureStartupStep`
|
||||
// reads each as a `() => number` closure (never the runner itself, Risk R1)
|
||||
// and emits the per-step delta. Empty when there is no runner (local runs,
|
||||
// the runner-less ACP→CLI fallback, or an SSH runner that does not
|
||||
// instrument the seam), so those steps simply omit the fields.
|
||||
// Merge the injected tracer + root parent-context into every step option set,
|
||||
// so each boundary span parents to the root span. With no injected trace
|
||||
// context both fields are no-ops and the span path stays inert.
|
||||
const stepMetrics: StartupStepMeasureOptions = {
|
||||
...buildStartupStepMetrics(
|
||||
executionTarget?.kind === "remote" && executionTarget.transport === "sandbox"
|
||||
? executionTarget.runner
|
||||
: undefined,
|
||||
),
|
||||
...input.spanParent,
|
||||
};
|
||||
// The two bridge-start steps intentionally overlap, so their runner counters
|
||||
// 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. A shared `batch` tag marks
|
||||
// The two bridge-start steps intentionally overlap. 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 = {
|
||||
|
|
@ -1971,10 +1939,8 @@ async function buildRuntime(input: {
|
|||
// dir/script setup first, then awaits that thunk right before its launch, so
|
||||
// the launch always observes the merged paperclip env.
|
||||
//
|
||||
// Measurement caveat: both starts share ONE runner counter, so their
|
||||
// overlapping `providerExecMs`/`roundTrips` deltas are approximate (the same
|
||||
// caveat as `acp.handshake`). Both `run.startup.step` events still emit —
|
||||
// `measureStartupStep` records them in a `finally`, even on a start failure.
|
||||
// Both `run.startup.step` events still emit — `measureStartupStep` records
|
||||
// them in a `finally`, even on a start failure.
|
||||
const paperclipStart = measureStartupStep(input.ctx, nowMs, "bridge.paperclip", () =>
|
||||
startAdapterExecutionTargetPaperclipBridge({
|
||||
runId,
|
||||
|
|
@ -3153,9 +3119,8 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
try {
|
||||
// Step 7 — acp.handshake: ACP session establishment (session/new or
|
||||
// resume). A throwing handshake still reports its duration before the
|
||||
// resume-retry path below runs. `roundTrips` is expected to be 0 (the
|
||||
// ACP client is external, not the host exec seam); the payload also
|
||||
// carries the createRuntime/ensureSession sub-split (Open Q2).
|
||||
// resume-retry path below runs. The createRuntime/ensureSession
|
||||
// sub-split rides the step span as fixed, closed keys (Open Q2).
|
||||
let ensureSessionMs: number | undefined;
|
||||
handle = await measureStartupStep(ctx, now, "acp.handshake", async () => {
|
||||
const ensureSessionStart = now();
|
||||
|
|
@ -3171,11 +3136,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
return established;
|
||||
}, {
|
||||
...prepared.stepMetrics,
|
||||
extra: () => ({
|
||||
...(createRuntimeMs !== undefined ? { createRuntimeMs } : {}),
|
||||
...(ensureSessionMs !== undefined ? { ensureSessionMs } : {}),
|
||||
}),
|
||||
// The same two sub-times ride the span as fixed, closed keys.
|
||||
// The two sub-times ride the span as fixed, closed keys.
|
||||
spanWallTimes: () => ({
|
||||
createRuntime: createRuntimeMs,
|
||||
ensureSession: ensureSessionMs,
|
||||
|
|
@ -3206,9 +3167,6 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||
return established;
|
||||
}, {
|
||||
...prepared.stepMetrics,
|
||||
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 }),
|
||||
|
|
|
|||
|
|
@ -82,60 +82,9 @@ describe("measureStartupStep", () => {
|
|||
expect(events[0]!.message).toBe("startup step: stage.sync (150ms)");
|
||||
});
|
||||
|
||||
it("includes the roundTrips delta in the payload when a round-trip reader is supplied", async () => {
|
||||
it("emits only the high-level fields (step, durationMs, outcome) on the payload", async () => {
|
||||
let t = 0;
|
||||
const now = () => t;
|
||||
// Cumulative host→sandbox exec counter; the step performs 3 execs.
|
||||
let execCount = 5;
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => {
|
||||
events.push(event);
|
||||
});
|
||||
|
||||
await measureStartupStep({ onEvent }, now, "stage.sync", async () => {
|
||||
t = 90;
|
||||
execCount += 3;
|
||||
return "ok";
|
||||
}, { roundTrips: () => execCount });
|
||||
|
||||
expect(events[0]!.payload).toMatchObject({
|
||||
step: "stage.sync",
|
||||
durationMs: 90,
|
||||
roundTrips: 3,
|
||||
});
|
||||
});
|
||||
|
||||
it("reports roundTrips: 0 for a step that performs no execs (reader supplied)", async () => {
|
||||
const now = () => 0;
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => {
|
||||
events.push(event);
|
||||
});
|
||||
|
||||
await measureStartupStep({ onEvent }, now, "workspace.resolve", async () => "ok", {
|
||||
roundTrips: () => 7,
|
||||
});
|
||||
|
||||
expect(events[0]!.payload).toMatchObject({ step: "workspace.resolve", roundTrips: 0 });
|
||||
});
|
||||
|
||||
it("omits roundTrips from the payload when no reader is supplied", async () => {
|
||||
const now = () => 0;
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => {
|
||||
events.push(event);
|
||||
});
|
||||
|
||||
await measureStartupStep({ onEvent }, now, "workspace.resolve", async () => "ok");
|
||||
|
||||
expect(events[0]!.payload).not.toHaveProperty("roundTrips");
|
||||
});
|
||||
|
||||
it("accumulates provider exec/get durations and merges extra fields into the payload", async () => {
|
||||
let t = 0;
|
||||
const now = () => t;
|
||||
let execMs = 100;
|
||||
let getMs = 40;
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => {
|
||||
events.push(event);
|
||||
|
|
@ -143,23 +92,18 @@ describe("measureStartupStep", () => {
|
|||
|
||||
await measureStartupStep({ onEvent }, now, "acp.handshake", async () => {
|
||||
t = 7000;
|
||||
execMs += 600; // one provider executeCommand round-trip
|
||||
getMs += 15; // one client.get re-fetch
|
||||
return "handle";
|
||||
}, {
|
||||
providerExecMs: () => execMs,
|
||||
providerGetMs: () => getMs,
|
||||
extra: () => ({ createRuntimeMs: 12, ensureSessionMs: 6988 }),
|
||||
});
|
||||
|
||||
expect(events[0]!.payload).toMatchObject({
|
||||
step: "acp.handshake",
|
||||
durationMs: 7000,
|
||||
providerExecMs: 600,
|
||||
providerGetMs: 15,
|
||||
createRuntimeMs: 12,
|
||||
ensureSessionMs: 6988,
|
||||
});
|
||||
// The detailed per-step round-trip and provider-duration numbers ride the
|
||||
// OTel spans now, so the run-log payload keeps only the high-level fields.
|
||||
const payload = events[0]!.payload as Record<string, unknown>;
|
||||
expect(Object.keys(payload).sort()).toEqual(["durationMs", "outcome", "step"]);
|
||||
expect(payload).not.toHaveProperty("roundTrips");
|
||||
expect(payload).not.toHaveProperty("providerExecMs");
|
||||
expect(payload).not.toHaveProperty("providerGetMs");
|
||||
expect(payload).not.toHaveProperty("createRuntimeMs");
|
||||
expect(payload).not.toHaveProperty("ensureSessionMs");
|
||||
});
|
||||
|
||||
it("returns the wrapped fn result unchanged", async () => {
|
||||
|
|
@ -282,64 +226,27 @@ describe("measureStartupStep", () => {
|
|||
expect(spans[0]!.status?.code).toBe(2);
|
||||
});
|
||||
|
||||
it("keeps the roundTrips / providerExecMs / providerGetMs deltas on the payload but off the span", async () => {
|
||||
let t = 0;
|
||||
const now = () => t;
|
||||
let execCount = 5;
|
||||
let execMs = 100;
|
||||
let getMs = 40;
|
||||
it("carries only the allowlisted attributes on the step span, never the removed round-trip detail", async () => {
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => {
|
||||
events.push(event);
|
||||
});
|
||||
const { tracer, spans } = makeMockTracer();
|
||||
|
||||
await measureStartupStep({ onEvent }, now, "stage.sync", async () => {
|
||||
t = 90;
|
||||
execCount += 3;
|
||||
execMs += 600;
|
||||
getMs += 15;
|
||||
return "ok";
|
||||
}, {
|
||||
await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", {
|
||||
tracer,
|
||||
roundTrips: () => execCount,
|
||||
providerExecMs: () => execMs,
|
||||
providerGetMs: () => getMs,
|
||||
provider: "daytona",
|
||||
});
|
||||
|
||||
// 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 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 () => {
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const onEvent = vi.fn(async (event: AdapterRuntimeEvent) => {
|
||||
events.push(event);
|
||||
});
|
||||
const { tracer, spans } = makeMockTracer();
|
||||
|
||||
await measureStartupStep({ onEvent }, () => 0, "workspace.resolve", async () => "ok", {
|
||||
tracer,
|
||||
// A reader may return undefined when the counter is unavailable. The guard
|
||||
// must omit the attribute rather than emit NaN or 0.
|
||||
roundTrips: () => undefined as unknown as number,
|
||||
providerExecMs: () => undefined as unknown as number,
|
||||
});
|
||||
|
||||
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);
|
||||
// The step span carries only the closed allowlist. The per-execution
|
||||
// `sandbox.exec` spans carry the round-trip and provider-duration detail.
|
||||
expect(Object.keys(spans[0]!.attributes).sort()).toEqual(
|
||||
[A.provider, A.stepWallMs, A.outcome].sort(),
|
||||
);
|
||||
const payload = events[0]!.payload as Record<string, unknown>;
|
||||
expect(payload).not.toHaveProperty("roundTrips");
|
||||
expect(payload).not.toHaveProperty("providerExecMs");
|
||||
expect(payload).not.toHaveProperty("providerGetMs");
|
||||
});
|
||||
|
||||
it("normalizes a plugin-backed provider key to plugin and keeps a built-in family as-is", async () => {
|
||||
|
|
@ -376,20 +283,11 @@ describe("measureStartupStep", () => {
|
|||
await measureStartupStep({ onEvent }, () => 0, "acp.handshake", async () => "ok", {
|
||||
tracer,
|
||||
provider: "daytona",
|
||||
roundTrips: () => 3,
|
||||
providerExecMs: () => 600,
|
||||
providerGetMs: () => 15,
|
||||
// extra() carries caller-measured numbers into the EVENT payload only.
|
||||
// It must never widen the span-attribute set.
|
||||
extra: () => ({ createRuntimeMs: 12, ensureSessionMs: 6988 }),
|
||||
});
|
||||
|
||||
expect(Object.keys(spans[0]!.attributes).sort()).toEqual(
|
||||
[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");
|
||||
// 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)) {
|
||||
|
|
@ -411,9 +309,7 @@ describe("measureStartupStep", () => {
|
|||
|
||||
// No tracer supplied. The helper must still emit the event and return the
|
||||
// value without throwing.
|
||||
const result = await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok", {
|
||||
roundTrips: () => 3,
|
||||
});
|
||||
const result = await measureStartupStep({ onEvent }, () => 0, "stage.sync", async () => "ok");
|
||||
|
||||
expect(result).toBe("ok");
|
||||
expect(events[0]!.payload).toMatchObject({ step: "stage.sync" });
|
||||
|
|
@ -471,9 +367,6 @@ describe("measureStartupStep", () => {
|
|||
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);
|
||||
|
|
@ -481,12 +374,9 @@ describe("measureStartupStep", () => {
|
|||
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.
|
||||
// The step wall time uses its type suffix.
|
||||
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);
|
||||
});
|
||||
});
|
||||
|
||||
|
|
|
|||
|
|
@ -53,7 +53,6 @@ export const SANDBOX_STARTUP_SPAN_ATTR_PREFIX = "paperclip.sandbox.startup.";
|
|||
* 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
|
||||
|
|
@ -66,12 +65,6 @@ export const SANDBOX_STARTUP_SPAN_ATTRS = {
|
|||
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. */
|
||||
|
|
@ -368,47 +361,20 @@ function setFiniteNumberAttr(
|
|||
}
|
||||
|
||||
/**
|
||||
* Compute a counter delta from a reader. Return `undefined` when the reader is
|
||||
* absent, or when either the start or the end snapshot is not a finite number.
|
||||
* A `undefined` result yields no payload field and no span attribute.
|
||||
*/
|
||||
function finiteDelta(
|
||||
read: (() => number) | undefined,
|
||||
start: number | undefined,
|
||||
): number | undefined {
|
||||
if (!read) return undefined;
|
||||
const end = read();
|
||||
if (typeof end !== "number" || !Number.isFinite(end)) return undefined;
|
||||
const base = typeof start === "number" && Number.isFinite(start) ? start : 0;
|
||||
return end - base;
|
||||
}
|
||||
|
||||
/**
|
||||
* Optional per-step attribution attached to a `run.startup.step` event, all
|
||||
* additive to the free-form jsonb payload (no schema change). Each reader is a
|
||||
* plain `() => number` closure so the timing helper stays decoupled from the
|
||||
* runner/provider it reads (Risk R1): `measureStartupStep` snapshots the reader
|
||||
* before `fn` and again in `finally`, emitting the delta.
|
||||
* Optional per-step attribution for a `run.startup.step` event and its span.
|
||||
* The event payload carries only the high-level fields (`step`, `durationMs`,
|
||||
* `outcome`). The detailed per-step round-trip and provider-duration numbers
|
||||
* ride the OTel spans (the per-execution `sandbox.exec` child spans and the
|
||||
* step span), not the payload. These options configure the span path and the
|
||||
* step context.
|
||||
*
|
||||
* - `roundTrips` — cumulative host→sandbox `runner.execute` count; the delta is
|
||||
* how many round-trips the step performed (Open Q1, host boundary).
|
||||
* - `providerExecMs` / `providerGetMs` — cumulative provider-reported wall-time
|
||||
* (ms) for the `executeCommand` REST call vs the `client.get` sandbox
|
||||
* re-fetch; the delta attributes the step's round-trip time to its parts
|
||||
* (Open Q1, finer provider attribution).
|
||||
* - `extra` — a reader (called once in `finally`, after `fn` settles) returning
|
||||
* any additional numeric fields to merge into the payload; used by
|
||||
* `acp.handshake` to carry its `createRuntimeMs` / `ensureSessionMs` sub-split
|
||||
* (Open Q2), which are measured by the caller rather than read from a counter.
|
||||
* The `extra` map feeds the EVENT payload only. Its keys never become span
|
||||
* 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 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.
|
||||
* round-trip and provider-duration detail rides 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
|
||||
|
|
@ -418,10 +384,6 @@ function finiteDelta(
|
|||
* low-cardinality `provider` span attribute. It never sets the raw key.
|
||||
*/
|
||||
export interface StartupStepMeasureOptions {
|
||||
roundTrips?: () => number;
|
||||
providerExecMs?: () => number;
|
||||
providerGetMs?: () => number;
|
||||
extra?: () => Record<string, number>;
|
||||
tracer?: StartupTracer;
|
||||
parentContext?: StartupSpanContext;
|
||||
provider?: string;
|
||||
|
|
@ -477,8 +439,8 @@ function buildStepEvent(payload: Record<string, unknown>): AdapterRuntimeEvent {
|
|||
|
||||
/**
|
||||
* Time `fn` with the injected `now` clock and emit exactly one
|
||||
* `run.startup.step` event carrying `{ step, durationMs }` plus any counters
|
||||
* supplied via `options`. The event fires in a `finally`, so a throwing step
|
||||
* `run.startup.step` event carrying only the high-level `{ step, durationMs,
|
||||
* outcome }`. The event fires in a `finally`, so a throwing step
|
||||
* still reports its duration before the error is re-thrown. `now` is injected
|
||||
* (never `Date.now()` here) so callers/tests stay deterministic, and
|
||||
* `ctx.onEvent` is optional — a missing sink is a no-op that neither throws nor
|
||||
|
|
@ -490,7 +452,8 @@ function buildStepEvent(payload: Record<string, unknown>): AdapterRuntimeEvent {
|
|||
* 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
|
||||
* outcome is `failed`. The round-trip and provider-duration detail rides the
|
||||
* spans, not the 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.
|
||||
|
|
@ -503,9 +466,6 @@ export async function measureStartupStep<T>(
|
|||
options: StartupStepMeasureOptions = {},
|
||||
): Promise<T> {
|
||||
const start = now();
|
||||
const roundTripsStart = options.roundTrips?.();
|
||||
const providerExecStart = options.providerExecMs?.();
|
||||
const providerGetStart = options.providerGetMs?.();
|
||||
|
||||
// Open the span with only the low-cardinality allowlisted attributes known at
|
||||
// the start: the normalized provider family. The span name already carries
|
||||
|
|
@ -554,28 +514,16 @@ export async function measureStartupStep<T>(
|
|||
} finally {
|
||||
const durationMs = now() - start;
|
||||
|
||||
// One attribute-build block feeds both the event payload and the span, so
|
||||
// the two paths never drift. `undefined` deltas produce neither a payload
|
||||
// field nor a span attribute (fail open — never `NaN`, never `0`).
|
||||
const roundTrips = finiteDelta(options.roundTrips, roundTripsStart);
|
||||
const providerExecMs = finiteDelta(options.providerExecMs, providerExecStart);
|
||||
const providerGetMs = finiteDelta(options.providerGetMs, providerGetStart);
|
||||
|
||||
// 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;
|
||||
|
||||
// The payload carries only the high-level fields. The detailed per-step
|
||||
// round-trip and provider-duration numbers ride the OTel spans now, so the
|
||||
// run-log copy is gone.
|
||||
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;
|
||||
if (options.extra) {
|
||||
// `extra` feeds the EVENT payload only. Its keys never become span
|
||||
// attributes, so it cannot widen the closed span allowlist.
|
||||
Object.assign(payload, options.extra());
|
||||
}
|
||||
|
||||
try {
|
||||
if (stepFailed) span.setStatus({ code: SPAN_STATUS_CODE_ERROR });
|
||||
|
|
|
|||
|
|
@ -25,25 +25,6 @@ export interface CommandManagedRuntimeRunner {
|
|||
* and let the caller choose a chunked upload path when progress is requested.
|
||||
*/
|
||||
supportsSingleStreamStdinProgress?: boolean;
|
||||
/**
|
||||
* Cumulative count of host→sandbox `execute` round-trips this runner has
|
||||
* performed (Open Q1). Present only on runners that instrument the single
|
||||
* exec seam (the sandbox runner); the per-step delta is emitted as
|
||||
* `run.startup.step` `payload.roundTrips`. A `() => number` reader, never the
|
||||
* runner itself, is threaded into `measureStartupStep` so the timing helper
|
||||
* stays runner-agnostic.
|
||||
*/
|
||||
execCount?(): number;
|
||||
/**
|
||||
* Cumulative provider-reported wall-time (ms) for the `executeCommand` REST
|
||||
* call ({@link providerExecMs}) vs the `client.get` sandbox re-fetch that
|
||||
* precedes it ({@link providerGetMs}), accumulated across every `execute`
|
||||
* round-trip (Open Q1, finer attribution). Present only when the provider
|
||||
* surfaces these durations on its result metadata; the per-step deltas are
|
||||
* emitted as `payload.providerExecMs` / `payload.providerGetMs`.
|
||||
*/
|
||||
providerExecMs?(): number;
|
||||
providerGetMs?(): number;
|
||||
execute(input: {
|
||||
command: string;
|
||||
args?: string[];
|
||||
|
|
@ -354,8 +335,7 @@ export function createCommandManagedRuntimeClient(input: {
|
|||
// replace untar for directories, direct `writeFile` for single files), then run
|
||||
// the operation's ordered `postUploadCommands` fail-fast. Byte-for-byte
|
||||
// behavior-equivalent to the caller-inlined tar path it will replace. All exec
|
||||
// rides the shared `execute` seam so `execCount`/`providerExecMs` still
|
||||
// attribute (Open Q1).
|
||||
// rides the shared `execute` seam.
|
||||
const fallbackSyncIn = async (operations: SandboxSyncOperation[]): Promise<SandboxSyncResult> => {
|
||||
const resultOperations: SandboxSyncResult["operations"] = [];
|
||||
const tempDir = await fs.mkdtemp(path.join(os.tmpdir(), "paperclip-syncin-fallback-"));
|
||||
|
|
|
|||
|
|
@ -226,6 +226,31 @@ record, so a worker can never forge a parent. The host validates the
|
|||
trace context the worker sends no span, so the whole provider-span path is a
|
||||
no-op.
|
||||
|
||||
## Sandbox Startup Run-Log Event
|
||||
|
||||
Paperclip writes one `run.startup.step` event to the run log for each bring-up
|
||||
step. This event is a run-log record, not a first-party telemetry event. The
|
||||
generated telemetry contract does not cover it, so this section is its canonical
|
||||
contract.
|
||||
|
||||
The event payload carries only three fields.
|
||||
|
||||
| Field | Type | Meaning |
|
||||
| --- | --- | --- |
|
||||
| `step` | string | The bring-up step name, for example `stage.sync`. |
|
||||
| `durationMs` | number | The wall time of the step. A skipped step reports `0`. |
|
||||
| `outcome` | string | The step outcome (`ok`, `skipped`, or `failed`). |
|
||||
|
||||
The event no longer carries the per-step round-trip count or the provider
|
||||
duration fields. It dropped `roundTrips`, `providerExecMs`, `providerGetMs`,
|
||||
`createRuntimeMs`, and `ensureSessionMs`. The startup spans in the section above
|
||||
carry that detail now. The `sandbox.exec` child spans hold the round-trip and
|
||||
provider durations. The `acp.handshake` step span holds the create-runtime and
|
||||
ensure-session sub-times.
|
||||
|
||||
To read the detailed timing, use the startup spans. The spans need an OTLP
|
||||
endpoint. A run with no endpoint keeps only the three run-log fields above.
|
||||
|
||||
## Dimension Values
|
||||
|
||||
Telemetry dimension values must be primitives. Use only the value types allowed
|
||||
|
|
|
|||
|
|
@ -367,7 +367,7 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
expect(target).not.toHaveProperty("paperclipApiUrl");
|
||||
});
|
||||
|
||||
it("exposes a sandbox runner that counts round-trips and accumulates provider durations", async () => {
|
||||
it("exposes a sandbox runner with single-stream stdin upload disabled", async () => {
|
||||
mockResolveEnvironmentDriverConfigForRuntime.mockResolvedValue({
|
||||
driver: "sandbox",
|
||||
config: {
|
||||
|
|
@ -377,8 +377,6 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
},
|
||||
});
|
||||
|
||||
// Each exec reports its provider-boundary durations on the free-form result
|
||||
// metadata (the Daytona plugin does this); the runner accumulates them.
|
||||
const environmentRuntime = {
|
||||
execute: vi.fn().mockResolvedValue({
|
||||
exitCode: 0,
|
||||
|
|
@ -404,66 +402,18 @@ describe("resolveEnvironmentExecutionTarget", () => {
|
|||
|
||||
const runner = (target as { runner?: {
|
||||
supportsSingleStreamStdinProgress?: boolean;
|
||||
execCount(): number;
|
||||
providerExecMs(): number;
|
||||
providerGetMs(): number;
|
||||
execute(input: { command: string; args?: string[] }): Promise<unknown>;
|
||||
} }).runner;
|
||||
expect(runner).toBeTruthy();
|
||||
// Single-stream stdin upload is enabled (research A1 / PAP-3159 #2): a
|
||||
// ≤96 MiB writeFile collapses to one round-trip.
|
||||
// Provider-backed sandbox RPCs do not surface bounded mid-stream progress
|
||||
// for a single stdin upload, so the runner leaves the capability disabled.
|
||||
expect(runner!.supportsSingleStreamStdinProgress).toBe(false);
|
||||
expect(runner!.execCount()).toBe(0);
|
||||
expect(runner!.providerExecMs()).toBe(0);
|
||||
expect(runner!.providerGetMs()).toBe(0);
|
||||
|
||||
// The exec seam still runs each command; the run-log no longer carries the
|
||||
// detailed per-step round-trip or provider-duration counts.
|
||||
await runner!.execute({ command: "echo", args: ["a"] });
|
||||
await runner!.execute({ command: "echo", args: ["b"] });
|
||||
|
||||
expect(runner!.execCount()).toBe(2);
|
||||
expect(runner!.providerExecMs()).toBe(1200);
|
||||
expect(runner!.providerGetMs()).toBe(30);
|
||||
});
|
||||
|
||||
it("tolerates a provider result with no timing metadata (counts the round-trip, accumulates nothing)", async () => {
|
||||
mockResolveEnvironmentDriverConfigForRuntime.mockResolvedValue({
|
||||
driver: "sandbox",
|
||||
config: { provider: "fake-plugin", reuseLease: false, timeoutMs: 30_000 },
|
||||
});
|
||||
|
||||
const environmentRuntime = {
|
||||
execute: vi.fn().mockResolvedValue({
|
||||
exitCode: 0,
|
||||
signal: null,
|
||||
timedOut: false,
|
||||
stdout: "",
|
||||
stderr: "",
|
||||
}),
|
||||
supportsSync: vi.fn().mockReturnValue(false),
|
||||
};
|
||||
|
||||
const target = await resolveEnvironmentExecutionTarget({
|
||||
db: {} as never,
|
||||
companyId: "company-1",
|
||||
adapterType: "codex_local",
|
||||
environment: { id: "env-1", driver: "sandbox", config: { provider: "fake-plugin" } },
|
||||
leaseId: "lease-1",
|
||||
leaseMetadata: { remoteCwd: "/workspace" },
|
||||
lease: { id: "lease-1" } as never,
|
||||
environmentRuntime: environmentRuntime as never,
|
||||
});
|
||||
|
||||
const runner = (target as { runner?: {
|
||||
execCount(): number;
|
||||
providerExecMs(): number;
|
||||
providerGetMs(): number;
|
||||
execute(input: { command: string }): Promise<unknown>;
|
||||
} }).runner;
|
||||
await runner!.execute({ command: "echo" });
|
||||
|
||||
expect(runner!.execCount()).toBe(1);
|
||||
expect(runner!.providerExecMs()).toBe(0);
|
||||
expect(runner!.providerGetMs()).toBe(0);
|
||||
expect(environmentRuntime.execute).toHaveBeenCalledTimes(2);
|
||||
});
|
||||
|
||||
// A recording tracer that captures each provider-exec span's name, attribute
|
||||
|
|
|
|||
|
|
@ -214,20 +214,6 @@ export async function resolveEnvironmentExecutionTarget(input: {
|
|||
? input.leaseMetadata.shellCommand
|
||||
: null;
|
||||
|
||||
// Per-lease-runner cumulative counters for startup-step attribution (Open
|
||||
// Q1). Closed over by the `runner.execute` seam below and read back as
|
||||
// deltas by `measureStartupStep`.
|
||||
let execCount = 0;
|
||||
let providerExecMs = 0;
|
||||
let providerGetMs = 0;
|
||||
const accumulateProviderDurations = (metadata: Record<string, unknown> | undefined): void => {
|
||||
if (!metadata) return;
|
||||
const exec = metadata.durationMs;
|
||||
const get = metadata.getDurationMs;
|
||||
if (typeof exec === "number" && Number.isFinite(exec)) providerExecMs += exec;
|
||||
if (typeof get === "number" && Number.isFinite(get)) providerGetMs += get;
|
||||
};
|
||||
|
||||
// The low-cardinality public provider family. A plugin-backed / operator-
|
||||
// defined key maps to `plugin`, so a raw unbounded key never rides a span.
|
||||
const providerFamily = normalizeProviderFamily(parsed.config.provider);
|
||||
|
|
@ -255,17 +241,7 @@ export async function resolveEnvironmentExecutionTarget(input: {
|
|||
// here. The client falls back to the chunked upload path when this is
|
||||
// false.
|
||||
supportsSingleStreamStdinProgress: false,
|
||||
// Round-trip counter + provider-duration accumulators on the single
|
||||
// host→sandbox exec seam (Open Q1). `measureStartupStep` reads the
|
||||
// per-step delta of each via the `() => number` closures below. The
|
||||
// provider durations ride the exec result's free-form `metadata`
|
||||
// (set by the Daytona plugin), so no protocol/schema change is
|
||||
// needed and providers that omit them simply accumulate nothing.
|
||||
execCount: () => execCount,
|
||||
providerExecMs: () => providerExecMs,
|
||||
providerGetMs: () => providerGetMs,
|
||||
execute: async (commandInput) => {
|
||||
execCount += 1;
|
||||
// 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();
|
||||
|
|
@ -324,7 +300,6 @@ export async function resolveEnvironmentExecutionTarget(input: {
|
|||
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
|
||||
|
|
|
|||
Loading…
Reference in New Issue