diff --git a/src/main/index.ts b/src/main/index.ts index a5e7cc50..094dd0da 100644 --- a/src/main/index.ts +++ b/src/main/index.ts @@ -14,7 +14,7 @@ import { getShouldPreventClose } from "@src/utils/shouldPreventClose" import icon from "../../resources/icon.png?asset" import { logMessage } from "@src/utils/logManager" import { createUpdaterLogger } from "@src/utils/updaterLogger" -import { makeConsoleOutputFaultTolerant } from "@src/utils/consoleTransportSafety" +import { createSuppressedErrorRecorder, makeConsoleOutputFaultTolerant } from "@src/utils/consoleTransportSafety" import { IPC_CHANNELS } from "@src/ipc/ipcChannels" import { isTrustedIpcSender, registerTrustedWebContents } from "@src/ipc/ipcSecurity" import { assertAllowedBrowserUrl, isAllowedRendererUrl, resolveContainedPath } from "@src/ipc/validation" @@ -37,7 +37,13 @@ import { clearTimeout, setTimeout } from "node:timers" // Placed before resolvePathFn rather than after it, unlike autoUpdater.logger below: this // guard touches no path and writes no file, so it has nothing to wait for, and running it // first means it is already in place for the very first line logged below. -makeConsoleOutputFaultTolerant(Logger.transports.console) +// #256: the guard swallows every console failure, so the first one leaves a line in the log +// file, otherwise an ordinary transport bug would be indistinguishable from silence. Handing it +// the file transport rather than Logger.error keeps the record off the console that just failed. +// The whole logger goes in rather than just its console transport: a format or transform failure +// is reported through Logger.processInternalErrorFn instead of the write, and that seam needs the +// same recorder for the failure to leave a trace. +makeConsoleOutputFaultTolerant(Logger, undefined, createSuppressedErrorRecorder(Logger.transports.file)) Logger.transports.file.resolvePathFn = (variables, message): string => { const logsPath = join(variables.userData, "Logs") diff --git a/src/utils/consoleTransportSafety.ts b/src/utils/consoleTransportSafety.ts index f39e1660..c45faf79 100644 --- a/src/utils/consoleTransportSafety.ts +++ b/src/utils/consoleTransportSafety.ts @@ -1,8 +1,8 @@ /** * Console output must never be able to take the launcher down (#247). * - * Two different failures are possible when the terminal that started the app goes away, and - * they need two different guards: + * Three different failures reach the console transport, at three different points, and they need + * three different guards. The first two are what a terminal that has gone away produces: * * 1. Asynchronous. On Linux and macOS a write to process.stdout completes on a later tick, * so the EPIPE arrives as an "error" event on the stream, long after console.info() has @@ -19,16 +19,24 @@ * Logger.info(). Wrapping writeFn covers both writes, since the internal error reporter * reads transports.console.writeFn at call time. * + * 3. Earlier than the write. The console transport formats and transforms the message before it + * writes anything, and a throw from that stage never reaches writeFn at all. electron-log + * catches it per transport, so it crashes nothing, and reports it through + * processInternalErrorFn, which is where the recorder has to be hooked for the failure to be + * diagnosable rather than merely survivable. See makeConsoleOutputFaultTolerant below. + * * Every write error on the guarded streams is swallowed, not only EPIPE: the same "nobody is * reading any more" condition surfaces as EIO on a closed pty, ERR_STREAM_DESTROYED or * ERR_STREAM_WRITE_AFTER_END on a follow-up write after the stream tore itself down, or * ECONNRESET for socket-backed stdio. An allowlist of codes leaves the app one unlisted code * away from the same modal dialog, which is the class of bug this guards against. The file - * transport is untouched by either guard, so the Logs directory still records every line the + * transport is untouched by all three, so the Logs directory still records every line the * app logs; only the console copy is dropped. The one thing this hides is a genuine ENOSPC * from a redirected stdout, judged acceptable since the file transport is the app's real log. */ +import { redactSensitiveText } from "./logManager" + /** Anything that accepts an "error" listener: process.stdout/process.stderr here, a plain EventEmitter in tests. */ export interface ErrorEmittingStream { on(event: "error", listener: (error: NodeJS.ErrnoException) => void): unknown @@ -37,12 +45,58 @@ export interface ErrorEmittingStream { /** * Diagnostics seam. Called with every error that was swallowed. Never wire this to logMessage * in production: logging to the same broken stream would emit another "error" event, which - * would call this handler again, an unbounded async loop. It exists so tests can observe - * suppression, and so a future caller can route to the file transport only if that ever - * becomes necessary. + * would call this handler again, an unbounded async loop. createSuppressedErrorRecorder below + * is the handler production uses; anything else here exists so tests can observe suppression. */ export type SuppressedErrorHandler = (error: unknown) => void +/** The subset of electron-log's file transport the recorder calls: Logger.transports.file satisfies it. */ +export type LogFileTransport = (message: { data: unknown[]; date: Date; level: "error" }) => void + +/** Error name, errno code and message on one line. The code is the part that separates a dead pipe from a real bug. */ +function describeSuppressedError(error: unknown): string { + if (!(error instanceof Error)) return redactSensitiveText(`non-Error value: ${String(error)}`) + + const code = (error as NodeJS.ErrnoException).code + return redactSensitiveText(`${error.name}${code ? ` (${code})` : ""}: ${error.message}`) +} + +/** + * Records the first suppressed console failure and stays silent afterwards (#256). + * + * The catches above keep a dead pipe from taking the app down, but on their own they hide an + * ordinary transport bug just as completely: a TypeError out of a format hook would vanish with + * no trace anywhere. This writes one line so that bug is findable. Three properties make the + * recording safe to do from inside a failing write: + * + * - It calls the file transport directly instead of Logger.error, which would fan the message + * back out to the very console transport that just failed. + * - It fires once. A dead pipe fails on every subsequent write, and a per-failure record would + * fill the log file with copies of the same error; the flag is set before the write, so a + * throw on the way out cannot leave it armed for a second attempt. + * - It swallows its own failure. The handler that would otherwise catch a throw from here is + * this same handler, so letting one escape is how the recursion the guard exists to prevent + * would come back. + */ +export function createSuppressedErrorRecorder(writeToFile: LogFileTransport): SuppressedErrorHandler { + let recorded = false + + return (error: unknown): void => { + if (recorded) return + recorded = true + + try { + writeToFile({ + data: [`[back] [index] [utils/consoleTransportSafety.ts] [onSuppressed] console output failed and was suppressed, later suppressions are silent: ${describeSuppressedError(error)}`], + date: new Date(), + level: "error" + }) + } catch { + // Nothing to do with it: reporting a failure to report a failure is where the loop starts. + } + } +} + /** Keeps a failed write on `stream` from becoming an unhandled "error" event, i.e. an uncaught exception. */ export function suppressStreamWriteErrors(stream: ErrorEmittingStream | undefined, onSuppressed?: SuppressedErrorHandler): void { if (!stream) return @@ -63,9 +117,17 @@ export function createSafeConsoleWrite(write: (...args: } } -/** Wires both guards. `consoleTransport` is electron-log's Logger.transports.console; the generic keeps its exact writeFn signature. */ +/** + * The parts of electron-log's Logger this file touches. The whole logger is accepted because the + * console transport must be guarded before electron-log's per-transport error handler runs. + */ +export interface FaultTolerantLogger { + transports: { console: { writeFn: (...args: Args) => void } } +} + +/** Wires all three guards. `logger` is electron-log's default export; the generic keeps writeFn's exact signature. */ export function makeConsoleOutputFaultTolerant( - consoleTransport: { writeFn: (...args: Args) => void }, + logger: FaultTolerantLogger, streams: readonly (ErrorEmittingStream | undefined)[] = [process.stdout, process.stderr], onSuppressed?: SuppressedErrorHandler ): void { @@ -73,5 +135,27 @@ export function makeConsoleOutputFaultTolerant( suppressStreamWriteErrors(stream, onSuppressed) } + const consoleTransport = logger.transports.console consoleTransport.writeFn = createSafeConsoleWrite(consoleTransport.writeFn, onSuppressed) + + // The write guard above is the last stage of the console transport, and only that stage. A + // console transport call is transform() over transports.console.transforms, one of which reads + // transports.console.format, and only then writeFn (node_modules/electron-log/src/node/ + // transports/console.js). A throw from a format hook or any other transform never reaches the + // write, so the wrapper cannot see it; processMessage catches it per transport and hands it to + // processInternalErrorFn. Wrap the callable transport itself so the failure reaches the same + // bounded recorder without replacing the logger's global error reporter. That keeps unrelated + // file, IPC, and remote transport errors on electron-log's normal diagnostic path. + if (onSuppressed) { + const callableTransport = consoleTransport as typeof consoleTransport & ((...args: unknown[]) => void) + logger.transports.console = new Proxy(callableTransport, { + apply(target, thisArg, args): void { + try { + Reflect.apply(target, thisArg, args) + } catch (error) { + onSuppressed(error) + } + } + }) as typeof consoleTransport + } } diff --git a/tests/utils/consoleTransportSafety.test.ts b/tests/utils/consoleTransportSafety.test.ts index a60f1d67..e23b1d92 100644 --- a/tests/utils/consoleTransportSafety.test.ts +++ b/tests/utils/consoleTransportSafety.test.ts @@ -3,7 +3,7 @@ import { EventEmitter } from "node:events" import Logger from "electron-log" import { afterEach, describe, it } from "vitest" -import { createSafeConsoleWrite, makeConsoleOutputFaultTolerant, suppressStreamWriteErrors } from "../../src/utils/consoleTransportSafety" +import { createSafeConsoleWrite, createSuppressedErrorRecorder, makeConsoleOutputFaultTolerant, suppressStreamWriteErrors } from "../../src/utils/consoleTransportSafety" /** What Node hands the app when the reader on the other end of stdout is gone. */ function brokenPipeError(): NodeJS.ErrnoException { @@ -123,50 +123,334 @@ describe("createSafeConsoleWrite", () => { describe("makeConsoleOutputFaultTolerant", () => { it("replaces the transport's writeFn with one that cannot throw", () => { - const transport = { - writeFn: (): void => { - throw brokenPipeError() + const logger = { + transports: { + console: Object.assign((): void => {}, { + writeFn: (): void => { + throw brokenPipeError() + } + }) } } - makeConsoleOutputFaultTolerant(transport, []) + makeConsoleOutputFaultTolerant(logger, []) - assert.doesNotThrow(() => transport.writeFn()) + assert.doesNotThrow(() => logger.transports.console.writeFn()) }) it("guards the streams it is given as well as the transport", () => { const stdoutLike = new EventEmitter() const stderrLike = new EventEmitter() - const transport = { writeFn: (): void => {} } + const logger = { + transports: { + console: Object.assign(() => {}, { writeFn: (): void => {} }) + } + } - makeConsoleOutputFaultTolerant(transport, [stdoutLike, stderrLike]) + makeConsoleOutputFaultTolerant(logger, [stdoutLike, stderrLike]) assert.doesNotThrow(() => stdoutLike.emit("error", brokenPipeError())) assert.doesNotThrow(() => stderrLike.emit("error", brokenPipeError())) }) + + it("captures callable transport failures without replacing the logger's internal reporter", () => { + const { errors, onSuppressed } = suppressedErrors() + const untouched = (): void => {} + const consoleTransport = Object.assign( + (): void => { + throw new TypeError("format hook failed") + }, + { writeFn: (): void => {} } + ) + const logger = { + transports: { console: consoleTransport }, + processInternalErrorFn: untouched + } + + makeConsoleOutputFaultTolerant(logger, [], onSuppressed) + assert.doesNotThrow(() => logger.transports.console()) + + assert.deepEqual( + errors.map((error) => String(error)), + ["TypeError: format hook failed"] + ) + assert.equal(logger.processInternalErrorFn, untouched) + }) + + it("leaves the reporter alone when there is nothing to record with", () => { + // Without a recorder, electron-log's own handler is still better than a silent no-op. + const untouched = (): void => {} + const logger = { + transports: { console: Object.assign(() => {}, { writeFn: (): void => {} }) }, + processInternalErrorFn: untouched + } + + makeConsoleOutputFaultTolerant(logger, []) + + assert.equal(logger.processInternalErrorFn, untouched) + }) +}) + +describe("createSuppressedErrorRecorder", () => { + /** Runs one suppression past a collecting file transport and returns the line it was handed. */ + function recordSuppression(error: unknown): { line: string; level: string } { + const written: { data: unknown[]; level: string }[] = [] + createSuppressedErrorRecorder((message) => void written.push(message))(error) + + const [record] = written + assert.ok(record, "the recorder wrote nothing to the file transport") + return { line: String(record.data[0]), level: record.level } + } + + it("records the first suppressed failure through the file transport", () => { + const { line, level } = recordSuppression(brokenPipeError()) + + assert.equal(level, "error") + assert.match(line, /console output failed and was suppressed.*Error \(EPIPE\): write EPIPE/) + }) + + it("stays silent after the first one, so a permanently dead pipe writes one line and not thousands", () => { + const written: unknown[] = [] + const record = createSuppressedErrorRecorder((message) => void written.push(message)) + + for (let i = 0; i < 5; i++) record(brokenPipeError()) + + assert.equal(written.length, 1) + }) + + it("names the error when it is not a dead pipe, which is the failure this exists to surface", () => { + const { line } = recordSuppression(new TypeError("hook is not a function")) + + // No errno code on this one, so nothing is invented to fill the slot. + assert.match(line, /TypeError: hook is not a function/) + assert.doesNotMatch(line, /TypeError \(/) + }) + + it("redacts credentials out of the error before it reaches disk", () => { + const { line } = recordSuppression(new Error("write failed for token=hunter2")) + + assert.match(line, /token=\[REDACTED\]/) + assert.doesNotMatch(line, /hunter2/) + }) + + it("describes a thrown value that is not an Error at all", () => { + assert.match(recordSuppression("just a string").line, /non-Error value: just a string/) + }) + + it("swallows a failure of its own, because the handler that would catch it is itself", () => { + const record = createSuppressedErrorRecorder((): void => { + throw new Error("the file transport is broken too") + }) + + assert.doesNotThrow(() => record(brokenPipeError())) + // And it does not arm itself for a retry: the flag is set before the write, not after it. + assert.doesNotThrow(() => record(brokenPipeError())) + }) }) describe("electron-log's own console failure, guarded and unguarded", () => { + /** processInternalErrorFn exists on electron-log's Logger class but not in its type definitions. */ + const loggerInternals = Logger as unknown as { processInternalErrorFn: (error: unknown) => void } + + const originalConsoleTransport = Logger.transports.console const originalWriteFn = Logger.transports.console.writeFn + const originalFileTransport = Logger.transports.file + const originalFormat = Logger.transports.console.format + const originalTransforms = Logger.transports.console.transforms + const originalProcessInternalErrorFn = loggerInternals.processInternalErrorFn afterEach(() => { + Logger.transports.console = originalConsoleTransport Logger.transports.console.writeFn = originalWriteFn + Logger.transports.file = originalFileTransport + Logger.transports.console.format = originalFormat + Logger.transports.console.transforms = originalTransforms + loggerInternals.processInternalErrorFn = originalProcessInternalErrorFn }) - it("a failing console transport escapes Logger.info while nothing guards it", () => { + /** + * Swaps the singleton's file transport for a collector, so these tests read what the file + * transport was handed without going near the developer's real Logs directory. The level is + * set because tests/setup-node.ts pins the real one to false, which would make processMessage + * skip it and hide the very delivery these tests are about. + */ + function collectFileTransport(): { data: unknown[] }[] { + const received: { data: unknown[] }[] = [] + const collector = (message: { data: unknown[] }): void => void received.push(message) + collector.level = "silly" + Logger.transports.file = collector as unknown as typeof Logger.transports.file + return received + } + + function breakTheConsoleTransport(): void { Logger.transports.console.writeFn = (): void => { throw brokenPipeError() } + } + + /** Splits what the file transport received into the suppression records and the ordinary log lines. */ + function partitionRecords(received: { data: unknown[] }[]): { records: string[]; lines: unknown[] } { + const isRecord = (message: { data: unknown[] }): boolean => /console output failed and was suppressed/.test(String(message.data[0])) + return { + records: received.filter(isRecord).map((message) => String(message.data[0])), + lines: received.filter((message) => !isRecord(message)).map((message) => message.data[0]) + } + } + + /** The same call src/main/index.ts makes, minus the real process streams. */ + function wireTheAppsGuards(): void { + makeConsoleOutputFaultTolerant(Logger, [], createSuppressedErrorRecorder(Logger.transports.file)) + } + + it("a failing console transport escapes Logger.info while nothing guards it", () => { + breakTheConsoleTransport() + + assert.throws(() => Logger.info("a line nobody can read"), { code: "EPIPE" }) + }) + + it("takes the file transport down with it while nothing guards it", () => { + // Not a partial record, none at all: electron-log walks its transports in order, console + // first, and the re-throw out of processInternalErrorFn leaves processMessage before the + // loop ever reaches the file transport. Losing the console copy loses the on-disk log too. + const received = collectFileTransport() + breakTheConsoleTransport() assert.throws(() => Logger.info("a line nobody can read"), { code: "EPIPE" }) + assert.equal(received.length, 0) }) it("Logger.info survives the same failing transport once it is made fault tolerant", () => { - Logger.transports.console.writeFn = (): void => { - throw brokenPipeError() - } + breakTheConsoleTransport() - makeConsoleOutputFaultTolerant(Logger.transports.console, []) + makeConsoleOutputFaultTolerant(Logger, []) assert.doesNotThrow(() => Logger.info("a line nobody can read")) }) + + it("keeps delivering to the file transport while the console transport is dead", () => { + const received = collectFileTransport() + breakTheConsoleTransport() + + makeConsoleOutputFaultTolerant(Logger, []) + Logger.info("first line after the pipe died") + Logger.info("second line after the pipe died") + + assert.deepEqual( + received.map((message) => message.data[0]), + ["first line after the pipe died", "second line after the pipe died"] + ) + }) + + it("leaves one suppression record in the file transport, wired the way the app wires it", () => { + const received = collectFileTransport() + breakTheConsoleTransport() + + // The same call src/main/index.ts makes, default streams included. + makeConsoleOutputFaultTolerant(Logger, undefined, createSuppressedErrorRecorder(Logger.transports.file)) + Logger.info("first line after the pipe died") + Logger.info("second line after the pipe died") + + // The record lands first, from inside the console write that failed, then the two log lines. + const [record] = received + assert.ok(record, "no suppression record reached the file transport") + assert.match(String(record.data[0]), /console output failed and was suppressed.*\(EPIPE\)/) + assert.deepEqual( + received.slice(1).map((message) => message.data[0]), + ["first line after the pipe died", "second line after the pipe died"] + ) + }) + + it("records a throwing console format, which never reaches the write guard at all", () => { + // The console transport runs its transforms, one of which reads transports.console.format, + // before it writes anything, so this failure comes out of processMessage's own catch and is + // reported through processInternalErrorFn. Unhooked, the file transport still gets the line + // and the app still runs, and the TypeError behind it is never written down anywhere. + const received = collectFileTransport() + Logger.transports.console.format = (): never => { + throw new TypeError("format hook failed") + } + + wireTheAppsGuards() + assert.doesNotThrow(() => Logger.info("first line after the format broke")) + Logger.info("second line after the format broke") + + const { records, lines } = partitionRecords(received) + assert.equal(records.length, 1, `expected one suppression record, got ${records.length}`) + assert.match(String(records[0]), /TypeError: format hook failed/) + assert.deepEqual(lines, ["first line after the format broke", "second line after the format broke"]) + }) + + it("redacts the format failure and writes it without going back through the console transport", () => { + const received = collectFileTransport() + let consoleWrites = 0 + Logger.transports.console.writeFn = (): void => void consoleWrites++ + Logger.transports.console.format = (): never => { + throw new TypeError("format hook failed for token=hunter2") + } + + wireTheAppsGuards() + Logger.info("a line the console never gets") + + const { records } = partitionRecords(received) + assert.match(String(records[0]), /token=\[REDACTED\]/) + assert.doesNotMatch(String(records[0]), /hunter2/) + // Nothing is echoed to the transport that just failed, which is where the loop would start. + assert.equal(consoleWrites, 0) + }) + + it("records a throwing transform the same way, since it fails at the same point in the transport", () => { + const received = collectFileTransport() + Logger.transports.console.transforms = [ + ...Logger.transports.console.transforms, + (): never => { + throw new TypeError("transform hook failed") + } + ] + + wireTheAppsGuards() + assert.doesNotThrow(() => Logger.info("first line after the transform broke")) + Logger.info("second line after the transform broke") + + const { records, lines } = partitionRecords(received) + assert.equal(records.length, 1, `expected one suppression record, got ${records.length}`) + assert.match(String(records[0]), /TypeError: transform hook failed/) + assert.deepEqual(lines, ["first line after the transform broke", "second line after the transform broke"]) + }) + + it("keeps an unrelated file transport failure on electron-log's normal diagnostic path", () => { + const received: { data: unknown[] }[] = [] + let fileAttempts = 0 + const failingFile = Object.assign( + (message: { data: unknown[] }): void => { + fileAttempts++ + if (fileAttempts === 1) throw new Error("disk write failed") + received.push(message) + }, + { level: "silly" } + ) + const consoleMessages: { data: unknown[] }[] = [] + Logger.transports.file = failingFile as unknown as typeof Logger.transports.file + Logger.transports.console.writeFn = ({ message }): void => void consoleMessages.push(message) + + wireTheAppsGuards() + assert.doesNotThrow(() => Logger.info("a line with a broken file transport")) + + assert.equal(fileAttempts, 1) + assert.equal(received.length, 0) + assert.match(String(consoleMessages[0]?.data[0]), /a line with a broken file transport/) + assert.equal(consoleMessages[1]?.data[0], "Unhandled electron-log error") + assert.equal(loggerInternals.processInternalErrorFn, originalProcessInternalErrorFn) + }) + + it("costs one record whichever stage fails first, because every stage shares the one recorder", () => { + const received = collectFileTransport() + breakTheConsoleTransport() + Logger.transports.console.format = (): never => { + throw new TypeError("format hook failed") + } + + wireTheAppsGuards() + for (let i = 0; i < 5; i++) Logger.info("a line nobody can read") + + assert.equal(partitionRecords(received).records.length, 1) + }) })