ci(runner): trace verified ACPX launch stages

packages/paperclip-runner/runner/crates/runner-core/src/acpx_sidecar_transport.rs

@@ -277,14 +277,13 @@ impl AcpxSidecarTransport {
                         ));
                     }
                     let error = response.error.expect("failed response has validated error");
-                    return Ok(CommandOutcome::Rejected(LocalRunnerError::invalid(
-                        format!(
-                            "ACPX sidecar command {} was rejected (retryable={}, classification={})",
-                            command.as_str(),
-                            error.retryable,
-                            response_error_classification(&error),
-                        ),
-                    )));
+                    return Ok(CommandOutcome::Rejected(LocalRunnerError::invalid(format!(
+                        "ACPX sidecar command {} was rejected (retryable={}, classification={}){}",
+                        command.as_str(),
+                        error.retryable,
+                        response_error_classification(&error),
+                        self.diagnostic_suffix(),
+                    ))));
                 }
             }
         }
@@ -591,7 +590,13 @@ fn nullable_identifier(
 }
 
 fn redact_diagnostic(value: &str) -> String {
-    if value.is_empty() {
+    if value.starts_with("[paperclip-acpx-launch] ")
+        && value
+            .chars()
+            .all(|character| character.is_ascii_alphanumeric() || "[]-_ ".contains(character))
+    {
+        value.to_owned()
+    } else if value.is_empty() {
         String::new()
     } else {
         "[REDACTED]".to_owned()

packages/paperclip-runner/src/drivers/acpx/codex-runtime-adapter.ts

@@ -54,7 +54,7 @@ const activeCodexRuntimeCleanupOwners = new Set<Promise<unknown>>();
 // Provider initialization may include a cold native app-server start on a
 // minimally provisioned runner. Keep admission finite while allowing the
 // qualified runtime enough time to complete that local handshake.
-const SESSION_HANDSHAKE_TIMEOUT_MS = 30_000;
+const SESSION_HANDSHAKE_TIMEOUT_MS = 12_000;
 
 class AcpxRuntimeCloseTimeoutError extends Error {
   constructor() {
@@ -268,6 +268,13 @@ export async function openQualifiedAcpxRuntime(
         : {}),
     }),
     spawnCwd: options.cwd,
+    onAgentStderr: (chunk) => {
+      for (const line of chunk.split(/\r?\n/)) {
+        if (line.startsWith("[paperclip-acpx-launch] ")) {
+          process.stderr.write(`${line}\n`);
+        }
+      }
+    },
     spawnAgent: (input) => {
       // ACPX can invoke this callback after its handshake caller has already
       // been cancelled. Check at the last host-owned boundary so a late

packages/paperclip-runner/src/drivers/acpx/installation-integrity.ts

@@ -82,6 +82,7 @@ try {
 export const PROVIDER_LIFETIME_GUARDIAN_SOURCE = `
 const fs = require("node:fs");
 const { spawn } = require("node:child_process");
+const diagnose = (stage) => { try { fs.writeSync(2, "[paperclip-acpx-launch] " + stage + "\\n"); } catch {} };
 const WATCHDOG_SOURCE = ${JSON.stringify(PROVIDER_LIFETIME_WATCHDOG_SOURCE)};
 const runtimeExecutable = process.env.${VERIFIED_RUNTIME_EXECUTABLE_ENV} || process.execPath;
 const dependencyAncestorCount = Number.parseInt(process.argv[4], 10);
@@ -94,6 +95,7 @@ const OWNERSHIP_FD = OWNER_FD + 1;
 const PROVIDER_EXIT_FD = OWNERSHIP_FD + 1;
 const CREDENTIAL_FENCE_FD_START = PROVIDER_EXIT_FD + 1;
 const dependencyAncestorFds = Array.from({ length: dependencyAncestorCount }, (_, index) => ${DEPENDENCY_ANCESTOR_FD_START} + index);
+diagnose("guardian_started");
 let provider;
 let watchdog;
 let reaped = false;
@@ -129,6 +131,7 @@ process.on("SIGHUP", shutdown);
 const startProvider = () => {
   if (provider || reaped || shutdownStarted) return;
   try {
+    diagnose("provider_spawn_requested");
     provider = spawn(
       runtimeExecutable,
       ["--eval", process.argv[1], ...process.argv.slice(2)],
@@ -144,10 +147,11 @@ const startProvider = () => {
         windowsHide: true,
       },
     );
-    provider.once("error", reap);
-    provider.once("exit", reap);
+    provider.once("error", () => { diagnose("provider_error"); reap(); });
+    provider.once("exit", () => { diagnose("provider_exit"); reap(); });
     provider.once("spawn", () => {
       try {
+        diagnose("provider_spawned");
         if (reaped || shutdownStarted) {
           reap();
           return;
@@ -178,6 +182,7 @@ try {
     stdio: ["ignore", "ignore", "ignore", "pipe", "pipe"],
     windowsHide: true,
   });
+  diagnose("watchdog_spawned");
   const watchdogOwnerPipe = watchdog.stdio[3];
   const watchdogReady = watchdog.stdio[4];
   if (watchdogOwnerPipe == null) throw new Error("ACPX provider lifetime watchdog omitted its owner pipe");
@@ -202,6 +207,7 @@ try {
     }
     if (!watchdogOutput.includes("armed\\n")) return;
     watchdogArmed = true;
+    diagnose("watchdog_armed");
     clearTimeout(watchdogReadyTimeout);
     watchdogReady.removeAllListeners("data");
     startProvider();
@@ -1407,6 +1413,8 @@ export function sanitizedNodeEnvironment(
 function snapshotBootstrap(format: AcpxCommandFormat, guarded = false): string {
   return [
     'const fs = require("node:fs");',
+    'const diagnose = (stage) => { try { fs.writeSync(2, "[paperclip-acpx-launch] " + stage + "\\n"); } catch {} };',
+    'diagnose("bootstrap_started");',
     'const { isBuiltin, registerHooks } = require("node:module");',
     'const { dirname, extname, join, normalize, relative, resolve } = require("node:path");',
     'const { fileURLToPath, pathToFileURL } = require("node:url");',
@@ -1462,6 +1470,7 @@ function snapshotBootstrap(format: AcpxCommandFormat, guarded = false): string {
     'const canonicalizeDescriptorResolution = (url) => { if (typeof url !== "string" || !url.startsWith("file:") || snapshotDescriptorAncestorIndex(url, directoryUrl, dependencyDirectoryUrls) < 0) return url; try { return pathToFileURL(fs.realpathSync(fileURLToPath(url))).href; } catch { const error = new Error("ACPX provider module could not be canonicalized through its retained descriptor"); error.code = "ERR_ACPX_UNVERIFIED_MODULE"; throw error; } };',
     'const rememberDependencyAncestor = (specifier, resolution) => { const canonicalUrl = canonicalizeDescriptorResolution(resolution?.url); const pinned = snapshotDescriptorResolution(canonicalUrl, directoryUrl, dependencyDirectoryUrls, canonicalDirectoryUrl, canonicalDependencyDirectoryUrls); guardSnapshotModuleResolution(isBuiltin(specifier), resolution?.url, pinned !== null); if (pinned !== null && typeof resolution?.url === "string") { for (const rememberedUrl of [resolution.url, canonicalUrl, pinned.url]) { if (typeof rememberedUrl !== "string") continue; dependencyAncestorByUrl.set(rememberedUrl, pinned.ancestorIndex); if (typeof resolution.format === "string") descriptorFormatByUrl.set(rememberedUrl, resolution.format); } } return pinned === null || pinned.url === resolution?.url ? resolution : { ...resolution, url: pinned.url }; };',
     `const source = fs.readFileSync(${COMMAND_SOURCE_FD});`,
+    'diagnose("source_loaded");',
     "let resolvingDescriptorBare = false;",
     "const resolveBareFromDescriptor = (specifier, dependencyDirectoryUrl) => { resolvingDescriptorBare = true; try { return require.resolve(specifier, { paths: [fileURLToPath(dependencyDirectoryUrl)] }); } finally { resolvingDescriptorBare = false; } };",
     "registerHooks({ resolve(specifier, context, nextResolve) {",
@@ -1537,7 +1546,8 @@ function snapshotBootstrap(format: AcpxCommandFormat, guarded = false): string {
     "} finally { fs.closeSync(moduleFd); }",
     "});",
     "} });",
-    "import(target).catch((error) => { console.error(error); process.exitCode = 1; });",
+    'diagnose("import_started");',
+    'import(target).then(() => diagnose("import_resolved"), (error) => { diagnose("import_rejected"); console.error(error); process.exitCode = 1; });',
   ].join("");
 }