Do not write verbose logs synchronously (#1167)

Author: ehmicky

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);

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)],
+		);
+	}
+});