Fix verbose discarding IPC messages when its function throws

Author: sindresorhus

docs/debugging.md

@@ -116,6 +116,8 @@ It is called once per log line. The first argument is the default log line strin
 
 If a string is returned, it is printed on `stderr`. If `undefined` is returned, nothing is printed.
 
+If the function throws, the subprocess fails with that error as [`error.cause`](api.md#errorcause). If it threw while logging the output of [`stdout`](api.md#resultstdout), [`stderr`](api.md#resultstderr) or another file descriptor, that file descriptor's output is then not kept.
+
 ### Filter logs
 
 ```js

lib/io/contents.js

@@ -111,6 +111,7 @@ export const getBufferedData = async streamPromise => {
 };
 
 // Ensure we are returning Uint8Arrays when using `encoding: 'buffer'`
-const handleBufferedData = ({bufferedData}) => isArrayBuffer(bufferedData)
-	? new Uint8Array(bufferedData)
-	: bufferedData;
+// The error might be any value thrown by the `verbose` function, including `null` or `undefined`
+const handleBufferedData = error => isArrayBuffer(error?.bufferedData)
+	? new Uint8Array(error.bufferedData)
+	: error?.bufferedData;

lib/ipc/buffer-messages.js

@@ -19,6 +19,8 @@ export const waitForIpcOutput = async ({
 	const isVerbose = shouldLogIpc(verboseInfo);
 	const buffer = getFdSpecificValue(bufferArray, 'ipc');
 	const maxBuffer = getFdSpecificValue(maxBufferArray, 'ipc');
+	// A throwing `verbose` function must not prevent the following messages from being buffered
+	const logErrors = [];
 
 	for await (const message of loopOnMessages({
 		anyProcess: subprocess,
@@ -34,10 +36,18 @@ export const waitForIpcOutput = async ({
 		}
 
 		if (isVerbose) {
-			logIpcOutput(message, verboseInfo);
+			try {
+				logIpcOutput(message, verboseInfo);
+			} catch (error) {
+				logErrors.push(error);
+			}
 		}
 	}
 
+	if (logErrors.length > 0) {
+		throw logErrors[0];
+	}
+
 	return ipcOutput;
 };
 

lib/verbose/log.js

@@ -43,12 +43,9 @@ const getPrintedLine = verboseObject => {
 	return {verboseLine, verboseObject};
 };
 
-// Serialize any type to a line string, for logging
+// Serialize any type to a line string, for logging.
+// Tabs are escaped by `escapeLines()`, like any other control character.
 export const serializeVerboseMessage = message => {
 	const messageString = typeof message === 'string' ? message : inspect(message);
-	const escapedMessage = escapeLines(messageString);
-	return escapedMessage.replaceAll('\t', () => ' '.repeat(TAB_SIZE));
+	return escapeLines(messageString);
 };
-
-// Same as `util.inspect()`
-const TAB_SIZE = 2;

test/verbose/custom-throw.js

@@ -1,4 +1,5 @@
 import test from 'ava';
+import {execa} from '../../index.js';
 import {setFixtureDirectory} from '../helpers/fixtures-directory.js';
 import {foobarString} from '../helpers/input.js';
 import {runVerboseSubprocess} from '../helpers/verbose.js';
@@ -65,3 +66,37 @@ const testCommandThrowWrap = async (t, type, options, isSync) => {
 test('Propagate wrapped exception in "verbose" function, "output", spawn error', testCommandThrowWrap, 'output', earlyErrorOptions, false);
 test('Propagate wrapped exception in "verbose" function, "ipc", spawn error', testCommandThrowWrap, 'ipc', earlyErrorOptions, false);
 test('Propagate wrapped exception in "verbose" function, "output", spawn error, sync', testCommandThrowWrap, 'output', earlyErrorOptionsSync, true);
+
+// A throwing `verbose` function is a logging error: it must not discard IPC messages which have already been buffered
+const getThrowingVerbose = (type, thrownValue = new Error(foobarString)) => ({
+	verbose: (line, verboseObject) => {
+		if (verboseObject.type === type) {
+			throw thrownValue;
+		}
+	},
+});
+
+test('IPC output is kept when the "verbose" function throws, "ipc"', async t => {
+	const {cause, ipcOutput} = await t.throwsAsync(execa('ipc-send-twice.js', {ipc: true, ...getThrowingVerbose('ipc')}));
+	t.is(cause.message, foobarString);
+	t.deepEqual(ipcOutput, ['foo', 'bar']);
+});
+
+// A `verbose` function might throw a non-Error, or a falsy value. Neither must be mistaken for no error at all
+test('A non-Error thrown by the "verbose" function is propagated, "output"', async t => {
+	const {cause, stdout} = await t.throwsAsync(execa('noop.js', [foobarString], getThrowingVerbose('output', foobarString)));
+	t.is(cause, foobarString);
+	t.is(stdout, undefined);
+});
+
+test('A null value thrown by the "verbose" function is propagated, "output"', async t => {
+	const {cause, stdout} = await t.throwsAsync(execa('noop.js', [foobarString], getThrowingVerbose('output', null)));
+	t.is(cause, null);
+	t.is(stdout, undefined);
+});
+
+test('IPC output is kept when the "verbose" function throws a falsy value, "ipc"', async t => {
+	const {cause, ipcOutput} = await t.throwsAsync(execa('ipc-send-twice.js', {ipc: true, ...getThrowingVerbose('ipc', 0)}));
+	t.is(cause, 0);
+	t.deepEqual(ipcOutput, ['foo', 'bar']);
+});

test/verbose/output-enable.js

@@ -114,6 +114,11 @@ test('Escapes control characters from stdout', async t => {
 	t.is(getOutputLine(stderr), `${testTimestamp} [0]   \\u0001`);
 });
 
+test('Escapes tabs from stdout', async t => {
+	const {stderr} = await nestedSubprocess('noop.js', [`${foobarString}\t${foobarString}`], {verbose: 'full'});
+	t.is(getOutputLine(stderr), `${testTimestamp} [0]   ${foobarString}\\t${foobarString}`);
+});
+
 const testStdioSame = async (t, fdNumber) => {
 	const {nestedResult: {stdio}} = await nestedSubprocess('noop-fd.js', [`${fdNumber}`, foobarString], {verbose: 'full'});
 	t.is(stdio[fdNumber], foobarString);