Files
PaperClipAI/server/src/__tests__/plugin-host-services-span.test.ts
T
Nicky LeachandPaperclip 1d571de5f9 Add shared native turn attribution boundaries (#18213)
## Thinking Path

> - Paperclip manages work performed by AI agents.
> - Native execution crosses the plugin worker, Runner, sidecar, and
durable event boundaries.
> - Existing outer spans leave repeated preparation and admission work
unattributed.
> - Optimizations need a common baseline with accurate ownership and
event meanings.
> - This change extends the existing opt-in tracing contract with
bounded timing receipts.
> - It preserves execution policy and keeps provider internals opaque
where the API provides no timing proof.

## Linked Issues or Issue Description

**What existing behavior does this improve?**
Attribution of native task preparation, retained/cold Runner handoff,
and completion-to-text work.

**Current behavior**
Worker spans use a flat provider contract. Workspace calls lack a
consistent dispatch envelope. Submitted-to-started timing is named as a
provider queue even though it includes other work. The transport does
not expose a shared breakdown of its waits.

**Proposed improvement**
Add invocation-scoped nesting, bounded numeric remote receipts,
current-run transport timing, durable receipt intervals, and distinct
completion/text milestones. Reuse the existing exporter. No latency
optimization is included.

Related public work: #17842 consolidates existing startup tracing tests;
it does not add this runtime coverage.

## What Changed

- Extend the optional SDK tracer with nested async scopes and completed
timing receipts. Keep the host responsible for parent identity,
capability checks, attributes, clocks, depth, and count limits.
- Add dispatch and bounded host-read timings for environment and
workspace providers.
- Resolve transport parents on each call so retained sessions do not
retain an earlier run's trace.
- Split cold/resume/attach/prepare/registration/command/started-event
waits. Add opt-in numeric ACPX Runner/sidecar status and prompt-start
receipts.
- Distinguish first completion request, validated tool receipt, final
result commit, first nonempty text, and event persistence. Rename the
submitted-to-started interval to match its meaning.
- Link completed earlier remote lifecycles to their host-owned observer
rather than placing them under a later polling request. Preserve
sampling, timestamp limits and budgets.
- Document the versioned coverage map, causal clock limits, and baseline
acceptance requirements.

## Verification

- Current head: GitHub CI is fully green. Standard Greptile and Apex are
both 5/5, with no unresolved review threads. Full-suite validation was
performed in CI; follow-up local validation was limited to affected
packages and tests.

- Review follow-up: early rejection, missing provider capability and
startup-parent regressions were reproduced and fixed. The affected
worker/SDK/timing set passes 128 tests; 28 timing/context tests, SDK
typecheck and direct server TypeScript checking pass. The server
typecheck wrapper reached an unrelated Runner rebuild and stopped
because Cargo was absent from PATH; full Runner/image validation remains
in CI.

- CI failure accounting: the earlier Turbo cache/force conflict and
Linux OpenCode shell assertion were reproduced and diagnosed. A direct
proc probe ruled out permissions; a portable shell comparison identified
Bash skipping BASH_ENV with stripped SHLVL and socket stdin. Upstream
#18230 now supplies the CI and ignored-stdin fixture fixes; this PR
adopts them without duplicate CI changes. The strict Linux OOM assertion
passed before this source-equivalent merge.
- Retry follow-up: the three insertion/replay/failure timing cases and
server typecheck pass. The existing database regression now asserts a
single marker across identical result replay; the current-head CI
integration gate passes.
- Upstream CI alignment: all three real-Turbo 2.11.10 integration cases
pass. The repository policy gate rejected committing a generated
lockfile; the final PR contains no lockfile edit and uses the maintained
inline stale-lockfile recovery.
- Linked-lifecycle follow-up: 44 focused host/export tests pass (three
optional SDK-dependent cases skip); SDK and server typechecks pass. The
API contract test verifies an explicit root context, host-owned observer
link and unsampled suppression.
- SDK typecheck and focused worker/invocation tests: 30 passed,
including clock changes, bounded legacy IPC, and manual-span
creation-scope parentage.
- Focused reviewed host/native/transaction-boundary checks: 44 passed.
The 86-test worker-manager suite passes after updating its exact
assertions for the host-owned timing budget found by CI. Earlier
preparation/first-text checks also passed.
- Affected server and Runner TypeScript checks pass after building local
workspace declarations.
- Merge follow-up: the profile/candidate startup subset passes 94 tests,
the four Grok source-identity checks pass, and Runner TypeScript
checking passes. A subsequent execution-factory merge passes 21 focused
timing/trace tests and server TypeScript checking.
- Pinned Rust build and the ACPX Rust subset pass. The hostile receipt
projection test passes. Source profile compatibility checks: 127 passed,
one existing skip. Grok identity checks: four passed.
- Broad transport/ACPX suite: 410 passed after building all fake
provider binaries. Earlier attempts failed on missing
Runner/fake-provider outputs; building the required fixtures resolved
those failures.
- The first CI run correctly rejected stale source attestations. After
integrating current master, Grok advances 13→14 and Copilot 84→85;
master’s historical fixtures and Pi 35 stay byte-identical. Provider
dependencies, models and permission defaults are unchanged. Identity
generation/checks now pass.
- The added real-Postgres result lock regression could not initialize
its local embedded cluster. The insertion/replay/failure unit
regressions pass. The current-head CI integration gate passes.
- Comprehensive repository checks and image builds are delegated to CI,
as requested for this instrumentation pass. No deployment, model run,
collector-ingestion proof, or latency improvement is claimed.

## Risks

The new SDK methods are optional. Legacy span calls and endpoint-off
behavior remain supported. The host accepts only closed timing names and
bounded attributes. Remote durations are anchored at local receipt;
transport/scheduling uncertainty remains explicit. Trace trees have
count/depth limits. The first rollout must inspect actual collector
exports before treating the baseline as accepted. Fresh live
qualification for the new source identities remains a rollout
requirement. Revert these commits to remove the new measurements; no
schema migration is required.

## Model Used

OpenAI Codex, GPT-6 family, with reasoning and local code/tool
execution. The exact runtime model ID and context-window size are not
exposed in this session.

## Checklist

- [x] I have included a thinking path that traces from project context
to this change
- [x] I have specified the model used (with version and capability
details)
- [x] I have checked ROADMAP.md and confirmed this PR does not duplicate
planned core work
- [x] I have searched GitHub for duplicate or related PRs and linked
them above
- [x] I have described the issue in-PR following the enhancement
template
- [x] I have not referenced internal/instance-local Paperclip issues or
links
- [x] My branch name describes the change and contains no internal issue
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] Standard Greptile and Apex are both 5/5, with no unresolved
findings
- [x] I will address all Greptile and reviewer comments before
requesting merge

---------

Co-authored-by: Paperclip <noreply@paperclip.ing>
2026-10-29 17:45:56 -07:00

382 lines
15 KiB
TypeScript

import { beforeEach, describe, expect, it, vi } from "vitest";
import { createHostClientHandlers } from "../../../packages/plugins/sdk/src/host-client-factory.js";
import type { WorkerHostCallContext } from "../../../packages/plugins/sdk/src/protocol.js";
import { SANDBOX_STARTUP_SPAN_ATTRS as A } from "@paperclipai/adapter-utils/acpx-engine/startup-timing";
import {
buildHostServices,
clampProviderSpanAttributes,
parseTraceparent,
recordWorkerProviderSpan,
} from "../services/plugin-host-services.js";
// Capture every span the host trust boundary hands to the real tracer.
const mockRecordSpan = vi.hoisted(() => vi.fn());
vi.mock("../instrumentation.js", () => ({
recordProviderPluginSpan: mockRecordSpan,
traceparentFromContextToken: () => undefined,
}));
function createEventBusStub() {
return {
forPlugin() {
return { emit: vi.fn(), subscribe: vi.fn() };
},
} as never;
}
// A well-formed W3C traceparent (the host mints it; the handler validates it).
const VALID_TRACEPARENT = "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01";
function servicesFor() {
return buildHostServices({} as never, "plugin-record-id", "daytona", createEventBusStub());
}
function handlersFor(capabilities: readonly string[]) {
return createHostClientHandlers({
pluginId: "daytona",
capabilities: capabilities as never,
services: servicesFor(),
});
}
describe("plugin provider span host handler", () => {
beforeEach(() => {
mockRecordSpan.mockReset();
});
it("records a span with the clamped name and the allowlisted attributes", async () => {
const services = servicesFor();
await services.tracer.record(
{
name: "pack",
attributes: {
[A.provider]: "daytona",
[A.packWallMs]: 12,
},
},
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
expect(mockRecordSpan).toHaveBeenCalledTimes(1);
const call = mockRecordSpan.mock.calls[0]![0] as {
name: string;
parent: { traceId: string; spanId: string; traceFlags: number };
attributes: Record<string, unknown>;
};
expect(call.name).toBe("sandbox.daytona.pack");
expect(call.parent).toEqual({
traceId: "0af7651916cd43dd8448eb211c80319c",
spanId: "b7ad6b7169203331",
traceFlags: 1,
});
expect(call.attributes[A.provider]).toBe("daytona");
expect(call.attributes[A.packWallMs]).toBe(12);
});
it("drops every forbidden attribute before the span reaches the tracer", async () => {
const services = servicesFor();
await services.tracer.record(
{
name: "transfer",
attributes: {
[A.transferGuardCount]: 2,
// Forbidden fields that must never ride a span.
[A.execCommand]: "bash",
command: "rm -rf /",
args: "--force",
stdout: "secret output",
stderr: "secret error",
path: "/etc/passwd",
extra: "leak",
},
},
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
expect(mockRecordSpan).toHaveBeenCalledTimes(1);
const attributes = (mockRecordSpan.mock.calls[0]![0] as { attributes: Record<string, unknown> })
.attributes;
// Only the allowlisted key survives; every forbidden key is dropped.
expect(attributes).toEqual({ [A.transferGuardCount]: 2 });
for (const forbidden of [A.execCommand, "command", "args", "stdout", "stderr", "path", "extra"]) {
expect(attributes).not.toHaveProperty(forbidden);
}
});
it("drops a status message (it could carry standard-stream text)", async () => {
const services = servicesFor();
await services.tracer.record(
{ name: "transfer", status: { code: 2, message: "secret error text" } },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
const call = mockRecordSpan.mock.calls[0]![0] as { status?: { code: number; message?: string } };
expect(call.status).toEqual({ code: 2 });
expect(call.status).not.toHaveProperty("message");
});
it("clamps an unknown span name to sandbox.daytona.other", async () => {
const services = servicesFor();
await services.tracer.record(
{ name: "rm -rf / --no-preserve-root" },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
expect((mockRecordSpan.mock.calls[0]![0] as { name: string }).name).toBe(
"sandbox.daytona.other",
);
});
it("admits each per-round-trip span name to sandbox.daytona.<name>", async () => {
const services = servicesFor();
for (const name of [
"ensureDirectory",
"checkSymlinkEscape",
"promote",
"extractTarball",
"postUploadCommand",
]) {
await services.tracer.record(
{ name },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
}
const recorded = mockRecordSpan.mock.calls.map((c) => (c[0] as { name: string }).name);
expect(recorded).toEqual([
"sandbox.daytona.ensureDirectory",
"sandbox.daytona.checkSymlinkEscape",
"sandbox.daytona.promote",
"sandbox.daytona.extractTarball",
"sandbox.daytona.postUploadCommand",
]);
});
it("admits the session open and close span names", async () => {
const services = servicesFor();
for (const name of ["session.open", "session.close"]) {
await services.tracer.record(
{ name },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
}
const recorded = mockRecordSpan.mock.calls.map((c) => (c[0] as { name: string }).name);
expect(recorded).toEqual([
"sandbox.daytona.session.open",
"sandbox.daytona.session.close",
]);
});
it("forwards a valid start-time and end-time pair to the recorder", async () => {
const services = servicesFor();
const startTimeMs = Date.now() - 4500;
const endTimeMs = startTimeMs + 4500;
await services.tracer.record(
{ name: "ensureDirectory", startTimeMs, endTimeMs },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
const call = mockRecordSpan.mock.calls[0]![0] as {
startTimeMs?: number;
endTimeMs?: number;
};
expect(call.startTimeMs).toBe(startTimeMs);
expect(call.endTimeMs).toBe(endTimeMs);
});
it("accepts a pair whose end is a small skew ahead of the host clock", async () => {
const services = servicesFor();
// The worker clock leads the host clock by a few seconds. This small skew
// is within the allowed bound, so the host keeps the native width.
const startTimeMs = Date.now() + 5000;
const endTimeMs = startTimeMs + 1000;
await services.tracer.record(
{ name: "ensureDirectory", startTimeMs, endTimeMs },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
const call = mockRecordSpan.mock.calls[0]![0] as {
startTimeMs?: number;
endTimeMs?: number;
};
expect(call.startTimeMs).toBe(startTimeMs);
expect(call.endTimeMs).toBe(endTimeMs);
});
it("drops an invalid timestamp pair so the synchronous path runs", async () => {
const services = servicesFor();
const now = Date.now();
const invalidPairs: Array<{ startTimeMs?: unknown; endTimeMs?: unknown; why: string }> = [
{ startTimeMs: now, endTimeMs: now - 1000, why: "reversed order" },
{ startTimeMs: Number.NaN, endTimeMs: now, why: "non-finite start" },
{ startTimeMs: now, endTimeMs: Number.POSITIVE_INFINITY, why: "non-finite end" },
{ startTimeMs: now, endTimeMs: now + 11 * 60 * 1000, why: "over-ceiling duration" },
{ startTimeMs: now - 2 * 60 * 60 * 1000, endTimeMs: now - 2 * 60 * 60 * 1000 + 10, why: "over-age start" },
{ startTimeMs: now, endTimeMs: now + 2 * 60 * 1000, why: "end far in the future" },
{ startTimeMs: now + 5 * 60 * 1000, endTimeMs: now + 5 * 60 * 1000 + 10, why: "start and end in the future" },
];
for (const pair of invalidPairs) {
mockRecordSpan.mockReset();
await services.tracer.record(
{ name: "ensureDirectory", startTimeMs: pair.startTimeMs, endTimeMs: pair.endTimeMs } as never,
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
// The span still records (the synchronous path), but without a timestamp.
const call = mockRecordSpan.mock.calls[0]![0] as {
startTimeMs?: number;
endTimeMs?: number;
};
expect(call.startTimeMs, pair.why).toBeUndefined();
expect(call.endTimeMs, pair.why).toBeUndefined();
}
});
it("records the synchronous path when the timestamp pair is absent", async () => {
const services = servicesFor();
await services.tracer.record(
{ name: "pack" },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
const call = mockRecordSpan.mock.calls[0]![0] as {
startTimeMs?: number;
endTimeMs?: number;
};
expect(call.startTimeMs).toBeUndefined();
expect(call.endTimeMs).toBeUndefined();
});
it("rejects a malformed traceparent — no span is recorded", async () => {
const services = servicesFor();
for (const bad of [
undefined,
"not-a-traceparent",
"00-xyz-b7ad6b7169203331-01",
"00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331", // missing flags
"00-00000000000000000000000000000000-b7ad6b7169203331-01", // all-zero trace id
]) {
await services.tracer.record(
{ name: "pack" },
{ traceparent: bad } as WorkerHostCallContext,
);
}
expect(mockRecordSpan).not.toHaveBeenCalled();
});
it("rejects a span from a plugin that lacks the environment-driver capability", async () => {
const handlers = handlersFor([]);
await expect(
handlers["span.record"](
{ name: "pack" },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
),
).rejects.toThrow(/capabilit/i);
expect(mockRecordSpan).not.toHaveBeenCalled();
});
it("admits a span from a plugin that holds the environment-driver capability", async () => {
const handlers = handlersFor(["environment.drivers.register"]);
await handlers["span.record"](
{ name: "pack", attributes: { [A.provider]: "daytona" } },
{ traceparent: VALID_TRACEPARENT } as WorkerHostCallContext,
);
expect(mockRecordSpan).toHaveBeenCalledTimes(1);
});
});
describe("parseTraceparent", () => {
it("accepts a well-formed traceparent and returns the parts", () => {
expect(parseTraceparent(VALID_TRACEPARENT)).toEqual({
traceId: "0af7651916cd43dd8448eb211c80319c",
spanId: "b7ad6b7169203331",
traceFlags: 1,
});
});
it("rejects malformed, all-zero, and forbidden-version traceparents", () => {
expect(parseTraceparent(undefined)).toBeNull();
expect(parseTraceparent("garbage")).toBeNull();
expect(parseTraceparent("00-0af7651916cd43dd8448eb211c80319c-0000000000000000-01")).toBeNull();
expect(parseTraceparent("ff-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01")).toBeNull();
});
});
describe("clampProviderSpanAttributes", () => {
it("keeps only allowlisted keys and normalizes the provider family", () => {
expect(
clampProviderSpanAttributes({
[A.provider]: "some-operator-key",
[A.packWallMs]: 7,
[A.transferWallMs]: Number.NaN,
[A.execCommand]: "bash",
}),
).toEqual({
// An unknown provider key maps to `plugin`, never the raw key.
[A.provider]: "plugin",
[A.packWallMs]: 7,
// A non-finite number yields no attribute; `exec.command` is not allowed.
});
});
it("keeps the transfer direction for each closed-set value", () => {
expect(clampProviderSpanAttributes({ [A.transferDirection]: "inbound" })).toEqual({
[A.transferDirection]: "inbound",
});
expect(clampProviderSpanAttributes({ [A.transferDirection]: "outbound" })).toEqual({
[A.transferDirection]: "outbound",
});
});
it("drops a transfer direction outside the closed set or of the wrong type", () => {
// A free-form string, an empty string, and a non-string all yield no
// attribute, so the direction stays bounded and low-cardinality.
expect(clampProviderSpanAttributes({ [A.transferDirection]: "sideways" })).toEqual({});
expect(clampProviderSpanAttributes({ [A.transferDirection]: "" })).toEqual({});
expect(clampProviderSpanAttributes({ [A.transferDirection]: 1 })).toEqual({});
});
});
describe("nested worker timing receipts",()=>{
it("uses host-generated parents, clamps content and bounds child clocks",()=>{
mockRecordSpan.mockReset();
const childParent={traceId:"0af7651916cd43dd8448eb211c80319c",spanId:"1111111111111111",traceFlags:1};
mockRecordSpan.mockReturnValue(childParent);
const now=Date.now();
recordWorkerProviderSpan({name:"plugin.worker",startTimeMs:now-100,endTimeMs:now,children:[
{name:"plugin.remote.operation",startTimeMs:now-90,endTimeMs:now-10,attributes:{"plugin.operation":"script.settings",secret:"private"}},
{name:"plugin.runtime.verify",startTimeMs:now-200,endTimeMs:now},
]},{traceparent:VALID_TRACEPARENT} as WorkerHostCallContext);
expect(mockRecordSpan).toHaveBeenCalledTimes(2);
expect(mockRecordSpan.mock.calls[1][0]).toMatchObject({parent:childParent,attributes:{"plugin.operation":"script.settings"}});
expect(JSON.stringify(mockRecordSpan.mock.calls)).not.toContain("private");
});
});
it("allows a workspace provider timing receipt without environment-driver authority",async()=>{
mockRecordSpan.mockReset();
await handlersFor(["workspaces.manage"])["span.record"]({name:"plugin.worker"},{traceparent:VALID_TRACEPARENT} as WorkerHostCallContext);
expect(mockRecordSpan).toHaveBeenCalledTimes(1);
});
it("retains short children of a multi-hour worker invocation and shares its aggregate budget",()=>{
mockRecordSpan.mockReset();mockRecordSpan.mockReturnValue({traceId:"0af7651916cd43dd8448eb211c80319c",spanId:"1111111111111111",traceFlags:1});
const now=Date.now(),context={traceparent:VALID_TRACEPARENT,providerSpanBudget:{remaining:3}};
recordWorkerProviderSpan({name:"plugin.worker",startTimeMs:now-7200000,endTimeMs:now,children:[
{name:"pack",startTimeMs:now-7199990,endTimeMs:now-7199980}
]},context);
recordWorkerProviderSpan({name:"pack"},context);recordWorkerProviderSpan({name:"pack"},context);
expect(mockRecordSpan).toHaveBeenCalledTimes(3);
expect(mockRecordSpan.mock.calls[1][0]).toMatchObject({name:"sandbox.daytona.pack",startTimeMs:now-7199990});
});
it("links bounded earlier remote lifecycles to their host-owned observer",()=>{
mockRecordSpan.mockReset();mockRecordSpan.mockReturnValue({traceId:"0af7651916cd43dd8448eb211c80319c",spanId:"1111111111111111",traceFlags:1});
const now=Date.now();
recordWorkerProviderSpan({name:"plugin.worker",startTimeMs:now-10,endTimeMs:now,children:[
{name:"plugin.remote.lifecycle",relationship:"linked",startTimeMs:now-1000,endTimeMs:now-100,children:[
{name:"plugin.remote.operation",startTimeMs:now-900,endTimeMs:now-200}
]},
{name:"plugin.remote.operation",relationship:"linked",startTimeMs:now-1000,endTimeMs:now-100},
{name:"plugin.remote.lifecycle",relationship:"linked",startTimeMs:now-700000,endTimeMs:now-100},
]},{traceparent:VALID_TRACEPARENT});
expect(mockRecordSpan).toHaveBeenCalledTimes(3);
expect(mockRecordSpan.mock.calls[1][0]).toMatchObject({name:"plugin.remote.lifecycle",linked:true,startTimeMs:now-1000});
expect(mockRecordSpan.mock.calls[2][0].linked).toBeUndefined();
});