Log IPC messages with verbose: 'full' (#1063)

docs/api.md

@@ -910,7 +910,7 @@ _Default:_ `'none'`
 
 If `verbose` is `'short'`, prints the command on [`stderr`](https://en.wikipedia.org/wiki/Standard_streams#Standard_error_(stderr)): its file, arguments, duration and (if it failed) error message.
 
-If `verbose` is `'full'`, the command's [`stdout`](https://en.wikipedia.org/wiki/Standard_streams#Standard_output_(stdout)) and `stderr` are also printed.
+If `verbose` is `'full'`, the command's [`stdout`](https://en.wikipedia.org/wiki/Standard_streams#Standard_output_(stdout)), `stderr` and [IPC messages](ipc.md) are also printed.
 
 By default, this applies to both `stdout` and `stderr`, but [different values can also be passed](output.md#stdoutstderr-specific-options).
 

docs/debugging.md

@@ -57,7 +57,7 @@ $ node build.js
 
 ### Full mode
 
-When the [`verbose`](api.md#optionsverbose) option is `'full'`, the subprocess' [`stdout` and `stderr`](output.md) are also logged. Both are printed on [`stderr`](https://en.wikipedia.org/wiki/Standard_streams#Standard_error_(stderr)).
+When the [`verbose`](api.md#optionsverbose) option is `'full'`, the subprocess' [`stdout`, `stderr`](output.md) and [IPC messages](ipc.md) are also logged. They are all printed on [`stderr`](https://en.wikipedia.org/wiki/Standard_streams#Standard_error_(stderr)).
 
 The output is not logged if either:
 - The [`stdout`](api.md#optionsstdout)/[`stderr`](api.md#optionsstderr) option is [`'ignore'`](output.md#ignore-output) or [`'inherit'`](output.md#terminal-output).

docs/output.md

@@ -102,7 +102,7 @@ console.log('3');
 
 ## Stdout/stderr-specific options
 
-Some options are related to the subprocess output: [`verbose`](api.md#optionsverbose), [`lines`](api.md#optionslines), [`stripFinalNewline`](api.md#optionsstripfinalnewline), [`buffer`](api.md#optionsbuffer), [`maxBuffer`](api.md#optionsmaxbuffer). By default, those options apply to all [file descriptors](https://en.wikipedia.org/wiki/File_descriptor) ([`stdout`](https://en.wikipedia.org/wiki/Standard_streams#Standard_output_(stdout)), [`stderr`](https://en.wikipedia.org/wiki/Standard_streams#Standard_error_(stderr)), and [others](#additional-file-descriptors)). A plain object can be passed instead to apply them to only `stdout`, `stderr`, [`fd3`](#additional-file-descriptors), etc.
+Some options are related to the subprocess output: [`verbose`](api.md#optionsverbose), [`lines`](api.md#optionslines), [`stripFinalNewline`](api.md#optionsstripfinalnewline), [`buffer`](api.md#optionsbuffer), [`maxBuffer`](api.md#optionsmaxbuffer). By default, those options apply to all [file descriptors](https://en.wikipedia.org/wiki/File_descriptor) ([`stdout`](https://en.wikipedia.org/wiki/Standard_streams#Standard_output_(stdout)), [`stderr`](https://en.wikipedia.org/wiki/Standard_streams#Standard_error_(stderr)), and [others](#additional-file-descriptors)) and [IPC messages](ipc.md). A plain object can be passed instead to apply them to only `stdout`, `stderr`, `all` (both stdout and stderr), [`ipc`](ipc.md), [`fd3`](#additional-file-descriptors), etc.
 
 ```js
 // Same value for stdout and stderr

lib/arguments/specific.js

@@ -16,7 +16,7 @@ export const normalizeFdSpecificOptions = options => {
 };
 
 export const normalizeFdSpecificOption = (options, optionName) => {
-	const optionBaseArray = Array.from({length: getStdioLength(options)});
+	const optionBaseArray = Array.from({length: getStdioLength(options) + 1});
 	const optionArray = normalizeFdSpecificValue(options[optionName], optionBaseArray, optionName);
 	return addDefaultValue(optionArray, optionName);
 };
@@ -51,10 +51,14 @@ const getFdNameOrder = fdName => {
 };
 
 const parseFdName = (fdName, optionName, optionArray) => {
+	if (fdName === 'ipc') {
+		return [optionArray.length - 1];
+	}
+
 	const fdNumber = parseFd(fdName);
 	if (fdNumber === undefined || fdNumber === 0) {
 		throw new TypeError(`"${optionName}.${fdName}" is invalid.
-It must be "${optionName}.stdout", "${optionName}.stderr", "${optionName}.all", or "${optionName}.fd3", "${optionName}.fd4" (and so on).`);
+It must be "${optionName}.stdout", "${optionName}.stderr", "${optionName}.all", "${optionName}.ipc", or "${optionName}.fd3", "${optionName}.fd4" (and so on).`);
 	}
 
 	if (fdNumber >= optionArray.length) {

lib/ipc/get-each.js

@@ -2,29 +2,33 @@ import {once, on} from 'node:events';
 import {validateIpcOption, validateConnection} from './validation.js';
 
 // Like `[sub]process.on('message')` but promise-based
-export const getEachMessage = function ({anyProcess, isSubprocess, ipc}) {
+export const getEachMessage = ({anyProcess, isSubprocess, ipc}) => loopOnMessages({
+	anyProcess,
+	isSubprocess,
+	ipc,
+	shouldAwait: !isSubprocess,
+});
+
+// Same but used internally
+export const loopOnMessages = ({anyProcess, isSubprocess, ipc, shouldAwait}) => {
 	const methodName = 'getEachMessage';
 	validateIpcOption(methodName, isSubprocess, ipc);
 	validateConnection(methodName, isSubprocess, anyProcess.channel !== null);
 
 	const controller = new AbortController();
-	stopOnExit(anyProcess, isSubprocess, controller);
-
-	return iterateOnMessages(anyProcess, isSubprocess, controller);
+	stopOnExit(anyProcess, controller);
+	return iterateOnMessages(anyProcess, shouldAwait, controller);
 };
 
-const stopOnExit = async (anyProcess, isSubprocess, controller) => {
+const stopOnExit = async (anyProcess, controller) => {
 	try {
-		const onDisconnect = once(anyProcess, 'disconnect', {signal: controller.signal});
-		await (isSubprocess
-			? onDisconnect
-			: Promise.race([onDisconnect, anyProcess]));
+		await once(anyProcess, 'disconnect', {signal: controller.signal});
 	} catch {} finally {
 		controller.abort();
 	}
 };
 
-const iterateOnMessages = async function * (anyProcess, isSubprocess, controller) {
+const iterateOnMessages = async function * (anyProcess, shouldAwait, controller) {
 	try {
 		for await (const [message] of on(anyProcess, 'message', {signal: controller.signal})) {
 			yield message;
@@ -34,10 +38,10 @@ const iterateOnMessages = async function * (anyProcess, isSubprocess, controller
 			throw error;
 		}
 	} finally {
-		if (!isSubprocess) {
+		controller.abort();
+
+		if (shouldAwait) {
 			await anyProcess;
 		}
-
-		controller.abort();
 	}
 };

lib/ipc/messages.js

@@ -0,0 +1,18 @@
+import {shouldLogIpc, logIpcMessage} from '../verbose/ipc.js';
+import {loopOnMessages} from './get-each.js';
+
+// Iterate through IPC messages sent by the subprocess
+export const waitForIpcMessages = async (subprocess, ipc, verboseInfo) => {
+	if (!ipc || !shouldLogIpc(verboseInfo)) {
+		return;
+	}
+
+	for await (const message of loopOnMessages({
+		anyProcess: subprocess,
+		isSubprocess: false,
+		ipc,
+		shouldAwait: false,
+	})) {
+		logIpcMessage(message, verboseInfo);
+	}
+};

lib/resolve/wait-subprocess.js

@@ -4,6 +4,7 @@ import {throwOnTimeout} from '../terminate/timeout.js';
 import {isStandardStream} from '../utils/standard-stream.js';
 import {TRANSFORM_TYPES} from '../stdio/type.js';
 import {getBufferedData} from '../io/contents.js';
+import {waitForIpcMessages} from '../ipc/messages.js';
 import {waitForAllStream} from './all-async.js';
 import {waitForStdioStreams} from './stdio.js';
 import {waitForExit, waitForSuccessfulExit} from './exit-async.js';
@@ -12,7 +13,15 @@ import {waitForStream} from './wait-stream.js';
 // Retrieve result of subprocess: exit code, signal, error, streams (stdout/stderr/all)
 export const waitForSubprocessResult = async ({
 	subprocess,
-	options: {encoding, buffer, maxBuffer, lines, timeoutDuration: timeout, stripFinalNewline},
+	options: {
+		encoding,
+		buffer,
+		maxBuffer,
+		lines,
+		timeoutDuration: timeout,
+		stripFinalNewline,
+		ipc,
+	},
 	context,
 	verboseInfo,
 	fileDescriptors,
@@ -59,6 +68,7 @@ export const waitForSubprocessResult = async ({
 				waitForSuccessfulExit(exitPromise),
 				Promise.all(stdioPromises),
 				allPromise,
+				waitForIpcMessages(subprocess, ipc, verboseInfo),
 				...originalPromises,
 				...customStreamsEndPromises,
 			]),

lib/verbose/ipc.js

@@ -0,0 +1,8 @@
+import {verboseLog, serializeLogMessage} from './log.js';
+
+// When `verbose` is `'full'`, print IPC messages from the subprocess
+export const shouldLogIpc = ({verbose}) => verbose.at(-1) === 'full';
+
+export const logIpcMessage = (message, {verboseId}) => {
+	verboseLog(serializeLogMessage(message), verboseId, 'ipc');
+};

lib/verbose/log.js

@@ -1,6 +1,8 @@
 import {writeFileSync} from 'node:fs';
+import {inspect} from 'node:util';
 import figures from 'figures';
 import {gray} from 'yoctocolors';
+import {escapeLines} from '../arguments/escape.js';
 
 // Write synchronously to ensure lines are properly ordered and not interleaved with `stdout`
 export const verboseLog = (string, verboseId, icon, color) => {
@@ -38,7 +40,18 @@ const ICONS = {
 	command: '$',
 	pipedCommand: '|',
 	output: ' ',
+	ipc: '*',
 	error: figures.cross,
 	warning: figures.warning,
 	success: figures.tick,
 };
+
+// Serialize any type to a line string, for logging
+export const serializeLogMessage = message => {
+	const messageString = typeof message === 'string' ? message : inspect(message);
+	const escapedMessage = escapeLines(messageString);
+	return escapedMessage.replaceAll('\t', ' '.repeat(TAB_SIZE));
+};
+
+// Same as `util.inspect()`
+const TAB_SIZE = 2;

lib/verbose/output.js

@@ -1,8 +1,6 @@
-import {inspect} from 'node:util';
-import {escapeLines} from '../arguments/escape.js';
 import {BINARY_ENCODINGS} from '../arguments/encoding-option.js';
 import {TRANSFORM_TYPES} from '../stdio/type.js';
-import {verboseLog} from './log.js';
+import {verboseLog, serializeLogMessage} from './log.js';
 
 // `ignore` opts-out of `verbose` for a specific stream.
 // `ipc` cannot use piping.
@@ -24,7 +22,7 @@ const fdUsesVerbose = fdNumber => fdNumber === 1 || fdNumber === 2;
 
 const PIPED_STDIO_VALUES = new Set(['pipe', 'overlapped']);
 
-// `verbose` printing logic with async methods
+// `verbose: 'full'` printing logic with async methods
 export const logLines = async (linesIterable, stream, verboseInfo) => {
 	for await (const line of linesIterable) {
 		if (!isPipingStream(stream)) {
@@ -33,7 +31,7 @@ export const logLines = async (linesIterable, stream, verboseInfo) => {
 	}
 };
 
-// `verbose` printing logic with sync methods
+// `verbose: 'full'` printing logic with sync methods
 export const logLinesSync = (linesArray, verboseInfo) => {
 	for (const line of linesArray) {
 		logLine(line, verboseInfo);
@@ -51,11 +49,5 @@ const isPipingStream = stream => stream._readableState.pipes.length > 0;
 
 // When `verbose` is `full`, print stdout|stderr
 const logLine = (line, {verboseId}) => {
-	const lines = typeof line === 'string' ? line : inspect(line);
-	const escapedLines = escapeLines(lines);
-	const spacedLines = escapedLines.replaceAll('\t', ' '.repeat(TAB_SIZE));
-	verboseLog(spacedLines, verboseId, 'output');
+	verboseLog(serializeLogMessage(line), verboseId, 'output');
 };
-
-// Same as `util.inspect()`
-const TAB_SIZE = 2;

test-d/arguments/specific.test-d.ts

@@ -10,6 +10,7 @@ await execa('unicorns', {maxBuffer: {all: 0}});
 await execa('unicorns', {maxBuffer: {fd1: 0}});
 await execa('unicorns', {maxBuffer: {fd2: 0}});
 await execa('unicorns', {maxBuffer: {fd3: 0}});
+await execa('unicorns', {maxBuffer: {ipc: 0}});
 expectError(await execa('unicorns', {maxBuffer: {stdout: '0'}}));
 
 execaSync('unicorns', {maxBuffer: {}});
@@ -21,6 +22,7 @@ execaSync('unicorns', {maxBuffer: {all: 0}});
 execaSync('unicorns', {maxBuffer: {fd1: 0}});
 execaSync('unicorns', {maxBuffer: {fd2: 0}});
 execaSync('unicorns', {maxBuffer: {fd3: 0}});
+execaSync('unicorns', {maxBuffer: {ipc: 0}});
 expectError(execaSync('unicorns', {maxBuffer: {stdout: '0'}}));
 
 await execa('unicorns', {verbose: {}});
@@ -32,6 +34,7 @@ await execa('unicorns', {verbose: {all: 'none'}});
 await execa('unicorns', {verbose: {fd1: 'none'}});
 await execa('unicorns', {verbose: {fd2: 'none'}});
 await execa('unicorns', {verbose: {fd3: 'none'}});
+await execa('unicorns', {verbose: {ipc: 'none'}});
 expectError(await execa('unicorns', {verbose: {stdout: 'other'}}));
 
 execaSync('unicorns', {verbose: {}});
@@ -43,6 +46,7 @@ execaSync('unicorns', {verbose: {all: 'none'}});
 execaSync('unicorns', {verbose: {fd1: 'none'}});
 execaSync('unicorns', {verbose: {fd2: 'none'}});
 execaSync('unicorns', {verbose: {fd3: 'none'}});
+execaSync('unicorns', {verbose: {ipc: 'none'}});
 expectError(execaSync('unicorns', {verbose: {stdout: 'other'}}));
 
 await execa('unicorns', {stripFinalNewline: {}});
@@ -54,6 +58,7 @@ await execa('unicorns', {stripFinalNewline: {all: true}});
 await execa('unicorns', {stripFinalNewline: {fd1: true}});
 await execa('unicorns', {stripFinalNewline: {fd2: true}});
 await execa('unicorns', {stripFinalNewline: {fd3: true}});
+await execa('unicorns', {stripFinalNewline: {ipc: true}});
 expectError(await execa('unicorns', {stripFinalNewline: {stdout: 'true'}}));
 
 execaSync('unicorns', {stripFinalNewline: {}});
@@ -65,6 +70,7 @@ execaSync('unicorns', {stripFinalNewline: {all: true}});
 execaSync('unicorns', {stripFinalNewline: {fd1: true}});
 execaSync('unicorns', {stripFinalNewline: {fd2: true}});
 execaSync('unicorns', {stripFinalNewline: {fd3: true}});
+execaSync('unicorns', {stripFinalNewline: {ipc: true}});
 expectError(execaSync('unicorns', {stripFinalNewline: {stdout: 'true'}}));
 
 await execa('unicorns', {lines: {}});
@@ -76,6 +82,7 @@ await execa('unicorns', {lines: {all: true}});
 await execa('unicorns', {lines: {fd1: true}});
 await execa('unicorns', {lines: {fd2: true}});
 await execa('unicorns', {lines: {fd3: true}});
+await execa('unicorns', {lines: {ipc: true}});
 expectError(await execa('unicorns', {lines: {stdout: 'true'}}));
 
 execaSync('unicorns', {lines: {}});
@@ -87,6 +94,7 @@ execaSync('unicorns', {lines: {all: true}});
 execaSync('unicorns', {lines: {fd1: true}});
 execaSync('unicorns', {lines: {fd2: true}});
 execaSync('unicorns', {lines: {fd3: true}});
+execaSync('unicorns', {lines: {ipc: true}});
 expectError(execaSync('unicorns', {lines: {stdout: 'true'}}));
 
 await execa('unicorns', {buffer: {}});
@@ -98,6 +106,7 @@ await execa('unicorns', {buffer: {all: true}});
 await execa('unicorns', {buffer: {fd1: true}});
 await execa('unicorns', {buffer: {fd2: true}});
 await execa('unicorns', {buffer: {fd3: true}});
+await execa('unicorns', {buffer: {ipc: true}});
 expectError(await execa('unicorns', {buffer: {stdout: 'true'}}));
 
 execaSync('unicorns', {buffer: {}});
@@ -109,6 +118,7 @@ execaSync('unicorns', {buffer: {all: true}});
 execaSync('unicorns', {buffer: {fd1: true}});
 execaSync('unicorns', {buffer: {fd2: true}});
 execaSync('unicorns', {buffer: {fd3: true}});
+execaSync('unicorns', {buffer: {ipc: true}});
 expectError(execaSync('unicorns', {buffer: {stdout: 'true'}}));
 
 expectError(await execa('unicorns', {preferLocal: {}}));
@@ -120,6 +130,7 @@ expectError(await execa('unicorns', {preferLocal: {all: 0}}));
 expectError(await execa('unicorns', {preferLocal: {fd1: 0}}));
 expectError(await execa('unicorns', {preferLocal: {fd2: 0}}));
 expectError(await execa('unicorns', {preferLocal: {fd3: 0}}));
+expectError(await execa('unicorns', {preferLocal: {ipc: 0}}));
 expectError(await execa('unicorns', {preferLocal: {stdout: '0'}}));
 
 expectError(execaSync('unicorns', {preferLocal: {}}));
@@ -131,6 +142,7 @@ expectError(execaSync('unicorns', {preferLocal: {all: 0}}));
 expectError(execaSync('unicorns', {preferLocal: {fd1: 0}}));
 expectError(execaSync('unicorns', {preferLocal: {fd2: 0}}));
 expectError(execaSync('unicorns', {preferLocal: {fd3: 0}}));
+expectError(execaSync('unicorns', {preferLocal: {ipc: 0}}));
 expectError(execaSync('unicorns', {preferLocal: {stdout: '0'}}));
 
 expectType<string[]>(execaSync('unicorns', {lines: {stdout: true, fd1: false}}).stdout);

test/fixtures/ipc-send-forever.js

@@ -0,0 +1,7 @@
+#!/usr/bin/env node
+import {sendMessage} from '../../index.js';
+import {foobarString} from '../helpers/input.js';
+
+await sendMessage(foobarString);
+
+setTimeout(() => {}, 1e8);

test/fixtures/ipc-send-json.js

@@ -0,0 +1,6 @@
+#!/usr/bin/env node
+import {argv} from 'node:process';
+import {sendMessage} from '../../index.js';
+
+const message = JSON.parse(argv[2]);
+await sendMessage(message);

test/fixtures/ipc-send.js

@@ -1,5 +1,7 @@
 #!/usr/bin/env node
+import {argv} from 'node:process';
 import {sendMessage} from '../../index.js';
 import {foobarString} from '../helpers/input.js';
 
-await sendMessage(foobarString);
+const message = argv[2] || foobarString;
+await sendMessage(message);

test/helpers/verbose.js

@@ -47,6 +47,9 @@ const isCommandLine = line => line.includes(' $ ') || line.includes(' | ');
 export const getOutputLine = stderr => getOutputLines(stderr)[0];
 export const getOutputLines = stderr => getNormalizedLines(stderr).filter(line => isOutputLine(line));
 const isOutputLine = line => line.includes(']   ');
+export const getIpcLine = stderr => getIpcLines(stderr)[0];
+export const getIpcLines = stderr => getNormalizedLines(stderr).filter(line => isIpcLine(line));
+const isIpcLine = line => line.includes(' * ');
 export const getErrorLine = stderr => getErrorLines(stderr)[0];
 export const getErrorLines = stderr => getNormalizedLines(stderr).filter(line => isErrorLine(line));
 const isErrorLine = line => (line.includes(' × ') || line.includes(' ‼ ')) && !isCompletionLine(line);
@@ -73,3 +76,6 @@ export const fdStderrFullOption = {stdout: 'none', stderr: 'full'};
 export const fd3NoneOption = {stdout: 'full', fd3: 'none'};
 export const fd3ShortOption = {stdout: 'none', fd3: 'short'};
 export const fd3FullOption = {stdout: 'none', fd3: 'full'};
+export const ipcNoneOption = {ipc: 'none'};
+export const ipcShortOption = {ipc: 'short'};
+export const ipcFullOption = {ipc: 'full'};