diff --git a/lib/verbose/log.js b/lib/verbose/log.js index df0de430d7..52f46b7a7d 100644 --- a/lib/verbose/log.js +++ b/lib/verbose/log.js @@ -1,15 +1,23 @@ -import {writeFileSync} from 'node:fs'; import {inspect} from 'node:util'; import {escapeLines} from '../arguments/escape.js'; import {defaultVerboseFunction} from './default.js'; import {applyVerboseOnLines} from './custom.js'; -// Write synchronously to ensure lines are properly ordered and not interleaved with `stdout` +// This prints on stderr. +// If the subprocess prints on stdout and is using `stdout: 'inherit'`, +// there is a chance both writes will compete (introducing a race condition). +// This means their respective order is not deterministic. +// In particular, this means the verbose command lines might be after the start of the subprocess output. +// Using synchronous I/O does not solve this problem. +// However, this only seems to happen when the stdout/stderr target +// (e.g. a terminal) is being written to by many subprocesses at once, which is unlikely in real scenarios. 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)); + } }; const getVerboseObject = ({ @@ -35,9 +43,6 @@ const getPrintedLine = verboseObject => { return {verboseLine, verboseObject}; }; -// Unless a `verbose` function is used, print all logs on `stderr` -const STDERR_FD = 2; - // Serialize any type to a line string, for logging export const serializeVerboseMessage = message => { const messageString = typeof message === 'string' ? message : inspect(message); diff --git a/test/verbose/log.js b/test/verbose/log.js index c54d012550..c2b447eea9 100644 --- a/test/verbose/log.js +++ b/test/verbose/log.js @@ -3,6 +3,8 @@ import test from 'ava'; import {setFixtureDirectory} from '../helpers/fixtures-directory.js'; import {foobarString} from '../helpers/input.js'; import {nestedSubprocess} from '../helpers/nested.js'; +import {getNormalizedLines, getCommandLine, getCompletionLine} from '../helpers/verbose.js'; +import {PARALLEL_COUNT} from '../helpers/parallel.js'; setFixtureDirectory(); @@ -25,3 +27,15 @@ const testColor = async (t, expectedResult, forceColor) => { test('Prints with colors if supported', testColor, true, '1'); test('Prints without colors if not supported', testColor, false, '0'); + +test.serial('Prints lines in order when interleaved with subprocess stderr', async t => { + const results = await Promise.all(Array.from({length: PARALLEL_COUNT}, () => + nestedSubprocess('noop-fd.js', ['2', `${foobarString}\n`], {verbose: 'full', stderr: 'inherit'}, {all: true}), + )); + for (const {all} of results) { + t.deepEqual( + getNormalizedLines(all), + [getCommandLine(all), foobarString, getCompletionLine(all)], + ); + } +});