mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-03 01:27:09 +01:00
## 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>
52 lines
3.7 KiB
TypeScript
52 lines
3.7 KiB
TypeScript
import { trace, SpanStatusCode, type Context, type Span } from "@opentelemetry/api";
|
|
import { getActiveStepContext, runWithRuntimeParent } from "@paperclipai/adapter-utils/acpx-engine/startup-timing";
|
|
|
|
const phases = new Set(["runner.transport.cold_start", "runner.transport.resume", "runner.transport.attach", "runner.transport.prepare",
|
|
"runner.transport.turn_start", "runner.transport.started_event", "runner.transport.command_ack", "runner.transport.registration", "runner.transport.provider_identity"]);
|
|
const keys = new Set(["inputBytes", "toolSchemaBytes", "toolCount", "contextReused", "tokenDataAvailable"]);
|
|
|
|
// Resolve the parent on every call: a retained transport belongs to several successive runs.
|
|
export function measureRunnerOperation<T>(phase: string, work: () => Promise<T>, attributes?: Record<string, number | boolean>): Promise<T> {
|
|
const parent = getActiveStepContext()?.parentContext;
|
|
if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() || !parent || !phases.has(phase)) return work();
|
|
let operation: Promise<T> | undefined;
|
|
const once = () => operation ??= Promise.resolve().then(work);
|
|
let span: Span | undefined;
|
|
try {
|
|
const bounded = Object.fromEntries(Object.entries(attributes ?? {}).filter(([key,value])=>keys.has(key) &&
|
|
(typeof value === "boolean" || Number.isSafeInteger(value) && value >= 0 && value <= 1e12)));
|
|
span = trace.getTracer("paperclip.native-runner").startSpan(phase,{attributes:bounded},parent as Context);
|
|
const currentSpan = span;
|
|
const child = trace.setSpan(parent as Context,currentSpan);
|
|
return runWithRuntimeParent(child,once).then(value=>{try {currentSpan.end();}catch{} return value;},error=>{
|
|
try{currentSpan.setStatus({code:SpanStatusCode.ERROR});currentSpan.end();}catch{} throw error;
|
|
});
|
|
} catch { try { span?.end(); } catch {} return once(); }
|
|
}
|
|
|
|
/** Numeric same-process durations, causally anchored at receipt. Remainders are unattributed. */
|
|
export function recordRunnerTimingReceipt(raw: unknown): void {
|
|
const parent = getActiveStepContext()?.parentContext;
|
|
if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() || !parent || !raw || typeof raw !== "object") return;
|
|
const row = raw as Record<string, unknown>;
|
|
const values = ["runnerMs", "sidecarMs", "statusMs", "promptMs", "statusOffsetMs", "promptOffsetMs", "roundTripMs"].map(key=>row[key]);
|
|
if (!values.every(value=>typeof value === "number" && Number.isFinite(value) && value >= 0 && value <= 300000)) return;
|
|
const [runner,sidecar,status,prompt,statusOffset,promptOffset,roundTrip] = values as number[];
|
|
if (runner > roundTrip || sidecar > runner || statusOffset + status > promptOffset || promptOffset + prompt > sidecar) return;
|
|
const opened: Array<{span:Span; end:number}> = [];
|
|
const end = Date.now(), start=end-runner, sidecarStart=end-sidecar;
|
|
try {
|
|
const tracer = trace.getTracer("paperclip.native-runner");
|
|
const root = tracer.startSpan("runner.remote.turn_start",{startTime:start},parent as Context);
|
|
opened.push({span:root,end});
|
|
const rootContext=trace.setSpan(parent as Context,root);
|
|
const child=tracer.startSpan("runner.sidecar.turn_start",{startTime:sidecarStart},rootContext);
|
|
opened.push({span:child,end});
|
|
const childContext=trace.setSpan(rootContext,child);
|
|
const settings=tracer.startSpan("runner.sidecar.status_read",{startTime:sidecarStart+statusOffset},childContext);opened.push({span:settings,end:sidecarStart+statusOffset+status});
|
|
const acknowledgement=tracer.startSpan("runner.sidecar.prompt_started",{startTime:sidecarStart+promptOffset},childContext);opened.push({span:acknowledgement,end:sidecarStart+promptOffset+prompt});
|
|
} catch {} finally {
|
|
for (const item of opened.reverse()) { try { item.span.end(item.end); } catch {} }
|
|
}
|
|
}
|