diff --git a/apps/desktop/src/features/server-runtime/process/__tests__/manager.test.ts b/apps/desktop/src/features/server-runtime/process/__tests__/manager.test.ts index 192bc3fbb..6ccfb090f 100644 --- a/apps/desktop/src/features/server-runtime/process/__tests__/manager.test.ts +++ b/apps/desktop/src/features/server-runtime/process/__tests__/manager.test.ts @@ -239,7 +239,8 @@ describe("ServerManager", () => { // The child writes directly to the log so its last error survives an early exit. const opts = spawnCall[2] as Record; expect(opts.detached).toBe(true); - expect(opts.stdio).toEqual(["ignore", "ignore", vi.mocked(NodeFS.createWriteStream).mock.results[0].value]); + const logStream = vi.mocked(NodeFS.createWriteStream).mock.results[0].value; + expect(opts.stdio).toEqual(["ignore", logStream, logStream]); expect(result.port).toBe(19600); expect(result.authToken).toBe("test-auth-token"); const portProbe = vi.mocked(NodeNet.createServer).mock.results[0]?.value; @@ -250,7 +251,7 @@ describe("ServerManager", () => { ); }); - it("isolates development server standard output and captures standard error", async () => { + it("captures development server standard output and error in the log file", async () => { const previousRendererUrl = process.env.ELECTRON_RENDERER_URL; process.env.ELECTRON_RENDERER_URL = "http://localhost:5173"; @@ -259,7 +260,8 @@ describe("ServerManager", () => { const spawnCall = vi.mocked(NodeChildProcess.spawn).mock.calls[0]; const opts = spawnCall[2] as Record; - expect(opts.stdio).toEqual(["ignore", "ignore", vi.mocked(NodeFS.createWriteStream).mock.results[0].value]); + const logStream = vi.mocked(NodeFS.createWriteStream).mock.results[0].value; + expect(opts.stdio).toEqual(["ignore", logStream, logStream]); expect(NodeFS.createWriteStream).toHaveBeenCalledWith( NodePath.join("/tmp/mcode", "server-stderr.log"), { fd: 99 }, diff --git a/apps/desktop/src/features/server-runtime/process/child.ts b/apps/desktop/src/features/server-runtime/process/child.ts index 647863dec..7229d2e88 100644 --- a/apps/desktop/src/features/server-runtime/process/child.ts +++ b/apps/desktop/src/features/server-runtime/process/child.ts @@ -32,8 +32,9 @@ export function spawnServerProcess(port: number, platform: NodeJS.Platform): Spa env: createServerEnvironment(paths, port, platform), detached: true, windowsHide: true, - // A direct file handle preserves the final error even if the child exits immediately. - stdio: ["ignore", "ignore", stderrStream], + // A direct file handle preserves the final error even if the child exits immediately; + // stdout shares it so server console output is captured instead of discarded. + stdio: ["ignore", stderrStream, stderrStream], }); child.unref(); console.info("[server-manager] Server process spawned", { pid: child.pid, port, errorLog: SERVER_LOG_PATH }); diff --git a/apps/server/src/application/transport/__tests__/push.test.ts b/apps/server/src/application/transport/__tests__/push.test.ts index 6cf5d9f3d..8e8a5f8c6 100644 --- a/apps/server/src/application/transport/__tests__/push.test.ts +++ b/apps/server/src/application/transport/__tests__/push.test.ts @@ -294,6 +294,20 @@ describe("broadcast", () => { expect(JSON.parse(b[0].buf.toString("utf-8")).data.threadId).toBe("thread-a"); }); + it("keeps broadcasting to other clients when one send throws", () => { + const good: Array<{ buf: Buffer; binary: boolean }> = []; + const dead = { + readyState: 1, + OPEN: 1, + send: () => { throw new Error("closed during send"); }, + } as unknown as WebSocket; + addClient(dead); + addClient(fakeOpenSocket(good)); + + expect(() => broadcast("skills.changed", { providerIds: ["claude"] })).not.toThrow(); + expect(good).toHaveLength(1); + }); + it("lets tests swap validating and pass-through payload adapters", () => { const validating: Array<{ buf: Buffer; binary: boolean }> = []; const validatingWs = fakeOpenSocket(validating); diff --git a/apps/server/src/application/transport/push.ts b/apps/server/src/application/transport/push.ts index 4cb150a43..fe0e48780 100644 --- a/apps/server/src/application/transport/push.ts +++ b/apps/server/src/application/transport/push.ts @@ -229,7 +229,13 @@ function sendBroadcastPayload(channel: WsChannelName, threadId: string | undefin for (const ws of clients) { if (ws.readyState !== ws.OPEN) continue; if (requiresThreadSubscription && threadId && !threadSubscriptions.get(ws)?.has(threadId)) continue; - ws.send(payload); + try { + ws.send(payload); + } catch { + // A socket can die between the readyState check and the send; one dead + // client must not abort the broadcast or take the server down. + logger.warn("Broadcast send failed", { channel }); + } } } diff --git a/apps/server/src/index.ts b/apps/server/src/index.ts index 3b61cdc8d..6b3387fab 100644 --- a/apps/server/src/index.ts +++ b/apps/server/src/index.ts @@ -1,5 +1,8 @@ /** Start the Mcode server process. */ import { startServer } from "./application/bootstrap/server-bootstrap.js"; +import { installServerDiagnostics } from "./runtime/diagnostics/server-diagnostics.js"; + +installServerDiagnostics(); void startServer().catch((error: unknown) => { console.error("Mcode server startup failed", error); diff --git a/apps/server/src/runtime/diagnostics/__tests__/server-diagnostics.test.ts b/apps/server/src/runtime/diagnostics/__tests__/server-diagnostics.test.ts new file mode 100644 index 000000000..de44dad1f --- /dev/null +++ b/apps/server/src/runtime/diagnostics/__tests__/server-diagnostics.test.ts @@ -0,0 +1,86 @@ +import { describe, it, expect, beforeEach, afterEach } from "vitest"; +import * as NodeFS from "node:fs"; +import * as NodeOS from "node:os"; +import * as NodePath from "node:path"; +import { appendDailyLogSync, recordFatalError } from "../server-diagnostics.js"; + +let dir: string; +let originalDataDir: string | undefined; + +beforeEach(() => { + dir = NodeFS.mkdtempSync(NodePath.join(NodeOS.tmpdir(), "mcode-diag-")); + originalDataDir = process.env.MCODE_DATA_DIR; + process.env.MCODE_DATA_DIR = dir; +}); + +afterEach(() => { + if (originalDataDir === undefined) delete process.env.MCODE_DATA_DIR; + else process.env.MCODE_DATA_DIR = originalDataDir; + NodeFS.rmSync(dir, { recursive: true, force: true }); +}); + +function readJsonl(path: string): Array> { + return NodeFS.readFileSync(path, "utf8") + .split("\n") + .filter(Boolean) + .map((line) => JSON.parse(line) as Record); +} + +function dailyLogFiles(): string[] { + const logsDir = NodePath.join(dir, "logs"); + if (!NodeFS.existsSync(logsDir)) return []; + return NodeFS.readdirSync(logsDir).filter((file) => file.startsWith("mcode.log.")); +} + +describe("recordFatalError", () => { + it("writes the fatal record to today's log and server-fatal.log", () => { + recordFatalError("uncaughtException", new Error("boom")); + + expect(dailyLogFiles()).toHaveLength(1); + const daily = readJsonl(NodePath.join(dir, "logs", dailyLogFiles()[0])); + const fatal = readJsonl(NodePath.join(dir, "server-fatal.log")); + + for (const records of [daily, fatal]) { + expect(records).toHaveLength(1); + expect(records[0]).toMatchObject({ + level: "fatal", + kind: "uncaughtException", + error: "boom", + pid: process.pid, + }); + expect(String(records[0].stack)).toContain("boom"); + expect(typeof records[0].timestamp).toBe("string"); + } + }); + + it("serializes non-Error rejection reasons", () => { + recordFatalError("unhandledRejection", "plain string reason"); + + const [record] = readJsonl(NodePath.join(dir, "server-fatal.log")); + expect(record).toMatchObject({ + level: "fatal", + kind: "unhandledRejection", + error: "plain string reason", + }); + }); + + it("survives a failure writing one of the targets", () => { + // A directory where server-fatal.log should be forces appendFileSync to fail. + NodeFS.mkdirSync(NodePath.join(dir, "server-fatal.log")); + + expect(() => recordFatalError("uncaughtException", new Error("partial"))).not.toThrow(); + expect(dailyLogFiles()).toHaveLength(1); + }); +}); + +describe("appendDailyLogSync", () => { + it("appends JSONL records to today's log file", () => { + appendDailyLogSync({ level: "info", message: "one" }); + appendDailyLogSync({ level: "warn", message: "two" }); + + const [file] = dailyLogFiles(); + const records = readJsonl(NodePath.join(dir, "logs", file)); + expect(records.map((record) => record.message)).toEqual(["one", "two"]); + expect(typeof records[0].timestamp).toBe("string"); + }); +}); diff --git a/apps/server/src/runtime/diagnostics/server-diagnostics.ts b/apps/server/src/runtime/diagnostics/server-diagnostics.ts new file mode 100644 index 000000000..e1b168be0 --- /dev/null +++ b/apps/server/src/runtime/diagnostics/server-diagnostics.ts @@ -0,0 +1,146 @@ +/** + * Crash-time diagnostics for the Bun server process. + * + * Winston writes through a buffered stream, so an uncaught error never reaches + * mcode.log.* — the process only gets Bun's bare stderr dump. These handlers + * synchronously append a JSONL record to today's log and to a dedicated + * server-fatal.log before exiting, so every crash leaves a full stack trace + * on disk. The module deliberately avoids project imports: the failure being + * recorded may live inside them. + */ + +import * as NodeFS from "node:fs"; +import * as NodeOS from "node:os"; +import * as NodePath from "node:path"; + +/** Dedicated crash log, beside the rotated server-stderr logs under the data dir. */ +const FATAL_LOG_NAME = "server-fatal.log"; + +/** Poll interval for the event-loop lag watch. */ +const LAG_CHECK_MS = 250; + +/** Stall duration beyond the check interval that warrants a log entry. */ +const LAG_WARN_MS = 500; + +function mcodeDir(): string { + if (process.env.MCODE_DATA_DIR) return process.env.MCODE_DATA_DIR; + const dirName = process.env.NODE_ENV !== "production" ? ".mcode-dev" : ".mcode"; + return NodePath.join(NodeOS.homedir(), dirName); +} + +function dailyLogPath(date: Date): string { + // Local calendar date, matching winston-daily-rotate-file's default naming. + const stamp = [ + date.getFullYear(), + String(date.getMonth() + 1).padStart(2, "0"), + String(date.getDate()).padStart(2, "0"), + ].join("-"); + return NodePath.join(mcodeDir(), "logs", `mcode.log.${stamp}`); +} + +function appendJsonlSync(path: string, record: Record): void { + try { + NodeFS.mkdirSync(NodePath.dirname(path), { recursive: true }); + NodeFS.appendFileSync(path, JSON.stringify(record) + "\n"); + } catch { + // A diagnostics write must never take the process down with it. + } +} + +/** Append one record to today's log without going through winston's stream. */ +export function appendDailyLogSync(record: Record): void { + appendJsonlSync(dailyLogPath(new Date()), { + timestamp: new Date().toISOString(), + ...record, + }); +} + +function describeError(error: unknown): Record { + if (error instanceof Error) { + const errno = error as NodeJS.ErrnoException; + return { + errorName: error.name, + error: error.message, + stack: error.stack, + ...(errno.code !== undefined ? { code: errno.code } : {}), + ...(errno.errno !== undefined ? { errno: errno.errno } : {}), + ...(errno.syscall !== undefined ? { syscall: errno.syscall } : {}), + }; + } + return { error: String(error) }; +} + +/** + * Write a fatal record to today's log and to server-fatal.log, then let the + * caller exit. The second file keeps a stable crash history even when the + * daily file rotates or is the component that failed. + */ +export function recordFatalError( + kind: "uncaughtException" | "unhandledRejection", + error: unknown, +): void { + const record = { + timestamp: new Date().toISOString(), + level: "fatal", + message: `Fatal ${kind}`, + kind, + pid: process.pid, + uptimeSeconds: Math.round(process.uptime() * 100) / 100, + ...describeError(error), + }; + appendJsonlSync(dailyLogPath(new Date()), record); + appendJsonlSync(NodePath.join(mcodeDir(), FATAL_LOG_NAME), record); +} + +/** + * Warn-log event-loop stalls so synchronous work blocking Bun's single + * thread becomes visible in the daily log with a duration attached. + */ +function startEventLoopLagWatch(): void { + let last = Date.now(); + const timer = setInterval(() => { + const now = Date.now(); + const stalledMs = now - last; + last = now; + if (stalledMs - LAG_CHECK_MS >= LAG_WARN_MS) { + appendDailyLogSync({ + level: "warn", + message: "Event loop stalled", + stalledMs, + }); + } + }, LAG_CHECK_MS); + // Never let a diagnostics timer keep a shutdown process alive. + timer.unref(); +} + +let installed = false; + +/** + * Install fatal-error capture, an exit record, and the event-loop lag watch. + * Handlers preserve Bun's fatal semantics — uncaught errors still exit 1 — + * but the stack now lands on disk first. + */ +export function installServerDiagnostics(): void { + if (installed) return; + installed = true; + + process.on("uncaughtException", (error) => { + recordFatalError("uncaughtException", error); + process.exit(1); + }); + process.on("unhandledRejection", (reason) => { + recordFatalError("unhandledRejection", reason); + process.exit(1); + }); + process.on("exit", (code) => { + appendDailyLogSync({ + level: "info", + message: "Server process exiting", + exitCode: code, + uptimeSeconds: Math.round(process.uptime() * 100) / 100, + }); + }); + + startEventLoopLagWatch(); +} diff --git a/apps/server/src/runtime/memory/__tests__/memory-pressure-service.test.ts b/apps/server/src/runtime/memory/__tests__/memory-pressure-service.test.ts index 2a05607f2..a566df2db 100644 --- a/apps/server/src/runtime/memory/__tests__/memory-pressure-service.test.ts +++ b/apps/server/src/runtime/memory/__tests__/memory-pressure-service.test.ts @@ -126,7 +126,7 @@ describe("MemoryPressureService", () => { await vi.advanceTimersByTimeAsync(30_000); - expect(db.run).toHaveBeenCalledWith("PRAGMA optimize"); + expect(db.run).toHaveBeenCalledWith("PRAGMA optimize = 0x10002"); expect(db.run).toHaveBeenCalledWith("PRAGMA shrink_memory"); }); diff --git a/apps/server/src/runtime/memory/memory-pressure-service.ts b/apps/server/src/runtime/memory/memory-pressure-service.ts index b8a468052..f663a178a 100644 --- a/apps/server/src/runtime/memory/memory-pressure-service.ts +++ b/apps/server/src/runtime/memory/memory-pressure-service.ts @@ -285,8 +285,9 @@ export class MemoryPressureService { private enterWarmIdle(): void { this.state = "warm-idle"; logger.info("Entering warm idle: shrinking SQLite + minor GC"); + const startedAt = performance.now(); try { - optimizeSQLiteConnection(this.db, "maintenance"); + optimizeSQLiteConnection(this.db); } catch (err) { logger.warn("SQLite optimization failed", { error: err instanceof Error ? err.message : String(err), @@ -302,6 +303,11 @@ export class MemoryPressureService { if (typeof global.gc === "function") { global.gc(); } + // These synchronous ops block the event loop; the duration ties stalls to + // the health-probe failures they can cause. + logger.info("Warm idle maintenance completed", { + durationMs: Math.round(performance.now() - startedAt), + }); } /** @@ -311,6 +317,7 @@ export class MemoryPressureService { */ private enterBackgroundIdle(): void { logger.info("Entering background idle: full GC + cache reduction"); + const startedAt = performance.now(); try { applySQLiteCacheBudget(this.db, "background"); } catch (err) { @@ -324,6 +331,9 @@ export class MemoryPressureService { global.gc(true); } this.state = "background-idle"; + logger.info("Background idle maintenance completed", { + durationMs: Math.round(performance.now() - startedAt), + }); } /** diff --git a/apps/server/src/runtime/persistence/sqlite/__tests__/database-connection-policy.test.ts b/apps/server/src/runtime/persistence/sqlite/__tests__/database-connection-policy.test.ts index 77eaf3099..09225af85 100644 --- a/apps/server/src/runtime/persistence/sqlite/__tests__/database-connection-policy.test.ts +++ b/apps/server/src/runtime/persistence/sqlite/__tests__/database-connection-policy.test.ts @@ -54,7 +54,9 @@ describe("SQLite connection policy", () => { database = openDatabase({ dbPath: NodePath.join(directory, "mcode.db") }); expect(run).toHaveBeenCalledWith("PRAGMA optimize = 0x10002"); - expect(run).toHaveBeenCalledWith("PRAGMA optimize"); + // The unmasked form can ANALYZE every index of a large database, so only + // the bounded mask is allowed even after schema changes. + expect(run).not.toHaveBeenCalledWith("PRAGMA optimize"); expect(run.mock.calls.some(([source]) => /^\s*(?:ANALYZE|VACUUM)\b/i.test(String(source)))) .toBe(false); }); diff --git a/apps/server/src/runtime/persistence/sqlite/database.ts b/apps/server/src/runtime/persistence/sqlite/database.ts index be7ebcdbe..db9205bc5 100644 --- a/apps/server/src/runtime/persistence/sqlite/database.ts +++ b/apps/server/src/runtime/persistence/sqlite/database.ts @@ -210,11 +210,11 @@ export function openDatabase(opts?: OpenDatabaseOptions): Database { try { db = new Database(resolvedPath, { strict: true }); applySQLiteConnectionPolicy(db, true); - optimizeSQLiteConnection(db, "open"); + optimizeSQLiteConnection(db); const schemaVersionBeforeMigrations = readSchemaVersion(db); runMigrations(db); if (readSchemaVersion(db) !== schemaVersionBeforeMigrations) { - optimizeSQLiteConnection(db, "maintenance"); + optimizeSQLiteConnection(db); } if (backupPath) { pruneMigrationBackups(resolvedPath); diff --git a/apps/server/src/runtime/persistence/sqlite/sqlite-connection-policy.ts b/apps/server/src/runtime/persistence/sqlite/sqlite-connection-policy.ts index 1c95a98ed..7003890cb 100644 --- a/apps/server/src/runtime/persistence/sqlite/sqlite-connection-policy.ts +++ b/apps/server/src/runtime/persistence/sqlite/sqlite-connection-policy.ts @@ -59,10 +59,10 @@ export function applySQLiteCacheBudget( return cacheKiB; } -/** Run SQLite's bounded optimization for connection startup or later maintenance. */ -export function optimizeSQLiteConnection( - db: Database, - phase: "open" | "maintenance", -): void { - db.run(phase === "open" ? "PRAGMA optimize = 0x10002" : "PRAGMA optimize"); +/** + * Run SQLite's bounded optimization. The unmasked form can ANALYZE every index + * of a large database, blocking the event loop for seconds on a 1GB file. + */ +export function optimizeSQLiteConnection(db: Database): void { + db.run("PRAGMA optimize = 0x10002"); } diff --git a/apps/web/src/transport/ws-transport.ts b/apps/web/src/transport/ws-transport.ts index 877c2ccf7..c86e39827 100644 --- a/apps/web/src/transport/ws-transport.ts +++ b/apps/web/src/transport/ws-transport.ts @@ -339,11 +339,19 @@ export function createWsTransport( /** Resolves when the current WebSocket connection is open. */ let ready: Promise; - let resolveReady: () => void; + let resolveReady: () => void = () => undefined; + let readyPending = false; function resetReady() { + // A still-pending promise may have rpc() calls parked on it; replacing it + // would strand them forever. + if (readyPending) return; + readyPending = true; ready = new Promise((resolve) => { - resolveReady = resolve; + resolveReady = () => { + readyPending = false; + resolve(); + }; }); } @@ -495,6 +503,9 @@ export function createWsTransport( rejectPending("WebSocket disconnected"); invalidateLiveTurnDiff(); if (!closed) { + // Re-arm `ready` so rpc() calls park until the reconnect opens instead + // of sending on a dead socket. + resetReady(); const isAuthFailure = event.code === 4001; options?.onStatusChange?.(isAuthFailure ? "authFailed" : "reconnecting"); scheduleReconnect(isAuthFailure); @@ -577,7 +588,10 @@ export function createWsTransport( const terminalClientSelector = new TerminalClientSelector( (method: string, params: Record) => rpc(method, params), - (frame) => ws.send(frame), + (frame) => { + // Drop terminal frames while the socket is down; reattach resyncs output. + if (ws.readyState === WebSocket.OPEN) ws.send(frame); + }, async (scopeId) => { const { useWorkspaceStore } = await import("@/features/projects/state/workspaceStore"); const state = useWorkspaceStore.getState(); @@ -1244,6 +1258,7 @@ export function createWsTransport( clearTimeout(reconnectTimer); reconnectTimer = null; } + resolveReady(); rejectPending("Transport closed"); ws.close(); }, diff --git a/docs/agents/runtime.md b/docs/agents/runtime.md index b13cad6f8..2d56ae2c4 100644 --- a/docs/agents/runtime.md +++ b/docs/agents/runtime.md @@ -70,11 +70,18 @@ minutes. ## Desktop startup diagnostics -Desktop launches save server errors to `server-stderr.log` in `MCODE_DATA_DIR`, +Desktop launches save server output to `server-stderr.log` in `MCODE_DATA_DIR`, including development launches. Normal worktree development uses `.dev/server-stderr.log`. The next launch moves the previous log to `server-stderr.1.log`. The startup failure dialog includes the last 40 lines. -Server stderr goes directly to this file; stdin and stdout stay isolated from the desktop terminal. +Server stderr and stdout both go directly to this file; stdin stays isolated +from the desktop terminal. + +The server also writes crash diagnostics synchronously, bypassing the buffered +logger: a `fatal` record in the daily `mcode.log.` file and a mirror in +`server-fatal.log` next to `server-stderr.log`. The fatal record carries the +error name, message, stack, errno fields, PID, and uptime. Event-loop stalls +over 500ms and every process exit are appended to the daily log the same way. Startup checkpoint logs use past-tense messages and include the completed stage, server PID, and elapsed milliseconds since the bootstrap function began. diff --git a/packages/providers/src/private/codex/codex-app-server.ts b/packages/providers/src/private/codex/codex-app-server.ts index 59abf0bea..815adb118 100644 --- a/packages/providers/src/private/codex/codex-app-server.ts +++ b/packages/providers/src/private/codex/codex-app-server.ts @@ -847,6 +847,12 @@ export async function warmCodexAppServer( child.once("error", () => finish({ initialized, rateLimitsPayload: latestRateLimitsPayload })); child.once("exit", () => finish({ initialized, rateLimitsPayload: latestRateLimitsPayload })); + // A dead child's stdin emits 'error' (EPIPE); without a listener the throw + // becomes an uncaught exception that kills the whole server process. + child.stdin!.on("error", (error: Error) => { + logger.warn("Codex app-server stdin error during warm-up", { error: error.message }); + }); + let buffer = ""; child.stdout!.setEncoding("utf8"); child.stdout!.on("data", (chunk: string) => { diff --git a/packages/providers/src/private/cursor/stream-json/cursor-turn-runner.ts b/packages/providers/src/private/cursor/stream-json/cursor-turn-runner.ts index fff7ad47e..d5c3a5069 100644 --- a/packages/providers/src/private/cursor/stream-json/cursor-turn-runner.ts +++ b/packages/providers/src/private/cursor/stream-json/cursor-turn-runner.ts @@ -190,6 +190,9 @@ export async function runCursorTurn( // Use stdin so prompt text does not cross shell parsing on Windows. const stdin = child.stdin; if (stdin) { + // An early CLI exit can close stdin first; an unhandled stream 'error' + // (EPIPE) would take the whole server down. + stdin.on("error", () => undefined); stdin.write(options.prompt); stdin.end(); }