From b698f54966638f99e7f3a0ef56c53563da12f47a Mon Sep 17 00:00:00 2001 From: Dotta Date: Sat, 10 Oct 2026 23:38:30 -0500 Subject: [PATCH] Preserve safe ACPX admission stages on startup timeout --- .../runner-core/src/acpx_sidecar_transport.rs | 102 +++++++++++++++++- .../src/cli/acpx-runtime-sidecar.ts | 1 + .../src/drivers/acpx/runtime-host.test.ts | 39 +++++++ .../src/drivers/acpx/runtime-host.ts | 25 +++++ 4 files changed, 165 insertions(+), 2 deletions(-) diff --git a/packages/paperclip-runner/runner/crates/runner-core/src/acpx_sidecar_transport.rs b/packages/paperclip-runner/runner/crates/runner-core/src/acpx_sidecar_transport.rs index a48f5c500f7..358bd5ad290 100644 --- a/packages/paperclip-runner/runner/crates/runner-core/src/acpx_sidecar_transport.rs +++ b/packages/paperclip-runner/runner/crates/runner-core/src/acpx_sidecar_transport.rs @@ -84,6 +84,7 @@ pub struct AcpxSidecarTransport { buffered_events: VecDeque, stderr_tail: BoundedLogBuffer, stderr_categories: BTreeSet<&'static str>, + admission_diagnostic: Option<(&'static str, u64)>, poisoned: bool, } @@ -322,6 +323,7 @@ impl AcpxSidecarTransport { buffered_events: VecDeque::new(), stderr_tail: BoundedLogBuffer::new(32, 8 * 1024), stderr_categories: BTreeSet::new(), + admission_diagnostic: None, poisoned: false, }) } @@ -601,6 +603,7 @@ impl AcpxSidecarTransport { fn diagnostic_suffix(&self) -> String { let diagnostics = self.stderr_tail.snapshot().lines.join("\n"); + let admission = admission_diagnostic_suffix(self.admission_diagnostic); let categories = if self.stderr_categories.is_empty() { String::new() } else { @@ -614,15 +617,22 @@ impl AcpxSidecarTransport { ) }; if diagnostics.is_empty() { - categories + format!("{admission}{categories}") } else { - format!("{categories} stderrTail={diagnostics:?}") + format!("{admission}{categories} stderrTail={diagnostics:?}") } } fn record_stderr(&mut self, line: &str) { // Only fixed categories cross this boundary. Raw errors, stack paths, // identifiers, and credential-bearing strings remain fully redacted. + if let Some(progress) = parse_admission_diagnostic(line) { + // Cleanup can race the outer deadline; preserve the admission step + // that failed rather than replacing it with generic teardown. + if progress.0 != "cleanup" || self.admission_diagnostic.is_none() { + self.admission_diagnostic = Some(progress); + } + } self.stderr_categories .extend(stderr_diagnostic_categories(line)); self.stderr_tail.push(redact_diagnostic(line)); @@ -787,6 +797,40 @@ fn nullable_identifier( Ok(Some(value.to_owned())) } +// Reuse the sidecar's diagnostic channel, retaining only a closed stage and +// bounded integer. Unknown lines remain fully redacted and never grant authority. +fn parse_admission_diagnostic(line: &str) -> Option<(&'static str, u64)> { + let (stage, elapsed) = line + .strip_prefix("[paperclip-acpx-sidecar] admission_")? + .split_once(": elapsedMs=")?; + let stage = match stage { + "binding" => "binding", + "installation" => "installation", + "sandbox" => "sandbox", + "lifetime" => "lifetime", + "agent_files" => "agent_files", + "skills" => "skills", + "command" => "command", + "tool_bridge" => "tool_bridge", + "handshake" => "handshake", + "verification" => "verification", + "ready" => "ready", + "cleanup" => "cleanup", + _ => return None, + }; + if elapsed.is_empty() || !elapsed.bytes().all(|byte| byte.is_ascii_digit()) { + return None; + } + let elapsed = elapsed.parse::().ok()?; + (elapsed <= 3_600_000).then_some((stage, elapsed)) +} + +fn admission_diagnostic_suffix(progress: Option<(&'static str, u64)>) -> String { + progress.map_or_else(String::new, |(stage, elapsed)| { + format!(" admissionStage={stage} admissionElapsedMs={elapsed}") + }) +} + fn redact_diagnostic(value: &str) -> String { if value.is_empty() { String::new() @@ -991,6 +1035,60 @@ fn response_error_classification(error: &ResponseError) -> &'static str { #[cfg(test)] mod tests { + #[test] + fn admission_diagnostics_accept_only_closed_stages_and_bounded_integer_timing() { + assert_eq!( + parse_admission_diagnostic( + "[paperclip-acpx-sidecar] admission_handshake: elapsedMs=321" + ), + Some(("handshake", 321)) + ); + for line in [ + "[paperclip-acpx-sidecar] admission_private-path: elapsedMs=321", + "[paperclip-acpx-sidecar] admission_handshake: elapsedMs=321 private-token", + "[paperclip-acpx-sidecar] admission_handshake: elapsedMs=-1", + "[paperclip-acpx-sidecar] admission_handshake: elapsedMs=NaN", + "[paperclip-acpx-sidecar] admission_handshake: elapsedMs=3600001", + "[paperclip-acpx-sidecar] admission_handshake: elapsedMs=18446744073709551616", + "private-prefix [paperclip-acpx-sidecar] admission_handshake: elapsedMs=321", + ] { + assert_eq!(parse_admission_diagnostic(line), None); + } + } + + #[cfg(unix)] + #[test] + fn admission_timeout_retains_last_safe_stage_without_untrusted_stderr() { + let config = AcpxSidecarTransportConfig { + command: PathBuf::from("/bin/sh"), + args: vec!["-c".into(), "printf '%s\\n' '[paperclip-acpx-sidecar] admission_sandbox: elapsedMs=1' '[paperclip-acpx-sidecar] admission_handshake: elapsedMs=24' '[paperclip-acpx-sidecar] admission_handshake: elapsedMs=25 /private/token-canary' '[paperclip-acpx-sidecar] admission_cleanup: elapsedMs=26' >&2; sleep 2".into()], + verified_launch: None, + request_timeout: Duration::from_millis(200), + shutdown_grace: Duration::from_millis(10), + }; + let mut transport = AcpxSidecarTransport::start(&config).unwrap(); + let error = transport + .request(GeneratedAcpxSidecarCommand::SessionOpen, json!({})) + .err() + .unwrap() + .to_string(); + assert!( + error.contains("request timed out at session.open"), + "{error}" + ); + assert!( + error.contains("admissionStage=handshake admissionElapsedMs=24"), + "{error}" + ); + assert!( + !error.contains("private") && !error.contains("token-canary"), + "{error}" + ); + assert!(transport + .request(GeneratedAcpxSidecarCommand::SessionOpen, json!({})) + .is_err()); + } + #[test] fn pi_credentials_require_a_bounded_binding_without_process_control_variables() { assert!(pi_credential_environment_keys(None).unwrap().is_empty()); diff --git a/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts b/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts index 63fc827217a..2580585bf6a 100644 --- a/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts +++ b/packages/paperclip-runner/src/cli/acpx-runtime-sidecar.ts @@ -315,6 +315,7 @@ async function dispatch( }, { retainAdmissionCleanup: retainFailedAdmissionCleanup, + onAdmissionStage: (stage, elapsedMs) => diagnostic(`admission_${stage}`, `elapsedMs=${elapsedMs}`), reportRetainedCleanupFailure: reportRetainedAcpxCleanupFailure, openRuntime: (options) => openCodexAcpxRuntime(options, { diff --git a/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts b/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts index e83681f749d..582dedb5175 100644 --- a/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts +++ b/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts @@ -201,6 +201,45 @@ afterEach(async () => { }); describe("ACPX runtime host", () => { + it.each(["throw", "reject"] as const)("keeps admission diagnostics observational when the observer can %s", async (failure) => { + const fixture = await hostFixture(); + const port = runtimePort({ getStatus: async () => ({ models: { currentModelId: "claude-sonnet-5" } }) }); + const gate = deferred(); + const stages: Array<{ stage: string; elapsedMs: number }> = []; + const openRuntime = vi.fn(() => gate.promise); + const opening = trackAdmissionOpening(AcpxRuntimeHost.open({ + ...fixture.options, agent: "claude", model: "claude-sonnet-5", + semanticTools: { tools: [], handler: async () => ({}) }, + }, { + ...fixture.dependencies({ openRuntime }), + onAdmissionStage: (stage, elapsedMs) => { + stages.push({ stage, elapsedMs }); + if (failure === "throw") throw new Error("private-observer-canary"); + return Promise.reject(new Error("private-observer-canary")); + }, + })); + try { + await vi.waitFor(() => expect(openRuntime).toHaveBeenCalledOnce()); + expect(stages.at(-1)?.stage).toBe("handshake"); + } finally { + gate.resolve(port); + } + const host = await opening; + expect(stages.map(({ stage }) => stage)).toEqual([ + "binding", "installation", "sandbox", "lifetime", "agent_files", "skills", + "command", "tool_bridge", "handshake", "verification", "ready", + ]); + for (const [index, { elapsedMs }] of stages.entries()) { + expect(Number.isInteger(elapsedMs)).toBe(true); + expect(elapsedMs).toBeGreaterThanOrEqual(stages[index - 1]?.elapsedMs ?? 0); + expect(elapsedMs).toBeLessThanOrEqual(3_600_000); + } + expect(host.identity().acpxRecordId).toBe("record-1"); + await host.close({ reason: "diagnostic observer test complete" }); + expect(port.close).toHaveBeenCalledOnce(); + expect(fixture.commandClose).toHaveBeenCalledOnce(); + }); + it.each([undefined, "plan", "ask"] as const)("requires observed Cursor mode %s in the host identity", async selected => { const fixture = await hostFixture(); const mode = selected ?? "agent"; diff --git a/packages/paperclip-runner/src/drivers/acpx/runtime-host.ts b/packages/paperclip-runner/src/drivers/acpx/runtime-host.ts index 22836bb95f6..f2b1ab14156 100644 --- a/packages/paperclip-runner/src/drivers/acpx/runtime-host.ts +++ b/packages/paperclip-runner/src/drivers/acpx/runtime-host.ts @@ -199,7 +199,12 @@ export interface AcpxRetainedCleanupFailure { error: unknown; } +export type AcpxAdmissionStage = "binding" | "installation" | "sandbox" | "lifetime" + | "agent_files" | "skills" | "command" | "tool_bridge" | "handshake" | "verification" | "ready" | "cleanup"; + export interface AcpxRuntimeHostDependencies { + /** Closed diagnostic progress only; observer failures cannot affect ownership. */ + onAdmissionStage?: (stage: AcpxAdmissionStage, elapsedMs: number) => void; verifyInstallation?: ( profile: QualifiedAcpxProfile, ) => Promise; @@ -325,6 +330,15 @@ export class AcpxRuntimeHost { options: OpenAcpxRuntimeHostOptions, dependencies: AcpxRuntimeHostDependencies, ): Promise { + const admissionStarted = performance.now(); + const reportStage = (stage: AcpxAdmissionStage): void => { + try { + void Promise.resolve(dependencies.onAdmissionStage?.(stage, + Math.max(0, Math.min(3_600_000, Math.round(performance.now() - admissionStarted))), + )).catch(() => undefined); + } catch { /* Diagnostics never own admission or cleanup. */ } + }; + reportStage("binding"); options.signal?.throwIfAborted(); if (options.agent === "pi" && typeof options.providerPolicy?.readOnly !== "boolean") { throw new Error("Pi admission requires an explicit task execution policy"); @@ -368,6 +382,7 @@ export class AcpxRuntimeHost { ); } + reportStage("installation"); const installation = await runAbortableAdmissionStage( options.signal, () => @@ -422,6 +437,7 @@ export class AcpxRuntimeHost { retainRuntimeHostCleanup(ownedCleanup); }; try { + reportStage("sandbox"); const sandbox = await runAbortableAdmissionStage( options.signal, () => @@ -443,6 +459,7 @@ export class AcpxRuntimeHost { }), dependencies.retainAdmissionCleanup, ); + reportStage("lifetime"); if (options.agent === "codex") { credential = await acquireAbortableAdmissionResource({ signal: options.signal, @@ -483,6 +500,7 @@ export class AcpxRuntimeHost { // agent and run. Environment/config values cannot widen the grant. Each // resumed process receives the newly registered copy; collection already // requires verified provider shutdown in the native executor. + reportStage("agent_files"); const agentFiles = options.runtimeContext?.persistentAgentHome || ["cursor", "copilot", "pi"].includes(options.agent) ? bindAcpxAgentFiles(options.runtimeContext, [sandbox.root, ...(installation.agentServerPackageJsonPath === null ? [] : [dirname(installation.agentServerPackageJsonPath)]), @@ -522,6 +540,7 @@ export class AcpxRuntimeHost { PAPERCLIP_PI_READ_ROOTS: JSON.stringify([...(options.providerPolicy?.readRoots ?? []), ...skills.readRoots]), }); } + reportStage("skills"); if (options.agent === "claude" || options.agent === "grok") { // The lifetime lease proves the previous provider has stopped. Refresh // the assigned snapshot before every launch, including durable resume; @@ -534,6 +553,7 @@ export class AcpxRuntimeHost { ); options.signal?.throwIfAborted(); } + reportStage("command"); command = await acquireAbortableAdmissionResource({ signal: options.signal, acquire: () => installation.openCommand({ signal: options.signal }), @@ -547,6 +567,7 @@ export class AcpxRuntimeHost { signal => installation.openCommand({ signal }), ); command = commandOwner.command; + reportStage("tool_bridge"); toolBridge = options.semanticTools ? await acquireAbortableAdmissionResource({ signal: options.signal, @@ -561,6 +582,7 @@ export class AcpxRuntimeHost { if (admittedLifetime === null) { throw new Error("ACPX provider lifetime lease is unavailable"); } + reportStage("handshake"); runtime = await acquireAbortableAdmissionResource({ signal: options.signal, acquire: async () => { @@ -628,6 +650,7 @@ export class AcpxRuntimeHost { }); }, }); + reportStage("verification"); const runtimeIdentity = await runAbortableAdmissionStage( options.signal, () => @@ -661,6 +684,7 @@ export class AcpxRuntimeHost { verifyExpectedAcpxIdentity(options.expectedIdentity, binding, identity); } options.signal?.throwIfAborted(); + reportStage("ready"); admissionSucceeded = true; return new AcpxRuntimeHost({ runtime, @@ -676,6 +700,7 @@ export class AcpxRuntimeHost { : [], }); } catch (error) { + reportStage("cleanup"); error = classifyAcpxProfileError(options.agent, error) ?? error; const cleanup = cleanupRuntimeResources( runtime,