Refactor verbose logic (#1126)

lib/arguments/command.js

@@ -5,11 +5,12 @@ import {joinCommand} from './escape.js';
 import {normalizeFdSpecificOption} from './specific.js';
 
 // Compute `result.command`, `result.escapedCommand` and `verbose`-related information
-export const handleCommand = (filePath, rawArguments, rawOptions) => {
+export const handleCommand = (filePath, rawArguments, {piped, ...rawOptions}) => {
 	const startTime = getStartTime();
 	const {command, escapedCommand} = joinCommand(filePath, rawArguments);
-	const verboseInfo = getVerboseInfo(normalizeFdSpecificOption(rawOptions, 'verbose'));
-	logCommand(escapedCommand, verboseInfo, rawOptions);
+	const verbose = normalizeFdSpecificOption(rawOptions, 'verbose');
+	const verboseInfo = getVerboseInfo(verbose, escapedCommand, {...rawOptions});
+	logCommand(escapedCommand, verboseInfo, piped);
 	return {
 		command,
 		escapedCommand,

lib/arguments/specific.js

@@ -1,6 +1,6 @@
+import {debuglog} from 'node:util';
 import isPlainObject from 'is-plain-obj';
 import {STANDARD_STREAMS_ALIASES} from '../utils/standard-stream.js';
-import {verboseDefault} from '../verbose/info.js';
 
 // Some options can have different values for `stdout`/`stderr`/`fd3`.
 // This normalizes those to array of values.
@@ -91,6 +91,9 @@ const addDefaultValue = (optionArray, optionName) => optionArray.map(optionValue
 	? DEFAULT_OPTIONS[optionName]
 	: optionValue);
 
+// Default value for the `verbose` option
+const verboseDefault = debuglog('execa').enabled ? 'full' : 'none';
+
 const DEFAULT_OPTIONS = {
 	lines: false,
 	buffer: true,
@@ -101,3 +104,8 @@ const DEFAULT_OPTIONS = {
 
 // List of options which can have different values for `stdout`/`stderr`
 export const FD_SPECIFIC_OPTIONS = ['lines', 'buffer', 'maxBuffer', 'verbose', 'stripFinalNewline'];
+
+// Retrieve fd-specific option
+export const getFdSpecificValue = (optionArray, fdNumber) => fdNumber === 'ipc'
+	? optionArray.at(-1)
+	: optionArray[fdNumber];

lib/io/contents.js

@@ -7,26 +7,19 @@ import {handleMaxBuffer} from './max-buffer.js';
 import {getStripFinalNewline} from './strip-newline.js';
 
 // Retrieve `result.stdout|stderr|all|stdio[*]`
-export const getStreamOutput = async ({stream, onStreamEnd, fdNumber, encoding, buffer, maxBuffer, lines, allMixed, stripFinalNewline, verboseInfo, streamInfo: {fileDescriptors}}) => {
-	if (shouldLogOutput({
-		stdioItems: fileDescriptors[fdNumber]?.stdioItems,
+export const getStreamOutput = async ({stream, onStreamEnd, fdNumber, encoding, buffer, maxBuffer, lines, allMixed, stripFinalNewline, verboseInfo, streamInfo}) => {
+	const logPromise = logOutputAsync({
+		stream,
+		onStreamEnd,
+		fdNumber,
 		encoding,
+		allMixed,
 		verboseInfo,
-		fdNumber,
-	})) {
-		const linesIterable = iterateForResult({
-			stream,
-			onStreamEnd,
-			lines: true,
-			encoding,
-			stripFinalNewline: true,
-			allMixed,
-		});
-		logLines(linesIterable, stream, verboseInfo);
-	}
+		streamInfo,
+	});
 
 	if (!buffer) {
-		await resumeStream(stream);
+		await Promise.all([resumeStream(stream), logPromise]);
 		return;
 	}
 
@@ -39,14 +32,39 @@ export const getStreamOutput = async ({stream, onStreamEnd, fdNumber, encoding,
 		stripFinalNewline: stripFinalNewlineValue,
 		allMixed,
 	});
-	return getStreamContents({
-		stream,
-		iterable,
+	const [output] = await Promise.all([
+		getStreamContents({
+			stream,
+			iterable,
+			fdNumber,
+			encoding,
+			maxBuffer,
+			lines,
+		}),
+		logPromise,
+	]);
+	return output;
+};
+
+const logOutputAsync = async ({stream, onStreamEnd, fdNumber, encoding, allMixed, verboseInfo, streamInfo: {fileDescriptors}}) => {
+	if (!shouldLogOutput({
+		stdioItems: fileDescriptors[fdNumber]?.stdioItems,
+		encoding,
+		verboseInfo,
 		fdNumber,
+	})) {
+		return;
+	}
+
+	const linesIterable = iterateForResult({
+		stream,
+		onStreamEnd,
+		lines: true,
 		encoding,
-		maxBuffer,
-		lines,
+		stripFinalNewline: true,
+		allMixed,
 	});
+	await logLines(linesIterable, stream, verboseInfo);
 };
 
 // When using `buffer: false`, users need to read `subprocess.stdout|stderr|all` right away

lib/io/max-buffer.js

@@ -1,5 +1,6 @@
 import {MaxBufferError} from 'get-stream';
 import {getStreamName} from '../utils/standard-stream.js';
+import {getFdSpecificValue} from '../arguments/specific.js';
 
 // When the `maxBuffer` option is hit, a MaxBufferError is thrown.
 // The stream is aborted, then specific information is kept for the error message.
@@ -59,11 +60,12 @@ const getMaxBufferInfo = (error, maxBuffer) => {
 	const {maxBufferInfo: {fdNumber, unit}} = error;
 	delete error.maxBufferInfo;
 
+	const threshold = getFdSpecificValue(maxBuffer, fdNumber);
 	if (fdNumber === 'ipc') {
-		return {streamName: 'IPC output', threshold: maxBuffer.at(-1), unit: 'messages'};
+		return {streamName: 'IPC output', threshold, unit: 'messages'};
 	}
 
-	return {streamName: getStreamName(fdNumber), threshold: maxBuffer[fdNumber], unit};
+	return {streamName: getStreamName(fdNumber), threshold, unit};
 };
 
 // The only way to apply `maxBuffer` with `spawnSync()` is to use the native `maxBuffer` option Node.js provides.

lib/io/output-sync.js

@@ -48,15 +48,14 @@ const transformOutputResultSync = (
 		fdNumber,
 	});
 
-	if (shouldLogOutput({
-		stdioItems,
-		encoding,
-		verboseInfo,
+	logOutputSync({
+		serializedResult,
 		fdNumber,
-	})) {
-		const linesArray = splitLinesSync(serializedResult, false, objectMode);
-		logLinesSync(linesArray, verboseInfo);
-	}
+		verboseInfo,
+		encoding,
+		stdioItems,
+		objectMode,
+	});
 
 	const returnedResult = buffer[fdNumber] ? finalResult : undefined;
 
@@ -102,6 +101,20 @@ const serializeChunks = ({chunks, objectMode, encoding, lines, stripFinalNewline
 	return {serializedResult};
 };
 
+const logOutputSync = ({serializedResult, fdNumber, verboseInfo, encoding, stdioItems, objectMode}) => {
+	if (!shouldLogOutput({
+		stdioItems,
+		encoding,
+		verboseInfo,
+		fdNumber,
+	})) {
+		return;
+	}
+
+	const linesArray = splitLinesSync(serializedResult, false, objectMode);
+	logLinesSync(linesArray, verboseInfo);
+};
+
 // When the `std*` target is a file path/URL or a file descriptor
 const writeToFiles = (serializedResult, stdioItems, outputFiles) => {
 	for (const {path} of stdioItems.filter(({type}) => FILE_TYPES.has(type))) {

lib/ipc/buffer-messages.js

@@ -1,5 +1,6 @@
 import {checkIpcMaxBuffer} from '../io/max-buffer.js';
 import {shouldLogIpc, logIpcOutput} from '../verbose/ipc.js';
+import {getFdSpecificValue} from '../arguments/specific.js';
 import {loopOnMessages} from './get-each.js';
 
 // Iterate through IPC messages sent by the subprocess
@@ -16,8 +17,8 @@ export const waitForIpcOutput = async ({
 	}
 
 	const isVerbose = shouldLogIpc(verboseInfo);
-	const buffer = bufferArray.at(-1);
-	const maxBuffer = maxBufferArray.at(-1);
+	const buffer = getFdSpecificValue(bufferArray, 'ipc');
+	const maxBuffer = getFdSpecificValue(maxBufferArray, 'ipc');
 
 	for await (const message of loopOnMessages({
 		anyProcess: subprocess,

lib/ipc/outgoing.js

@@ -1,4 +1,5 @@
 import {createDeferred} from '../utils/deferred.js';
+import {getFdSpecificValue} from '../arguments/specific.js';
 import {SUBPROCESS_OPTIONS} from '../arguments/fd-options.js';
 import {validateStrictDeadlock} from './strict.js';
 
@@ -41,6 +42,6 @@ export const hasMessageListeners = (anyProcess, ipcEmitter) => ipcEmitter.listen
 // When `buffer` is `false`, we set up a `message` listener that should be ignored.
 // That listener is only meant to intercept `strict` acknowledgement responses.
 const getMinListenerCount = anyProcess => SUBPROCESS_OPTIONS.has(anyProcess)
-	&& !SUBPROCESS_OPTIONS.get(anyProcess).options.buffer.at(-1)
+	&& !getFdSpecificValue(SUBPROCESS_OPTIONS.get(anyProcess).options.buffer, 'ipc')
 	? 1
 	: 0;

lib/return/reject.js

@@ -3,7 +3,7 @@ import {logFinalResult} from '../verbose/complete.js';
 // Applies the `reject` option.
 // Also print the final log line with `verbose`.
 export const handleResult = (result, verboseInfo, {reject}) => {
-	logFinalResult(result, reject, verboseInfo);
+	logFinalResult(result, verboseInfo);
 
 	if (result.failed && reject) {
 		throw result;

lib/stdio/handle.js

@@ -17,7 +17,7 @@ import {filterDuplicates, getDuplicateStream} from './duplicate.js';
 // They are converted into an array of `fileDescriptors`.
 // Each `fileDescriptor` is normalized, validated and contains all information necessary for further handling.
 export const handleStdio = (addProperties, options, verboseInfo, isSync) => {
-	const stdio = normalizeStdioOption(options, isSync);
+	const stdio = normalizeStdioOption(options, verboseInfo, isSync);
 	const initialFileDescriptors = stdio.map((stdioOption, fdNumber) => getFileDescriptor({
 		stdioOption,
 		fdNumber,

lib/stdio/stdio-option.js

@@ -1,12 +1,13 @@
 import {STANDARD_STREAMS_ALIASES} from '../utils/standard-stream.js';
 import {normalizeIpcStdioArray} from '../ipc/array.js';
+import {isFullVerbose} from '../verbose/info.js';
 
 // Add support for `stdin`/`stdout`/`stderr` as an alias for `stdio`.
 // Also normalize the `stdio` option.
-export const normalizeStdioOption = ({stdio, ipc, buffer, verbose, ...options}, isSync) => {
+export const normalizeStdioOption = ({stdio, ipc, buffer, ...options}, verboseInfo, isSync) => {
 	const stdioArray = getStdioArray(stdio, options).map((stdioOption, fdNumber) => addDefaultValue(stdioOption, fdNumber));
 	return isSync
-		? normalizeStdioSync(stdioArray, buffer, verbose)
+		? normalizeStdioSync(stdioArray, buffer, verboseInfo)
 		: normalizeIpcStdioArray(stdioArray, ipc);
 };
 
@@ -47,10 +48,10 @@ const addDefaultValue = (stdioOption, fdNumber) => {
 
 // Using `buffer: false` with synchronous methods implies `stdout`/`stderr`: `ignore`.
 // Unless the output is needed, e.g. due to `verbose: 'full'` or to redirecting to a file.
-const normalizeStdioSync = (stdioArray, buffer, verbose) => stdioArray.map((stdioOption, fdNumber) =>
+const normalizeStdioSync = (stdioArray, buffer, verboseInfo) => stdioArray.map((stdioOption, fdNumber) =>
 	!buffer[fdNumber]
 	&& fdNumber !== 0
-	&& verbose[fdNumber] !== 'full'
+	&& !isFullVerbose(verboseInfo, fdNumber)
 	&& isOutputPipeOnly(stdioOption)
 		? 'ignore'
 		: stdioOption);

lib/verbose/complete.js

@@ -1,58 +1,38 @@
 import prettyMs from 'pretty-ms';
-import {gray} from 'yoctocolors';
 import {escapeLines} from '../arguments/escape.js';
 import {getDurationMs} from '../return/duration.js';
 import {isVerbose} from './info.js';
 import {verboseLog} from './log.js';
 import {logError} from './error.js';
 
 // When `verbose` is `short|full`, print each command's completion, duration and error
-export const logFinalResult = ({shortMessage, failed, durationMs}, reject, verboseInfo) => {
-	logResult({
-		message: shortMessage,
-		failed,
-		reject,
-		durationMs,
-		verboseInfo,
-	});
+export const logFinalResult = ({shortMessage, durationMs, failed}, verboseInfo) => {
+	logResult(shortMessage, durationMs, verboseInfo, failed);
 };
 
 // Same but for early validation errors
-export const logEarlyResult = (error, startTime, verboseInfo) => {
-	logResult({
-		message: escapeLines(String(error)),
-		failed: true,
-		reject: true,
-		durationMs: getDurationMs(startTime),
-		verboseInfo,
-	});
+export const logEarlyResult = (error, startTime, {rawOptions, ...verboseInfo}) => {
+	const shortMessage = escapeLines(String(error));
+	const durationMs = getDurationMs(startTime);
+	const earlyVerboseInfo = {...verboseInfo, rawOptions: {...rawOptions, reject: true}};
+	logResult(shortMessage, durationMs, earlyVerboseInfo, true);
 };
 
-const logResult = ({message, failed, reject, durationMs, verboseInfo: {verbose, verboseId}}) => {
-	if (!isVerbose(verbose)) {
+const logResult = (shortMessage, durationMs, verboseInfo, failed) => {
+	if (!isVerbose(verboseInfo)) {
 		return;
 	}
 
-	const icon = getIcon(failed, reject);
-	logError({
-		message,
-		failed,
-		reject,
-		verboseId,
-		icon,
-	});
-	logDuration(durationMs, verboseId, icon);
-};
-
-const logDuration = (durationMs, verboseId, icon) => {
-	const durationMessage = `(done in ${prettyMs(durationMs)})`;
-	verboseLog(durationMessage, verboseId, icon, gray);
+	logError(shortMessage, verboseInfo, failed);
+	logDuration(durationMs, verboseInfo, failed);
 };
 
-const getIcon = (failed, reject) => {
-	if (!failed) {
-		return 'success';
-	}
-
-	return reject ? 'error' : 'warning';
+const logDuration = (durationMs, verboseInfo, failed) => {
+	const logMessage = `(done in ${prettyMs(durationMs)})`;
+	verboseLog({
+		type: 'duration',
+		logMessage,
+		verboseInfo,
+		failed,
+	});
 };

lib/verbose/default.js

@@ -0,0 +1,46 @@
+import figures from 'figures';
+import {
+	gray,
+	bold,
+	redBright,
+	yellowBright,
+} from 'yoctocolors';
+
+// Default logger for the `verbose` option
+export const defaultLogger = ({type, message, timestamp, failed, piped, commandId, options: {reject = true}}) => {
+	const timestampString = serializeTimestamp(timestamp);
+	const icon = ICONS[type]({failed, reject, piped});
+	const color = COLORS[type]({reject});
+	return `${gray(`[${timestampString}]`)} ${gray(`[${commandId}]`)} ${color(icon)} ${color(message)}`;
+};
+
+// Prepending the timestamp allows debugging the slow paths of a subprocess
+const serializeTimestamp = timestamp => `${padField(timestamp.getHours(), 2)}:${padField(timestamp.getMinutes(), 2)}:${padField(timestamp.getSeconds(), 2)}.${padField(timestamp.getMilliseconds(), 3)}`;
+
+const padField = (field, padding) => String(field).padStart(padding, '0');
+
+const getFinalIcon = ({failed, reject}) => {
+	if (!failed) {
+		return figures.tick;
+	}
+
+	return reject ? figures.cross : figures.warning;
+};
+
+const ICONS = {
+	command: ({piped}) => piped ? '|' : '$',
+	output: () => ' ',
+	ipc: () => '*',
+	error: getFinalIcon,
+	duration: getFinalIcon,
+};
+
+const identity = string => string;
+
+const COLORS = {
+	command: () => bold,
+	output: () => identity,
+	ipc: () => identity,
+	error: ({reject}) => reject ? redBright : yellowBright,
+	duration: () => gray,
+};