fix(logging): record suppressed console failures and pin file logging - #279
Open
Pixnop wants to merge 2 commits into
Open
fix(logging): record suppressed console failures and pin file logging#279Pixnop wants to merge 2 commits into
Pixnop wants to merge 2 commits into
Conversation
The guard added for #247 catches every synchronous failure of the console transport, which is what keeps a closed terminal from taking the launcher down. On its own it also hides an ordinary bug, a TypeError out of a format hook say, with no trace left anywhere: onSuppressed existed for exactly this but nothing wired it in production. The first suppression now writes one line through the file transport, and every later one stays silent. Calling the file transport directly keeps the record off the console that just failed, the once-only flag keeps a permanently dead pipe from filling the log with copies of the same error, and the recorder swallows a failure of its own, since the handler that would otherwise catch it is the recorder. The error name, its errno code and its message go through the same redaction every other line gets. Refs #256
The review of #252 asked for this and did not get it. Three separate places claim the file transport keeps the complete record when the console copy is dropped, and nothing checked it. Probing it turned up something sharper. Unguarded, the file transport receives nothing at all rather than a partial record: 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. So the guard did not only stop the dialog, it put back file logging that was being dropped with the console copy. Both halves are now pinned against the real electron-log singleton, with the file transport swapped for a collector so nothing goes near a real Logs directory and both transports restored afterwards. Refs #257
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Two follow-ups from #252, which stopped a dead stdout from crashing the launcher but left the guard completely silent. Issue #256 asked for suppressed console failures to leave a trace somewhere, and issue #257 asked for the regression coverage the review of #252 requested and did not get.
What gets recorded, and where
createSuppressedErrorRecorderinsrc/utils/consoleTransportSafety.tsis theonSuppressedhandler production now uses.src/main/index.tsbuilds it fromLogger.transports.fileand hands it tomakeConsoleOutputFaultTolerant, which is the wiring the hook was written for and never got.The first suppressed failure produces one line at error level, through the file transport, reading
console output failed and was suppressed, later suppressions are silent:followed by the error name, its errno code where there is one, and its message. Everything after the first is dropped on the floor.Three things keep the recording from re-entering the trap it reports on. It calls the file transport as a function rather than going through
Logger.error, so the message never fans back out to the console transport that just failed. It fires once, because a dead pipe fails on every subsequent write and a per-failure record would fill the log file with thousands of copies of the same EPIPE; the flag is set before the write rather than after, so a throw on the way out cannot leave it armed for a retry. And it catches its own failure and does nothing with it, since the handler that would otherwise catch a throw from there is that same handler.The line goes through
redactSensitiveText, the same redaction every other line in the app gets, so a credential or an absolute path carried in an error message does not reach disk.Keeping no allowlist of error codes was right and nothing here changes it. A dead pipe still costs one line rather than a crash. What changes is that a TypeError out of a format hook, the failure this guard would otherwise hide forever, now names itself in the log file.
What the new coverage pins
For #257, two assertions against the real electron-log singleton with its file transport swapped for a collector.
Unguarded, a failing console transport takes the file transport down with it, and not partially: the collector receives nothing at all. electron-log walks its transports in order with console first, and the re-throw out of
processInternalErrorFnleavesprocessMessagebefore the loop ever reaches the file transport. That is the sharper finding from the review of #252, and it means the guard did two things rather than one, stopping the dialog and putting back on-disk logging that was being dropped along with the console copy.Guarded, both later log lines arrive at the file transport with the console write still throwing EPIPE on every call.
A third test covers the #256 path end to end, wired the way
src/main/index.tswires it, default streams included: with the console transport dead, the file transport receives exactly one suppression record followed by both log lines, and no second record.The collector replaces
Logger.transports.filefor the duration and both transports are restored afterwards, so nothing touches a real Logs directory. It needs an explicit level becausetests/setup-node.tspins the real file transport tofalse, which would makeprocessMessageskip it and hide the very delivery these tests are about.Driven for real, and mocked
The singleton is real in all five of those tests: real
Logger.info, realprocessMessage, real transport loop, real internal error path. What is faked is the failure itself, awriteFnthat throws a hand-built EPIPE, and the destination, a collector standing in for the file transport.Outside the suite I checked the same wiring against a genuine dead pipe, the shape the review of #252 used: a node process logging through
electron-log/nodewith its stdout piped intohead -c 1, one line first, then a pause so the reader has definitely exited, then eleven more. With the guards and the recorder inlined, the log file ends with all twelve lines followed by exactly one record readingconsole output failed and was suppressed, later suppressions are silent: Error (EPIPE): write EPIPE. So the recording path fires on a real EPIPE from a real closed pipe, not only on a thrown fake.One difference from the review's environment worth stating. On this machine, Node 22.22 on Linux, the unguarded run of that probe did not crash: stdout to a pipe is synchronous here, so the EPIPE lands inside the window where Node's own console holds a temporary noop listener. A bare
process.stdout.writewith no listener at all does still produce an uncaught EPIPE, so the mechanism is present, it just does not surface throughconsole.infoon this setup. That environment dependence is the same one #252 documented, and it is why both guards exist rather than either alone.Mutation testing
Three mutations, one at a time, against the new suite.
Removing the try/catch from
createSafeConsoleWritefails seven tests, including both new file transport ones. Removing the once-only flag from the recorder fails two, the silence test and the end to end one. Removing the recorder's own catch fails one, the test that a broken file transport does not escape into the handler. Each guard is carrying its own weight.Testing
npm run typecheck: passes.npm run lint:ci: 0 errors, 15 warnings, all pre-existing and unchanged fromdev.npm run format:check: passes.npm run test:coverage: 137 files, 1642 passed, 2 skipped, up by the 9 new tests. Coverage 92.61% statements, 89.86% branches, 92.06% functions, 94.06% lines, every one above thevitest.config.tsfloors of 87/85/85/89.Related issues
Follow-ups to #252, addressing #256 and #257.