Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Do not write verbose logs synchronously #1167

Merged
merged 1 commit into from
Oct 28, 2024
Merged

Do not write verbose logs synchronously #1167

merged 1 commit into from
Oct 28, 2024

Conversation

ehmicky
Copy link
Collaborator

@ehmicky ehmicky commented Oct 28, 2024

Background in #1165 and #600.

When the verbose option is enabled, logs are printed on stderr. At the same time, the subprocess might print its output on stdout or stderr. To ensure that verbose logs are always printed in the same order when they interleave with the subprocess output, we are using synchronous I/O (fs.writeFileSync(2, ...)).

Unfortunately, this does not work. That's because, even when stderr is written synchronously, it seems to be buffered by the OS. Since stdout and stderr are using different file descriptors, verbose logs might still be written out-of-order.

At least, that's how I explain it, I could be wrong. The thing that's sure is that, when writing automated tests for this, the out-of-order problem was still clearly present.

The current solution using fs.writeFileSync() has several caveats:

  • It uses sync I/O, i.e. is poorer performance-wise.
  • As described in fix unicode problems with verbose log #1165, Node.js does not use the same logic with fs.writeFileSync() than with process.stderr.write(). In particular, it does not use some TTY-specific logic, which includes some UTF-8 to UTF-16 conversion on Windows. This leads to weird characters being printed on Windows. In general, I am not surprised fs.writeFileSync(2, ...) leads to weird behavior since this is quite an unusual way to write to a terminal's stderr which Node.js probably hasn't optimized for.
  • This is not benefiting from console which has some niceties when printing to a TTY (which verbose logs are likely to) such as more graceful error handling.

With all of this taken into account, this PR is reverting to using console.warn() (as opposed to console.log(), so we still print to stderr) instead of fs.writeFileSync().

export const verboseLog = ({type, verboseMessage, fdNumber, verboseInfo, result}) => {
const verboseObject = getVerboseObject({type, result, verboseInfo});
const printedLines = getPrintedLines(verboseMessage, verboseObject);
const finalLines = applyVerboseOnLines(printedLines, verboseInfo, fdNumber);
writeFileSync(STDERR_FD, finalLines);
if (finalLines !== '') {
console.warn(finalLines.slice(0, -1));
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

finalLines might be an empty string, indicating nothing should be printed.
Else, it is guaranteed to end with a newline due to the logic in applyVerboseOnLines(). We strip that newline since console.warn() appends one.

@sindresorhus sindresorhus merged commit e3572d0 into main Oct 28, 2024
14 checks passed
@sindresorhus sindresorhus deleted the add-tests branch October 28, 2024 06:29
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants