Allow verbose option to be a function for custom logging (#1130)

Author: ehmicky

docs/api.md

@@ -1033,12 +1033,14 @@ More info [here](ipc.md#send-an-initial-message) and [there](input.md#any-input-
 
 ### options.verbose
 
-_Type:_ `'none' | 'short' | 'full'`\
+_Type:_ `'none' | 'short' | 'full' | Function`\
 _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)), `stderr` and [IPC messages](ipc.md) are also printed.
+If `verbose` is `'full'` or a function, the command's [`stdout`](https://en.wikipedia.org/wiki/Standard_streams#Standard_output_(stdout)), `stderr` and [IPC messages](ipc.md) are also printed.
+
+A [function](#verbose-function) can be passed to customize logging. Please see [this page](debugging.md#custom-logging) for more information.
 
 By default, this applies to both `stdout` and `stderr`, but [different values can also be passed](output.md#stdoutstderr-specific-options).
 
@@ -1170,6 +1172,84 @@ If `false`, escapes the command arguments on Windows.
 
 [More info.](windows.md#cmdexe-escaping)
 
+## Verbose function
+
+_Type_: `(string, VerboseObject) => string | undefined`
+
+Function passed to the [`verbose`](#optionsverbose) option to customize logging.
+
+[More info.](debugging.md#custom-logging)
+
+### Verbose object
+
+_Type_: `VerboseObject` or `SyncVerboseObject`
+
+Subprocess event object, for logging purpose, using the [`verbose`](#optionsverbose) option.
+
+#### verboseObject.type
+
+_Type_: `string`
+
+Event type. This can be:
+- `'command'`: subprocess start
+- `'output'`: `stdout`/`stderr` [output](output.md#stdout-and-stderr)
+- `'ipc'`: IPC [output](ipc.md#retrieve-all-messages)
+- `'error'`: subprocess [failure](errors.md#subprocess-failure)
+- `'duration'`: subprocess success or failure
+
+#### verboseObject.message
+
+_Type_: `string`
+
+Depending on [`verboseObject.type`](#verboseobjecttype), this is:
+- `'command'`: the [`result.escapedCommand`](#resultescapedcommand)
+- `'output'`: one line from [`result.stdout`](#resultstdout) or [`result.stderr`](#resultstderr)
+- `'ipc'`: one IPC message from [`result.ipcOutput`](#resultipcoutput)
+- `'error'`: the [`error.shortMessage`](#errorshortmessage)
+- `'duration'`: the [`result.durationMs`](#resultdurationms)
+
+#### verboseObject.escapedCommand
+
+_Type_: `string`
+
+The file and [arguments](input.md#command-arguments) that were run. This is the same as [`result.escapedCommand`](#resultescapedcommand).
+
+#### verboseObject.options
+
+_Type_: [`Options`](#options-1) or [`SyncOptions`](#options-1)
+
+The [options](#options-1) passed to the subprocess.
+
+#### verboseObject.commandId
+
+_Type_: `string`
+
+Serial number identifying the subprocess within the current process. It is incremented from `'0'`.
+
+This is helpful when multiple subprocesses are running at the same time.
+
+This is similar to a [PID](https://en.wikipedia.org/wiki/Process_identifier) except it has no maximum limit, which means it never repeats. Also, it is usually shorter.
+
+#### verboseObject.timestamp
+
+_Type_: `Date`
+
+Event date/time.
+
+#### verboseObject.result
+
+_Type_: [`Result`](#result), [`SyncResult`](#result) or `undefined`
+
+Subprocess [result](#result).
+
+This is `undefined` if [`verboseObject.type`](#verboseobjecttype) is `'command'`, `'output'` or `'ipc'`.
+
+#### verboseObject.piped
+
+_Type_: `boolean`
+
+Whether another subprocess is [piped](pipe.md) into this subprocess. This is `false` when [`result.pipedFrom`](#resultfailed) is empty.
+
 ## Transform options
 
 A transform or an [array of transforms](transform.md#combining) can be passed to the [`stdin`](#optionsstdin), [`stdout`](#optionsstdout), [`stderr`](#optionsstderr) or [`stdio`](#optionsstdio) option.

docs/debugging.md

@@ -106,6 +106,96 @@ When printed to a terminal, the verbose mode uses colors.
 
 <img alt="execa verbose output" src="../media/verbose.png" width="603">
 
+## Custom logging
+
+### Verbose function
+
+The [`verbose`](api.md#optionsverbose) option can be a function to customize logging.
+
+It is called once per log line. The first argument is the default log line string. The second argument is the same information but as an object instead (documented [here](api.md#verbose-object)).
+
+If a string is returned, it is printed on `stderr`. If `undefined` is returned, nothing is printed.
+
+### Filter logs
+
+```js
+import {execa as execa_} from 'execa';
+
+// Only print log lines showing the subprocess duration
+const execa = execa_({
+	verbose(verboseLine, {type}) {
+		return type === 'duration' ? verboseLine : undefined;
+	},
+});
+```
+
+### Transform logs
+
+```js
+import {execa as execa_} from 'execa';
+
+// Prepend current process' PID
+const execa = execa_({
+	verbose(verboseLine) {
+		return `[${process.pid}] ${verboseLine}`
+	},
+});
+```
+
+### Custom log format
+
+```js
+import {execa as execa_} from 'execa';
+
+// Use a different format for the timestamp
+const execa = execa_({
+	verbose(verboseLine, {timestamp}) {
+		return verboseLine.replace(timestampRegExp, timestamp.toISOString());
+	},
+});
+
+// Timestamp at the start of each log line
+const timestampRegExp = /\d{2}:\d{2}:\d{2}\.\d{3}/;
+```
+
+### JSON logging
+
+```js
+import {execa as execa_} from 'execa';
+
+const execa = execa_({
+	verbose(verboseLine, verboseObject) {
+		return JSON.stringify(verboseObject)
+	},
+});
+```
+
+### Advanced logging
+
+```js
+import {execa as execa_} from 'execa';
+import {createLogger, transports} from 'winston';
+
+// Log to a file using Winston
+const transport = new transports.File({filename: 'logs.txt'});
+const logger = createLogger({transports: [transport]});
+
+const execa = execa_({
+	verbose(verboseLine, {type, message, ...verboseObject}) {
+		const level = LOG_LEVELS[type];
+		logger[level](message, verboseObject);
+	},
+});
+
+const LOG_LEVELS = {
+	command: 'info',
+	output: 'verbose',
+	ipc: 'verbose',
+	error: 'error',
+	duration: 'info',
+};
+```
+
 <hr>
 
 [**Next**: 📎 Windows](windows.md)\

docs/typescript.md

@@ -8,7 +8,7 @@
 
 ## Available types
 
-The following types can be imported: [`ResultPromise`](api.md#return-value), [`Subprocess`](api.md#subprocess), [`Result`](api.md#result), [`ExecaError`](api.md#execaerror), [`Options`](api.md#options-1), [`StdinOption`](api.md#optionsstdin), [`StdoutStderrOption`](api.md#optionsstdout), [`TemplateExpression`](api.md#execacommand), [`Message`](api.md#subprocesssendmessagemessage-sendmessageoptions), [`ExecaMethod`](api.md#execaoptions), [`ExecaNodeMethod`](api.md#execanodeoptions) and [`ExecaScriptMethod`](api.md#options).
+The following types can be imported: [`ResultPromise`](api.md#return-value), [`Subprocess`](api.md#subprocess), [`Result`](api.md#result), [`ExecaError`](api.md#execaerror), [`Options`](api.md#options-1), [`StdinOption`](api.md#optionsstdin), [`StdoutStderrOption`](api.md#optionsstdout), [`TemplateExpression`](api.md#execacommand), [`Message`](api.md#subprocesssendmessagemessage-sendmessageoptions), [`VerboseObject`](api.md#verbose-object), [`ExecaMethod`](api.md#execaoptions), [`ExecaNodeMethod`](api.md#execanodeoptions) and [`ExecaScriptMethod`](api.md#options).
 
 ```ts
 import {
@@ -21,6 +21,7 @@ import {
 	type StdoutStderrOption,
 	type TemplateExpression,
 	type Message,
+	type VerboseObject,
 	type ExecaMethod,
 } from 'execa';
 
@@ -32,6 +33,9 @@ const options: Options = {
 	stderr: 'pipe' satisfies StdoutStderrOption,
 	timeout: 1000,
 	ipc: true,
+	verbose(verboseLine: string, verboseObject: VerboseObject) {
+		return verboseObject.type === 'duration' ? verboseLine : undefined;
+	},
 };
 const task: TemplateExpression = 'build';
 const message: Message = 'hello world';
@@ -50,7 +54,7 @@ try {
 
 ## Synchronous execution
 
-Their [synchronous](#synchronous-execution) counterparts are [`SyncResult`](api.md#result), [`ExecaSyncError`](api.md#execasyncerror), [`SyncOptions`](api.md#options-1), [`StdinSyncOption`](api.md#optionsstdin), [`StdoutStderrSyncOption`](api.md#optionsstdout), [`TemplateExpression`](api.md#execacommand), [`ExecaSyncMethod`](api.md#execasyncoptions) and [`ExecaScriptSyncMethod`](api.md#syncoptions).
+Their [synchronous](#synchronous-execution) counterparts are [`SyncResult`](api.md#result), [`ExecaSyncError`](api.md#execasyncerror), [`SyncOptions`](api.md#options-1), [`StdinSyncOption`](api.md#optionsstdin), [`StdoutStderrSyncOption`](api.md#optionsstdout), [`TemplateExpression`](api.md#execacommand), [`SyncVerboseObject`](api.md#verbose-object), [`ExecaSyncMethod`](api.md#execasyncoptions) and [`ExecaScriptSyncMethod`](api.md#syncoptions).
 
 ```ts
 import {
@@ -61,6 +65,7 @@ import {
 	type StdinSyncOption,
 	type StdoutStderrSyncOption,
 	type TemplateExpression,
+	type SyncVerboseObject,
 	type ExecaSyncMethod,
 } from 'execa';
 
@@ -71,6 +76,9 @@ const options: SyncOptions = {
 	stdout: 'pipe' satisfies StdoutStderrSyncOption,
 	stderr: 'pipe' satisfies StdoutStderrSyncOption,
 	timeout: 1000,
+	verbose(verboseLine: string, verboseObject: SyncVerboseObject) {
+		return verboseObject.type === 'duration' ? verboseLine : undefined;
+	},
 };
 const task: TemplateExpression = 'build';
 
@@ -93,6 +101,7 @@ import {
 	execa as execa_,
 	ExecaError,
 	type Result,
+	type VerboseObject,
 } from 'execa';
 
 const execa = execa_({preferLocal: true});
@@ -107,6 +116,9 @@ const options = {
 	stderr: 'pipe',
 	timeout: 1000,
 	ipc: true,
+	verbose(verboseLine: string, verboseObject: VerboseObject) {
+		return verboseObject.type === 'duration' ? verboseLine : undefined;
+	},
 } as const;
 const task = 'build';
 const message = 'hello world';

index.d.ts

@@ -24,3 +24,4 @@ export {
 	getCancelSignal,
 	type Message,
 } from './types/ipc.js';
+export type {VerboseObject, SyncVerboseObject} from './types/verbose.js';

lib/arguments/command.js

@@ -5,12 +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, {piped, ...rawOptions}) => {
+export const handleCommand = (filePath, rawArguments, rawOptions) => {
 	const startTime = getStartTime();
 	const {command, escapedCommand} = joinCommand(filePath, rawArguments);
 	const verbose = normalizeFdSpecificOption(rawOptions, 'verbose');
 	const verboseInfo = getVerboseInfo(verbose, escapedCommand, {...rawOptions});
-	logCommand(escapedCommand, verboseInfo, piped);
+	logCommand(escapedCommand, verboseInfo);
 	return {
 		command,
 		escapedCommand,

lib/io/contents.js

@@ -64,7 +64,7 @@ const logOutputAsync = async ({stream, onStreamEnd, fdNumber, encoding, allMixed
 		stripFinalNewline: true,
 		allMixed,
 	});
-	await logLines(linesIterable, stream, verboseInfo);
+	await logLines(linesIterable, stream, fdNumber, verboseInfo);
 };
 
 // When using `buffer: false`, users need to read `subprocess.stdout|stderr|all` right away

lib/io/output-sync.js

@@ -51,6 +51,7 @@ const transformOutputResultSync = (
 	logOutputSync({
 		serializedResult,
 		fdNumber,
+		state,
 		verboseInfo,
 		encoding,
 		stdioItems,
@@ -101,7 +102,7 @@ const serializeChunks = ({chunks, objectMode, encoding, lines, stripFinalNewline
 	return {serializedResult};
 };
 
-const logOutputSync = ({serializedResult, fdNumber, verboseInfo, encoding, stdioItems, objectMode}) => {
+const logOutputSync = ({serializedResult, fdNumber, state, verboseInfo, encoding, stdioItems, objectMode}) => {
 	if (!shouldLogOutput({
 		stdioItems,
 		encoding,
@@ -112,7 +113,12 @@ const logOutputSync = ({serializedResult, fdNumber, verboseInfo, encoding, stdio
 	}
 
 	const linesArray = splitLinesSync(serializedResult, false, objectMode);
-	logLinesSync(linesArray, verboseInfo);
+
+	try {
+		logLinesSync(linesArray, fdNumber, verboseInfo);
+	} catch (error) {
+		state.error ??= error;
+	}
 };
 
 // When the `std*` target is a file path/URL or a file descriptor

lib/methods/main-async.js

@@ -14,7 +14,6 @@ import {pipeOutputAsync} from '../io/output-async.js';
 import {subprocessKill} from '../terminate/kill.js';
 import {cleanupOnExit} from '../terminate/cleanup.js';
 import {pipeToSubprocess} from '../pipe/setup.js';
-import {logEarlyResult} from '../verbose/complete.js';
 import {makeAllStream} from '../resolve/all-async.js';
 import {waitForSubprocessResult} from '../resolve/wait-subprocess.js';
 import {addConvertedStreams} from '../convert/add.js';
@@ -48,25 +47,19 @@ export const execaCoreAsync = (rawFile, rawArguments, rawOptions, createNested)
 // Compute arguments to pass to `child_process.spawn()`
 const handleAsyncArguments = (rawFile, rawArguments, rawOptions) => {
 	const {command, escapedCommand, startTime, verboseInfo} = handleCommand(rawFile, rawArguments, rawOptions);
-
-	try {
-		const {file, commandArguments, options: normalizedOptions} = normalizeOptions(rawFile, rawArguments, rawOptions);
-		const options = handleAsyncOptions(normalizedOptions);
-		const fileDescriptors = handleStdioAsync(options, verboseInfo);
-		return {
-			file,
-			commandArguments,
-			command,
-			escapedCommand,
-			startTime,
-			verboseInfo,
-			options,
-			fileDescriptors,
-		};
-	} catch (error) {
-		logEarlyResult(error, startTime, verboseInfo);
-		throw error;
-	}
+	const {file, commandArguments, options: normalizedOptions} = normalizeOptions(rawFile, rawArguments, rawOptions);
+	const options = handleAsyncOptions(normalizedOptions);
+	const fileDescriptors = handleStdioAsync(options, verboseInfo);
+	return {
+		file,
+		commandArguments,
+		command,
+		escapedCommand,
+		startTime,
+		verboseInfo,
+		options,
+		fileDescriptors,
+	};
 };
 
 // Options normalization logic specific to async methods.