From 1d571de5f9f886d66e520800baec8fc2f67d0948 Mon Sep 17 00:00:00 2001 From: Nicky Leach Date: Thu, 29 Oct 2026 17:45:56 -0700 Subject: [PATCH] Add shared native turn attribution boundaries (#18213) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## 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 --- doc/observability.md | 49 +++++++++- packages/paperclip-runner/acpx-profiles.json | 8 +- .../runner-core/src/acpx_provider_backend.rs | 60 +++++++++++- .../runner-core/src/acpx_provider_session.rs | 12 ++- .../src/generated_acpx_profiles.rs | 4 +- .../scripts/copilot-profile-identity.mjs | 4 +- .../scripts/grok-profile-identity.mjs | 4 +- .../src/cli/acpx-runtime-sidecar.ts | 11 ++- .../drivers/acpx/copilot-installation.test.ts | 4 +- .../src/drivers/acpx/generated-profiles.ts | 8 +- .../src/drivers/acpx/profile-compatibility.ts | 4 +- .../src/live/runnerd-codex-transport.ts | 91 +++++++++++++++++-- .../src/providers/grok/launcher.cjs | 2 +- .../copilot-profile-v85-identity.json | 88 ++++++++++++++++++ .../fixtures/grok-profile-v14-identity.json | 35 +++++++ .../plugins/sdk/src/host-client-factory.ts | 5 +- packages/plugins/sdk/src/invocation-tracer.ts | 51 +++++++++++ packages/plugins/sdk/src/protocol.ts | 34 +++---- packages/plugins/sdk/src/types.ts | 7 ++ packages/plugins/sdk/src/worker-rpc-host.ts | 46 +++++++--- .../sdk/tests/invocation-tracer.test.ts | 68 ++++++++++++++ .../plugins/sdk/tests/worker-rpc-host.test.ts | 28 +++++- server/src/__tests__/instrumentation.test.ts | 35 +++++++ .../plugin-host-services-span.test.ts | 50 ++++++++++ .../__tests__/plugin-worker-manager.test.ts | 47 ++++++---- server/src/instrumentation.ts | 18 ++-- .../execution-preparation-timing.test.ts | 21 +++++ .../services/execution-preparation-timing.ts | 12 ++- .../native-runtime/native-run-trace.test.ts | 4 +- .../native-runtime/native-run-trace.ts | 1 + .../native-runtime/native-session-executor.ts | 23 ++++- .../native-runtime/native-tool-trace.test.ts | 8 ++ .../native-runtime/native-tool-trace.ts | 6 ++ .../paperclip-control-plane-port.test.ts | 12 ++- .../paperclip-control-plane-port.ts | 14 ++- .../paperclip-control-plane-timing.test.ts | 14 +++ .../runner-operation-timing.test.ts | 39 ++++++++ .../native-runtime/runner-operation-timing.ts | 51 +++++++++++ server/src/services/plugin-host-services.ts | 59 +++++++++--- server/src/services/plugin-worker-manager.ts | 29 ++++-- 40 files changed, 939 insertions(+), 127 deletions(-) create mode 100644 packages/paperclip-runner/test/fixtures/copilot-profile-v85-identity.json create mode 100644 packages/paperclip-runner/test/fixtures/grok-profile-v14-identity.json create mode 100644 packages/plugins/sdk/src/invocation-tracer.ts create mode 100644 packages/plugins/sdk/tests/invocation-tracer.test.ts create mode 100644 server/src/services/native-runtime/paperclip-control-plane-timing.test.ts create mode 100644 server/src/services/native-runtime/runner-operation-timing.test.ts create mode 100644 server/src/services/native-runtime/runner-operation-timing.ts diff --git a/doc/observability.md b/doc/observability.md index ae89537d6a6..8da760ebf8d 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -655,7 +655,7 @@ task.provider_session │ │ ├── runner.session.bootstrap | runner.session.resume │ │ └── runner.turn.submit │ └── agent.turn -│ ├── provider.turn.queue +│ ├── runner.turn.submitted_to_started │ ├── provider.time_to_first_agent_event │ ├── tool.request.input_stream │ └── tool.execute @@ -2053,3 +2053,50 @@ PostgreSQL benchmark with 114 mixed skills and at least 400 remote files. It reports one cold sample and ten warm samples (one in a new process), refresh and fetch counts, rebuilds, missing entries, and content checks. Upstream responses are deterministic fixtures; use real deployed run spans for user-facing latency. + +## Invocation and native turn attribution (v1) + +The existing opt-in OTLP endpoint gate also controls invocation timing. No new +exporter is installed. Generic plugin timing uses `span.record`, still gated by +`environment.drivers.register` or `workspaces.manage`, and the host-owned invocation ID. The host clamps +names, attributes, status and timestamps again. A worker cannot choose a trace +parent. Existing provider `startSpan` calls are retained as children of the +worker receipt. `ctx.tracer.withSpan` supplies async-local nesting; it is optional +for compatibility with older SDK fixtures. The host generates each child span's +identity. Receipts share one invocation-wide budget of 256 nodes and 12 levels. The worker root supports up to 24 hours; short children keep their widths on long execute calls. Nested timestamps share one monotonic origin. Missing, invalid, +expired and cross-invocation context cannot select another call's parent. + +| Boundary | Coverage | Owner and clock | Meaning / limit | +| --- | --- | --- | --- | +| Dispatch / receipt / return | `execution.plugin_dispatch` → `plugin.worker` | Host invocation; worker monotonic durations anchored to its epoch start | Outer minus worker time is an unattributed dispatch/scheduling remainder. It is not network latency. | +| Repeated host reads | `plugin.host.identity.read`, `config.read`, `progress.read`, `progress.write` | Worker invocation, one span per awaited call, bounded by receipt budget | Round trip and host service together. Span count is call count; overlapping reads are not additive. | +| Plugin coordination | `plugin.storage.queue`, `storage.execute`, `runtime.queue`, `runtime.prepare`, `runtime.reconcile`, `runtime.verify`, `workspace.prepare` | Invoking plugin, monotonic durations | The plugin keeps its locking and authorization owners. `plugin.reused` is boolean. | +| Completed remote lifecycle | `plugin.remote.lifecycle`, linked to the host-owned observer | Bounded prior monotonic durations, up to ten minutes old | Independent lifecycle trace; never a child of a later polling request. The worker cannot supply link IDs. | +| Remote operation receipt | `plugin.remote.request` → `plugin.remote.operation` | Remote monotonic offsets, checked against local round trip and parent bounds | Closed operation classes cover mount refresh, guest setup, process execution, scripts and cleanup. No remote wall-clock subtraction. | +| Retained/cold transport | `runner.transport.attach`, `resume`, `cold_start`, `prepare`, `registration`, `provider_identity` | Controller process, current active context on every operation | A retained transport must not capture the preceding run's trace. These parents overlap their children. | +| Command and provider admission | `runner.transport.turn_start`, `command_ack`, `started_event`; optional ACPX `runner.remote.turn_start` → `runner.sidecar.turn_start` → `status_read`, `prompt_started` | Local monotonic spans; remote numeric durations anchored at receipt | Command ACK proves durable command completion. ACPX `promptStarted` proves the runtime prompt-start barrier, not a model token or provider queue exit. SDK-internal work stays opaque. | +| Durable events | `runner.event.persist` with bounded event kind | Host-local monotonic interval | Receipt through event transaction commit, before live publication. Duplicate receipts are not new provider starts. | +| First event / first text | Existing `provider.time_to_first_agent_event`, `task.time_to_first_token`; `response.first_nonempty_text` | Durable event observations | First event can be a tool; text must be nonempty and pass the existing deliverable-text observer. | +| Completion | `completion.request.first`, existing `tool.request.input_stream`, `completion.tool_accepted`, `completion.result_committed` | Same turn; provider tool identity retained only in memory | Input-stream end is the last observed argument update. `run.result.proposed` is the validated tool receipt; `completion.result_committed` follows the successful result transaction; the earlier `run.result.accepted` event alone does not prove persistence. Neither certifies response publication. | +| Reply commit / publication | Existing response transaction/write/publish phases | Response owner, transaction and local publication | Keep separate from tool acceptance and first text. | +| Input/context | `inputBytes`, `toolSchemaBytes`, `toolCount`, `contextReused`, `tokenDataAvailable` | Controller numeric/boolean metadata | Counts only. No prompts, instructions, tool arguments or credentials. Token/cache counters remain unavailable unless supplied by a provider with known semantics. Model/effort stay in existing effective run settings. | + +Remote receipt spans use their measured duration and causal bounds. Their absolute +placement inside a round trip remains uncertain by transport/scheduling time. +Never add parent and child widths, sum concurrent host reads, or label this +remainder inference or network delay. Failure receipts carry status codes without +exception text. Incomplete or malformed receipts are discarded without affecting +execution. A receipt cap can omit further detail; it does not truncate work. + +The linked private implementation owns its remote stage names and protocol. +Core contains generic operation semantics only. Before using this coverage to +rank optimizations, deploy a compatible source set and inspect actual collector +exports for parentage, concurrent ownership, widths and closed failure spans. +Unit tests do not establish ingestion or a latency improvement. + +The shared ACPX instrumentation advances Grok source profile 13 to 14 and +Copilot 84 to 85. Historical identities remain unchanged and decodable. Provider +packages, models and permission defaults are unchanged; Pi's bound declaration +is unchanged. These are source attestations, not evidence of fresh live provider +qualification. Re-run compatibility qualification for the new identities before +rollout. diff --git a/packages/paperclip-runner/acpx-profiles.json b/packages/paperclip-runner/acpx-profiles.json index 7444d913f41..462243d04fe 100644 --- a/packages/paperclip-runner/acpx-profiles.json +++ b/packages/paperclip-runner/acpx-profiles.json @@ -15,12 +15,12 @@ "qualificationStatus": "pending" }, "grok": { - "agentProfileVersion": 13, + "agentProfileVersion": 14, "agentServerPackage": "builtin:grok-acp", "agentServerVersion": "1", "agentRuntimePackage": "native:grok", "agentRuntimeVersion": "1.0.13", - "commandDigest": "sha256:e311f8111dd12f0c49bf12a80345cfe5f31a1222e0189209adeabf2f9bd0e1b0", + "commandDigest": "sha256:ca59edc7f416cc1e86ac7d7d1e288d3d91065b7ab59e79bcb62bae5f0cc5cf49", "requiresProviderPolicy": false }, "pi": { @@ -42,12 +42,12 @@ "requiresProviderPolicy": true }, "copilot": { - "agentProfileVersion": 84, + "agentProfileVersion": 85, "agentServerPackage": "@github/copilot", "agentServerVersion": "1.0.88", "agentRuntimePackage": null, "agentRuntimeVersion": null, - "commandDigest": "sha256:a95f1d8e4d0a18d0c2cbc3bffdf998a2c5b8a582bdf51a72085b01d948d0a04e", + "commandDigest": "sha256:267e04ce9335f7641f665d9b952bc4637056ee1cfeac23715b7aefbc3a8df3c9", "requiresProviderPolicy": true }, "claude": { diff --git a/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_backend.rs b/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_backend.rs index 912e9e26531..7f3a2c4897a 100644 --- a/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_backend.rs +++ b/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_backend.rs @@ -38,6 +38,28 @@ use crate::provider_events::{ }; use crate::qualified_launch::{verify_executable_launch_artifact, verify_launch_artifact}; +fn bounded_turn_timing(response: &Value, elapsed: Duration) -> Value { + let mut receipt = serde_json::Map::new(); + for key in [ + "statusMs", + "statusOffsetMs", + "promptMs", + "promptOffsetMs", + "sidecarMs", + ] { + if let Some(value) = response + .get("timing") + .and_then(|v| v.get(key)) + .and_then(Value::as_f64) + .filter(|v| v.is_finite() && *v >= 0.0 && *v <= 300_000.0) + { + receipt.insert(key.to_owned(), json!(value)); + } + } + receipt.insert("runnerMs".to_owned(), json!(elapsed.as_secs_f64() * 1000.0)); + Value::Object(receipt) +} + fn is_reserved_terminal_operation_id(operation_id: &str) -> bool { matches!(operation_id, "paperclip_finish" | "paperclip_block") } @@ -1536,12 +1558,14 @@ impl AcpxCommandExecutor { .as_ref() .map(|state| PathBuf::from(&state.descriptor.cwd)) .expect("ACPX state exists before turn start"); - if let Err(error) = self + let measure = payload.get("performance").and_then(Value::as_bool) == Some(true); + let timing_started = std::time::Instant::now(); + let start_result = self .session .as_mut() .expect("ACPX session exists before turn start") - .start_turn(&provider_turn_id, text, &working_directory) - { + .start_turn_timed(&provider_turn_id, text, &working_directory, measure); + if let Err(error) = &start_result { let state = self .state .as_mut() @@ -1555,6 +1579,15 @@ impl AcpxCommandExecutor { "ACPX turn start failed closed: {error}" ))); } + // Copy numeric timing fields only. Sidecar contents never enter the receipt. + let timing = if measure { + bounded_turn_timing( + &start_result.ok().unwrap_or(Value::Null), + timing_started.elapsed(), + ) + } else { + Value::Null + }; let state = self .state .as_mut() @@ -1612,7 +1645,11 @@ impl AcpxCommandExecutor { }), )); Ok(CommandExecution { - result: json!({"status": "accepted", "providerTurnId": provider_turn_id}), + result: if measure { + json!({"status":"accepted", "providerTurnId":provider_turn_id, "timing":timing}) + } else { + json!({"status": "accepted", "providerTurnId": provider_turn_id}) + }, events, }) } @@ -2622,6 +2659,21 @@ mod tests { "origin":{"adapter":"acpx-runtime-sidecar","provider":"cursor","method":"cursor/ask_question"}}) } + #[test] + fn timing_receipt_drops_sidecar_contents_and_invalid_numeric_fields() { + let receipt = bounded_turn_timing( + &json!({"timing":{ + "statusMs":10, "statusOffsetMs":0, "promptMs":-1, + "promptOffsetMs":"private", "sidecarMs":300001, "prompt":"secret" + }}), + Duration::from_millis(20), + ); + assert_eq!( + receipt, + json!({"statusMs":10.0,"statusOffsetMs":0.0,"runnerMs":20.0}) + ); + } + #[test] fn live_request_snapshot_preserves_durable_turn_and_provider_callback_bindings() { use crate::acpx_provider_state::AcpxProviderState; diff --git a/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_session.rs b/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_session.rs index 270036a3514..943f3b78aa8 100644 --- a/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_session.rs +++ b/packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_session.rs @@ -464,6 +464,16 @@ impl AcpxProviderSession { turn_id: &str, message: &str, working_directory: &Path, + ) -> Result { + self.start_turn_timed(turn_id, message, working_directory, false) + } + + pub fn start_turn_timed( + &mut self, + turn_id: &str, + message: &str, + working_directory: &Path, + performance: bool, ) -> Result { self.ensure_open()?; if self.runtime_retired { @@ -555,7 +565,7 @@ impl AcpxProviderSession { } let response = match self.transport.request( GeneratedAcpxSidecarCommand::TurnStart, - json!({"turnId":turn_id,"message":message}), + json!({"turnId":turn_id,"message":message,"performance":performance}), ) { Ok(response) => response, Err(error) => return Err(self.fail_closed(error)), diff --git a/packages/paperclip-runner/runner/crates/runner-core/src/generated_acpx_profiles.rs b/packages/paperclip-runner/runner/crates/runner-core/src/generated_acpx_profiles.rs index 9e76995b3e3..881671f1c04 100644 --- a/packages/paperclip-runner/runner/crates/runner-core/src/generated_acpx_profiles.rs +++ b/packages/paperclip-runner/runner/crates/runner-core/src/generated_acpx_profiles.rs @@ -31,7 +31,7 @@ pub(crate) fn acpx_release_profile(agent: &str) -> Option { agent_runtime_package: Some("native:grok"), agent_runtime_version: Some("1.0.13"), command_digest: - "sha256:e311f8111dd12f0c49bf12a80345cfe5f31a1222e0189209adeabf2f9bd0e1b0", + "sha256:ca59edc7f416cc1e86ac7d7d1e288d3d91065b7ab59e79bcb62bae5f0cc5cf49", requires_provider_policy: false, qualification_pending: false, }, @@ -61,7 +61,7 @@ pub(crate) fn acpx_release_profile(agent: &str) -> Option { agent_runtime_package: None, agent_runtime_version: None, command_digest: - "sha256:a95f1d8e4d0a18d0c2cbc3bffdf998a2c5b8a582bdf51a72085b01d948d0a04e", + "sha256:267e04ce9335f7641f665d9b952bc4637056ee1cfeac23715b7aefbc3a8df3c9", requires_provider_policy: true, qualification_pending: false, }, diff --git a/packages/paperclip-runner/scripts/copilot-profile-identity.mjs b/packages/paperclip-runner/scripts/copilot-profile-identity.mjs index 4a80c6fbd76..15777f782cb 100644 --- a/packages/paperclip-runner/scripts/copilot-profile-identity.mjs +++ b/packages/paperclip-runner/scripts/copilot-profile-identity.mjs @@ -7,9 +7,9 @@ import { fileURLToPath } from "node:url"; import { resolve, dirname } from "node:path"; const root = resolve(dirname(fileURLToPath(import.meta.url)), ".."); -const fixture = resolve(root, "test/fixtures/copilot-profile-v84-identity.json"); +const fixture = resolve(root, "test/fixtures/copilot-profile-v85-identity.json"); const historical = JSON.parse(readFileSync(resolve(root, "test/fixtures/copilot-profile-v12-identity.json"), "utf8")); -const declaration = { ...historical.declaration, agentProfileVersion: 84 }; +const declaration = { ...historical.declaration, agentProfileVersion: 85 }; delete declaration.permissionIdentitySourceSha256; const sources = { displayEventSourceSha256: "src/drivers/acpx/copilot-events.ts", diff --git a/packages/paperclip-runner/scripts/grok-profile-identity.mjs b/packages/paperclip-runner/scripts/grok-profile-identity.mjs index bf43ad20a48..de52546004b 100644 --- a/packages/paperclip-runner/scripts/grok-profile-identity.mjs +++ b/packages/paperclip-runner/scripts/grok-profile-identity.mjs @@ -7,9 +7,9 @@ import { fileURLToPath } from "node:url"; const packageRoot = resolve(dirname(fileURLToPath(import.meta.url)), ".."); const repositoryRoot = resolve(packageRoot, "../.."); -// Versions 1–12 remain decodable historical identities. Versioned fixtures are +// Versions 1–13 remain decodable historical identities. Versioned fixtures are // immutable; advance this version before changing a versioned declaration. -export const GROK_PROFILE_VERSION = 13; +export const GROK_PROFILE_VERSION = 14; // Contract surfaces: ACPX wire patch; sidecar parsing and error translation; // native effort/search/credential admission; host/sandbox/tool-bridge execution; // launcher integrity and platform pins; Rust descriptor writes, session state, diff --git a/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts b/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts index 56933071772..bbab91adaa7 100644 --- a/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts +++ b/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts @@ -232,7 +232,7 @@ async function receiveLine(line: string): Promise { request.command, ); if (blocked) throw blocked; - response(request.id, true, await dispatch(request)); + response(request.id, true, await dispatch(request, request.params.performance === true ? performance.now() : 0)); } catch (error) { const normalized = error instanceof Error ? error : new Error(String(error)); @@ -255,6 +255,7 @@ async function receiveLine(line: string): Promise { async function dispatch( request: AcpxSidecarRequest, + receivedAt = 0, ): Promise> { if (request.command === "initialize") { if (initializedModel) @@ -419,8 +420,13 @@ async function dispatch( }); activeCopilotEvidence = toolEvidence && "captureSemanticReceipt" in toolEvidence ? toolEvidence as CopilotToolEvidence : undefined; let usageBefore: unknown; + const timed = request.params.performance === true; + const timingStart = receivedAt; + let statusMs = 0; + const statusStart = timed ? performance.now() : 0; try { usageBefore = await readSidecarHostStatusWithin(activeHost); + if (timed) statusMs = performance.now() - statusStart; runtimeTurn = activeHost.startTurn({ requestId: `${runId}:${currentTurnId}`, text: boundedText(request.params.message, "message", 1024 * 1024), @@ -438,8 +444,9 @@ async function dispatch( void pumpTurn(currentTurnId, runtimeTurn, activeHost, usageBefore, extensions.drain, activity, toolEvidence); // Warm sessions may defer initialize until their first prompt. Publish only // the capabilities of that live initialized connection, never old disk state. + const promptStart = timed ? performance.now() : 0; await runtimeTurn.promptStarted; - return { turnId: currentTurnId, turnControls: activeHost.steeringCapability() ?? { steering: false, queuedFollowUp: false } }; + return { ...(timed ? {timing:{statusMs, statusOffsetMs:statusStart-timingStart, promptMs:performance.now()-promptStart, promptOffsetMs:promptStart-timingStart, sidecarMs:performance.now()-timingStart}} : {}), turnId: currentTurnId, turnControls: activeHost.steeringCapability() ?? { steering: false, queuedFollowUp: false } }; } if (request.command === "turn.steer") { const control = parseAcpxTurnControl(request.params); diff --git a/packages/paperclip-runner/src/drivers/acpx/copilot-installation.test.ts b/packages/paperclip-runner/src/drivers/acpx/copilot-installation.test.ts index 707120eb163..049fd34ff22 100644 --- a/packages/paperclip-runner/src/drivers/acpx/copilot-installation.test.ts +++ b/packages/paperclip-runner/src/drivers/acpx/copilot-installation.test.ts @@ -87,9 +87,9 @@ vi.mock("./installation-integrity.js", () => ({ verifyNativeAcpxInstallation: vi describe("Copilot build-owned installation", () => { it("admits the current profile with environment launch preparation", () => { - expect(QUALIFIED_ACPX_PROFILES.copilot.agentProfileVersion).toBe(84); + expect(QUALIFIED_ACPX_PROFILES.copilot.agentProfileVersion).toBe(85); expect(QUALIFIED_ACPX_PROFILES.copilot.qualificationStatus).toBeUndefined(); - expect(QUALIFIED_ACPX_PROFILES.copilot.commandDigest).toBe("sha256:a95f1d8e4d0a18d0c2cbc3bffdf998a2c5b8a582bdf51a72085b01d948d0a04e"); + expect(QUALIFIED_ACPX_PROFILES.copilot.commandDigest).toBe("sha256:267e04ce9335f7641f665d9b952bc4637056ee1cfeac23715b7aefbc3a8df3c9"); }); it("preserves published v65 while binding retained-maintenance waits in v66", async () => { diff --git a/packages/paperclip-runner/src/drivers/acpx/generated-profiles.ts b/packages/paperclip-runner/src/drivers/acpx/generated-profiles.ts index 0ffc9fbcc25..01ac0e5227f 100644 --- a/packages/paperclip-runner/src/drivers/acpx/generated-profiles.ts +++ b/packages/paperclip-runner/src/drivers/acpx/generated-profiles.ts @@ -23,12 +23,12 @@ export const QUALIFIED_ACPX_PROFILE_DATA = { "protocolVersion": 1, "acpxVersion": "0.13.1", "agent": "grok", - "agentProfileVersion": 13, + "agentProfileVersion": 14, "agentServerPackage": "builtin:grok-acp", "agentServerVersion": "1", "agentRuntimePackage": "native:grok", "agentRuntimeVersion": "1.0.13", - "commandDigest": "sha256:e311f8111dd12f0c49bf12a80345cfe5f31a1222e0189209adeabf2f9bd0e1b0", + "commandDigest": "sha256:ca59edc7f416cc1e86ac7d7d1e288d3d91065b7ab59e79bcb62bae5f0cc5cf49", "permissionPolicy": "interactive" }, "pi": { @@ -62,12 +62,12 @@ export const QUALIFIED_ACPX_PROFILE_DATA = { "protocolVersion": 1, "acpxVersion": "0.13.1", "agent": "copilot", - "agentProfileVersion": 84, + "agentProfileVersion": 85, "agentServerPackage": "@github/copilot", "agentServerVersion": "1.0.88", "agentRuntimePackage": null, "agentRuntimeVersion": null, - "commandDigest": "sha256:a95f1d8e4d0a18d0c2cbc3bffdf998a2c5b8a582bdf51a72085b01d948d0a04e", + "commandDigest": "sha256:267e04ce9335f7641f665d9b952bc4637056ee1cfeac23715b7aefbc3a8df3c9", "permissionPolicy": "interactive" }, "claude": { diff --git a/packages/paperclip-runner/src/drivers/acpx/profile-compatibility.ts b/packages/paperclip-runner/src/drivers/acpx/profile-compatibility.ts index 41707246f27..dc7de909eee 100644 --- a/packages/paperclip-runner/src/drivers/acpx/profile-compatibility.ts +++ b/packages/paperclip-runner/src/drivers/acpx/profile-compatibility.ts @@ -2,13 +2,13 @@ import { QUALIFIED_ACPX_PROFILE_DATA } from "./generated-profiles.js"; /** Decodable historical profile revisions, not permission to launch them. * Exact current profile/package/digest admission is checked separately. */ -type HistoricalAcpxProfileVersion = 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9 | 10 | 11 | 12 | 13 | 14 | 15 | 16 | 17 | 18 | 19 | 20 | 21 | 22 | 23 | 24 | 25 | 26 | 27 | 28 | 29 | 30 | 31 | 32 | 33 | 34 | 35 | 36 | 37 | 38 | 39 | 40 | 41 | 42 | 43 | 44 | 45 | 46 | 47 | 48 | 49 | 50 | 51 | 52 | 53 | 54 | 55 | 56 | 57 | 58 | 59 | 60 | 61 | 62 | 63 | 64 | 65 | 66 | 67 | 68 | 69 | 70 | 71 | 72 | 73 | 74 | 75 | 76 | 77 | 78 | 79 | 80 | 81 | 82 | 83; +type HistoricalAcpxProfileVersion = 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9 | 10 | 11 | 12 | 13 | 14 | 15 | 16 | 17 | 18 | 19 | 20 | 21 | 22 | 23 | 24 | 25 | 26 | 27 | 28 | 29 | 30 | 31 | 32 | 33 | 34 | 35 | 36 | 37 | 38 | 39 | 40 | 41 | 42 | 43 | 44 | 45 | 46 | 47 | 48 | 49 | 50 | 51 | 52 | 53 | 54 | 55 | 56 | 57 | 58 | 59 | 60 | 61 | 62 | 63 | 64 | 65 | 66 | 67 | 68 | 69 | 70 | 71 | 72 | 73 | 74 | 75 | 76 | 77 | 78 | 79 | 80 | 81 | 82 | 83 | 84; type CurrentAcpxProfileVersion = typeof QUALIFIED_ACPX_PROFILE_DATA[keyof typeof QUALIFIED_ACPX_PROFILE_DATA]["agentProfileVersion"]; export type AcpxProfileVersion = HistoricalAcpxProfileVersion | CurrentAcpxProfileVersion; const historicalVersions: Readonly> = { pi: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34], claude: [1, 2, 3, 4, 5], codex: [1, 2, 3, 4, 5], - grok: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12], copilot: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83], + grok: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13], copilot: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84], cursor: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15], }; diff --git a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts index 07ac0d5696f..5ba7f88d37f 100644 --- a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts +++ b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts @@ -1319,6 +1319,9 @@ export interface CapabilityRunnerdCodexTransportOptions extends RunnerExecutionD closeGraceMs?: number; /** Bounded provider turn-admission wait; defaults to 30 seconds. */ turnStartTimeoutMs?: number; + /** Controller-owned opt-in operation timing. No exporter lives in Runner. */ + measureOperation?(phase: string, work: () => Promise, attributes?: Record): Promise; + recordTimingReceipt?(receipt: unknown): void; onDiagnostic?: (message: string) => void; onEvidence?: (evidence: Readonly) => void; /** Persist process ownership immediately after spawn, before waiting for @@ -4183,6 +4186,18 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { turnId: string; itemId: string; currentRunGrant?: NativeRunRuntimeGrant; + }): Promise { + const previous = record(this.#runAttachTemplate?.provider).runtimeContext; + const current = input.currentRunGrant?.runtimeContext; + return this.options.measureOperation ? this.options.measureOperation("runner.transport.attach", () => this.#attachRunWork(input), + previous === undefined ? undefined : {contextReused:current === undefined || commandDigest(current) === commandDigest(previous)}) : this.#attachRunWork(input); + } + + async #attachRunWork(input: { + runId: string; + turnId: string; + itemId: string; + currentRunGrant?: NativeRunRuntimeGrant; }): Promise { if (this.#pendingWarmRecoveryCompletion !== null) { throw new Error("native_runner_warm_transition_completion_pending"); @@ -4325,7 +4340,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { } throw failure; } - } + + } async resolveRuntimeRequest(input: { requestId: string; @@ -4975,6 +4991,13 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #prepareLaunch( params: Record, identity: DurableRecoveryIdentity, dynamicTools: Record[], + ) { + return this.options.measureOperation ? this.options.measureOperation("runner.transport.prepare", () => this.#prepareLaunchWork(params, identity, dynamicTools), {toolCount:dynamicTools.length, toolSchemaBytes:Buffer.byteLength(JSON.stringify(dynamicTools))}) : this.#prepareLaunchWork(params, identity, dynamicTools); + } + + async #prepareLaunchWork( + params: Record, identity: DurableRecoveryIdentity, + dynamicTools: Record[], ) { if (this.options.acpxCandidateAdmission) { const candidate = this.options.acpxCandidateAdmission; @@ -5169,10 +5192,17 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { this.options.environment, ), }; - } + + } async #start( params: Record, + ): Promise> { + return this.options.measureOperation ? this.options.measureOperation("runner.transport.cold_start", () => this.#startWork(params)) : this.#startWork(params); + } + + async #startWork( + params: Record, ): Promise> { if (this.#core !== null) throw new Error("PRP provider thread is already started"); @@ -5304,7 +5334,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { this.#startupComplete = true; this.#diagnostic("runnerd authenticated to the durable PRP control plane"); return this.#openedThreadResponse(params); - } + + } #openedThreadResponse(params: Record): Record { const provider = this.options.provider ?? "codex"; @@ -5344,6 +5375,10 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { } async #resume(): Promise { + return this.options.measureOperation ? this.options.measureOperation("runner.transport.resume", () => this.#resumeWork()) : this.#resumeWork(); + } + + async #resumeWork(): Promise { if (this.options.acpxCandidateAdmission) throw new Error("ACPX candidate durable runner recovery is not admitted"); const desiredIdentity = this.options.prpIdentity; if (desiredIdentity === undefined) { @@ -6123,7 +6158,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { : "runnerd restored its durable PRP session and provider thread", ); this.#recoverPendingSemanticInputsWhenReady(); - } + + } async #recoverSemanticToolInput(call: Parameters>[0]) { if (call.operationId === "paperclip_finish" || call.operationId === "paperclip_block") { @@ -6238,6 +6274,12 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #startTurn( params: Record, + ): Promise> { + return this.options.measureOperation ? this.options.measureOperation("runner.transport.turn_start", () => this.#startTurnWork(params), {inputBytes:Buffer.byteLength(JSON.stringify(params)), tokenDataAvailable:false}) : this.#startTurnWork(params); + } + + async #startTurnWork( + params: Record, ): Promise> { const turnStartTimeoutMs = this.options.turnStartTimeoutMs ?? 30_000; if (!Number.isSafeInteger(turnStartTimeoutMs) || turnStartTimeoutMs <= 0) { @@ -6286,10 +6328,12 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { // it as its provider request identity, so a same-run recovery turn cannot // alias an already-settled request from the retained provider session. // Codex and OpenCode continue to return their provider-assigned identity. + const commandStarted = this.options.recordTimingReceipt ? performance.now() : 0; const startResult = await this.#commandResult( "turn.start", { text: message, + ...(this.options.recordTimingReceipt ? {performance:true} : {}), ...((this.options.provider ?? "codex") === "codex" && params.effort !== undefined ? { effort: params.effort } : {}), ...(reasoningMode === undefined ? {} : { reasoningMode }), ...(skills.length ? { skills } : {}), @@ -6297,6 +6341,7 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { }, commandDeadline, ); + try { this.options.recordTimingReceipt?.({...record(startResult.timing), roundTripMs:performance.now()-commandStarted}); } catch {} const expectedProviderTurnId = typeof startResult.providerTurnId === "string" && startResult.providerTurnId.length > 0 @@ -6340,6 +6385,7 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { expectedProviderTurnId, boundTurnId: this.#turnId, }); + const waitForStarted = async () => { while (!providerTurnStarted() && Date.now() < deadline) { this.#throwIfFailed(); this.#pumpEvents(); @@ -6350,6 +6396,9 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { } if (!providerTurnStarted()) throw new Error("runnerd did not report the provider turn identity"); + }; + if (this.options.measureOperation) await this.options.measureOperation("runner.transport.started_event", waitForStarted); + else await waitForStarted(); responseReady = true; return { turn: { id: this.#turnId, status: "inProgress" } }; } finally { @@ -6376,7 +6425,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { release.unref(); } } - } + + } async #command( type: string, @@ -6484,6 +6534,13 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #waitForProviderIdentity( expectedEventType?: "harness.ready" | "session.started" | "session.resumed", deadline = Date.now() + 30_000, + ): Promise { + return this.options.measureOperation ? this.options.measureOperation("runner.transport.provider_identity", () => this.#waitForProviderIdentityWork(expectedEventType, deadline)) : this.#waitForProviderIdentityWork(expectedEventType, deadline); + } + + async #waitForProviderIdentityWork( + expectedEventType?: "harness.ready" | "session.started" | "session.resumed", + deadline = Date.now() + 30_000, ): Promise { while (Date.now() < deadline) { this.#throwIfFailed(); @@ -6503,13 +6560,23 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { await new Promise((resolveWait) => setTimeout(resolveWait, 10)); } throw new Error("runnerd did not report its provider identity"); - } + + } async #waitCommand( type: string, commandId?: string, deadline = Date.now() + 30_000, abortOnClose = false, + ): Promise { + return this.options.measureOperation ? this.options.measureOperation("runner.transport.command_ack", () => this.#waitCommandWork(type, commandId, deadline, abortOnClose)) : this.#waitCommandWork(type, commandId, deadline, abortOnClose); + } + + async #waitCommandWork( + type: string, + commandId?: string, + deadline = Date.now() + 30_000, + abortOnClose = false, ): Promise { await waitForRunnerCommand({ type, @@ -6523,7 +6590,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { runnerHasExited: () => this.#runnerHasExited(), failureCode: () => this.#startupComplete ? "provider_transport_failed" : this.#startupFailureCode, }); - } + + } #pumpEvents(): void { @@ -7397,6 +7465,12 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #awaitRegistrationReady( ready: (() => Promise) | undefined, + ): Promise { + return this.options.measureOperation ? this.options.measureOperation("runner.transport.registration", () => this.#awaitRegistrationReadyWork(ready)) : this.#awaitRegistrationReadyWork(ready); + } + + async #awaitRegistrationReadyWork( + ready: (() => Promise) | undefined, ): Promise { this.#assertStartupOpen(); if (ready === undefined) { @@ -7409,7 +7483,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { ]); this.#assertStartupOpen(); this.#throwIfFailed(); - } + + } #diagnostic(message: string): void { message = redactObservabilityDiagnostic(message, this.options.environment, this.options.observability?.otelConfig); diff --git a/packages/paperclip-runner/src/providers/grok/launcher.cjs b/packages/paperclip-runner/src/providers/grok/launcher.cjs index e9e24f46bff..a03c6cc4445 100755 --- a/packages/paperclip-runner/src/providers/grok/launcher.cjs +++ b/packages/paperclip-runner/src/providers/grok/launcher.cjs @@ -1,4 +1,4 @@ -// Grok admission source identity: sha256:9d778ec8c5987e304d3121787806f546c7c9f545cf5e0628ce0035c59a559907 +// Grok admission source identity: sha256:b70868731d297017152e4675aebe0c5435b70468695f8c5cdf225faba8ced795 // This launcher is admitted by digest and receives a verified native executable. // Never resolve an executable through PATH or accept command-line overrides. const { isAbsolute, join } = require("node:path"); diff --git a/packages/paperclip-runner/test/fixtures/copilot-profile-v85-identity.json b/packages/paperclip-runner/test/fixtures/copilot-profile-v85-identity.json new file mode 100644 index 00000000000..5d0c78a3b24 --- /dev/null +++ b/packages/paperclip-runner/test/fixtures/copilot-profile-v85-identity.json @@ -0,0 +1,88 @@ +{ + "commandDigest": "sha256:267e04ce9335f7641f665d9b952bc4637056ee1cfeac23715b7aefbc3a8df3c9", + "declaration": { + "schema": "paperclip.acpx_profile_declaration.v1", + "agent": "copilot", + "agentProfileVersion": 85, + "acpxVersion": "0.13.1", + "agentServerVersion": "1.0.88", + "protocolPolicyRevision": "copilot-agent-manual-v1", + "acpxPatchSha256": "1e7dae8c83bf8620f53f2bea13c175eeff95e7e955783f6f529bb1dcbdcdb6d2", + "policySha256": "a4be69be43db84052560420a3ca546a665c9165573c24d543eb33d144ba138a3", + "distributionSourceSha256": "c0a65e247fc47b263bd369a3d5ab505c4b323d4e6493be8a9ecbeb0e9dbb9107", + "agentFilesBinding": "registered-runtime-context-v1", + "systemInstructionDelivery": "COPILOT_HOME/copilot-instructions.md:replace-under-lifetime-lease-before-launch:v1", + "sharedRuntimeContract": "paperclip.acpx-runtime-contract.v1", + "innerDistributionSourceSha256": "9bb08347eed01f1ab44e065c8b06ead9be3a25973d6e6329dc4c0a099096279a", + "upstreamAppSha256": "7b48282a19b5b0814a0c96ad5e3a125173d792cc55f9525b2effea962f6063c0", + "patchedAppSha256": "61f8eebe0c30cc03b311c6818b2acb158a6d16ca58c8bfac5ebd42db095c2679", + "messageIdentityContract": "copilot-native-message-id-v1", + "ownedDistributionDelivery": "COPILOT_CLI_DIST_DIR:lease-owned-guarded-inner-distribution:v1", + "permissionContextContract": "copilot-edit-permission-context-v1", + "permissionContextSourceSha256": "de2d38d702b3c574161af0c0c04790fb6f6347916eb3916ce7a131a8c229121b", + "permissionAdapterSourceSha256": "ee5929ed2ee647ad0369465dee9d51a00b2dd28e1ff735b43e969ddc9c164668", + "permissionLocationsSourceSha256": "f39a81da395b6e23aa2a1a45572a28846e5e81bfd3d764d9a456f74a79c752e9", + "permissionRedactionSourceSha256": "ad6770c69269087951790e2e87e22ac088e3d432769adf17ebc865ed512e6c4f", + "permissionClassifierSourceSha256": "1161eabd82e26133e3b3db3ab567f65d52808b03f176e93497e02c8330349fb4", + "semanticToolReceiptContract": "paperclip.semantic_tool_receipt.v2", + "semanticReceiptSourceSha256": "b2795726b2234a663fec1a6ca11f0551ae69882fe9e82aa39686e952d036e791", + "semanticBridgeSourceSha256": "8764b8c9032fdc7d1415b01e75a9fc57c550e7a5e11da4bed7d9100082872ae5", + "toolEvidenceSourceSha256": "6eef5039afc75bb851eaf9cd82a6f099e4bd398ca2deb59dd66f5b2a81a7a706", + "semanticNormalizedInputContract": "validated-forwarded-input-commit-v1", + "semanticSidecarSourceSha256": "b6d5888f47a47838c507a43fbe31a778ac63d4fcbcdc9a869108f604c34c3824", + "semanticDirectDriverSourceSha256": "4ec65aa1d4e905a1e732f2d043bbd39de1ab92f380276ede37d6a72efc19c64d", + "semanticValidationSourceSha256": "02fbb92681c78c5de5d2f1aae25aabc25a0e5df6b0ff4baccac652192a8da975", + "semanticNormalizationSourceSha256": "8b628b82e8eacc91cdcc6fdca2210ba4cf282f01e9c6f74e95ff271655b5047e", + "semanticCompletionContractSourceSha256": "f49398b682a5623812f5d3c33d6bb9a749008e47cc0ed969072041615f66df59", + "semanticValidatorsSourceSha256": "b20ec8ee6e7165117233ce4421a975bb9d3f276220ce31655c0b9a717cb2d9cb", + "semanticSchemaBundleSourceSha256": "81ef98ca7b34896a0f76390ac7af3dd8ef7609fe6f38d54bd6a69373d50fe40b", + "semanticSidecarProtocolSourceSha256": "26b6b21dad582810d00f46e947e682a9615ee9761c487f6315970d6d014c05ab", + "semanticSidecarReceiptCommitContract": "correlated-tool-resolve-v1", + "displayEventSourceSha256": "d72f9a6035c247bc6a42c067c05753076c54322c4b58984e93922f3325dc6877", + "displayProjectionSourceSha256": "75952606b26dd93bbc582c1f0a4424487377272ea745fb3a27ceae031fd5dc7e", + "configuredEnvironmentSourceSha256": "ecef0ada320a762e0a3d91c38c72d4e19e2c8e8be8c060938a47e7f1a029058a", + "configuredEnvironmentRustSourceSha256": "1671cb2735b3fa119d32f08d4a12b21b9f78a0e4d7285eb63c35df79ce17bd3c", + "profileActivitySourceSha256": "4fdb6b0f9125fd8372ba6f27945fa5c8a3d3b2ec891df544092e3dc7a75d5282", + "profileExtensionsSourceSha256": "a80ddc95eb4505095bfdbbf85c758199949ab20be9c84b34c77f762eb7180571", + "profileInstallationSourceSha256": "58841b2d3b47ab9956db20608802edcd0e55cf5856002dc7c51e05e75bdcb8f6", + "attachmentPolicySourceSha256": "4f7638b7cc64e18f6a4ba33fd46de2b3d49225e32aeab41f5c695b268fa4f8e2", + "singleReadEvidenceSourceSha256": "4069393405089bde613cecec04f5123c426594811da4c668bd96f0e7e283550f", + "nativeSessionRuntimeSourceSha256": "1fe6fa9e6b96d84d70432b85a57c473f833606d4a521563d5022b4d3c41576ce", + "nativeRuntimeContextSourceSha256": "71607f80dbb8dc5cc6c123d0b8f3995d6c5407277695a8c82cbedc90fb8f4842", + "nativeRuntimePromptsSourceSha256": "fff5755dba9b7dce8a5f10ff6ac6d5ed06b92ed079ce1e0a44ac72f2ce7869c1", + "nativeSessionContractSourceSha256": "22a8c96ce41ba4f03e976fc37f0cc7c5d05cee99fa789941da31ee1dab440b90", + "harnessSessionContractSourceSha256": "baba1a210b863518f01e0c875606ed37f9467c433222251438578bd999bc43b5", + "harnessBackendSourceSha256": "dc827e281ae6731545b166ee4d709a4f67f594a556dcbe63c70fe8f1aca26249", + "harnessSessionSourceSha256": "81361733e86b56dd5a66415aefc6f72e69be24acc8d3417370154ebb7fef6e94", + "transportContractSourceSha256": "06f06c53ecae304f72034ffb2f659ff087c82a70ed4994daf21a9d2edaf56e4e", + "nativeBackendSourceSha256": "7495d9898d22dca1ebf6336361d332bafefc4498f6e49f1135025fad846c8586", + "nativeBackendFactorySourceSha256": "7e431c926b76d53c4c08e3a4105353dcd34bd940f6588a1a68f79631f6feeb44", + "nativeInstructionsSourceSha256": "82ac6e5f7275b4ef79fb166c7330efc504e80cab3d7e9081e4e40a8b570bc50b", + "providerLaunchSourceSha256": "c744235b3067ea75973523f78f1e13399337bc155f1775af694e34782d5c9bef", + "launchPreparationStoreSourceSha256": "ff6025568bbc0aa6ce545772d73dfca2d3da226740bd3a7b386b069e76cff296", + "runtimeRequestBridgeSourceSha256": "68dad92a921ff15feba4cb3fab3b13df4c72aae9260a4d7eb121e8945c603b79", + "runtimeRequestFacadeSourceSha256": "d0ed28e0c5ddad34db8f437e704c8a755eb0b47f27e08e44185f66d1d2205295", + "runtimeRequestNotificationSourceSha256": "6196c6175f11c69295dc00fc773201f4fdeca26c500653870253c43b81e65211", + "guardedInstallationSourceSha256": "64b137e3ef695e7d03013ea2b6c8830171e0a73e0bf2e73d55e9ced57a47bcf6", + "nativeExecutionSourceSha256": "116c348e232848a80c5556494c109314baafb20fb5c97133d9656c7732ee54be", + "profileCompatibilitySourceSha256": "f23df7ed573c58c495a480827efa6cc5004aa9d4b106ba7f929a928f35607d72", + "installationSourceSha256": "a1c7c6f103b898216973e77ffbac0ef7572e250aa574d1a4065270e9dfa0dc2d", + "assetOwnershipSourceSha256": "e5bb6bc58b3f0e957a64b2cd99c710337ffcd9c0e1fadb341f48e033b64b99f5", + "assetInstallerSourceSha256": "d3bd9514e5920d0cc3567aa50487fb534c57a6f66b8da0d3f22c5f6e499c841f", + "credentialBindingSourceSha256": "2ed68b9aed9756fdd682721833eb2aeaa58f30f1dc8825c88886cc8e7ee92abe", + "admissionDiagnosticsSourceSha256": "df8f1aa4f2d1bc63b2635bdd09cb8165c8b7681ddcc2618435c7c08ca90475af", + "grokAdmissionSourceSha256": "f1e46cf2e1e36b7704bd797b678e3db8db2003f97bdb9d827cfa3d7662698777", + "sidecarErrorSourceSha256": "17948ad74350dc487ab20d24a0fb89daf0b426b98396454fff0e3856e922d82c", + "profileSourceSha256": "f5538b3dbefa7634a332b87d5ededcefb56aa7e5790cede1c7a0d948a548a456", + "metadataProbeSourceSha256": "be4c8416edd27061109bc1f33d0c26071b4facbb3f651beaae6b3c0275cce727", + "permissionToolIdentitySourceSha256": "770b47305e571a81f344883057d0e4a482a1cd59ac77d045836593a8e739deb1", + "semanticContinuationSourceSha256": "c9cc0fd516b3df92a6655f56ee9bef37615a889c371e2e137d8ac5c1176de811", + "preparedHarnessHomeSourceSha256": "bb286f7ddc6e9597c56d46bf7ff6e3b556c5b680d7e147fd46518724432b083e", + "runtimeHostSourceSha256": "26b2e115b3f4ae7c20e9d963d117e0286c958af81386deade83397f12abf9662", + "runtimeAdapterSourceSha256": "fab1e278e0f2aed55b35e57d14329eb431b79a08040fa079aa2403842d16085e", + "runtimeSandboxSourceSha256": "b9f05e522f92b6bade51c7a17f8d28bf31ab9db26510b8d5ddce8519d563a875", + "cancellationSourceSha256": "a07d1a9e982dec0ae130c1ad1efa5bc75c6a39e013b730ba3ee45256f09ceeca", + "agentFilesSourceSha256": "fb32f6badc13dfa22f231479509b631b2f0eba0c99b1ab9f3cd5c0c601aa03ba", + "nativeDistributionSourceSha256": "aed327c389e957483a503cb1bb8b247ee7cd7ff4b528fb4567c39bcb4577690b" + } +} diff --git a/packages/paperclip-runner/test/fixtures/grok-profile-v14-identity.json b/packages/paperclip-runner/test/fixtures/grok-profile-v14-identity.json new file mode 100644 index 00000000000..428385e99ee --- /dev/null +++ b/packages/paperclip-runner/test/fixtures/grok-profile-v14-identity.json @@ -0,0 +1,35 @@ +{ + "commandDigest": "sha256:ca59edc7f416cc1e86ac7d7d1e288d3d91065b7ab59e79bcb62bae5f0cc5cf49", + "sourceDigest": "sha256:b70868731d297017152e4675aebe0c5435b70468695f8c5cdf225faba8ced795", + "declaration": { + "schema": "paperclip.grok-profile-identity.v1", + "agent": "grok", + "agentProfileVersion": 14, + "agentServerPackage": "builtin:grok-acp", + "agentServerVersion": "1", + "agentRuntimePackage": "native:grok", + "agentRuntimeVersion": "1.0.13", + "requiresProviderPolicy": false, + "acpxVersion": "0.13.1", + "sources": { + "patches/acpx@0.13.1.patch": "sha256:1e7dae8c83bf8620f53f2bea13c175eeff95e7e955783f6f529bb1dcbdcdb6d2", + "packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts": "sha256:b6d5888f47a47838c507a43fbe31a778ac63d4fcbcdc9a869108f604c34c3824", + "packages/paperclip-runner/src/cli/acpx-sidecar-input.ts": "sha256:17948ad74350dc487ab20d24a0fb89daf0b426b98396454fff0e3856e922d82c", + "packages/paperclip-runner/src/drivers/acpx/admission-diagnostics.ts": "sha256:df8f1aa4f2d1bc63b2635bdd09cb8165c8b7681ddcc2618435c7c08ca90475af", + "packages/paperclip-runner/src/drivers/acpx/grok-effort.ts": "sha256:f1e46cf2e1e36b7704bd797b678e3db8db2003f97bdb9d827cfa3d7662698777", + "packages/paperclip-runner/src/drivers/acpx/grok-web-search.ts": "sha256:754b5ca2345c045421f6007f34999508d996e1cea035f0f1952b3d5f00072b9c", + "packages/paperclip-runner/src/drivers/acpx/grok-credentials.ts": "sha256:1c4ff0be6da798b6fcc604d20a9198dcc8523a3806d563b5b5345b7260549f73", + "packages/paperclip-runner/src/drivers/acpx/codex-runtime-adapter.ts": "sha256:fab1e278e0f2aed55b35e57d14329eb431b79a08040fa079aa2403842d16085e", + "packages/paperclip-runner/src/drivers/acpx/runtime-host.ts": "sha256:26b2e115b3f4ae7c20e9d963d117e0286c958af81386deade83397f12abf9662", + "packages/paperclip-runner/src/drivers/preconfigured-home.ts": "sha256:bb286f7ddc6e9597c56d46bf7ff6e3b556c5b680d7e147fd46518724432b083e", + "packages/paperclip-runner/src/drivers/acpx/runtime-sandbox.ts": "sha256:b9f05e522f92b6bade51c7a17f8d28bf31ab9db26510b8d5ddce8519d563a875", + "packages/paperclip-runner/src/drivers/acpx/sidecar-protocol.ts": "sha256:26b6b21dad582810d00f46e947e682a9615ee9761c487f6315970d6d014c05ab", + "packages/paperclip-runner/src/drivers/acpx/native-distribution-integrity.ts": "sha256:aed327c389e957483a503cb1bb8b247ee7cd7ff4b528fb4567c39bcb4577690b", + "packages/paperclip-runner/src/providers/grok/launcher.cjs": "sha256:f0b698395a3704ed2ffaf84ea19bdb20c36c8a0a70b7c629c7b6ffe144e59e55", + "packages/paperclip-runner/src/providers/grok/platforms.json": "sha256:931eed3abbf2bf041e6c72e6e9486d976f4352613cf069b216ddf010c9a8e704", + "packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_backend.rs": "sha256:eed57e3ba2ab2f12c2e6abba7b683e64adfc0e281e9e8a63c854b8eabdfb5183", + "packages/paperclip-runner/runner/crates/runner-core/src/acpx_provider_session.rs": "sha256:fc8d7cce62e0c02efddece8696e8d24f6a9fe19e5288a5e67a01ffbf931a3f6e", + "packages/paperclip-runner/runner/crates/runner-core/src/acpx_sidecar_transport.rs": "sha256:839cb1d2ac19462f2bcef94d014e528e56beb7a1a1cbf6c3b10906d0ab7eb10c" + } + } +} diff --git a/packages/plugins/sdk/src/host-client-factory.ts b/packages/plugins/sdk/src/host-client-factory.ts index 9e6a6cf8ce8..f1bba9f1830 100644 --- a/packages/plugins/sdk/src/host-client-factory.ts +++ b/packages/plugins/sdk/src/host-client-factory.ts @@ -432,8 +432,8 @@ const METHOD_CAPABILITY_MAP: Record boolean, + record: (span: PluginSpanRecord) => void, +) { + type Scope = { span: PluginSpanRecord; budget: { remaining: number }; closed: boolean; clock: {epoch:number; origin:number} }; + const active = new AsyncLocalStorage(); + async function withSpan(name: string, work: () => T | Promise, attributes?: Record): Promise { + if (!enabled()) return work(); + const parent = active.getStore(); + // Detached work cannot outlive or inherit a completed invocation receipt. + if (parent?.closed) return work(); + const budget = parent?.budget ?? { remaining: 256 }; + if (budget.remaining-- <= 0) return work(); + const clock = parent?.clock ?? {epoch:Date.now(), origin:performance.now()}; + const startTimeMs = clock.epoch + performance.now() - clock.origin; + const span: PluginSpanRecord = { name, startTimeMs, attributes, children: [] }; + const scope: Scope = { span, budget, closed: false, clock }; + parent?.span.children?.push(span); + try { return await active.run(scope, work); } + catch (error) { span.status = { code: 2 }; throw error; } + finally { + scope.closed = true; + span.endTimeMs = clock.epoch + performance.now() - clock.origin; + if (!parent) { try { record(span); } catch {} } + } + } + function appendSpan(scope:Scope | undefined, span:PluginSpanRecord):boolean { + if (!scope) return false; + if (!enabled() || scope.closed || scope.budget.remaining-- <= 0) return true; + scope.span.children?.push(span); + return true; + } + return { + withSpan, + clock: () => { + const clock=active.getStore()?.clock ?? {epoch:Date.now(),origin:performance.now()}; + return () => clock.epoch+performance.now()-clock.origin; + }, + now: () => { const clock=active.getStore()?.clock; return clock ? clock.epoch+performance.now()-clock.origin : Date.now(); }, + isRecording: enabled, + recordSpan: (span:PluginSpanRecord) => appendSpan(active.getStore(),span), + captureRecorder: () => { + const scope=active.getStore(); + return (span:PluginSpanRecord) => appendSpan(scope,span); + }, + }; +} diff --git a/packages/plugins/sdk/src/protocol.ts b/packages/plugins/sdk/src/protocol.ts index e76615d1687..464a7f3fec1 100644 --- a/packages/plugins/sdk/src/protocol.ts +++ b/packages/plugins/sdk/src/protocol.ts @@ -314,6 +314,8 @@ export interface PluginInvocationContext { * host-issued invocation id. */ export interface WorkerHostCallContext { + /** Host-owned aggregate timing budget; never received from the worker. */ + providerSpanBudget?: { remaining: number }; invocationScope?: PluginInvocationScope | null; invalidInvocationScope?: boolean; /** @@ -1567,6 +1569,18 @@ export const HOST_TO_WORKER_OPTIONAL_METHODS: readonly HostToWorkerMethodName[] * These represent the SDK client calls that the worker makes back to the * host to access platform services (state, entities, config, etc.). */ +export interface PluginSpanRecord { + name: string; + /** A completed remote lifecycle is linked to its observer, never made its child. */ + relationship?: "linked"; + attributes?: Record; + status?: { code: number; message?: string }; + startTimeMs?: number; + endTimeMs?: number; + /** Nested timing receipts, bounded and validated again by the host. */ + children?: PluginSpanRecord[]; +} + export interface WorkerToHostMethods { // Config "config.get": [params: { companyId?: string }, result: Record]; @@ -1760,25 +1774,7 @@ export interface WorkerToHostMethods { // real tracer. The worker never sends the parent `traceparent`; the host // recovers it from the echoed invocation id. The RPC is capability-gated. "span.record": [ - params: { - /** The bounded span name (for example `pack` or `transfer`). The host - * clamps it to a closed set, so a name never carries free-form data. */ - name: string; - /** The span attributes. The host drops every key that is not on the closed - * plugin-span allowlist and re-clamps each remaining value. */ - attributes?: Record; - /** The optional span status. */ - status?: { code: number; message?: string }; - /** The optional span start time as epoch milliseconds (`Date.now()`). - * The worker captures it when it opens the span. The host validates the - * pair and records the span with its true native width. An omitted value - * makes the host fall back to a synchronous open-and-end. */ - startTimeMs?: number; - /** The optional span end time as epoch milliseconds (`Date.now()`). The - * worker captures it when it ends the span. The host uses it as the span - * end time when the pair passes the clock-safety check. */ - endTimeMs?: number; - }, + params: PluginSpanRecord, result: void, ]; diff --git a/packages/plugins/sdk/src/types.ts b/packages/plugins/sdk/src/types.ts index 9f0ea69b7fe..7bd956f0fe0 100644 --- a/packages/plugins/sdk/src/types.ts +++ b/packages/plugins/sdk/src/types.ts @@ -1107,6 +1107,13 @@ export interface PluginSpan { * active host trace context. */ export interface PluginTracer { + /** Invocation-wide monotonic clock anchored to epoch milliseconds. */ + now?(): number; + isRecording?(): boolean; + /** Completed bounded timing receipt; the host validates times and parentage. */ + recordSpan?(span: import("./protocol.js").PluginSpanRecord): void; + /** Invocation-scoped nesting; absent on older hosts. No additional IPC per child. */ + withSpan?(name: string, work: () => T | Promise, attributes?: Record): Promise; /** Start one span. `options.attributes` seeds the span attributes. */ startSpan( name: string, diff --git a/packages/plugins/sdk/src/worker-rpc-host.ts b/packages/plugins/sdk/src/worker-rpc-host.ts index daad66769c0..b7a907298cf 100644 --- a/packages/plugins/sdk/src/worker-rpc-host.ts +++ b/packages/plugins/sdk/src/worker-rpc-host.ts @@ -6,6 +6,7 @@ import type { AgentLifecycleRequest, AgentLifecycleResult } from "@paperclipai/s import type { AiConnectionRouterRequest, AiConnectionRouterResult } from "@paperclipai/shared"; import { environmentCreationCleanupErrorData } from "./environment-creation-cleanup.js"; import { environmentSyncErrorData, withEnvironmentSyncErrorCapture } from "./environment-sync-error.js"; +import { createInvocationTracer } from "./invocation-tracer.js"; import { createPluginIdleDrain } from "./idle-drain.js"; /** * Worker-side RPC host — runs inside the child process spawned by the host. @@ -353,6 +354,14 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost let configCompanyId: string | null = null; let databaseNamespace: string | null = null; const invocationContextStorage = new AsyncLocalStorage(); + const canRecordSpans = () => Boolean(invocationContextStorage.getStore()?.traceparent) + && (manifest?.capabilities.includes("environment.drivers.register") === true + || manifest?.capabilities.includes("workspaces.manage") === true); + const invocationTracer = createInvocationTracer( + canRecordSpans, + span => { void callHostRaw("span.record", span).catch(() => undefined); }, + ); + const { withSpan } = invocationTracer; // Plugin handler registrations (populated during setup()) const eventHandlers: EventRegistration[] = []; @@ -392,7 +401,15 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost /** * Send a typed JSON-RPC request to the host and await the response. */ - function callHost( + function callHost(method: M, params: WorkerToHostMethods[M][0], timeoutMs?: number): Promise { + const operation = method === "agents.getRuntimeIdentity" || method === "agents.getRuntime" ? "identity.read" + : method === "config.get" ? "config.read" : method === "entities.list" ? "progress.read" + : method === "entities.upsert" ? "progress.write" : undefined; + return operation ? withSpan(`plugin.host.${operation}`, () => callHostRaw(method, params, timeoutMs)) + : callHostRaw(method, params, timeoutMs); + } + + function callHostRaw( method: M, params: WorkerToHostMethods[M][0], timeoutMs?: number, @@ -1528,21 +1545,27 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost }, tracer: { + withSpan, + now: invocationTracer.now, + isRecording: invocationTracer.isRecording, + recordSpan: invocationTracer.recordSpan, startSpan( name: string, options?: { attributes?: Record }, ) { // Read the active host trace context from the per-call invocation - // channel. A `traceparent` means a host span is active, so this span - // may record. No `traceparent` means tracing is off: the span is a - // no-op, so a lifecycle hook can always wrap work in a span. - const hasTraceContext = Boolean(invocationContextStorage.getStore()?.traceparent); + // channel. Only providers permitted to record receipts collect spans; + // other plugins and tracing-off invocations keep no-op behavior. + const recordSpan = invocationTracer.captureRecorder(); + const spanInvocation = invocationContextStorage.getStore(); + const hasTraceContext = canRecordSpans(); const attributes: Record = { ...(options?.attributes ?? {}), }; // Capture the real start time once when the span opens. The host uses // it as the span start time, so the span shows its true native width. - const startTimeMs = Date.now(); + const spanNow = invocationTracer.clock(); + const startTimeMs = spanNow(); let status: { code: number; message?: string } | undefined; let ended = false; return { @@ -1555,21 +1578,22 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost end(): void { if (ended) return; ended = true; - if (!hasTraceContext) return; + if (!hasTraceContext || invocationContextStorage.getStore()?.id !== spanInvocation?.id) return; // Capture the real end time once at the first end call. The host // uses the pair to record the span with its true wall-clock width. - const endTimeMs = Date.now(); + const endTimeMs = spanNow(); // Send the finished span to the host once. The host re-clamps the // name and the attributes, mints the parentage from its own // invocation record, and records the span through the real tracer. // Fire-and-forget: a span must never block or fail plugin work. - void callHost("span.record", { + const receipt = { name, attributes, ...(status ? { status } : {}), startTimeMs, endTimeMs, - }).catch(() => undefined); + }; + if (!recordSpan(receipt)) void callHost("span.record", receipt).catch(() => undefined); }, }; }, @@ -1602,7 +1626,7 @@ export function startWorkerRpcHost(options: WorkerRpcHostOptions): WorkerRpcHost if (method !== "prepareIdleSleep" && method !== "releaseIdleSleep" && method !== "shutdown") { done = idleDrain.begin(); } - const invoke = () => dispatchMethod(method, params); + const invoke = () => withSpan("plugin.worker", () => dispatchMethod(method, params)); const result = request.paperclipInvocation ? await invocationContextStorage.run(request.paperclipInvocation, invoke) : await invoke(); diff --git a/packages/plugins/sdk/tests/invocation-tracer.test.ts b/packages/plugins/sdk/tests/invocation-tracer.test.ts new file mode 100644 index 00000000000..73990cf27bc --- /dev/null +++ b/packages/plugins/sdk/tests/invocation-tracer.test.ts @@ -0,0 +1,68 @@ +import { AsyncLocalStorage } from "node:async_hooks"; +import { describe, expect, it, vi } from "vitest"; +import { createInvocationTracer } from "../src/invocation-tracer.js"; +import type { PluginSpanRecord } from "../src/protocol.js"; + +describe("invocation timing receipts",()=>{ + it("keeps concurrent roots and nested failures separate",async()=>{ + const records:PluginSpanRecord[]=[]; + const tracer=createInvocationTracer(()=>true,span=>records.push(span)); + let release!:()=>void; + const waiting=new Promise(resolve=>release=resolve); + const first=tracer.withSpan("first",async()=>{await waiting;return tracer.withSpan("child",async()=>42);}); + const error=new Error("private"); + await expect(tracer.withSpan("second",()=>tracer.withSpan("failed",async()=>{throw error;}))).rejects.toBe(error); + release();expect(await first).toBe(42); + expect(records.map(span=>span.name)).toEqual(["second","first"]); + expect(records[0].children?.[0].status).toEqual({code:2}); + expect(records[1].children?.[0].name).toBe("child"); + for(const span of records) expect(span.endTimeMs!).toBeGreaterThanOrEqual(span.startTimeMs!); + expect(JSON.stringify(records)).not.toContain("private"); + }); + it("is inert without an invocation trace and isolates recording failures",async()=>{ + const records:PluginSpanRecord[]=[]; + let count=0; + const disabled=createInvocationTracer(()=>false,span=>records.push(span)); + expect(await disabled.withSpan("disabled",async()=>++count)).toBe(1); + expect(records).toEqual([]); + const broken=createInvocationTracer(()=>true,()=>{throw Error("export");}); + expect(await broken.withSpan("broken",async()=>++count)).toBe(2); + }); + it("bounds children and excludes detached work after its parent closes",async()=>{ + const records:PluginSpanRecord[]=[];const tracer=createInvocationTracer(()=>true,span=>records.push(span)); + let detached!:()=>Promise; + await tracer.withSpan("root",async()=>{ + for(let n=0;n<300;n++)await tracer.withSpan("child",async()=>{}); + detached=AsyncLocalStorage.bind(()=>tracer.withSpan("late",async()=>{})); + }); + expect(records[0].children).toHaveLength(255); + await detached();expect(records).toHaveLength(1); + }); +}); + +it("uses one monotonic origin across children even if the epoch clock changes",async()=>{ + const records:PluginSpanRecord[]=[];const tracer=createInvocationTracer(()=>true,span=>records.push(span)); + const clock=vi.spyOn(Date,"now").mockReturnValueOnce(1000).mockReturnValue(999999); + try {await tracer.withSpan("root",async()=>{await tracer.withSpan("child",async()=>{});});} + finally {clock.mockRestore();} + const root=records[0],child=root.children![0]; + expect(child.startTimeMs!).toBeGreaterThanOrEqual(root.startTimeMs!); + expect(child.endTimeMs!).toBeLessThanOrEqual(root.endTimeMs!); + expect(root.endTimeMs!).toBeLessThan(999999); +}); +it("consumes excess legacy records instead of falling back to standalone export",async()=>{ + const tracer=createInvocationTracer(()=>true,()=>{}); + await tracer.withSpan("root",async()=>{ + for(let n=0;n<300;n++)expect(tracer.recordSpan({name:"pack"})).toBe(true); + }); +}); + +it("manual spans retain their creation scope when ended inside a nested operation",async()=>{ + const records:PluginSpanRecord[]=[];const tracer=createInvocationTracer(()=>true,span=>records.push(span)); + await tracer.withSpan("root",async()=>{ + const record=tracer.captureRecorder(),startTimeMs=tracer.now(); + await tracer.withSpan("nested",async()=>{record({name:"manual",startTimeMs,endTimeMs:tracer.now()});}); + }); + expect(records[0].children?.map(span=>span.name)).toEqual(["nested","manual"]); + expect(records[0].children?.[0].children).toEqual([]); +}); diff --git a/packages/plugins/sdk/tests/worker-rpc-host.test.ts b/packages/plugins/sdk/tests/worker-rpc-host.test.ts index 67adcba34b0..aa26cc23eb0 100644 --- a/packages/plugins/sdk/tests/worker-rpc-host.test.ts +++ b/packages/plugins/sdk/tests/worker-rpc-host.test.ts @@ -569,7 +569,7 @@ describe("worker provider tracer", () => { // worker→host traffic. The host injects a `traceparent` on the invocation, so // the worker must emit one `span.record` request that echoes the invocation id // and carries the span name and attributes. - async function runSpanProbe(invocation: PluginInvocationContext) { + async function runSpanProbe(invocation: PluginInvocationContext, count=1, capabilities = ["environment.drivers.register"]) { const hostToWorker = new PassThrough(); const workerToHost = new PassThrough(); const hostReadline = createInterface({ input: workerToHost }); @@ -580,11 +580,13 @@ describe("worker provider tracer", () => { const plugin = definePlugin({ async setup(ctx) { ctx.data.register("probe", async () => { + for(let index=0;index { description: "Tracer test", author: "Paperclip", categories: ["automation"], - capabilities: ["environment.drivers.register"], + capabilities, entrypoints: { worker: "dist/worker.js" }, }, config: {}, @@ -666,7 +668,8 @@ describe("worker provider tracer", () => { expect(spanRecords).toHaveLength(1); const record = spanRecords[0]!; expect(record.invocationId).toBe("invocation-a"); - expect(record.params).toMatchObject({ + expect(record.params).toMatchObject({name:"plugin.worker"}); + expect((record.params as {children:unknown[]}).children[0]).toMatchObject({ name: "pack", attributes: { "paperclip.sandbox.startup.pack.wall_ms": 12, @@ -691,6 +694,25 @@ describe("worker provider tracer", () => { expect(params.endTimeMs!).toBeGreaterThanOrEqual(params.startTimeMs!); }); + it("never falls back to per-span IPC after the legacy span budget is exhausted",async()=>{ + const records=await runSpanProbe({id:"bounded",scope:{companyId:"company-a"},traceparent:"00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01"},300); + expect(records).toHaveLength(1); + expect((records[0].params as {children:unknown[]}).children).toHaveLength(255); + }); + + it.each([{ capabilities: [] }, { capabilities: ["companies.read"] }])("does not collect automatic or legacy receipts without a permitted capability: $capabilities", async ({ capabilities }) => { + const records = await runSpanProbe({ id: "not-permitted", scope: { companyId: "company-a" }, + traceparent: "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01" }, 1, capabilities); + expect(records).toEqual([]); + }); + + it("collects receipts for workspace providers without environment-driver permission", async () => { + const records = await runSpanProbe({ id: "workspace", scope: { companyId: "company-a" }, + traceparent: "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01" }, 1, ["workspaces.manage"]); + expect(records).toHaveLength(1); + expect(records[0].params).toMatchObject({ name: "plugin.worker", children: [{ name: "pack" }] }); + }); + it("emits no span.record when the invocation carries no traceparent (tracing off)", async () => { const spanRecords = await runSpanProbe({ id: "invocation-a", diff --git a/server/src/__tests__/instrumentation.test.ts b/server/src/__tests__/instrumentation.test.ts index cf9764967cd..25aef61825b 100644 --- a/server/src/__tests__/instrumentation.test.ts +++ b/server/src/__tests__/instrumentation.test.ts @@ -386,6 +386,24 @@ describe.skipIf(!otelSdk)("recordProviderPluginSpan native duration", () => { } }); + it("exports an earlier lifecycle as a separate trace linked to its observer",async()=>{ + const {api,sdk}=otelSdk!; + const exporter=new sdk.InMemorySpanExporter(); + const provider=new sdk.BasicTracerProvider({spanProcessors:[new sdk.SimpleSpanProcessor(exporter)]}); + api.trace.setGlobalTracerProvider(provider); + try { + const {recordProviderPluginSpan}=await import("../instrumentation.js"); + const parent={traceId:"0af7651916cd43dd8448eb211c80319c",spanId:"b7ad6b7169203331",traceFlags:1}; + const end=Date.now()-100; + recordProviderPluginSpan({name:"plugin.remote.lifecycle",parent,linked:true,attributes:{},startTimeMs:end-500,endTimeMs:end}); + const span=exporter.getFinishedSpans()[0]!; + expect(span.parentSpanContext).toBeUndefined(); + expect(span.spanContext().traceId).not.toBe(parent.traceId); + expect(span.links[0].context).toMatchObject(parent); + expect(Math.round(hrTimeToMs(span.duration as [number,number]))).toBe(500); + } finally {api.trace.disable();} + }); + it("opens and ends the span now when the timestamp pair is absent", async () => { const { api, sdk } = otelSdk!; const exporter = new sdk.InMemorySpanExporter(); @@ -413,3 +431,20 @@ describe.skipIf(!otelSdk)("recordProviderPluginSpan native duration", () => { } }); }); + +it("gives a linked lifecycle an explicit root context and a host-owned observer link",async()=>{ + const root={},active={};const end=vi.fn(); + const startSpan=vi.fn(()=>({end,setStatus:vi.fn(),spanContext:()=>({traceId:"a".repeat(32),spanId:"b".repeat(16),traceFlags:1})})); + const setSpanContext=vi.fn(()=>active); + vi.doMock("node:module",()=>({createRequire:()=>()=>({ROOT_CONTEXT:root,context:{active:()=>active},trace:{getTracer:()=>({startSpan}),setSpanContext}})})); + try { + const {recordProviderPluginSpan}=await importFreshInstrumentation(); + const parent={traceId:"0af7651916cd43dd8448eb211c80319c",spanId:"b7ad6b7169203331",traceFlags:1}; + recordProviderPluginSpan({name:"plugin.remote.lifecycle",parent,linked:true,attributes:{},startTimeMs:100,endTimeMs:500}); + expect(startSpan).toHaveBeenCalledWith("plugin.remote.lifecycle",{attributes:{},startTime:100,links:[{context:{...parent,isRemote:true}}]},root); + expect(setSpanContext).not.toHaveBeenCalled();expect(end).toHaveBeenCalledWith(500); + startSpan.mockClear(); + recordProviderPluginSpan({name:"plugin.remote.lifecycle",parent:{...parent,traceFlags:0},linked:true,attributes:{},startTimeMs:100,endTimeMs:500}); + expect(startSpan).not.toHaveBeenCalled(); + } finally {vi.doUnmock("node:module");vi.resetModules();} +}); diff --git a/server/src/__tests__/plugin-host-services-span.test.ts b/server/src/__tests__/plugin-host-services-span.test.ts index cd3ad20cd66..01b7eb06c7a 100644 --- a/server/src/__tests__/plugin-host-services-span.test.ts +++ b/server/src/__tests__/plugin-host-services-span.test.ts @@ -6,6 +6,7 @@ import { buildHostServices, clampProviderSpanAttributes, parseTraceparent, + recordWorkerProviderSpan, } from "../services/plugin-host-services.js"; // Capture every span the host trust boundary hands to the real tracer. @@ -329,3 +330,52 @@ describe("clampProviderSpanAttributes", () => { 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(); +}); diff --git a/server/src/__tests__/plugin-worker-manager.test.ts b/server/src/__tests__/plugin-worker-manager.test.ts index 7e6b32d696b..db81a002f40 100644 --- a/server/src/__tests__/plugin-worker-manager.test.ts +++ b/server/src/__tests__/plugin-worker-manager.test.ts @@ -27,6 +27,7 @@ vi.mock("../middleware/logger.js", () => { }); import { logger } from "../middleware/logger.js"; +import { withRunExecutionTiming } from "../services/execution-preparation-timing.js"; import { appendStderrExcerpt, createDuplexRouteSlotController, @@ -236,7 +237,8 @@ describe("plugin-worker-manager stderr failure context", () => { } }); - it("does not emit an unhandled rejection when a plugin responds with terminated before callers attach handlers", async () => { + it.each(["", "http://collector.test"])("does not emit an unhandled rejection before callers attach handlers (endpoint %s)", async endpoint => { + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT", endpoint); const unhandledRejection = vi.fn(); process.on("unhandledRejection", unhandledRejection); @@ -255,28 +257,35 @@ describe("plugin-worker-manager stderr failure context", () => { try { await handle.start(); - const pendingCall = handle.call( - "environmentExecute" as keyof HostToWorkerMethods, - { - driverKey: "e2b", - companyId: "company-1", - environmentId: "environment-1", - config: {}, - lease: { providerLeaseId: "lease-1" }, - command: "echo", - } as HostToWorkerMethods[keyof HostToWorkerMethods][0], - ); + await withRunExecutionTiming("early-worker-error", async () => { + let settled!: () => void; + const workerSettled = new Promise(resolve => { settled = resolve; }); + const pendingCall = handle.call( + "environmentExecute" as keyof HostToWorkerMethods, + { + driverKey: "e2b", + companyId: "company-1", + environmentId: "environment-1", + config: {}, + lease: { providerLeaseId: "lease-1" }, + command: "echo", + } as HostToWorkerMethods[keyof HostToWorkerMethods][0], + undefined, undefined, settled, + ); - await new Promise((resolve) => setImmediate(resolve)); + await workerSettled; + await new Promise((resolve) => setImmediate(resolve)); - await expect(pendingCall).rejects.toBeInstanceOf(JsonRpcCallError); - await expect(pendingCall).rejects.toMatchObject({ - message: expect.stringContaining("terminated"), + await expect(pendingCall).rejects.toBeInstanceOf(JsonRpcCallError); + await expect(pendingCall).rejects.toMatchObject({ + message: expect.stringContaining("terminated"), + }); + expect(unhandledRejection).not.toHaveBeenCalled(); }); - expect(unhandledRejection).not.toHaveBeenCalled(); } finally { process.off("unhandledRejection", unhandledRejection); await handle.stop().catch(() => undefined); + vi.unstubAllEnvs(); } }); @@ -352,7 +361,7 @@ describe("plugin-worker-manager stderr failure context", () => { }); expect(companiesGet).toHaveBeenCalledWith( { companyId: "company-a" }, - { invocationScope: { companyId: "company-a" } }, + { invocationScope: { companyId: "company-a" }, traceparent: undefined, providerSpanBudget: { remaining: 256 } }, ); } finally { await handle.stop().catch(() => undefined); @@ -389,7 +398,7 @@ describe("plugin-worker-manager stderr failure context", () => { expect(companiesGet).toHaveBeenCalledWith( { companyId: "company-1" }, - { invocationScope: { companyId: "company-1" } }, + { invocationScope: { companyId: "company-1" }, traceparent: undefined, providerSpanBudget: { remaining: 256 } }, ); } finally { await handle.stop().catch(() => undefined); diff --git a/server/src/instrumentation.ts b/server/src/instrumentation.ts index fe8f0665bfd..ac632a57e15 100644 --- a/server/src/instrumentation.ts +++ b/server/src/instrumentation.ts @@ -235,6 +235,7 @@ export function traceparentFromContextToken(contextToken: unknown): string | und */ export function recordProviderPluginSpan(input: { name: string; + linked?: boolean; parent: ParsedTraceparent; attributes: Record; status?: { code: number; message?: string }; @@ -244,7 +245,7 @@ export function recordProviderPluginSpan(input: { startTimeMs?: number; /** The optional span end time as an epoch-millisecond number. */ endTimeMs?: number; -}): void { +}): ParsedTraceparent | undefined { try { const require = createRequire(import.meta.url); const api = require("@opentelemetry/api") as { @@ -253,6 +254,7 @@ export function recordProviderPluginSpan(input: { setSpanContext(context: unknown, spanContext: unknown): unknown; }; context?: { active(): unknown }; + ROOT_CONTEXT?: unknown; }; const trace = api.trace; const context = api.context; @@ -263,22 +265,26 @@ export function recordProviderPluginSpan(input: { traceFlags: input.parent.traceFlags, isRemote: true, }; - const parentContext = trace.setSpanContext(context.active(), remoteSpanContext); + if (input.linked && (!api.ROOT_CONTEXT || (input.parent.traceFlags & 1) === 0)) return; + const parentContext = input.linked ? api.ROOT_CONTEXT : trace.setSpanContext(context.active(), remoteSpanContext); const tracer = trace.getTracer("paperclip.startup"); // Pass the true start time as the OpenTelemetry `startTime` option, so the // span opens at its real wall-clock start. An epoch-millisecond number is a // valid OpenTelemetry `TimeInput`. - const startSpanOptions = - input.startTimeMs !== undefined - ? { attributes: input.attributes, startTime: input.startTimeMs } - : { attributes: input.attributes }; + const startSpanOptions = { + attributes: input.attributes, + ...(input.startTimeMs !== undefined ? { startTime: input.startTimeMs } : {}), + ...(input.linked ? { links: [{ context: remoteSpanContext }] } : {}), + }; const span = tracer.startSpan(input.name, startSpanOptions, parentContext); + const childParent = (span as typeof span & { spanContext?(): ParsedTraceparent }).spanContext?.(); if (input.status) span.setStatus(input.status); // Pass the true end time to `span.end`, so the span ends at its real // wall-clock end and shows its true native width. When the end time is // absent, the span ends now, so its native width is near zero. if (input.endTimeMs !== undefined) span.end(input.endTimeMs); else span.end(); + return childParent; } catch { // Observability must not change control flow. } diff --git a/server/src/services/execution-preparation-timing.test.ts b/server/src/services/execution-preparation-timing.test.ts index b6ca3732864..fc89d789ed0 100644 --- a/server/src/services/execution-preparation-timing.test.ts +++ b/server/src/services/execution-preparation-timing.test.ts @@ -1,3 +1,4 @@ +import { getActiveStepContext, runWithRuntimeParent } from "@paperclipai/adapter-utils/acpx-engine/startup-timing"; import { afterEach, beforeEach, expect, it, vi } from "vitest"; import { createRunPreparationTiming, measureRunPhase, recordRepositoryObjectCacheDetail, withRunExecutionTiming, withRunWorkspaceFinalizationTiming } from "./execution-preparation-timing.js"; import { ROOT_CONTEXT, trace, SpanStatusCode, type Context } from "@opentelemetry/api"; @@ -141,3 +142,23 @@ it("does not let cache attribute failures replace the operation result", async ( await expect(withRunExecutionTiming("run", () => measureRunPhase("workspace.checkout.cache_publish", work))).resolves.toBe(42); expect(work).toHaveBeenCalledOnce(); }); + +it("keeps plugin dispatch beneath its active startup step and gives the worker the dispatch parent", async () => { + const parents = new Map(); + const spans = new Map; setStatus: ReturnType }>(); + handles.startActiveSpan.mockImplementation((name, _options, parent, callback) => { + parents.set(name, parent); + const span = { end: vi.fn(), setStatus: vi.fn() }; + spans.set(name, span); + return callback(span); + }); + const step = trace.wrapSpanContext({ traceId: "1".repeat(32), spanId: "2".repeat(16), traceFlags: 1 }); + const stepContext = trace.setSpan(ROOT_CONTEXT, step); + await withRunExecutionTiming("startup", () => runWithRuntimeParent(stepContext, async () => { + await measureRunPhase("execution.plugin_dispatch", () => { + expect(trace.getSpan(getActiveStepContext()!.parentContext as Context)).toBe(spans.get("execution.plugin_dispatch")); + }); + expect(getActiveStepContext()!.parentContext).toBe(stepContext); + })); + expect(parents.get("execution.plugin_dispatch")).toBe(stepContext); +}); diff --git a/server/src/services/execution-preparation-timing.ts b/server/src/services/execution-preparation-timing.ts index 86c257dd68e..fe352bd55a8 100644 --- a/server/src/services/execution-preparation-timing.ts +++ b/server/src/services/execution-preparation-timing.ts @@ -1,5 +1,5 @@ import { AsyncLocalStorage } from "node:async_hooks"; -import { EXECUTION_PREPARATION_SPAN_ATTRS, runWithRuntimeParent } from "@paperclipai/adapter-utils/acpx-engine/startup-timing"; +import { EXECUTION_PREPARATION_SPAN_ATTRS, getActiveStepContext, runWithRuntimeParent } from "@paperclipai/adapter-utils/acpx-engine/startup-timing"; import { createHash } from "node:crypto"; import { isSpanContextValid, ROOT_CONTEXT, SpanStatusCode, trace, type Context } from "@opentelemetry/api"; @@ -102,7 +102,7 @@ export type ExecutionPhase = | "execution.runtime" | "execution.workspace_ownership" | "execution.workspace_finalize" | "execution.workspace_restore" | "execution.workspace_commit" | "execution.workspace_ownership_wait" | "execution.realtime" | "execution.usage" | "execution.native_finalize" - | "execution.plugin_prepare" | "execution.plugin_project_auth" | "execution.plugin_submit" | "execution.plugin_connection" + | "execution.plugin_dispatch" | "execution.plugin_prepare" | "execution.plugin_project_auth" | "execution.plugin_submit" | "execution.plugin_connection" | "execution.usage_startup" | "execution.mcp_handoff" | "execution.dispatch_admission" | "execution.budget_reservation" | "completion.run" | "completion.output" | "completion.terminal_write" | "completion.cost" | "completion.liveness" | "completion.summary" | "response.transaction" | "response.transaction.entry" | "response.transaction.commit" | "response.transaction.rollback" | "response.row_lock" | "response.write" @@ -143,7 +143,7 @@ export function isRunPhaseActive(phase: ExecutionPhase): boolean { return endpointEnabled() && owned?.phase === phase && !owned.ended; } -function measure(runId: string, name: string, work: () => T | Promise, independent = false, counts: { fileCount?: number; bytes?: number } = {}): Promise { +function measure(runId: string, name: string, work: () => T | Promise, independent = false, counts: { fileCount?: number; bytes?: number } = {}, activeParent?: Context): Promise { let operation: Promise | undefined; const run = (span?: { setStatus(status: { code: number }): void; end(): void }, parent?: Context) => { if (operation) return operation; @@ -168,7 +168,7 @@ function measure(runId: string, name: string, work: () => T | Promise, ind }; if (!endpointEnabled()) return (async () => work())(); try { - const parent = independent ? undefined : getRunExecutionTraceContext(runId); + const parent = independent ? undefined : activeParent ?? getRunExecutionTraceContext(runId); const trigger = parent ? undefined : trace.getActiveSpan()?.spanContext(); const traced = trace.getTracer(name.startsWith("heartbeat.prepare.") ? "paperclip.heartbeat-preparation" : name.startsWith("native.controller.") ? "paperclip.native-controller" : "paperclip.execution").startActiveSpan(name, { @@ -202,7 +202,9 @@ export async function measureRunPhase(phase: ExecutionPhase, work: () => T | const count = owned.details.get(phase) ?? 0; if (count >= 16) return work(); owned.details.set(phase, count + 1); - return measure(owned.runId, phase, work, false, counts); + // A startup step can be more specific than the owning run phase. Keep that + // causal parent while the child publishes its own context to plugin workers. + return measure(owned.runId, phase, work, false, counts, getActiveStepContext()?.parentContext as Context | undefined); } export function beginRunPhase(phase: ExecutionPhase): (failed?: boolean) => void { diff --git a/server/src/services/native-runtime/native-run-trace.test.ts b/server/src/services/native-runtime/native-run-trace.test.ts index 8b3a076850c..a195cc28d6f 100644 --- a/server/src/services/native-runtime/native-run-trace.test.ts +++ b/server/src/services/native-runtime/native-run-trace.test.ts @@ -439,7 +439,7 @@ describe("native runner performance trace", () => { ).toBe("agent.turn"); await trace.measure("provider.dynamic", async () => undefined); await trace.record({ - name: "provider.turn.queue", + name: "runner.turn.submitted_to_started", parentName: "agent.turn", startedAtMs: 1_085, endedAtMs: 1_090, @@ -469,7 +469,7 @@ describe("native runner performance trace", () => { expect(parentOf("stage.asset.ca_bundle")).toBe("stage.sync"); expect(parentOf("agent.turn")).toBe("native.session.execute"); expect(parentOf("provider.dynamic")).toBe("agent.turn"); - expect(parentOf("provider.turn.queue")).toBe("agent.turn"); + expect(parentOf("runner.turn.submitted_to_started")).toBe("agent.turn"); expect(spans.filter((span) => span.name === "task.provider_session")).toHaveLength(1); expect(spans.some((span) => span.name === "task.provider_session.measured")).toBe(false); diff --git a/server/src/services/native-runtime/native-run-trace.ts b/server/src/services/native-runtime/native-run-trace.ts index 7c38e99cda4..faef91b5f30 100644 --- a/server/src/services/native-runtime/native-run-trace.ts +++ b/server/src/services/native-runtime/native-run-trace.ts @@ -150,6 +150,7 @@ const NOOP_SPAN: SpanHandle = { const SAFE_NATIVE_RUN_SPAN_ATTRIBUTE_KEYS = new Set([ "adapter", "bytesTransferred", + "inputBytes", "toolSchemaBytes", "toolCount", "contextReused", "tokenDataAvailable", "connectionOwner", "driver", "duration_ms", diff --git a/server/src/services/native-runtime/native-session-executor.ts b/server/src/services/native-runtime/native-session-executor.ts index 1f1ed05fa57..650908db374 100644 --- a/server/src/services/native-runtime/native-session-executor.ts +++ b/server/src/services/native-runtime/native-session-executor.ts @@ -1,3 +1,4 @@ +import { measureRunnerOperation, recordRunnerTimingReceipt } from "./runner-operation-timing.js"; import { notifyExternalAgentSettlement } from "../../modules/external-agents/index.js"; import { notifyNativeResultCommit } from "../native-result-commit-notifications.js"; import { releaseRetainedNativeSessionCleanup } from "../retained-native-session-cleanup-notifications.js"; @@ -8642,13 +8643,29 @@ async function executePaperclipNativeSessionWithinScope( privateKeyPem: input.runnerEnvironment?.PAPERCLIP_AGENT_PRIVATE_KEY, assertControllerActive, assertRunAdmissionActive, + onResultCommitted: async () => { + const at=Date.now(); + await trace.record({name:"completion.result_committed",parentName:"native.session.execute",startedAtMs:at,endedAtMs:at}); + }, + onEventPersistence: async (event, startedAtMs, endedAtMs) => { + if (["turn.submitted", "turn.started", "turn.accepted", "run.result.accepted"].includes(event.eventType)) { + await trace.record({name: "runner.event.persist", parentName: "native.session.execute", startedAtMs, endedAtMs, + attributes:{eventKind:event.eventType}}); + } + }, onCommittedEvent: async (event) => { + if (event.eventType === "run.result.proposed") { + const at = Date.now(); + await trace.record({name:"completion.tool_accepted",parentName:"native.session.execute",startedAtMs:at,endedAtMs:at}); + } if (event.eventType === "harness.diagnostic") { await recordNativeProviderPerformanceSpans(trace, parseProviderPerformanceSpans(event.payload, Date.now())); } const textKind = !firstTokenRecorded ? observeDeliverableText(event) : null; if (textKind) { firstTokenRecorded = true; + const textAt = Date.now(); + await trace.record({name:"response.first_nonempty_text",parentName:"native.session.execute",startedAtMs:textAt,endedAtMs:textAt}); await trace.record({ name: "task.time_to_first_token", parentName: "task.provider_session", @@ -8737,7 +8754,7 @@ async function executePaperclipNativeSessionWithinScope( if (event.eventType === "turn.started" && turnStartedAtMs === null) { turnStartedAtMs = milestoneAtMs; await trace.record({ - name: "provider.turn.queue", + name: "runner.turn.submitted_to_started", parentName: "agent.turn", startedAtMs: turnSubmittedAtMs ?? milestoneAtMs, endedAtMs: milestoneAtMs, @@ -12273,6 +12290,8 @@ async function createRunnerdBackendWithinSessionClaim( return nativeCompletionFeedback(input.db, current.runId, result); }, codexTransportFactory: recovery => createRunnerdCodexTransport({ provider: provider.kind, stateDirectory: root, + measureOperation: process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() ? measureRunnerOperation : undefined, + recordTimingReceipt: process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() ? recordRunnerTimingReceipt : undefined, ...owner.driver, runnerArtifact: input.controllerPersistence?.runnerArtifact ?? description.runner, controlPlaneRegistration: input.controllerPersistence ? async (authority, identity, signal) => { await nativeRunnerCheckpointRegistration({ @@ -13755,6 +13774,8 @@ async function createRunnerdBackendWithinSessionClaim( ), codexTransportFactory: (recoveryContext) => { const bundle = createRunnerdCodexTransport({ + measureOperation: process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() ? measureRunnerOperation : undefined, + recordTimingReceipt: process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() ? recordRunnerTimingReceipt : undefined, onSpawn: input.onSpawn, ...(input.execution.provider.kind === "codex" ? { disableCodexWebSearch: "webSearch" in input.execution.provider && input.execution.provider.webSearch === "disabled" } : {}), homeMode: preconfiguredHome ? "preconfigured" : "isolated", diff --git a/server/src/services/native-runtime/native-tool-trace.test.ts b/server/src/services/native-runtime/native-tool-trace.test.ts index 824486db7ff..b5606caf2d0 100644 --- a/server/src/services/native-runtime/native-tool-trace.test.ts +++ b/server/src/services/native-runtime/native-tool-trace.test.ts @@ -72,3 +72,11 @@ describe("native tool timing", () => { expect(spans.filter((span) => span.span === "tool.request.input_stream").map((span) => span.durationMs)).toEqual([10, 31]); }); }); + +it("marks the first completion tool request once per turn without arguments",async()=>{ + const {spans,timing}=fixture(); + const completion=(id:string)=>({...event("started",id,1000),payload:{executionId:id,name:"paperclip_finish",arguments:"private"}}); + await timing.observe(completion("a"));await timing.observe(completion("b")); + expect(spans.filter(span=>span.span==="completion.request.first")).toHaveLength(1); + expect(JSON.stringify(spans)).not.toContain("private"); +}); diff --git a/server/src/services/native-runtime/native-tool-trace.ts b/server/src/services/native-runtime/native-tool-trace.ts index d0e348572b8..95f29785ae8 100644 --- a/server/src/services/native-runtime/native-tool-trace.ts +++ b/server/src/services/native-runtime/native-tool-trace.ts @@ -9,11 +9,13 @@ function operation(value: unknown): string { /** Provider stream IDs and MCP request IDs are separate namespaces. Never join by name or order. */ export function createNativeToolTrace(trace: NativeRunTrace, now = Date.now) { + let firstCompletion = false; const announced = new Map(); return { observe(event: { eventType: string; emittedAt: string; payload: unknown }): void | Promise { if (["turn.started", "turn.completed", "turn.failed", "turn.cancelled"].includes(event.eventType)) { announced.clear(); + firstCompletion = false; return; } if (!event.eventType.startsWith("tool.execution.")) return; @@ -25,6 +27,10 @@ export function createNativeToolTrace(trace: NativeRunTrace, now = Date.now) { if (announced.has(id)) return; if (announced.size >= 512) announced.delete(announced.keys().next().value!); announced.set(id, { startedAtMs: time, operation: operation(payload?.name) }); + if (!firstCompletion && typeof payload?.name === "string" && /^(?:mcp__paperclip__)?paperclip_(?:finish|block)$/.test(payload.name)) { + firstCompletion = true; + return trace.record({name:"completion.request.first",parentName:"agent.turn",startedAtMs:time,endedAtMs:time}); + } return; } const pending = announced.get(id); diff --git a/server/src/services/native-runtime/paperclip-control-plane-port.test.ts b/server/src/services/native-runtime/paperclip-control-plane-port.test.ts index 20fc3e0bfb1..2edc3e1b718 100644 --- a/server/src/services/native-runtime/paperclip-control-plane-port.test.ts +++ b/server/src/services/native-runtime/paperclip-control-plane-port.test.ts @@ -1120,6 +1120,7 @@ describe("PaperclipControlPlanePort conformance", () => { credentialBindings: [], runtimeContext: nativeRuntimeContextFixture(), }); + let resultCommitMarkers = 0; const port = new PaperclipControlPlanePort(db, { companyId: identity.companyId, issueId: taskIssueId, @@ -1130,7 +1131,7 @@ describe("PaperclipControlPlanePort conformance", () => { completionContractSha256: "phase6-task-contract", sourceInstanceId: taskRunnerId, controlPlaneSourceInstanceId: "phase6-control-plane", - }); + }, {onResultCommitted:async()=>{resultCommitMarkers++;}}); const completed = await executeNativeSession({ input: execution, backend, @@ -1210,6 +1211,7 @@ describe("PaperclipControlPlanePort conformance", () => { callerResultId: `phase6-scripted-runner:${taskRunId}:result`, callerDedupeKey: `${taskRunId}:phase6-task-contract`, })).rejects.toThrow("structured_result_replay_conflict"); + expect(resultCommitMarkers).toBe(1); await Promise.all([ finalizeNativeRun({ db, runId: taskRunId, workspaceFinalizeStatus: "succeeded" }), finalizeNativeRun({ db, runId: taskRunId, workspaceFinalizeStatus: "succeeded" }), @@ -1345,10 +1347,14 @@ describe("PaperclipControlPlanePort conformance", () => { nativeSessionId: identity.sessionId, runnerInstanceId: conformanceRunnerId, completionContractId: contractId, completionContractSha256: contractSha, }); + let resultCommitted = false; const port = kind === "port" ? new PaperclipControlPlanePort(db, { ...identity, runId, completionContractId: contractId, completionContractSha256: contractSha, sourceInstanceId: conformanceRunnerId, controlPlaneSourceInstanceId: "result-lock-order", - }) : new NativeRunCoordinatorStore(db, { + }, {onResultCommitted:async()=>{ + const rows=await db.select().from(nativeRunResults).where(eq(nativeRunResults.runId,runId)); + expect(rows).toHaveLength(1);resultCommitted=true; + }}) : new NativeRunCoordinatorStore(db, { ...identity, runId, completionContractId: contractId, completionContractSha256: contractSha, normalizedSessionId: identity.sessionId, runnerSourceInstanceId: conformanceRunnerId, completionContractRevision: "standalone-v1", completionContractCriterionIds: ["objective"], @@ -1371,11 +1377,13 @@ describe("PaperclipControlPlanePort conformance", () => { await new Promise(resolve => setTimeout(resolve, 10)); } expect(waiting).toBe(true); + expect(resultCommitted).toBe(false); await tx.execute(sql`set local lock_timeout = '1s'`); await tx.update(heartbeatRuns).set({ updatedAt: new Date() }).where(eq(heartbeatRuns.id, runId)); }); } finally { expect(await completion).toBeNull(); + expect(resultCommitted).toBe(kind === "port"); } }); diff --git a/server/src/services/native-runtime/paperclip-control-plane-port.ts b/server/src/services/native-runtime/paperclip-control-plane-port.ts index ef0dfa235cb..172fe5f0636 100644 --- a/server/src/services/native-runtime/paperclip-control-plane-port.ts +++ b/server/src/services/native-runtime/paperclip-control-plane-port.ts @@ -86,6 +86,8 @@ export class PaperclipControlPlanePort implements ControlPlanePort { #sessionId: string | null = null; readonly #assertControllerActive?: () => void; readonly #assertRunAdmissionActive?: () => void; + readonly #onResultCommitted?: () => Promise; + readonly #onEventPersistence?: (event: PrpEvent, startedAtMs: number, endedAtMs: number) => Promise; readonly #onCommittedEvent?: (event: PrpEvent) => Promise; readonly #onDuplicateEvent?: (event: PrpEvent) => Promise; @@ -99,6 +101,8 @@ export class PaperclipControlPlanePort implements ControlPlanePort { assertControllerActive?: () => void; /** Read-only admission may finish an existing startup solely for restart detachment. */ assertRunAdmissionActive?: () => void; + onResultCommitted?: () => Promise; + onEventPersistence?: (event: PrpEvent, startedAtMs: number, endedAtMs: number) => Promise; onCommittedEvent?: (event: PrpEvent) => Promise; onDuplicateEvent?: (event: PrpEvent) => Promise; } = {}, @@ -109,6 +113,8 @@ export class PaperclipControlPlanePort implements ControlPlanePort { this.#identityRedactor = createAgentIdentityRedactor(options.privateKeyPem); this.#binding = structuredClone(binding); this.#onCommittedEvent = options.onCommittedEvent; + this.#onEventPersistence = options.onEventPersistence; + this.#onResultCommitted = options.onResultCommitted; this.#onDuplicateEvent = options.onDuplicateEvent; } @@ -217,6 +223,7 @@ export class PaperclipControlPlanePort implements ControlPlanePort { } async appendEvent(value: NativeRunEvent | PrpEvent, options?: { signal: AbortSignal }) { + const persistenceStartedAt = Date.now(), persistenceClock = performance.now(); this.#assertActive(options); if (!isPrpEvent(value)) throw new Error("native_legacy_event_not_supported"); const validated = validatePrpEvent(value); @@ -287,6 +294,7 @@ export class PaperclipControlPlanePort implements ControlPlanePort { return receipt; }); this.#assertActive(options); + try { await this.#onEventPersistence?.(event, persistenceStartedAt, persistenceStartedAt + performance.now() - persistenceClock); } catch {} if (persisted.disposition === "committed") { try { publishLiveEvent({ @@ -377,7 +385,7 @@ export class PaperclipControlPlanePort implements ControlPlanePort { canonicalSha256, }); - await this.#db.transaction(async (tx) => { + const insertedResult = await this.#db.transaction(async (tx) => { // Result insertion checks the task foreign key. Acquire that parent lock // before the run, matching task mutations that subsequently update a run. // Otherwise concurrent chat/status writes can deadlock after generation. @@ -401,7 +409,7 @@ export class PaperclipControlPlanePort implements ControlPlanePort { if (existing) { this.#assertActive(options); if (existing.canonicalSha256 !== canonicalSha256) throw new Error("structured_result_replay_conflict"); - return; + return false; } const resultJson = { result: validated.result, @@ -457,6 +465,8 @@ export class PaperclipControlPlanePort implements ControlPlanePort { updatedAt: new Date(), }).where(eq(heartbeatRuns.id, this.#binding.runId)); this.#assertActive(options); + return true; }); + if (insertedResult) { try { await this.#onResultCommitted?.(); } catch {} } } } diff --git a/server/src/services/native-runtime/paperclip-control-plane-timing.test.ts b/server/src/services/native-runtime/paperclip-control-plane-timing.test.ts new file mode 100644 index 00000000000..c1815a76b43 --- /dev/null +++ b/server/src/services/native-runtime/paperclip-control-plane-timing.test.ts @@ -0,0 +1,14 @@ +import { expect,it,vi } from "vitest"; +import { PaperclipControlPlanePort } from "./paperclip-control-plane-port.js"; +import { CONTROL_PLANE_CONFORMANCE_OPEN as OPEN,CONTROL_PLANE_CONFORMANCE_RESULT as result,CONTROL_PLANE_CONFORMANCE_TERMINAL as terminal } from "../../vendor/paperclip-runner/testing.js"; + +it.each(["inserted","replayed","failed"])("marks only a new result after transaction success (%s)",async(outcome)=>{ + let resolve!:(inserted:boolean)=>void,reject!:(error:unknown)=>void; + const transaction=vi.fn(()=>new Promise((yes,no)=>{resolve=yes;reject=no;})); + const committed=vi.fn(async()=>{}); + const port=new PaperclipControlPlanePort({transaction} as never,{...OPEN.identity,completionContractId:"fixture",completionContractSha256:"fixture",sourceInstanceId:"fixture",controlPlaneSourceInstanceId:"fixture"},{onResultCommitted:committed}); + const pending=port.completeRun({result,terminal}); + expect(transaction).toHaveBeenCalledOnce();expect(committed).not.toHaveBeenCalled(); + if(outcome === "failed"){const error=Error("transaction rejected");reject(error);await expect(pending).rejects.toBe(error);expect(committed).not.toHaveBeenCalled();} + else{resolve(outcome === "inserted");await pending;expect(committed).toHaveBeenCalledTimes(outcome === "inserted" ? 1 : 0);} +}); diff --git a/server/src/services/native-runtime/runner-operation-timing.test.ts b/server/src/services/native-runtime/runner-operation-timing.test.ts new file mode 100644 index 00000000000..7230b1f5df1 --- /dev/null +++ b/server/src/services/native-runtime/runner-operation-timing.test.ts @@ -0,0 +1,39 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +const mocks=vi.hoisted(()=>({parent:undefined as unknown, spans:[] as any[]})); +vi.mock("@opentelemetry/api",()=>({SpanStatusCode:{ERROR:2},trace:{ + getTracer:()=>({startSpan:(name:string,options:unknown,parent:unknown)=>{const span={name,options,parent,end:vi.fn(),setStatus:vi.fn()};mocks.spans.push(span);return span;}}), + setSpan:(parent:unknown,span:unknown)=>({parent,span}), +}})); +vi.mock("@paperclipai/adapter-utils/acpx-engine/startup-timing",()=>({ + getActiveStepContext:()=>mocks.parent?{parentContext:mocks.parent}:null, + runWithRuntimeParent:(_parent:unknown,work:()=>unknown)=>work(), +})); +import { measureRunnerOperation, recordRunnerTimingReceipt } from "./runner-operation-timing.js"; +afterEach(()=>{vi.unstubAllEnvs();mocks.spans=[];mocks.parent=undefined;}); +describe("Runner operation ownership",()=>{ + it("does no tracer work when disabled and preserves the operation",async()=>{ + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT","");mocks.parent={run:"a"};let count=0; + expect(await measureRunnerOperation("runner.transport.resume",async()=>++count)).toBe(1); + expect(mocks.spans).toEqual([]); + }); + it("reads each current run parent and closes concurrent failures",async()=>{ + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT","http://collector.test"); + const a={run:"a"},b={run:"b"};mocks.parent=a; + let done!:()=>void;const pending=measureRunnerOperation("runner.transport.resume",()=>new Promise(resolve=>done=resolve)); + await Promise.resolve();mocks.parent=b; + const error=Error("private");await expect(measureRunnerOperation("runner.transport.attach",async()=>{throw error;})).rejects.toBe(error); + done();await pending; + expect(mocks.spans.map(span=>span.parent)).toEqual([a,b]); + expect(mocks.spans.every(span=>span.end.mock.calls.length===1)).toBe(true); + expect(mocks.spans[1].setStatus).toHaveBeenCalledWith({code:2}); + }); + it("validates numeric receipt bounds and rejects names or content",()=>{ + vi.stubEnv("OTEL_EXPORTER_OTLP_ENDPOINT","http://collector.test");mocks.parent={run:"a"}; + recordRunnerTimingReceipt({runnerMs:100,roundTripMs:120,sidecarMs:80,statusMs:30,promptMs:40,statusOffsetMs:0,promptOffsetMs:40,secret:"private"}); + expect(mocks.spans.map(span=>span.name)).toEqual(["runner.remote.turn_start","runner.sidecar.turn_start","runner.sidecar.status_read","runner.sidecar.prompt_started"]); + expect(JSON.stringify(mocks.spans)).not.toContain("private"); + recordRunnerTimingReceipt({runnerMs:10,roundTripMs:120,sidecarMs:80,statusMs:30,promptMs:40,statusOffsetMs:0,promptOffsetMs:40}); + recordRunnerTimingReceipt({runnerMs:100,roundTripMs:120,sidecarMs:80,statusMs:NaN,promptMs:40,statusOffsetMs:0,promptOffsetMs:40}); + expect(mocks.spans).toHaveLength(4); + }); +}); diff --git a/server/src/services/native-runtime/runner-operation-timing.ts b/server/src/services/native-runtime/runner-operation-timing.ts new file mode 100644 index 00000000000..235d6b296ac --- /dev/null +++ b/server/src/services/native-runtime/runner-operation-timing.ts @@ -0,0 +1,51 @@ +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(phase: string, work: () => Promise, attributes?: Record): Promise { + const parent = getActiveStepContext()?.parentContext; + if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() || !parent || !phases.has(phase)) return work(); + let operation: Promise | 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; + 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 {} } + } +} diff --git a/server/src/services/plugin-host-services.ts b/server/src/services/plugin-host-services.ts index e6b1238e0f9..2a9a845d01a 100644 --- a/server/src/services/plugin-host-services.ts +++ b/server/src/services/plugin-host-services.ts @@ -537,6 +537,10 @@ const KNOWN_PROVIDER_SPAN_NAMES: ReadonlySet = new Set([ "postUploadCommand", "session.open", "session.close", + "plugin.worker", "plugin.host.identity.read", "plugin.host.config.read", "plugin.host.progress.read", "plugin.host.progress.write", + "plugin.workspace.prepare", "plugin.storage.queue", "plugin.storage.execute", + "plugin.runtime.queue", "plugin.runtime.prepare", "plugin.runtime.reconcile", "plugin.runtime.verify", + "plugin.remote.request", "plugin.remote.operation", "plugin.remote.lifecycle", ]); /** Clamp the span name to a closed, namespaced set. A known name maps to @@ -547,7 +551,7 @@ const KNOWN_PROVIDER_SPAN_NAMES: ReadonlySet = new Set([ * `provider` family attribute on the span instead of this literal. */ function clampProviderSpanName(raw: unknown): string { const name = typeof raw === "string" && KNOWN_PROVIDER_SPAN_NAMES.has(raw) ? raw : "other"; - return `sandbox.daytona.${name}`; + return name.startsWith("plugin.") ? name : `sandbox.daytona.${name}`; } /** The closed allowlist of attribute keys a provider span may carry. The host @@ -560,6 +564,7 @@ const PROVIDER_SPAN_ATTR_ALLOWLIST: ReadonlySet = new Set([ SPAN_ATTRS.transferWallMs, SPAN_ATTRS.transferGuardCount, SPAN_ATTRS.transferDirection, + "plugin.operation", "plugin.reused", "plugin.item_count", "plugin.bytes", "plugin.call_count", ]); /** The subset of allowed keys that carry a finite number. */ @@ -567,6 +572,7 @@ const PROVIDER_SPAN_NUMERIC_ATTRS: ReadonlySet = new Set([ SPAN_ATTRS.packWallMs, SPAN_ATTRS.transferWallMs, SPAN_ATTRS.transferGuardCount, + "plugin.item_count", "plugin.bytes", "plugin.call_count", ]); /** The closed value set for the `outcome` attribute. */ @@ -589,6 +595,11 @@ export function clampProviderSpanAttributes( if (!raw) return clamped; for (const [key, value] of Object.entries(raw)) { if (!PROVIDER_SPAN_ATTR_ALLOWLIST.has(key)) continue; + if (key === "plugin.operation") { + if (typeof value === "string" && ["request", "queue.wait", "launch.wait", "mount.refresh", "guest.setup", "process.execute", "script.workspace", "script.git", "script.settings", "script.publication", "cleanup", "process.start", "hello", "checkpoint.load"].includes(value)) clamped[key] = value; + continue; + } + if (key === "plugin.reused") { if (typeof value === "boolean") clamped[key] = value; continue; } if (key === SPAN_ATTRS.provider) { clamped[key] = normalizeProviderFamily(typeof value === "string" ? value : undefined); continue; @@ -602,7 +613,7 @@ export function clampProviderSpanAttributes( continue; } if (PROVIDER_SPAN_NUMERIC_ATTRS.has(key)) { - if (typeof value === "number" && Number.isFinite(value)) clamped[key] = value; + if (typeof value === "number" && Number.isFinite(value) && (!key.startsWith("plugin.") || value >= 0 && value <= 1e12)) clamped[key] = value; continue; } } @@ -664,12 +675,14 @@ const MAX_PROVIDER_SPAN_END_SKEW_MS = 60 * 1000; // 1 minute function validateProviderSpanTimes( startTimeMs: unknown, endTimeMs: unknown, + maxDurationMs = MAX_PROVIDER_SPAN_DURATION_MS, + maxAgeMs = MAX_PROVIDER_SPAN_START_AGE_MS, ): { startTimeMs: number; endTimeMs: number } | undefined { if (typeof startTimeMs !== "number" || !Number.isFinite(startTimeMs)) return undefined; if (typeof endTimeMs !== "number" || !Number.isFinite(endTimeMs)) return undefined; if (startTimeMs > endTimeMs) return undefined; - if (endTimeMs - startTimeMs > MAX_PROVIDER_SPAN_DURATION_MS) return undefined; - if (Date.now() - startTimeMs > MAX_PROVIDER_SPAN_START_AGE_MS) return undefined; + if (endTimeMs - startTimeMs > maxDurationMs) return undefined; + if (Date.now() - startTimeMs > maxAgeMs) return undefined; if (endTimeMs - Date.now() > MAX_PROVIDER_SPAN_END_SKEW_MS) return undefined; return { startTimeMs, endTimeMs }; } @@ -691,20 +704,40 @@ export function recordWorkerProviderSpan( status?: { code?: unknown; message?: unknown }; startTimeMs?: unknown; endTimeMs?: unknown; + children?: unknown; + relationship?: unknown; }, context: WorkerHostCallContext | undefined, ): void { const parent = parseTraceparent(context?.traceparent); if (!parent) return; // reject a missing or malformed traceparent - const times = validateProviderSpanTimes(params.startTimeMs, params.endTimeMs); - const status = clampSpanStatus(params.status); - recordProviderPluginSpan({ - name: clampProviderSpanName(params.name), - parent, - attributes: clampProviderSpanAttributes(params.attributes), - ...(status ? { status } : {}), - ...(times ? { startTimeMs: times.startTimeMs, endTimeMs: times.endTimeMs } : {}), - }); + const budget = context?.providerSpanBudget ?? {remaining:256}; + const longInvocation = params.name === "plugin.worker"; + const invocationLimitMs = 24 * 60 * 60 * 1000; + const visit = (params: { name: string; attributes?: Record; status?: { code?: unknown }; startTimeMs?: unknown; endTimeMs?: unknown; children?: unknown; relationship?: unknown }, parent: ParsedTraceparent, depth: number, enclosing?: { startTimeMs: number; endTimeMs: number }) => { + if (depth > 12 || budget.remaining-- <= 0) return; + const times = validateProviderSpanTimes(params.startTimeMs, params.endTimeMs, + depth === 0 && longInvocation ? invocationLimitMs : MAX_PROVIDER_SPAN_DURATION_MS, + longInvocation ? invocationLimitMs : MAX_PROVIDER_SPAN_START_AGE_MS); + const linked = params.relationship === "linked" && params.name === "plugin.remote.lifecycle"; + if (params.relationship !== undefined && !linked) return; + if (linked && (!times || Date.now() - times.startTimeMs > MAX_PROVIDER_SPAN_DURATION_MS)) return; + if (enclosing && (!times || (!linked && times.startTimeMs < enclosing.startTimeMs) || times.endTimeMs > enclosing.endTimeMs)) return; + const status = clampSpanStatus(params.status); + const childParent = recordProviderPluginSpan({ + name: clampProviderSpanName(params.name), + parent, + ...(linked ? { linked: true } : {}), + attributes: clampProviderSpanAttributes(params.attributes), + ...(status ? { status } : {}), + ...(times ? { startTimeMs: times.startTimeMs, endTimeMs: times.endTimeMs } : {}), + }); + if (childParent && times && Array.isArray(params.children)) for (const child of params.children.slice(0, 256)) { + if (budget.remaining <= 0) break; + if (child && typeof child === "object" && typeof child.name === "string") visit(child, childParent, depth + 1, times); + } + }; + try { visit(params, parent, 0); } catch {} } export function buildHostServices( diff --git a/server/src/services/plugin-worker-manager.ts b/server/src/services/plugin-worker-manager.ts index d932f61fd9a..b738e2e9aa9 100644 --- a/server/src/services/plugin-worker-manager.ts +++ b/server/src/services/plugin-worker-manager.ts @@ -66,6 +66,8 @@ import { type LoginCommandKey, } from "./login-command.js"; import { logger } from "../middleware/logger.js"; +import { measureRunPhase } from "./execution-preparation-timing.js"; +import { context as otelContext } from "@opentelemetry/api"; import { traceparentFromContextToken } from "../instrumentation.js"; // --------------------------------------------------------------------------- @@ -539,6 +541,7 @@ interface PendingRequest { } interface ActiveInvocation { + providerSpanBudget: {remaining:number}; scope: PluginInvocationScope; timer?: ReturnType; // The host-minted W3C `traceparent` for the active startup span, or undefined @@ -1198,20 +1201,18 @@ export function createPluginWorkerHandle( } function registerInvocation(scope: PluginInvocationScope, ttlMs?: number): PluginInvocationContext { - // Mint a W3C `traceparent` from the active startup span, so the worker's - // provider span can parent to it. The host keeps the value on its own record - // (below) and never trusts the worker to supply the parent. Outside a - // measured startup step there is no active span, so this is undefined. + // Keep the owning operation's parent host-side; workspace/runtime operations + // use the same per-invocation contract as measured provider startup. const activeStep = getActiveStepContext(); const traceparent = activeStep ? traceparentFromContextToken(activeStep.parentContext) - : undefined; + : process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim() ? traceparentFromContextToken(otelContext.active()) : undefined; const invocation: PluginInvocationContext = { id: randomUUID(), scope, ...(traceparent ? { traceparent } : {}), }; - const entry: ActiveInvocation = { scope, traceparent }; + const entry: ActiveInvocation = { scope, traceparent, providerSpanBudget:{remaining:256} }; if (ttlMs !== undefined) { entry.timer = setTimeout(() => { activeInvocations.delete(invocation.id); @@ -2746,7 +2747,7 @@ export function createPluginWorkerHandle( } const entry = activeInvocations.get(invocationId); if (!entry) return { invalidInvocationScope: true }; - return { invocationScope: entry.scope, traceparent: entry.traceparent }; + return { invocationScope: entry.scope, traceparent: entry.traceparent, providerSpanBudget:entry.providerSpanBudget }; } /** @@ -3377,6 +3378,20 @@ export function createPluginWorkerHandle( timeoutMs?: number, executeLogSink?: ExecuteLogSink, onWorkerSettled?: () => void, + ): Promise { + const dispatched = measureRunPhase("execution.plugin_dispatch", () => callInternalRaw(method, params, timeoutMs, executeLogSink, onWorkerSettled)); + // Tracing wraps the RPC in a new promise. Guard the promise handed to the + // caller as well, without swallowing its eventual rejection for that caller. + void dispatched.catch(() => undefined); + return dispatched; + } + + function callInternalRaw( + method: M, + params: HostToWorkerMethods[M][0], + timeoutMs?: number, + executeLogSink?: ExecuteLogSink, + onWorkerSettled?: () => void, ): Promise { const rpcPromise = new Promise((resolve, reject) => { const idleControl = method === "prepareIdleSleep" || method === "releaseIdleSleep";