diff --git a/CLI/CMUXCLI+PiExtensionSource.swift b/CLI/CMUXCLI+PiExtensionSource.swift index 5f280136c4a..23a257c3c94 100644 --- a/CLI/CMUXCLI+PiExtensionSource.swift +++ b/CLI/CMUXCLI+PiExtensionSource.swift @@ -1,6 +1,7 @@ extension CMUXCLI { static let piExtensionSource = [ piExtensionSourcePart1, + piExtensionSourceDiagnostics, piExtensionSourceDispatch, piExtensionSourcePart2, ].joined(separator: "\n") diff --git a/CLI/CMUXCLI+PiExtensionSourceDiagnostics.swift b/CLI/CMUXCLI+PiExtensionSourceDiagnostics.swift new file mode 100644 index 00000000000..34fa9bd64f3 --- /dev/null +++ b/CLI/CMUXCLI+PiExtensionSourceDiagnostics.swift @@ -0,0 +1,221 @@ +extension CMUXCLI { + static let piExtensionSourceDiagnostics = #""" +type CommandFailureReason = "timeout" | "nonzero-exit" | "spawn-error" | "cancelled"; +type CommandTerminationReason = "timeout" | "cancelled"; + +// Loaded repositories have produced successful 9s+ lifecycle hooks. Leave +// headroom above that observed tail without allowing a stuck child to block a +// session's serialized control queue indefinitely. +const defaultPiHookTimeoutMilliseconds = 15_000; +const maximumPiHookTimeoutMilliseconds = 60_000; +// Feed's CLI owns a four-second end-to-end deadline. Give the wrapper enough +// headroom that the child reports that outcome itself instead of being killed +// mid-deadline, while lifecycle tuning still cannot pin the shared Feed pool. +const maximumPiFeedCommandTimeoutMilliseconds = 4_500; +// Diagnostics are best effort and may hold a serialized hook queue only briefly. +const piHookDiagnosticWriteDeadlineMilliseconds = 100; + +function piHookTimeoutMilliseconds( + rawValue: string | undefined = process.env.CMUX_PI_HOOK_TIMEOUT_MS, +): number { + const normalized = rawValue?.trim(); + if (!normalized || !/^\d+$/.test(normalized)) return defaultPiHookTimeoutMilliseconds; + const parsed = Number(normalized); + if (parsed >= maximumPiHookTimeoutMilliseconds) return maximumPiHookTimeoutMilliseconds; + return Number.isSafeInteger(parsed) && parsed > 0 ? parsed : defaultPiHookTimeoutMilliseconds; +} + +function piCommandTimeoutMilliseconds( + args: string[], + rawValue: string | undefined = process.env.CMUX_PI_HOOK_TIMEOUT_MS, +): number { + const configured = piHookTimeoutMilliseconds(rawValue); + return args[0] === "hooks" && args[1] === "feed" + ? Math.min(configured, maximumPiFeedCommandTimeoutMilliseconds) + : configured; +} + +function commandFailureReason( + status: number | null, + error: unknown, + terminationReason?: CommandTerminationReason, +): CommandFailureReason | undefined { + if (terminationReason) return terminationReason; + if (status === 0) return undefined; + if (status !== null && status !== 0) return "nonzero-exit"; + return "spawn-error"; +} + +function boundedPiHookName(value: string): string { + return utf8Prefix(value, 128) || "unknown"; +} + +function piHookName(args: string[]): string { + if (args[0] === "hooks" && args[1] === "pi") { + return boundedPiHookName(firstString(args[2]) || "unknown"); + } + if (args[0] === "hooks" && args[1] === "feed") { + const eventIndex = args.indexOf("--event"); + const eventName = eventIndex >= 0 ? firstString(args[eventIndex + 1]) : null; + return boundedPiHookName(eventName ? `feed:${eventName}` : "feed"); + } + if (args[0] === "--json" && args[1] === "surface" && args[2] === "resume") { + return boundedPiHookName(`surface-resume-${firstString(args[3]) || "unknown"}`); + } + return "cmux-command"; +} + +function expandedPiHookLogPath(value: string, home: string | undefined = process.env.HOME): string { + if (value === "~") return home || value; + if (value.startsWith("~/") && home) { + return path.join(home, value.slice(2)); + } + return value; +} + +function isOwnedRegularPiHookFile(metadata: fs.Stats): boolean { + return metadata.isFile() + && typeof process.getuid === "function" + && metadata.uid === process.getuid(); +} + +let activePiHookDiagnosticWrite: Promise | undefined; + +async function runPiHookDiagnosticWrite(operation: () => Promise): Promise { + // Retain at most one file operation. If it stalls after the caller's deadline, + // later diagnostics are dropped instead of accumulating promises or handles. + if (activePiHookDiagnosticWrite) return; + let tracked: Promise; + tracked = Promise.resolve() + .then(operation) + .catch(() => {}) + .finally(() => { + if (activePiHookDiagnosticWrite === tracked) activePiHookDiagnosticWrite = undefined; + }); + activePiHookDiagnosticWrite = tracked; + + let deadline: ReturnType | undefined; + try { + await Promise.race([ + tracked, + new Promise((resolve) => { + deadline = setTimeout(resolve, piHookDiagnosticWriteDeadlineMilliseconds); + }), + ]); + } finally { + if (deadline !== undefined) clearTimeout(deadline); + } +} + +function piHookDiagnosticPath( + environment: Record = process.env, + lastDebugLogPathFile = "/tmp/cmux-last-debug-log-path", + fallbackLogPath = "/tmp/cmux-debug.log", +): string { + const explicit = firstString(environment.CMUX_DEBUG_LOG); + if (explicit) return expandedPiHookLogPath(explicit, environment.HOME); + + const socketPath = firstString(environment.CMUX_SOCKET_PATH, environment.CMUX_SOCKET); + if (socketPath) { + const socketName = path.basename(socketPath); + if (socketName.startsWith("cmux-debug-") && socketName.endsWith(".sock")) { + return path.join("/tmp", `${socketName.slice(0, -".sock".length)}.log`); + } + } + + let pointerDescriptor: number | undefined; + try { + // The shared pointer is untrusted: inspect a nonblocking descriptor and + // bound the read so a special or oversized file cannot stall Pi. + pointerDescriptor = fs.openSync( + lastDebugLogPathFile, + fs.constants.O_RDONLY | fs.constants.O_NONBLOCK | fs.constants.O_NOFOLLOW, + ); + if (isOwnedRegularPiHookFile(fs.fstatSync(pointerDescriptor))) { + const pointerContents = Buffer.alloc(4096); + const bytesRead = fs.readSync( + pointerDescriptor, + pointerContents, + 0, + pointerContents.byteLength, + 0, + ); + const lastPath = firstString(pointerContents.subarray(0, bytesRead).toString("utf8")); + if (lastPath) return expandedPiHookLogPath(lastPath, environment.HOME); + } + } catch (_) { + } finally { + if (pointerDescriptor !== undefined) { + try { fs.closeSync(pointerDescriptor); } catch (_) {} + } + } + return fallbackLogPath; +} + +async function appendPiHookDiagnostic( + payload: Record, + environment: Record = process.env, + lastDebugLogPathFile = "/tmp/cmux-last-debug-log-path", + fallbackLogPath = "/tmp/cmux-debug.log", +): Promise { + let line: string; + try { + line = JSON.stringify({ timestamp: new Date().toISOString(), ...payload }); + } catch (_) { + line = JSON.stringify({ + timestamp: new Date().toISOString(), + source: "cmux-pi-extension", + level: "warning", + message: "failed to serialize Pi hook diagnostic", + hook_name: "extension", + reason: "serialization-error", + timeout_ms: piHookTimeoutMilliseconds(), + elapsed_ms: 0, + }); + } + try { + // Read/write permits checking the existing JSONL boundary, while O_NONBLOCK + // keeps special files such as a FIFO from stalling Pi's lifecycle queue. + const flags = fs.constants.O_RDWR + | fs.constants.O_APPEND + | fs.constants.O_CREAT + | fs.constants.O_NONBLOCK + | fs.constants.O_NOFOLLOW; + const handle = await fs.promises.open( + piHookDiagnosticPath(environment, lastDebugLogPathFile, fallbackLogPath), + flags, + 0o600, + ); + try { + const metadata = await handle.stat(); + // cmux diagnostics are files; drop device, socket, and pipe destinations. + if (!isOwnedRegularPiHookFile(metadata)) return; + let prefix = ""; + if (metadata.size > 0) { + const trailingByte = Buffer.alloc(1); + const { bytesRead } = await handle.read(trailingByte, 0, 1, metadata.size - 1); + if (bytesRead !== 1 || trailingByte[0] !== 0x0a) prefix = "\n"; + } + await handle.writeFile(`${prefix}${line}\n`, "utf8"); + } finally { + try { await handle.close(); } catch (_) {} + } + } catch (_) {} +} + +function commandFailureDetails( + args: string[], + result: CommandResult, +): Record { + return { + hook_name: piHookName(args), + reason: result.reason || commandFailureReason(result.status, result.error) || "spawn-error", + timeout_ms: result.timeoutMs, + elapsed_ms: result.elapsedMs, + status: result.status, + stderr_available: result.stderr.trim().length > 0, + error_available: result.error !== undefined, + }; +} +"""# +} diff --git a/CLI/CMUXCLI+PiExtensionSourceDispatch.swift b/CLI/CMUXCLI+PiExtensionSourceDispatch.swift index 4605324fc10..b6ba66c939a 100644 --- a/CLI/CMUXCLI+PiExtensionSourceDispatch.swift +++ b/CLI/CMUXCLI+PiExtensionSourceDispatch.swift @@ -335,7 +335,7 @@ class PiCmuxCommandDispatcher { this.failTerminalFeedForSession(sessionId); this.discardFeedForSession(sessionId); } - } else if (result.error instanceof Error && result.error.message.includes("timed out after")) { + } else if (result.reason === "timeout") { const sessionId = command.context.sessionId; if (sessionId) { this.failTerminalFeedForSession(sessionId); @@ -367,18 +367,20 @@ class PiCmuxCommandDispatcher { } const result = await this.spawnCmux(args, cwd, input, cancellation); - if (this.isSurfaceResolutionFailure(result)) { - const shouldWarn = !sessionId || !this.unavailableSessions.has(sessionId); - if (sessionId) this.unavailableSessions.add(sessionId); - if (shouldWarn) { - warn(context, "cmux hook command failed", { - status: result.status, - stderr_available: result.stderr.trim().length > 0, - error_available: result.error !== undefined, - surface_unavailable: true, - dispatch_disabled: true, - }); - } + const surfaceUnavailable = this.isSurfaceResolutionFailure(result); + let shouldLogFailure = true; + if (surfaceUnavailable && sessionId) { + // Claim synchronously so overlapping Feed/control failures emit one diagnostic. + shouldLogFailure = !this.unavailableSessions.has(sessionId); + this.unavailableSessions.add(sessionId); + } + if (!result.ok && result.reason !== "cancelled" && shouldLogFailure) { + await warn(context, "cmux hook command failed", { + ...commandFailureDetails(args, result), + ...(surfaceUnavailable ? { surface_unavailable: true, dispatch_disabled: true } : {}), + }); + } + if (surfaceUnavailable) { return { ...result, surfaceUnavailable: true }; } return result; @@ -391,6 +393,8 @@ class PiCmuxCommandDispatcher { cancellation?: PiCommandCancellation, ): Promise { return new Promise((resolve) => { + const startedAt = performance.now(); + const timeoutMs = piCommandTimeoutMilliseconds(args); let settled = false; let stdout = ""; let stderr = ""; @@ -399,6 +403,7 @@ class PiCmuxCommandDispatcher { let terminateGrace: ReturnType | null = null; let forceSettleTimeout: ReturnType | null = null; let terminationError: Error | undefined; + let terminationReason: CommandTerminationReason | undefined; const appendOutput = (current: string, chunk: unknown): string => { const limit = 1024 * 1024; @@ -414,12 +419,18 @@ class PiCmuxCommandDispatcher { if (cancellation) cancellation.cancel = undefined; resolve(result); }; + const elapsedMilliseconds = (): number => ( + Math.max(0, Math.round(performance.now() - startedAt)) + ); const terminatedResult = (): CommandResult => ({ ok: false, status: null, stdout, stderr, error: terminationError, + reason: commandFailureReason(null, terminationError, terminationReason), + timeoutMs, + elapsedMs: elapsedMilliseconds(), }); try { @@ -438,9 +449,10 @@ class PiCmuxCommandDispatcher { child.stdin.on("error", (error) => { inputError = error; }); - const beginTermination = (error: Error) => { + const beginTermination = (reason: CommandTerminationReason, error: Error) => { if (terminationError) return; terminationError = error; + terminationReason = reason; child.stdin.destroy(); try { child.kill("SIGTERM"); @@ -458,7 +470,16 @@ class PiCmuxCommandDispatcher { }, 250); }; child.on("error", (error) => { - settle(terminationError ? terminatedResult() : { ok: false, status: null, stdout, stderr, error }); + settle(terminationError ? terminatedResult() : { + ok: false, + status: null, + stdout, + stderr, + error, + reason: commandFailureReason(null, error), + timeoutMs, + elapsedMs: elapsedMilliseconds(), + }); }); child.on("close", (code) => { if (terminationError) { @@ -466,24 +487,38 @@ class PiCmuxCommandDispatcher { return; } const status = typeof code === "number" ? code : null; + const error = inputError; + const reason = commandFailureReason(status, error); settle({ - ok: status === 0 && inputError === undefined, + ok: reason === undefined, status, stdout, stderr, - error: inputError, + error, + reason, + timeoutMs, + elapsedMs: elapsedMilliseconds(), }); }); if (cancellation) { - cancellation.cancel = () => beginTermination(new Error("cmux feed command cancelled")); + cancellation.cancel = () => beginTermination("cancelled", new Error("cmux feed command cancelled")); if (cancellation.cancelled) cancellation.cancel(); } timeout = setTimeout(() => { - beginTermination(new Error("cmux command timed out after 5000ms")); - }, 5000); + beginTermination("timeout", new Error(`cmux command timed out after ${timeoutMs}ms`)); + }, timeoutMs); child.stdin.end(input); } catch (error) { - settle({ ok: false, status: null, stdout, stderr, error }); + settle({ + ok: false, + status: null, + stdout, + stderr, + error, + reason: commandFailureReason(null, error), + timeoutMs, + elapsedMs: elapsedMilliseconds(), + }); } }); } @@ -498,6 +533,8 @@ class PiCmuxCommandDispatcher { status: null, stdout: "", stderr: "", + timeoutMs: piHookTimeoutMilliseconds(), + elapsedMs: 0, surfaceUnavailable: true, }; } diff --git a/CLI/CMUXCLI+PiExtensionSourcePart1.swift b/CLI/CMUXCLI+PiExtensionSourcePart1.swift index 49bc16915af..2ceb0b4a83a 100644 --- a/CLI/CMUXCLI+PiExtensionSourcePart1.swift +++ b/CLI/CMUXCLI+PiExtensionSourcePart1.swift @@ -1,6 +1,6 @@ extension CMUXCLI { static let piExtensionSourcePart1 = #""" -// cmux-pi-session-extension-marker v2 +// cmux-pi-session-extension-marker v3 // Bridges Pi session lifecycle, tool telemetry, notifications, and resume bindings into cmux. // Installed by `cmux hooks pi install` or `cmux hooks setup`. // DO NOT EDIT MANUALLY. cmux upgrades this file in place. @@ -34,13 +34,15 @@ interface CommandResult { stdout: string; stderr: string; error?: unknown; + reason?: CommandFailureReason; + timeoutMs: number; + elapsedMs: number; surfaceUnavailable?: boolean; } interface PiExtensionContextSnapshot { readonly sessionId: string | null; readonly cwd: string; - readonly notifyWarning?: () => void; } function firstString(...values: unknown[]): string | null { @@ -348,6 +350,7 @@ function safeCmuxEnvKey(key: string): boolean { if (key.startsWith("CMUX_AGENT_LAUNCH_")) return !secretLikeEnvKey(key); if (key === "CMUX_AGENT_HOOK_STATE_DIR") return true; if (key === "CMUX_PI_CMUX_BIN" || key === "CMUX_PI_HOOKS_DISABLED") return true; + if (key === "CMUX_PI_HOOK_TIMEOUT_MS") return true; if (key === "CMUX_SURFACE_ID" || key === "CMUX_WORKSPACE_ID" || key === "CMUX_WINDOW_ID") return true; if (key === "CMUX_PANE_ID" || key === "CMUX_TAB_ID" || key === "CMUX_PANEL_ID") return true; if (key === "CMUX_SOCKET" || key === "CMUX_SOCKET_PATH") return true; @@ -460,17 +463,9 @@ function cwdFrom(ctx: ExtensionContext): string { } function snapshotContext(ctx: ExtensionContext): PiExtensionContextSnapshot { - let notifyWarning: (() => void) | undefined; - try { - const ui = (ctx as unknown as { ui?: { notify?: (message: string, type?: string) => void } }).ui; - if (typeof ui?.notify === "function") { - notifyWarning = () => ui.notify?.("cmux Pi integration warning - check the terminal for details", "warning"); - } - } catch (_) {} return { sessionId: sessionIdFrom(ctx), cwd: cwdFrom(ctx), - notifyWarning, }; } @@ -528,26 +523,20 @@ function settleTurn(sessionStates: Map, sessionId: string) return completion; } -function warn( - ctx: PiExtensionContextSnapshot | null, +async function warn( + _ctx: PiExtensionContextSnapshot | null, message: string, details: Record = {}, - notifyUser = false, -): void { - const payload = { source: "cmux-pi-extension", level: "warning", message, ...details }; - try { - console.warn(JSON.stringify(payload)); - } catch (_) { - console.warn(`[cmux-pi-extension] ${message}`); - } - // Hook transport is best-effort telemetry. Keep routine command failures in - // the terminal instead of interrupting Pi with a generic toast; reserve the - // UI warning for an unexpected extension-task exception. - if (notifyUser) { - try { - ctx?.notifyWarning?.(); - } catch (_) {} - } +): Promise { + const payload = { + source: "cmux-pi-extension", + level: "warning", + message, + hook_name: "extension", + reason: "extension-error", + ...details, + }; + await runPiHookDiagnosticWrite(() => appendPiHookDiagnostic(payload)); } function cmuxExecutable(): string { diff --git a/CLI/CMUXCLI+PiExtensionSourcePart2.swift b/CLI/CMUXCLI+PiExtensionSourcePart2.swift index 30ff202787f..bbdd76798a5 100644 --- a/CLI/CMUXCLI+PiExtensionSourcePart2.swift +++ b/CLI/CMUXCLI+PiExtensionSourcePart2.swift @@ -27,14 +27,6 @@ async function sendHook( context, ); if (result.ok) rememberSurfaceTarget(dispatcher, sessionId, result); - if (!result.ok && !result.surfaceUnavailable) { - warn(context, "cmux hook command failed", { - subcommand, - status: result.status, - stderr_available: result.stderr.trim().length > 0, - error_available: result.error !== undefined, - }); - } return result.ok; } @@ -206,14 +198,7 @@ async function ensureResumeBinding( "--", ...resumeArgv, ], cwd, undefined, context); - if (!set.ok && !set.surfaceUnavailable) { - warn(context, "failed to set Pi resume binding", { - status: set.status, - stderr_available: set.stderr.trim().length > 0, - error_available: set.error !== undefined, - }); - return; - } + if (!set.ok && !set.surfaceUnavailable) return; if (set.surfaceUnavailable) return; const verification = await dispatcher.run( @@ -225,7 +210,11 @@ async function ensureResumeBinding( if (verification.surfaceUnavailable) return; const verified = parseJSONOutput(verification); if (!resumeBindingMatches(verified, sessionId)) { - warn(context, "Pi resume binding did not verify after write", { session_id: sessionId }); + await warn(context, "Pi resume binding did not verify after write", { + session_id: sessionId, + hook_name: "surface-resume-get", + reason: "verification-failure", + }); } } @@ -238,7 +227,7 @@ async function clearResumeBinding( const target = surfaceTargetArgs(dispatcher, sessionId); if (!target) return; const cwd = context.cwd; - const result = await dispatcher.run([ + await dispatcher.run([ "--json", "surface", "resume", @@ -249,14 +238,6 @@ async function clearResumeBinding( "--source", "agent-hook", ], cwd, undefined, context); - if (result.surfaceUnavailable) return; - if (!result.ok) { - warn(context, "failed to clear Pi resume binding", { - status: result.status, - stderr_available: result.stderr.trim().length > 0, - error_available: result.error !== undefined, - }); - } } type PiFeedEventName = @@ -341,6 +322,17 @@ function prepareFeedDispatch( }; } +async function warnFeedDeliveryDropped( + context: PiExtensionContextSnapshot, + sessionId: string, +): Promise { + await warn(context, "cmux feed delivery dropped", { + session_id: sessionId, + hook_name: "feed", + reason: "dispatch-dropped", + }); +} + async function publishPendingCompletion( dispatcher: PiCmuxCommandDispatcher, sessionStates: Map, @@ -352,9 +344,7 @@ async function publishPendingCompletion( const state = stateFor(sessionStates, sessionId); const feedDelivered = !state.feedDeliveryFailed; state.feedDeliveryFailed = false; - if (!feedDelivered) { - warn(context, "cmux hook command failed", { session_id: sessionId }); - } + if (!feedDelivered) await warnFeedDeliveryDropped(context, sessionId); const stopPayload: HookExtra = { last_assistant_message: completion.lastAssistantMessage, turn_id: completion.turnId, @@ -374,34 +364,77 @@ async function publishPendingCompletion( await sendHook(dispatcher, "stop", context, stopPayload); } -export default function cmuxPiSessionExtension(pi: ExtensionAPI) { - const dispatcher = new PiCmuxCommandDispatcher(); - const sessionStates = new Map(); - const lifecycleTails = new Map>(); +// A stalled lifecycle hook may run for its full configured timeout while Pi +// keeps emitting tool events. Bound the pending tasks a session can stack +// behind it so bursts cannot pin unbounded event payloads: droppable Feed +// preparation is shed first and surfaces as a dropped delivery at completion. +const maximumPiLifecycleBacklogTasks = 32; - const enqueueLifecycleTask = ( +interface PiLifecycleQueue { + enqueue( + sessionId: string, + context: PiExtensionContextSnapshot, + operation: () => Promise | unknown, + ): Promise; + tryEnqueue( + sessionId: string, + context: PiExtensionContextSnapshot, + operation: () => Promise | unknown, + ): boolean; +} + +function createPiLifecycleQueue(): PiLifecycleQueue { + const tails = new Map>(); + const pendingCounts = new Map(); + const enqueue = ( sessionId: string, context: PiExtensionContextSnapshot, operation: () => Promise | unknown, ): Promise => { - const previous = lifecycleTails.get(sessionId) || Promise.resolve(); + pendingCounts.set(sessionId, (pendingCounts.get(sessionId) || 0) + 1); + const previous = tails.get(sessionId) || Promise.resolve(); let tracked: Promise; tracked = previous .then(operation) .then(() => undefined) .catch((error) => { const errorMessage = error instanceof Error ? error.message : undefined; - warn(context, "cmux lifecycle task failed", { + return warn(context, "cmux lifecycle task failed", { + hook_name: "lifecycle-task", + reason: "extension-error", error_available: error !== undefined, error_message: utf8Prefix(errorMessage, 512), - }, true); + }); }) .finally(() => { - if (lifecycleTails.get(sessionId) === tracked) lifecycleTails.delete(sessionId); + const remaining = (pendingCounts.get(sessionId) || 1) - 1; + if (remaining > 0) pendingCounts.set(sessionId, remaining); + else pendingCounts.delete(sessionId); + if (tails.get(sessionId) === tracked) tails.delete(sessionId); }); - lifecycleTails.set(sessionId, tracked); + tails.set(sessionId, tracked); return tracked; }; + return { + enqueue, + tryEnqueue(sessionId, context, operation) { + if ((pendingCounts.get(sessionId) || 0) >= maximumPiLifecycleBacklogTasks) return false; + void enqueue(sessionId, context, operation); + return true; + }, + }; +} + +export default function cmuxPiSessionExtension(pi: ExtensionAPI) { + const dispatcher = new PiCmuxCommandDispatcher(); + const sessionStates = new Map(); + const lifecycleTasks = createPiLifecycleQueue(); + + const enqueueLifecycleTask = ( + sessionId: string, + context: PiExtensionContextSnapshot, + operation: () => Promise | unknown, + ): Promise => lifecycleTasks.enqueue(sessionId, context, operation); pi.on("session_start", (_event, ctx) => { const context = snapshotContext(ctx); @@ -439,7 +472,10 @@ export default function cmuxPiSessionExtension(pi: ExtensionAPI) { if (!sessionId) return; const dispatch = prepareFeedDispatch(dispatcher, sessionStates, eventName, context, event); if (!dispatch) return; - enqueueLifecycleTask(sessionId, context, dispatch); + if (!lifecycleTasks.tryEnqueue(sessionId, context, dispatch)) { + // A shed completion must fail visibly instead of reporting delivery. + if (isTerminalFeedEvent(eventName)) stateFor(sessionStates, sessionId).feedDeliveryFailed = true; + } }; pi.on("tool_execution_start", (event, ctx) => { @@ -513,7 +549,7 @@ export default function cmuxPiSessionExtension(pi: ExtensionAPI) { await dispatcher.finishFeedForSession(sessionId); const feedDelivered = !state.feedDeliveryFailed; state.feedDeliveryFailed = false; - if (!feedDelivered) warn(context, "cmux hook command failed", { session_id: sessionId }); + if (!feedDelivered) await warnFeedDeliveryDropped(context, sessionId); if (stopPayload) await sendHook(dispatcher, "stop", context, stopPayload); try { await clearResumeBinding(dispatcher, context, sessionId); diff --git a/cmux.xcodeproj/project.pbxproj b/cmux.xcodeproj/project.pbxproj index c0e45026121..c94d233d5b8 100644 --- a/cmux.xcodeproj/project.pbxproj +++ b/cmux.xcodeproj/project.pbxproj @@ -675,6 +675,7 @@ C0DE71B10000000000000001 /* AppDelegate+AgentChatNotifications.swift in Sources C08672010000000000000005 /* CMUXCLI+PiCompactedFeed.swift in Sources */ = {isa = PBXBuildFile; fileRef = C08672010000000000000006 /* CMUXCLI+PiCompactedFeed.swift */; }; C05555010000000000000001 /* CMUXCLI+PiExtension.swift in Sources */ = {isa = PBXBuildFile; fileRef = C05555010000000000000002 /* CMUXCLI+PiExtension.swift */; }; C05555010000000000000003 /* CMUXCLI+PiExtensionSource.swift in Sources */ = {isa = PBXBuildFile; fileRef = C05555010000000000000004 /* CMUXCLI+PiExtensionSource.swift */; }; + C10128010000000000000001 /* CMUXCLI+PiExtensionSourceDiagnostics.swift in Sources */ = {isa = PBXBuildFile; fileRef = C10128010000000000000002 /* CMUXCLI+PiExtensionSourceDiagnostics.swift */; }; C08672010000000000000001 /* CMUXCLI+PiExtensionSourceDispatch.swift in Sources */ = {isa = PBXBuildFile; fileRef = C08672010000000000000002 /* CMUXCLI+PiExtensionSourceDispatch.swift */; }; C05555010000000000000005 /* CMUXCLI+PiExtensionSourcePart1.swift in Sources */ = {isa = PBXBuildFile; fileRef = C05555010000000000000006 /* CMUXCLI+PiExtensionSourcePart1.swift */; }; C05555010000000000000007 /* CMUXCLI+PiExtensionSourcePart2.swift in Sources */ = {isa = PBXBuildFile; fileRef = C05555010000000000000008 /* CMUXCLI+PiExtensionSourcePart2.swift */; }; @@ -3510,6 +3511,7 @@ C0DE71B10000000000000002 /* AppDelegate+AgentChatNotifications.swift */ = {isa = C08672010000000000000006 /* CMUXCLI+PiCompactedFeed.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CMUXCLI+PiCompactedFeed.swift"; sourceTree = ""; }; C05555010000000000000002 /* CMUXCLI+PiExtension.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CMUXCLI+PiExtension.swift"; sourceTree = ""; }; C05555010000000000000004 /* CMUXCLI+PiExtensionSource.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CMUXCLI+PiExtensionSource.swift"; sourceTree = ""; }; + C10128010000000000000002 /* CMUXCLI+PiExtensionSourceDiagnostics.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CMUXCLI+PiExtensionSourceDiagnostics.swift"; sourceTree = ""; }; C08672010000000000000002 /* CMUXCLI+PiExtensionSourceDispatch.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CMUXCLI+PiExtensionSourceDispatch.swift"; sourceTree = ""; }; C05555010000000000000006 /* CMUXCLI+PiExtensionSourcePart1.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CMUXCLI+PiExtensionSourcePart1.swift"; sourceTree = ""; }; C05555010000000000000008 /* CMUXCLI+PiExtensionSourcePart2.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CMUXCLI+PiExtensionSourcePart2.swift"; sourceTree = ""; }; @@ -7696,6 +7698,7 @@ C0DE71B10000000000000002 /* AppDelegate+AgentChatNotifications.swift */ = {isa = C05555010000000000000002 /* CMUXCLI+PiExtension.swift */, C08672010000000000000006 /* CMUXCLI+PiCompactedFeed.swift */, C05555010000000000000004 /* CMUXCLI+PiExtensionSource.swift */, + C10128010000000000000002 /* CMUXCLI+PiExtensionSourceDiagnostics.swift */, C08672010000000000000002 /* CMUXCLI+PiExtensionSourceDispatch.swift */, C05555010000000000000006 /* CMUXCLI+PiExtensionSourcePart1.swift */, C05555010000000000000008 /* CMUXCLI+PiExtensionSourcePart2.swift */, @@ -10782,6 +10785,7 @@ C0DE71B10000000000000002 /* AppDelegate+AgentChatNotifications.swift */ = {isa = C08672010000000000000005 /* CMUXCLI+PiCompactedFeed.swift in Sources */, C05555010000000000000001 /* CMUXCLI+PiExtension.swift in Sources */, C05555010000000000000003 /* CMUXCLI+PiExtensionSource.swift in Sources */, + C10128010000000000000001 /* CMUXCLI+PiExtensionSourceDiagnostics.swift in Sources */, C08672010000000000000001 /* CMUXCLI+PiExtensionSourceDispatch.swift in Sources */, C05555010000000000000005 /* CMUXCLI+PiExtensionSourcePart1.swift in Sources */, C05555010000000000000007 /* CMUXCLI+PiExtensionSourcePart2.swift in Sources */, diff --git a/tests/test_pi_extension_dispatch.py b/tests/test_pi_extension_dispatch.py index e93ecd4eea7..5e810a7ebe5 100644 --- a/tests/test_pi_extension_dispatch.py +++ b/tests/test_pi_extension_dispatch.py @@ -7,6 +7,7 @@ import os import shutil import subprocess +import sys import tempfile from pathlib import Path @@ -18,6 +19,20 @@ def make_executable(path: Path, content: str) -> None: path.chmod(0o755) +def diagnostic_payloads(path: Path) -> list[dict[str, object]]: + if not path.exists(): + return [] + payloads: list[dict[str, object]] = [] + for line in path.read_text(encoding="utf-8").splitlines(): + try: + payload = json.loads(line) + except json.JSONDecodeError: + continue + if isinstance(payload, dict): + payloads.append(payload) + return payloads + + def run_extension( *, bun: str, @@ -1270,8 +1285,8 @@ def update(delta): const mod = await import(extensionPath); const handlers = new Map(); mod.default({ on(name, handler) { handlers.set(name, handler); } }); -async function waitForAggregateState(label, predicate) { - const deadline = performance.now() + 5000; +async function waitForAggregateState(label, predicate, timeoutMs = 5000) { + const deadline = performance.now() + timeoutMs; let lastState = null; let lastError = null; while (performance.now() < deadline) { @@ -1308,6 +1323,7 @@ def update(delta): await waitForAggregateState( "waiting for aggregate Feed drain", (state) => state.starts === 34 && state.active === 0, + 10000, ); """ result = run_extension( @@ -1517,6 +1533,89 @@ def check_feed_cancellation(bun: str, root: Path, extension_path: Path) -> int: return 0 +def check_lifecycle_backlog_shedding(bun: str, root: Path, extension_path: Path) -> int: + backlog_log = root / "lifecycle-backlog-cmux.log" + diagnostic_log = root / "lifecycle-backlog-diagnostics.log" + release_marker = root / "lifecycle-backlog-release" + backlog_cmux = root / "lifecycle-backlog-cmux" + make_executable( + backlog_cmux, + """#!/usr/bin/env python3 +import os +import sys +import time + +args = " ".join(sys.argv[1:]) +sys.stdin.read() +with open(os.environ["CMUX_TEST_PI_BACKLOG_LOG"], "a", encoding="utf-8") as stream: + stream.write(args + "\\n") +if "hooks pi session-start" in args: + while not os.path.exists(os.environ["CMUX_TEST_PI_BACKLOG_RELEASE"]): + time.sleep(0.01) +print("{}") +""", + ) + backlog_source = """ +const extensionPath = process.env.CMUX_TEST_PI_EXTENSION_PATH; +const mod = await import(extensionPath); +const handlers = new Map(); +mod.default({ on(name, handler) { handlers.set(name, handler); } }); +const ctx = { + cwd: "/tmp/pi-lifecycle-backlog-project", + sessionManager: { getSessionId() { return "pi-lifecycle-backlog-session"; } } +}; +handlers.get("session_start")({}, ctx); +const logPath = process.env.CMUX_TEST_PI_BACKLOG_LOG; +while (!Bun.file(logPath).size) { + await new Promise((resolve) => setTimeout(resolve, 10)); +} +for (let index = 0; index < 60; index += 1) { + handlers.get("tool_execution_end")({ + toolCallId: `backlog-tool-${index}`, + toolName: "bash", + result: { content: [{ type: "text", text: `terminal result ${index}` }] }, + isError: false + }, ctx); +} +await Bun.write(process.env.CMUX_TEST_PI_BACKLOG_RELEASE, "release"); +await handlers.get("session_shutdown")({ reason: "reload" }, ctx); +""" + result = run_extension( + bun=bun, + root=root, + extension_path=extension_path, + fake_cmux=backlog_cmux, + source=backlog_source, + extra_env={ + "CMUX_TEST_PI_BACKLOG_LOG": str(backlog_log), + "CMUX_TEST_PI_BACKLOG_RELEASE": str(release_marker), + "CMUX_DEBUG_LOG": str(diagnostic_log), + }, + ) + if result.returncode != 0: + print(f"FAIL: lifecycle backlog harness failed: {result.stderr!r}") + return 1 + if result.stdout or result.stderr: + print( + "FAIL: lifecycle backlog shedding leaked into Pi's prompt: " + f"stdout={result.stdout!r} stderr={result.stderr!r}" + ) + return 1 + dropped = [ + payload + for payload in diagnostic_payloads(diagnostic_log) + if payload.get("message") == "cmux feed delivery dropped" + and payload.get("reason") == "dispatch-dropped" + ] + if len(dropped) != 1: + print( + "FAIL: a stalled lifecycle hook did not shed excess Feed work as a " + f"dropped delivery: {diagnostic_payloads(diagnostic_log)!r}" + ) + return 1 + return 0 + + def check_completion_order(bun: str, root: Path, extension_path: Path) -> int: completion_cmux = make_feed_lifecycle_cmux(root, "completion-order-cmux") completion_log = root / "completion-order-cmux.log" @@ -1683,13 +1782,17 @@ def check_terminal_feed_failure_emits_one_stop(bun: str, root: Path, extension_p ("shutdown", shutdown_source), ): log_path = root / f"terminal-feed-{label}-failure.log" + diagnostic_log = root / f"terminal-feed-{label}-diagnostics.log" result = run_extension( bun=bun, root=root, extension_path=extension_path, fake_cmux=failure_cmux, source=source, - extra_env={"CMUX_TEST_PI_FAILURE_LOG": str(log_path)}, + extra_env={ + "CMUX_TEST_PI_FAILURE_LOG": str(log_path), + "CMUX_DEBUG_LOG": str(diagnostic_log), + }, ) if result.returncode != 0: print(f"FAIL: terminal-feed {label} failure harness failed: {result.stderr!r}") @@ -1706,8 +1809,19 @@ def check_terminal_feed_failure_emits_one_stop(bun: str, root: Path, extension_p if any("hooks pi notification" in line for line in calls): print(f"FAIL: terminal-feed {label} failure emitted a completion notification: {calls!r}") return 1 - if '"message":"cmux hook command failed"' not in result.stderr: - print(f"FAIL: failed terminal-feed {label} delivery was not surfaced: {result.stderr!r}") + diagnostics = diagnostic_payloads(diagnostic_log) + command_failure = next( + (payload for payload in diagnostics if payload.get("message") == "cmux hook command failed"), + None, + ) + if command_failure is None or command_failure.get("reason") != "nonzero-exit": + print(f"FAIL: failed terminal-feed {label} delivery was not diagnosed: {diagnostics!r}") + return 1 + if result.stdout or result.stderr: + print( + f"FAIL: failed terminal-feed {label} delivery leaked into Pi's prompt: " + f"stdout={result.stdout!r} stderr={result.stderr!r}" + ) return 1 return 0 @@ -1762,6 +1876,9 @@ def check_nonterminal_timeout_marks_dropped_completion( stdout: "", stderr: "", error: new Error("cmux command timed out after 5000ms"), + reason: "timeout", + timeoutMs: 5000, + elapsedMs: 5000, surfaceUnavailable: false }); const settleDeadline = Date.now() + 1_000; @@ -1794,6 +1911,7 @@ def check_nonterminal_timeout_marks_dropped_completion( def check_completion_drain_deadline(bun: str, root: Path, extension_path: Path) -> int: ordered_log = root / "completion-drain-order-cmux.log" + ordered_diagnostic_log = root / "completion-drain-order-diagnostics.log" ordered_cmux = root / "completion-drain-order-cmux" make_executable( ordered_cmux, @@ -1851,7 +1969,10 @@ def check_completion_drain_deadline(bun: str, root: Path, extension_path: Path) extension_path=extension_path, fake_cmux=ordered_cmux, source=ordered_source, - extra_env={"CMUX_TEST_PI_DRAIN_ORDER_LOG": str(ordered_log)}, + extra_env={ + "CMUX_TEST_PI_DRAIN_ORDER_LOG": str(ordered_log), + "CMUX_DEBUG_LOG": str(ordered_diagnostic_log), + }, ) if ordered.returncode != 0: print(f"FAIL: completion-drain ordering harness failed: {ordered.stderr!r}") @@ -1894,11 +2015,13 @@ def check_completion_drain_deadline(bun: str, root: Path, extension_path: Path) f"{ordered_calls!r}" ) return 1 - if '"message":"cmux hook command failed"' in ordered.stderr: - print(f"FAIL: late successful terminal Feed result was marked failed: {ordered.stderr!r}") + ordered_diagnostics = diagnostic_payloads(ordered_diagnostic_log) + if any(payload.get("message") == "cmux hook command failed" for payload in ordered_diagnostics): + print(f"FAIL: late successful terminal Feed result was marked failed: {ordered_diagnostics!r}") return 1 deadline_log = root / "completion-deadline-cmux.log" + deadline_diagnostic_log = root / "completion-deadline-diagnostics.log" deadline_cmux = root / "completion-deadline-cmux" make_executable( deadline_cmux, @@ -1962,7 +2085,10 @@ def handle_term(_signum, _frame): extension_path=extension_path, fake_cmux=deadline_cmux, source=deadline_source, - extra_env={"CMUX_TEST_PI_DEADLINE_LOG": str(deadline_log)}, + extra_env={ + "CMUX_TEST_PI_DEADLINE_LOG": str(deadline_log), + "CMUX_DEBUG_LOG": str(deadline_diagnostic_log), + }, ) if deadline.returncode != 0: print(f"FAIL: completion-drain deadline harness failed: {deadline.stderr!r}") @@ -1983,8 +2109,16 @@ def handle_term(_signum, _frame): if any("hooks pi notification" in line for line in deadline_calls): print(f"FAIL: terminal-feed drain deadline emitted a completion notification: {deadline_calls!r}") return 1 - if '"message":"cmux hook command failed"' not in deadline.stderr: - print(f"FAIL: terminal-feed drain deadline was not surfaced: {deadline.stderr!r}") + deadline_diagnostics = diagnostic_payloads(deadline_diagnostic_log) + dropped = next( + (payload for payload in deadline_diagnostics if payload.get("message") == "cmux feed delivery dropped"), + None, + ) + if dropped is None or dropped.get("reason") != "dispatch-dropped": + print(f"FAIL: terminal-feed drain deadline was not diagnosed: {deadline_diagnostics!r}") + return 1 + if "timeout_ms" in dropped or "elapsed_ms" in dropped: + print(f"FAIL: terminal-feed drop reported unrelated command timing: {dropped!r}") return 1 return 0 @@ -2057,6 +2191,7 @@ def handle_term(_signum, _frame): extra_env={ "CMUX_TEST_PI_TIMEOUT_LOG": str(timeout_log), "CMUX_TEST_PI_TIMEOUT_LOCK": str(timeout_lock), + "CMUX_PI_HOOK_TIMEOUT_MS": "1000", }, ) if timed_out.returncode != 0: @@ -2308,6 +2443,7 @@ def check_failed_resume_clear_releases_session_runtime( extension_path: Path, ) -> int: log_path = root / "failed-resume-clear.log" + diagnostic_log = root / "failed-resume-clear-diagnostics.log" fake_cmux = root / "failed-resume-clear-cmux" make_executable( fake_cmux, @@ -2364,7 +2500,10 @@ def check_failed_resume_clear_releases_session_runtime( extension_path=inspectable_extension, fake_cmux=fake_cmux, source=source, - extra_env={"CMUX_TEST_PI_FAILED_CLEAR_LOG": str(log_path)}, + extra_env={ + "CMUX_TEST_PI_FAILED_CLEAR_LOG": str(log_path), + "CMUX_DEBUG_LOG": str(diagnostic_log), + }, ) if result.returncode != 0: print(f"FAIL: failed resume clear retained Pi runtime state: {result.stderr!r}") @@ -2378,8 +2517,13 @@ def check_failed_resume_clear_releases_session_runtime( if len(prompt_calls) != 1 or expected_new_target not in prompt_calls[0]: print(f"FAIL: failed resume clear retained the old resolved target: {calls!r}") return 1 - if '"message":"failed to clear Pi resume binding"' not in result.stderr: - print(f"FAIL: failed resume clear was not reported: {result.stderr!r}") + diagnostics = diagnostic_payloads(diagnostic_log) + clear_failure = next( + (payload for payload in diagnostics if payload.get("hook_name") == "surface-resume-clear"), + None, + ) + if clear_failure is None or clear_failure.get("reason") != "nonzero-exit": + print(f"FAIL: failed resume clear was not diagnosed: {diagnostics!r}") return 1 return 0 @@ -2523,6 +2667,7 @@ def check_session_isolation_within_runtime(bun: str, root: Path, extension_path: def check_stale_surface(bun: str, root: Path, extension_path: Path) -> int: stale_log = root / "stale-cmux.log" + stale_diagnostic_log = root / "stale-cmux-diagnostics.log" stale_cmux = root / "stale-cmux" make_executable( stale_cmux, @@ -2563,7 +2708,10 @@ def check_stale_surface(bun: str, root: Path, extension_path: Path) -> int: extension_path=extension_path, fake_cmux=stale_cmux, source=stale_source, - extra_env={"CMUX_TEST_PI_STALE_LOG": str(stale_log)}, + extra_env={ + "CMUX_TEST_PI_STALE_LOG": str(stale_log), + "CMUX_DEBUG_LOG": str(stale_diagnostic_log), + }, ) if stale.returncode != 0: print("FAIL: stale-surface Pi harness failed to execute") @@ -2576,14 +2724,640 @@ def check_stale_surface(bun: str, root: Path, extension_path: Path) -> int: if len(stale_calls) != 1: print(f"FAIL: stale CMUX_SURFACE_ID was retried after its first permanent failure: {stale_calls!r}") return 1 - warning_count = stale.stderr.count('"source":"cmux-pi-extension"') - if warning_count != 1: - print(f"FAIL: stale surface emitted {warning_count} warnings instead of one: {stale.stderr!r}") + diagnostics = diagnostic_payloads(stale_diagnostic_log) + command_failures = [ + payload for payload in diagnostics if payload.get("message") == "cmux hook command failed" + ] + if len(command_failures) != 1: + print(f"FAIL: stale surface logged {len(command_failures)} failures instead of one: {diagnostics!r}") + return 1 + if stale.stdout or stale.stderr: + print( + "FAIL: stale surface warning leaked into Pi's prompt: " + f"stdout={stale.stdout!r} stderr={stale.stderr!r}" + ) + return 1 + + return 0 + + +def check_concurrent_stale_surface_logs_once( + bun: str, + root: Path, + extension_path: Path, +) -> int: + diagnostic_log = root / "concurrent-stale-surface-diagnostics.log" + inspectable_extension = root / "concurrent-stale-surface.ts" + inspectable_extension.write_text( + extension_path.read_text(encoding="utf-8") + + "\nexport { PiCmuxCommandDispatcher };\n", + encoding="utf-8", + ) + source = """ +const extensionPath = process.env.CMUX_TEST_PI_EXTENSION_PATH; +const mod = await import(extensionPath); +process.env.CMUX_PI_CMUX_BIN = "/bin/sh"; +process.env.CMUX_DEBUG_LOG = process.env.CMUX_TEST_PI_CONCURRENT_STALE_DIAGNOSTIC_LOG; +process.env.CMUX_PI_HOOK_TIMEOUT_MS = "5000"; + +const iterations = 8; +for (let index = 0; index < iterations; index += 1) { + const dispatcher = new mod.PiCmuxCommandDispatcher(); + const context = { + sessionId: `pi-concurrent-stale-${index}`, + cwd: "/tmp", + }; + dispatcher.enqueueFeed(`feed-${index}`, { + args: ["-c", "exit 69"], + cwd: "/tmp", + payload: {}, + context, + terminal: true, + }); + await dispatcher.run(["-c", "exit 69"], "/tmp", undefined, context); + const deadline = performance.now() + 5000; + while (dispatcher.activeFeeds.size > 0 && performance.now() < deadline) { + await new Promise((resolve) => setTimeout(resolve, 2)); + } + if (dispatcher.activeFeeds.size > 0) { + throw new Error(`concurrent stale Feed did not finish for iteration ${index}`); + } +} +""" + result = run_extension( + bun=bun, + root=root, + extension_path=inspectable_extension, + fake_cmux=Path("/bin/sh"), + source=source, + extra_env={ + "CMUX_TEST_PI_CONCURRENT_STALE_DIAGNOSTIC_LOG": str(diagnostic_log), + }, + ) + if result.returncode != 0: + print(f"FAIL: concurrent stale-surface harness failed: {result.stderr!r}") + return 1 + diagnostics = [ + payload + for payload in diagnostic_payloads(diagnostic_log) + if payload.get("dispatch_disabled") is True + ] + if len(diagnostics) != 8: + print( + "FAIL: concurrent Feed/control stale failures emitted " + f"{len(diagnostics)} dispatch-disabled diagnostics instead of 8: {diagnostics!r}" + ) + return 1 + if result.stdout or result.stderr: + print( + "FAIL: concurrent stale-surface diagnostics leaked into Pi's prompt: " + f"stdout={result.stdout!r} stderr={result.stderr!r}" + ) + return 1 + return 0 + + +def check_timeout_configuration_and_failure_telemetry( + bun: str, + root: Path, + extension_path: Path, +) -> int: + extension_text = extension_path.read_text(encoding="utf-8") + if "CMUX_PI_HOOK_TIMEOUT_MS" not in extension_text: + print("FAIL: generated Pi extension does not expose CMUX_PI_HOOK_TIMEOUT_MS") + return 1 + if "cmux-pi-session-extension-marker v3" not in extension_text: + print("FAIL: generated Pi extension did not advance its regeneration marker to v3") + return 1 + forbidden_console_calls = [ + call + for call in ("console.warn(", "console.error(") + if call in extension_text + ] + if forbidden_console_calls: + print( + "FAIL: generated Pi extension can render failure diagnostics in Pi's prompt: " + f"{forbidden_console_calls!r}" + ) + return 1 + + inspectable_extension = root / "timeout-telemetry-cmux-session.ts" + inspectable_extension.write_text( + extension_text + + "\nexport { PiCmuxCommandDispatcher, piHookTimeoutMilliseconds, piCommandTimeoutMilliseconds, commandFailureReason, piHookName, createPiLifecycleQueue };\n", + encoding="utf-8", + ) + + fake_cmux = root / "timeout-telemetry-cmux" + make_executable( + fake_cmux, + """#!/usr/bin/env python3 +import sys +import time + +sys.stdin.read() +if "session-start" in sys.argv: + time.sleep(5) + print("{}") +elif "prompt-submit" in sys.argv: + raise SystemExit(23) +else: + print("{}") +""", + ) + + diagnostic_log = root / "pi-hook-diagnostics.log" + missing_cmux = root / "missing-cmux" + timeout_source = """ +const extensionPath = process.env.CMUX_TEST_PI_EXTENSION_PATH; +const mod = await import(extensionPath); + +const parsingCases = [ + [undefined, 15000], + ["", 15000], + [" ", 15000], + [" 25000 ", 25000], + ["0017", 17], + ["0", 15000], + ["-1", 15000], + ["1.5", 15000], + ["1e3", 15000], + ["not-a-number", 15000], + ["59999", 59999], + ["60000", 60000], + ["999999", 60000], + ["999999999999999999999999", 60000], + ["9".repeat(309), 60000], +]; +for (const [value, expected] of parsingCases) { + const actual = mod.piHookTimeoutMilliseconds(value); + if (actual !== expected) { + throw new Error(`timeout parse ${JSON.stringify(value)} produced ${actual}, expected ${expected}`); + } +} + +const commandTimeoutCases = [ + [["hooks", "pi", "session-start"], undefined, 15000], + [["hooks", "feed", "--source", "pi"], undefined, 4500], + [["hooks", "feed", "--source", "pi"], "25000", 4500], + [["hooks", "feed", "--source", "pi"], "4200", 4200], + [["hooks", "feed", "--source", "pi"], "1000", 1000], +]; +for (const [args, value, expected] of commandTimeoutCases) { + const actual = mod.piCommandTimeoutMilliseconds(args, value); + if (actual !== expected) { + throw new Error(`command timeout for ${JSON.stringify(args)} and ${value} produced ${actual}, expected ${expected}`); + } +} + +const lifecycle = mod.createPiLifecycleQueue(); +const lifecycleContext = { + sessionId: "pi-lifecycle-backlog", + cwd: "/tmp/pi-lifecycle-backlog", +}; +let releaseStalledLifecycleHook; +const stalledLifecycleHook = new Promise((resolve) => { + releaseStalledLifecycleHook = resolve; +}); +const stalledTask = lifecycle.enqueue( + "pi-lifecycle-backlog", + lifecycleContext, + () => stalledLifecycleHook, +); +let queuedDroppableRuns = 0; +let acceptedDroppableTasks = 0; +for (let index = 0; index < 40; index += 1) { + const accepted = lifecycle.tryEnqueue("pi-lifecycle-backlog", lifecycleContext, () => { + queuedDroppableRuns += 1; + }); + if (accepted) acceptedDroppableTasks += 1; +} +if (acceptedDroppableTasks !== 31) { + throw new Error(`stalled lifecycle backlog accepted ${acceptedDroppableTasks} droppable tasks, expected 31`); +} +if (!lifecycle.tryEnqueue("pi-lifecycle-backlog-other", lifecycleContext, () => {})) { + throw new Error("saturated session backlog rejected another session's work"); +} +let criticalRuns = 0; +const criticalTask = lifecycle.enqueue("pi-lifecycle-backlog", lifecycleContext, () => { + criticalRuns += 1; +}); +if (queuedDroppableRuns !== 0) { + throw new Error("droppable lifecycle tasks ran ahead of the stalled hook"); +} +releaseStalledLifecycleHook(); +await stalledTask; +await criticalTask; +if (queuedDroppableRuns !== 31 || criticalRuns !== 1) { + throw new Error(`queued lifecycle tasks did not run after drain: droppable=${queuedDroppableRuns} critical=${criticalRuns}`); +} +if (!lifecycle.tryEnqueue("pi-lifecycle-backlog", lifecycleContext, () => {})) { + throw new Error("drained lifecycle backlog rejected new droppable work"); +} + +const classified = [ + [mod.commandFailureReason(null, undefined, "timeout"), "timeout"], + [mod.commandFailureReason(0, new Error("write EPIPE")), undefined], + [mod.commandFailureReason(42, undefined), "nonzero-exit"], + [mod.commandFailureReason(null, new Error("ENOENT")), "spawn-error"], +]; +for (const [actual, expected] of classified) { + if (actual !== expected) { + throw new Error(`failure classification produced ${actual}, expected ${expected}`); + } +} + +const boundedHookName = mod.piHookName(["hooks", "pi", "x".repeat(10_000)]); +if (boundedHookName.length > 128) { + throw new Error(`hook name was not bounded: ${boundedHookName.length}`); +} + +process.env.CMUX_PI_HOOK_TIMEOUT_MS = "80"; +process.env.CMUX_DEBUG_LOG = process.env.CMUX_TEST_PI_DIAGNOSTIC_LOG; +const context = { + sessionId: "pi-timeout-telemetry-session", + cwd: "/tmp/pi-timeout-telemetry", +}; +const dispatcher = new mod.PiCmuxCommandDispatcher(); +const timedOut = await dispatcher.run( + ["hooks", "pi", "session-start"], + context.cwd, + "{}", + context, +); +if (timedOut.reason !== "timeout") { + throw new Error(`signal-killed child was classified as ${timedOut.reason}`); +} +if (timedOut.timeoutMs !== 80 || timedOut.elapsedMs < 1) { + throw new Error(`timeout result omitted timing metadata: ${JSON.stringify(timedOut)}`); +} + +process.env.CMUX_PI_HOOK_TIMEOUT_MS = "5000"; +const nonzero = await dispatcher.run( + ["hooks", "pi", "prompt-submit"], + context.cwd, + "{}", + context, +); +if (nonzero.reason !== "nonzero-exit" || nonzero.status !== 23) { + throw new Error(`nonzero child was misclassified: ${JSON.stringify(nonzero)}`); +} + +process.env.CMUX_PI_CMUX_BIN = process.env.CMUX_TEST_PI_MISSING_CMUX; +const spawnError = await dispatcher.run( + ["hooks", "pi", "stop"], + context.cwd, + "{}", + context, +); +if (spawnError.reason !== "spawn-error" || spawnError.status !== null) { + throw new Error(`spawn failure was misclassified: ${JSON.stringify(spawnError)}`); +} + +const logPath = process.env.CMUX_TEST_PI_DIAGNOSTIC_LOG; +let diagnostics = []; +const deadline = performance.now() + 3000; +while (performance.now() < deadline) { + try { + diagnostics = (await Bun.file(logPath).text()) + .split("\\n") + .filter(Boolean) + .map((line) => JSON.parse(line)); + } catch (_) {} + if (diagnostics.length >= 3) break; + await new Promise((resolve) => setTimeout(resolve, 10)); +} + +const expectedFailures = new Map([ + ["session-start", { reason: "timeout", timeout_ms: 80 }], + ["prompt-submit", { reason: "nonzero-exit", timeout_ms: 5000 }], + ["stop", { reason: "spawn-error", timeout_ms: 5000 }], +]); +for (const [hookName, expected] of expectedFailures) { + const payload = diagnostics.find((candidate) => candidate.hook_name === hookName); + if (!payload) throw new Error(`missing ${hookName} diagnostic: ${JSON.stringify(diagnostics)}`); + if (payload.reason !== expected.reason || payload.timeout_ms !== expected.timeout_ms) { + throw new Error(`wrong ${hookName} diagnostic: ${JSON.stringify(payload)}`); + } + if (!Number.isFinite(payload.elapsed_ms) || payload.elapsed_ms < 0) { + throw new Error(`missing ${hookName} elapsed_ms: ${JSON.stringify(payload)}`); + } +} +""" + result = run_extension( + bun=bun, + root=root, + extension_path=inspectable_extension, + fake_cmux=fake_cmux, + source=timeout_source, + extra_env={ + "CMUX_TEST_PI_DIAGNOSTIC_LOG": str(diagnostic_log), + "CMUX_TEST_PI_MISSING_CMUX": str(missing_cmux), + }, + ) + if result.returncode != 0: + print(f"FAIL: Pi timeout telemetry harness failed: {result.stderr!r}") + return 1 + if result.stdout or result.stderr: + print( + "FAIL: Pi timeout telemetry wrote to the host streams: " + f"stdout={result.stdout!r} stderr={result.stderr!r}" + ) return 1 return 0 +def check_diagnostic_log_safety_and_routing( + bun: str, + root: Path, + extension_path: Path, +) -> int: + extension_text = extension_path.read_text(encoding="utf-8") + inspectable_extension = root / "diagnostic-log-cmux-session.ts" + inspectable_extension.write_text( + extension_text + + "\nexport { PiCmuxCommandDispatcher, appendPiHookDiagnostic, piHookDiagnosticPath, runPiHookDiagnosticWrite, warn };\n", + encoding="utf-8", + ) + + fake_cmux = root / "diagnostic-log-cmux" + make_executable( + fake_cmux, + """#!/usr/bin/env bash +set -euo pipefail +cat >/dev/null +exit 23 +""", + ) + + home = root / "diagnostic-home" + home.mkdir() + boundary_log = root / "diagnostic-boundary.log" + boundary_log.write_text('{"existing":true}', encoding="utf-8") + pointer_file = root / "last-debug-log-path" + pointer_file.write_text("~/pointer.log\n", encoding="utf-8") + pointer_symlink = root / "last-debug-log-path.symlink" + pointer_symlink.symlink_to(pointer_file) + pointer_fifo = root / "last-debug-log-path.fifo" + os.mkfifo(pointer_fifo) + missing_pointer = root / "missing-last-debug-log-path" + fallback_log = root / "fallback.log" + invalid_log_destination = root / "diagnostic-directory" + invalid_log_destination.mkdir() + symlink_log_target = root / "diagnostic-symlink-target.log" + symlink_log_target.write_text("symlink canary\n", encoding="utf-8") + symlink_log = root / "diagnostic-symlink.log" + symlink_log.symlink_to(symlink_log_target) + fifo_log = root / "diagnostic.fifo" + os.mkfifo(fifo_log) + socket_tag = f"pi-routing-{os.getpid()}" + socket_path_log = Path(f"/tmp/cmux-debug-{socket_tag}.log") + legacy_socket_log = Path(f"/tmp/cmux-debug-{socket_tag}-legacy.log") + shadow_socket_log = Path(f"/tmp/cmux-debug-{socket_tag}-shadow.log") + for path in (socket_path_log, legacy_socket_log, shadow_socket_log): + path.unlink(missing_ok=True) + + source = r""" +import { existsSync, readFileSync, unlinkSync } from "node:fs"; +const extensionPath = process.env.CMUX_TEST_PI_EXTENSION_PATH; +const mod = await import(extensionPath); +const failures = []; + +process.env.CMUX_DEBUG_LOG = process.env.CMUX_TEST_PI_BOUNDARY_LOG; +await mod.appendPiHookDiagnostic({ + source: "cmux-pi-extension", + level: "warning", + message: "boundary canary", + hook_name: "boundary", + reason: "test", +}); +const boundaryText = readFileSync(process.env.CMUX_TEST_PI_BOUNDARY_LOG, "utf8"); +const boundaryLines = boundaryText.split("\n").filter(Boolean); +if (boundaryLines.length !== 2) { + failures.push(`diagnostic append did not preserve a JSONL boundary: ${JSON.stringify(boundaryText)}`); +} else { + try { + const parsed = boundaryLines.map((line) => JSON.parse(line)); + if (parsed[0].existing !== true || parsed[1].hook_name !== "boundary") { + failures.push(`diagnostic append changed existing JSONL content: ${JSON.stringify(parsed)}`); + } + } catch (error) { + failures.push(`diagnostic append produced invalid JSONL: ${String(error)}`); + } +} + +const home = process.env.CMUX_TEST_PI_ROUTING_HOME; +const pointerFile = process.env.CMUX_TEST_PI_POINTER_FILE; +const missingPointer = process.env.CMUX_TEST_PI_MISSING_POINTER; +const fallbackLog = process.env.CMUX_TEST_PI_FALLBACK_LOG; +const socketTag = process.env.CMUX_TEST_PI_SOCKET_TAG; +const cases = [ + { + label: "explicit", + environment: { + HOME: home, + CMUX_DEBUG_LOG: "~/explicit.log", + CMUX_SOCKET_PATH: `/tmp/cmux-debug-${socketTag}-shadow.sock`, + }, + pointer: pointerFile, + fallback: fallbackLog, + expected: `${home}/explicit.log`, + }, + { + label: "socket-path", + environment: { HOME: home, CMUX_SOCKET_PATH: `/tmp/cmux-debug-${socketTag}.sock` }, + pointer: pointerFile, + fallback: fallbackLog, + expected: `/tmp/cmux-debug-${socketTag}.log`, + }, + { + label: "socket", + environment: { HOME: home, CMUX_SOCKET: `/tmp/cmux-debug-${socketTag}-legacy.sock` }, + pointer: pointerFile, + fallback: fallbackLog, + expected: `/tmp/cmux-debug-${socketTag}-legacy.log`, + }, + { + label: "pointer", + environment: { HOME: home }, + pointer: pointerFile, + fallback: fallbackLog, + expected: `${home}/pointer.log`, + }, + { + label: "fallback", + environment: { HOME: home }, + pointer: missingPointer, + fallback: fallbackLog, + expected: fallbackLog, + }, +]; + +let routesMatched = true; +for (const candidate of cases) { + const actual = mod.piHookDiagnosticPath( + candidate.environment, + candidate.pointer, + candidate.fallback, + ); + if (actual !== candidate.expected) { + routesMatched = false; + failures.push(`${candidate.label} diagnostic route was ${actual}, expected ${candidate.expected}`); + } +} + +const pointerFifoRoute = mod.piHookDiagnosticPath( + { HOME: home }, + process.env.CMUX_TEST_PI_POINTER_FIFO, + fallbackLog, +); +if (pointerFifoRoute !== fallbackLog) { + failures.push(`FIFO pointer route was ${pointerFifoRoute}, expected ${fallbackLog}`); +} + +const pointerSymlinkRoute = mod.piHookDiagnosticPath( + { HOME: home }, + process.env.CMUX_TEST_PI_POINTER_SYMLINK, + fallbackLog, +); +if (pointerSymlinkRoute !== fallbackLog) { + failures.push(`symlink pointer route was ${pointerSymlinkRoute}, expected ${fallbackLog}`); +} + +if (routesMatched) { + for (const candidate of cases) { + try { unlinkSync(candidate.expected); } catch (_) {} + await mod.appendPiHookDiagnostic( + { + source: "cmux-pi-extension", + level: "warning", + message: "routing canary", + hook_name: candidate.label, + reason: "test", + }, + candidate.environment, + candidate.pointer, + candidate.fallback, + ); + if (!existsSync(candidate.expected)) { + failures.push(`${candidate.label} diagnostic route did not create ${candidate.expected}`); + continue; + } + try { + const lines = readFileSync(candidate.expected, "utf8").split("\n").filter(Boolean); + const payload = JSON.parse(lines.at(-1)); + if (payload.hook_name !== candidate.label) { + failures.push(`${candidate.label} diagnostic route wrote the wrong payload`); + } + } catch (error) { + failures.push(`${candidate.label} diagnostic route was not JSONL: ${String(error)}`); + } + } + const explicitText = readFileSync(`${home}/explicit.log`, "utf8"); + if (explicitText.includes("socket-path") || explicitText.includes("pointer")) { + failures.push("lower-priority diagnostics leaked into the explicit log"); + } +} + +const symlinkLogTarget = process.env.CMUX_TEST_PI_SYMLINK_LOG_TARGET; +const symlinkLogBefore = readFileSync(symlinkLogTarget, "utf8"); +await mod.appendPiHookDiagnostic( + { + source: "cmux-pi-extension", + level: "warning", + message: "symlink destination canary", + hook_name: "symlink-destination", + reason: "test", + }, + { CMUX_DEBUG_LOG: process.env.CMUX_TEST_PI_SYMLINK_LOG }, + missingPointer, + fallbackLog, +); +const symlinkLogAfter = readFileSync(symlinkLogTarget, "utf8"); +if (symlinkLogAfter !== symlinkLogBefore) { + failures.push("diagnostic append followed a symlink destination"); +} + +process.env.CMUX_DEBUG_LOG = process.env.CMUX_TEST_PI_FIFO_LOG; +const dispatcher = new mod.PiCmuxCommandDispatcher(); +const context = { + sessionId: "pi-diagnostic-fifo-session", + cwd: "/tmp/pi-diagnostic-fifo", +}; +await dispatcher.run(["hooks", "pi", "prompt-submit"], context.cwd, "{}", context); + +let notificationCount = 0; +process.env.CMUX_DEBUG_LOG = process.env.CMUX_TEST_PI_INVALID_LOG_DESTINATION; +await Promise.resolve(mod.warn( + { ui: { notify() { notificationCount += 1; } } }, + "failed append canary", +)); +if (notificationCount !== 0) { + failures.push(`failed diagnostic append emitted ${notificationCount} Pi UI notifications`); +} + +let hungDiagnosticStarts = 0; +let laterDiagnosticStarts = 0; +await mod.runPiHookDiagnosticWrite(() => { + hungDiagnosticStarts += 1; + return new Promise(() => {}); +}); +await mod.runPiHookDiagnosticWrite(async () => { + laterDiagnosticStarts += 1; +}); +if (hungDiagnosticStarts !== 1 || laterDiagnosticStarts !== 0) { + failures.push( + `diagnostic writer was not bounded: hung=${hungDiagnosticStarts} later=${laterDiagnosticStarts}`, + ); +} + +for (const candidate of cases) { + if (candidate.expected.startsWith("/tmp/")) { + try { unlinkSync(candidate.expected); } catch (_) {} + } +} +if (failures.length) throw new Error(failures.join("\n")); +""" + + try: + result = run_extension( + bun=bun, + root=root, + extension_path=inspectable_extension, + fake_cmux=fake_cmux, + source=source, + extra_env={ + "CMUX_TEST_PI_BOUNDARY_LOG": str(boundary_log), + "CMUX_TEST_PI_ROUTING_HOME": str(home), + "CMUX_TEST_PI_POINTER_FILE": str(pointer_file), + "CMUX_TEST_PI_POINTER_SYMLINK": str(pointer_symlink), + "CMUX_TEST_PI_POINTER_FIFO": str(pointer_fifo), + "CMUX_TEST_PI_MISSING_POINTER": str(missing_pointer), + "CMUX_TEST_PI_FALLBACK_LOG": str(fallback_log), + "CMUX_TEST_PI_FIFO_LOG": str(fifo_log), + "CMUX_TEST_PI_INVALID_LOG_DESTINATION": str(invalid_log_destination), + "CMUX_TEST_PI_SYMLINK_LOG": str(symlink_log), + "CMUX_TEST_PI_SYMLINK_LOG_TARGET": str(symlink_log_target), + "CMUX_TEST_PI_SOCKET_TAG": socket_tag, + }, + ) + finally: + for path in (socket_path_log, legacy_socket_log, shadow_socket_log): + path.unlink(missing_ok=True) + + if result.returncode != 0: + print(f"FAIL: Pi diagnostic log safety harness failed: {result.stderr!r}") + return 1 + if result.stdout or result.stderr: + print( + "FAIL: Pi diagnostic log safety wrote to the host streams: " + f"stdout={result.stdout!r} stderr={result.stderr!r}" + ) + return 1 + return 0 + + def run_checks(bun: str, root: Path, extension_path: Path) -> int: checks = ( check_responsiveness, @@ -2602,6 +3376,7 @@ def run_checks(bun: str, root: Path, extension_path: Path) -> int: check_aggregate_feed_bound, check_feed_failure_overflow_fails_closed, check_feed_cancellation, + check_lifecycle_backlog_shedding, check_completion_order, check_terminal_feed_failure_emits_one_stop, check_nonterminal_timeout_marks_dropped_completion, @@ -2615,6 +3390,9 @@ def run_checks(bun: str, root: Path, extension_path: Path) -> int: check_runtime_isolation, check_session_isolation_within_runtime, check_stale_surface, + check_concurrent_stale_surface_logs_once, + check_timeout_configuration_and_failure_telemetry, + check_diagnostic_log_safety_and_routing, ) for check in checks: if check(bun, root, extension_path) != 0: