diff --git a/apps/packaged/src/logging.ts b/apps/packaged/src/logging.ts index 505ce331022..1867df8c1fa 100644 --- a/apps/packaged/src/logging.ts +++ b/apps/packaged/src/logging.ts @@ -218,26 +218,117 @@ export function createPackagedDesktopLogger(paths: PackagedNamespacePaths): Pack warn: console.warn.bind(console), }; + // Packaged Electron on Windows / Linux has no controlling terminal: + // `process.stdout` / `process.stderr` are typically detached or + // piped to a closed handle, so the very first `console.info(...)` + // a renderer lifecycle handler fires (e.g. `did-start-loading`) + // raises `Error: EPIPE: broken pipe, write` from + // `node:internal/streams/writable:508`. The error escapes the + // wrapper because the throws happen *inside* `Writable.write`, not + // at the call site, and lands in the packaged main process as an + // uncaught exception that crashes the whole app with Electron's + // native "JavaScript error in main process" dialog. + // + // The structured file logger above already swallows its own + // append failures (see `appendDesktopLogLine`). This wrapper does + // the same for the stdout / stderr echo: only the two known-safe + // stream-closure error codes are swallowed, and the matcher is + // intentionally narrow (a future `code: 'EACCES'`-style regression + // that broadens the filter trips the regression test in + // `tests/logging.test.ts`). + // + // This try/catch alone is NOT sufficient to stop the crash: it only + // catches a *synchronous* throw, and a detached stdout/stderr pipe + // fails asynchronously instead. See `installStdioErrorGuard` below + // for the layer that actually covers that path. + const safeEcho = (fn: (...a: unknown[]) => void) => (...args: unknown[]) => { + if (!echo) return; + try { + fn(...args); + } catch (error) { + if (isHarmlessStdoutError(error)) return; + throw error; + } + }; + console.log = (...args: unknown[]) => { logger.info("console.log", { args }); - if (echo) originalConsole.log(...args); + safeEcho(originalConsole.log)(...args); }; console.info = (...args: unknown[]) => { logger.info("console.info", { args }); - if (echo) originalConsole.info(...args); + safeEcho(originalConsole.info)(...args); }; console.warn = (...args: unknown[]) => { logger.warn("console.warn", { args }); - if (echo) originalConsole.warn(...args); + safeEcho(originalConsole.warn)(...args); }; console.error = (...args: unknown[]) => { logger.error("console.error", { args }); - if (echo) originalConsole.error(...args); + safeEcho(originalConsole.error)(...args); }; + // safeEcho's try/catch only covers a *synchronous* throw. It does not + // cover this failure mode: verified live on a packaged Windows build + // where safeEcho alone did not stop the crash. See installStdioErrorGuard. + installStdioErrorGuard([process.stdout, process.stderr]); + return logger; } +/** + * Second, independent layer on top of `safeEcho` above. `safeEcho`'s + * try/catch only catches a *synchronous* throw from the echo call, but + * `Writable#write` on a detached stdout/stderr pipe (no controlling + * terminal — the packaged Electron case) fails *asynchronously* + * instead: Node's internal `onwriteError` path schedules the stream's + * own `'error'` event via `process.nextTick` during `destroy()`, so by + * the time it fires, the `try { fn(...args) }` call has already + * returned normally and there is nothing left on the stack to catch. + * + * This is easy to miss because the resulting uncaught exception's + * `.stack` is misleading: V8 fixes `.stack` at `Error` *construction* + * time — deep inside the synchronous write attempt, which includes + * this file's `safeEcho` frames — not at throw time. It looks like the + * error went through `safeEcho` and escaped it, when it actually never + * reached that catch block at all. + * + * Streams are passed in (rather than reading `process.stdout` / + * `process.stderr` directly) so this can be unit tested against fakes. + */ +export function installStdioErrorGuard(streams: Iterable): void { + for (const stream of streams) { + stream.on("error", (error) => { + if (isHarmlessStdoutError(error)) return; + throw error; + }); + } +} + +/** + * Recognise the two known-harmless stream-closure error codes that + * packaged Electron's stdout / stderr can raise when the underlying + * pipe has been detached (no controlling terminal, redirected to a + * closed handle, or explicitly `.destroy()`ed by the host). + * + * - `EPIPE` — classic POSIX broken-pipe on `write` + * - `ERR_STREAM_DESTROYED` — Node's "stream was destroyed" state + * + * The matcher is intentionally narrow: it requires the structured + * `code` property to be present and to equal one of the two known + * values. A bare `Error` with "broken pipe" in its message but no + * `code` is rejected so that real I/O failures (e.g. an EACCES on + * a file write that happens to mention pipes) are not silently + * dropped. Tests in `tests/logging.test.ts` pin both edges. + * + * @see https://github.com/nexu-io/open-design/issues/6964 + */ +export function isHarmlessStdoutError(error: unknown): boolean { + if (error == null || typeof error !== "object") return false; + const code = (error as { code?: unknown }).code; + return code === "EPIPE" || code === "ERR_STREAM_DESTROYED"; +} + export function attachPackagedDesktopProcessLogging(options: { logger: PackagedDesktopLogger; paths: PackagedNamespacePaths; diff --git a/apps/packaged/tests/logging.test.ts b/apps/packaged/tests/logging.test.ts index f3db9f90115..306fe3e1d81 100644 --- a/apps/packaged/tests/logging.test.ts +++ b/apps/packaged/tests/logging.test.ts @@ -14,7 +14,8 @@ * @see https://github.com/nexu-io/open-design/issues/895 */ -import { mkdtempSync, rmSync } from 'node:fs'; +import { EventEmitter } from 'node:events'; +import { mkdtempSync, readFileSync, rmSync } from 'node:fs'; import { join } from 'node:path'; import { tmpdir } from 'node:os'; @@ -25,7 +26,9 @@ import { createPackagedDesktopLogger, createFatalUncaughtExceptionHandler, createFatalUnhandledRejectionHandler, + installStdioErrorGuard, isHarmlessSocketOptionError, + isHarmlessStdoutError, type PackagedDesktopLogger, } from '../src/logging.js'; import type { PackagedNamespacePaths } from '../src/paths.js'; @@ -146,6 +149,185 @@ describe('isHarmlessSocketOptionError (issue #895)', () => { }); }); +/** + * Regression coverage for the packaged main-process EPIPE crash that + * surfaces the first time a renderer lifecycle handler calls + * `console.info(...)` in an Electron build with no controlling + * terminal. The wrapper installed by `createPackagedDesktopLogger` + * must swallow only the two known-safe stream-closure codes + * (`EPIPE`, `ERR_STREAM_DESTROYED`) and re-throw anything else, so + * real I/O failures are not silently dropped. + */ +describe('isHarmlessStdoutError (packaged console echo EPIPE guard)', () => { + it('matches an Error with code: EPIPE', () => { + const error = new Error('write EPIPE') as NodeJS.ErrnoException; + error.code = 'EPIPE'; + expect(isHarmlessStdoutError(error)).toBe(true); + }); + + it('matches an Error with code: ERR_STREAM_DESTROYED', () => { + const error = new Error('stream destroyed') as NodeJS.ErrnoException; + error.code = 'ERR_STREAM_DESTROYED'; + expect(isHarmlessStdoutError(error)).toBe(true); + }); + + it('does NOT match a bare Error that mentions "broken pipe" in its message but has no code', () => { + const error = new Error('broken pipe, write'); + expect(isHarmlessStdoutError(error)).toBe(false); + }); + + it('does NOT match an unrelated errno like EACCES even if the message mentions pipes', () => { + const error = new Error('broken pipe while writing to log file') as NodeJS.ErrnoException; + error.code = 'EACCES'; + expect(isHarmlessStdoutError(error)).toBe(false); + }); + + it('does NOT match non-objects (null, undefined, strings)', () => { + expect(isHarmlessStdoutError(null)).toBe(false); + expect(isHarmlessStdoutError(undefined)).toBe(false); + expect(isHarmlessStdoutError('EPIPE')).toBe(false); + }); +}); + +describe('createPackagedDesktopLogger console echo EPIPE guard', () => { + it('swallows an EPIPE thrown by the original console.info echo and still records the call to the desktop log file', () => { + const root = mkdtempSync(join(tmpdir(), 'od-packaged-echo-epipe-')); + const previousEcho = process.env.OD_DESKTOP_LOG_ECHO; + // echo must be on (the default) for safeEcho to be in the path. + delete process.env.OD_DESKTOP_LOG_ECHO; + // Stub the host's console.info BEFORE constructing the logger so + // the factory captures the throwing original as `originalConsole.info` + // (the wrapper then calls safeEcho(originalConsole.info), which is + // the only place the EPIPE filter is applied — see issue #6964). + const epipe = new Error('write EPIPE') as NodeJS.ErrnoException; + epipe.code = 'EPIPE'; + console.info = () => { + throw epipe; + }; + const desktopLogPath = join(root, 'desktop.log'); + try { + createPackagedDesktopLogger(makePaths(root, desktopLogPath)); + + // The wrapped call must NOT throw — the unwrapped version + // crashed the main process via an uncaught exception that + // propagated out of `Writable.write`. + expect(() => + console.info('main window did-start-loading', { url: 'about:blank' }), + ).not.toThrow(); + + // The wrapper must have actually run (and called the file + // logger) — not the bare stub. If the wrapper had been + // bypassed, no record would land in the desktop log file. + const line = readFileSync(desktopLogPath, 'utf8'); + expect(line).toContain('console.info'); + expect(line).toContain('main window did-start-loading'); + } finally { + if (previousEcho == null) { + delete process.env.OD_DESKTOP_LOG_ECHO; + } else { + process.env.OD_DESKTOP_LOG_ECHO = previousEcho; + } + rmSync(root, { recursive: true, force: true }); + } + }); + + it('still re-throws non-harmless errors thrown by the original console.error echo and records the call to the desktop log file', () => { + const root = mkdtempSync(join(tmpdir(), 'od-packaged-echo-other-')); + const previousEcho = process.env.OD_DESKTOP_LOG_ECHO; + delete process.env.OD_DESKTOP_LOG_ECHO; + // Same before/after ordering as the EPIPE case: stub the host's + // console.error BEFORE the factory so originalConsole.error + // captures the throwing stub. + const eacces = new Error('permission denied writing to log file') as NodeJS.ErrnoException; + eacces.code = 'EACCES'; + console.error = () => { + throw eacces; + }; + const desktopLogPath = join(root, 'desktop.log'); + try { + createPackagedDesktopLogger(makePaths(root, desktopLogPath)); + + // The wrapper must surface non-harmless errors so real I/O + // failures are not silently dropped. + expect(() => console.error('fatal write failure')).toThrow(eacces); + + // The wrapper must have actually run (and called the file + // logger BEFORE the echo) — proving the throw escaped via + // safeEcho, not via the bare stub. + const line = readFileSync(desktopLogPath, 'utf8'); + expect(line).toContain('console.error'); + expect(line).toContain('fatal write failure'); + } finally { + if (previousEcho == null) { + delete process.env.OD_DESKTOP_LOG_ECHO; + } else { + process.env.OD_DESKTOP_LOG_ECHO = previousEcho; + } + rmSync(root, { recursive: true, force: true }); + } + }); +}); + +// Regression coverage for the gap `safeEcho`'s try/catch cannot close: +// a detached stdout/stderr pipe fails *asynchronously* (the stream +// emits its own 'error' event, e.g. from `process.nextTick` during +// internal `destroy()`), not as a synchronous throw from `.write()`. +// Reproduced live on a packaged Windows build: the crash's stack trace +// still showed `safeEcho`'s frames (because V8 fixes `.stack` at Error +// *construction* time, not throw time), which made it look like the +// try/catch had been bypassed when in fact it was never reached at all. +describe('installStdioErrorGuard (async stdio pipe-closure guard)', () => { + function fakeStream(): NodeJS.WritableStream { + return new EventEmitter() as unknown as NodeJS.WritableStream; + } + + it('swallows an EPIPE emitted asynchronously on the stream, not thrown synchronously', () => { + const stream = fakeStream(); + installStdioErrorGuard([stream]); + + const epipe = new Error('write EPIPE') as NodeJS.ErrnoException; + epipe.code = 'EPIPE'; + + // This is exactly what safeEcho's try/catch cannot see: nothing on + // the call stack, just an 'error' event firing on its own. + expect(() => (stream as unknown as EventEmitter).emit('error', epipe)).not.toThrow(); + }); + + it('swallows an ERR_STREAM_DESTROYED emitted asynchronously on the stream', () => { + const stream = fakeStream(); + installStdioErrorGuard([stream]); + + const destroyed = new Error('stream destroyed') as NodeJS.ErrnoException; + destroyed.code = 'ERR_STREAM_DESTROYED'; + + expect(() => (stream as unknown as EventEmitter).emit('error', destroyed)).not.toThrow(); + }); + + it('re-throws a non-harmless error emitted on the stream instead of silently dropping it', () => { + const stream = fakeStream(); + installStdioErrorGuard([stream]); + + const eacces = new Error('permission denied') as NodeJS.ErrnoException; + eacces.code = 'EACCES'; + + // EventEmitter re-throws synchronously out of emit() when an + // 'error' listener itself throws. + expect(() => (stream as unknown as EventEmitter).emit('error', eacces)).toThrow(eacces); + }); + + it('installs an independent guard per stream (stdout failure does not depend on stderr)', () => { + const stdout = fakeStream(); + const stderr = fakeStream(); + installStdioErrorGuard([stdout, stderr]); + + const epipe = new Error('write EPIPE') as NodeJS.ErrnoException; + epipe.code = 'EPIPE'; + + expect(() => (stdout as unknown as EventEmitter).emit('error', epipe)).not.toThrow(); + expect(() => (stderr as unknown as EventEmitter).emit('error', epipe)).not.toThrow(); + }); +}); + describe('createPackagedDesktopLogger log-write failures', () => { it('drops descriptor-pressure append failures instead of throwing', () => { const emfile = new Error('too many files') as NodeJS.ErrnoException;