diff --git a/lib/io/contents.js b/lib/io/contents.js index aaadf8b6c..a8c30768b 100644 --- a/lib/io/contents.js +++ b/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 diff --git a/lib/io/output-sync.js b/lib/io/output-sync.js index 508d647c9..fd3e53e55 100644 --- a/lib/io/output-sync.js +++ b/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,13 @@ 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; + throw error; + } }; // When the `std*` target is a file path/URL or a file descriptor diff --git a/lib/verbose/complete.js b/lib/verbose/complete.js index dd6174057..b3e196d9a 100644 --- a/lib/verbose/complete.js +++ b/lib/verbose/complete.js @@ -5,7 +5,7 @@ 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 +// When `verbose` is `short|full|custom`, print each command's completion, duration and error export const logFinalResult = ({shortMessage, durationMs, failed}, verboseInfo) => { logResult(shortMessage, durationMs, verboseInfo, failed); }; diff --git a/lib/verbose/default.js b/lib/verbose/default.js index 0ee31a52a..2f182be7f 100644 --- a/lib/verbose/default.js +++ b/lib/verbose/default.js @@ -6,7 +6,7 @@ import { yellowBright, } from 'yoctocolors'; -// Default logger for the `verbose` option +// Default logger when `verbose` is not a function export const defaultLogger = ({type, message, timestamp, failed, piped, commandId, options: {reject = true}}) => { const timestampString = serializeTimestamp(timestamp); const icon = ICONS[type]({failed, reject, piped}); diff --git a/lib/verbose/error.js b/lib/verbose/error.js index a3ca076af..265c73128 100644 --- a/lib/verbose/error.js +++ b/lib/verbose/error.js @@ -1,6 +1,6 @@ import {verboseLog} from './log.js'; -// When `verbose` is `short|full`, print each command's error when it fails +// When `verbose` is `short|full|custom`, print each command's error when it fails export const logError = (logMessage, verboseInfo, failed) => { if (failed) { verboseLog({ diff --git a/lib/verbose/info.js b/lib/verbose/info.js index 3623f6da6..2266399b1 100644 --- a/lib/verbose/info.js +++ b/lib/verbose/info.js @@ -31,9 +31,9 @@ const validateVerbose = verbose => { throw new TypeError('The "verbose: true" option was renamed to "verbose: \'short\'".'); } - if (!VERBOSE_VALUES.has(fdVerbose)) { + if (!VERBOSE_VALUES.has(fdVerbose) && !isCustomFdVerbose(fdVerbose)) { const allowedValues = [...VERBOSE_VALUES].map(allowedValue => `'${allowedValue}'`).join(', '); - throw new TypeError(`The "verbose" option must not be ${fdVerbose}. Allowed values are: ${allowedValues}.`); + throw new TypeError(`The "verbose" option must not be ${fdVerbose}. Allowed values are: ${allowedValues} or a function.`); } } }; @@ -44,7 +44,26 @@ const VERBOSE_VALUES = new Set(['none', 'short', 'full']); export const isVerbose = ({verbose}) => getFdGenericVerbose(verbose) !== 'none'; // Whether IPC and output and logged -export const isFullVerbose = ({verbose}, fdNumber) => getFdSpecificValue(verbose, fdNumber) === 'full'; +export const isFullVerbose = ({verbose}, fdNumber) => { + const fdVerbose = getFdSpecificValue(verbose, fdNumber); + return fdVerbose === 'full' || isCustomFdVerbose(fdVerbose); +}; + +// The `verbose` option can be a function to customize logging +export const getLogger = ({verbose}, fdNumber) => { + const fdVerbose = getFdVerbose(verbose, fdNumber); + return isCustomFdVerbose(fdVerbose) ? fdVerbose : undefined; +}; + +const isCustomFdVerbose = fdVerbose => typeof fdVerbose === 'function'; + +// When using `verbose: {stdout, stderr, fd3, ipc}`: +// - `verbose.stdout|stderr|fd3` is used for 'output' +// - `verbose.ipc` is only used for 'ipc' +// - first non-'none' `verbose.*` is used for 'command', 'error' and 'duration' +const getFdVerbose = (verbose, fdNumber) => fdNumber === undefined + ? getFdGenericVerbose(verbose) + : getFdSpecificValue(verbose, fdNumber); const getFdGenericVerbose = verbose => verbose.every(fdVerbose => fdVerbose === verbose[0]) ? verbose[0] diff --git a/lib/verbose/ipc.js b/lib/verbose/ipc.js index 01a690c46..542f138d4 100644 --- a/lib/verbose/ipc.js +++ b/lib/verbose/ipc.js @@ -9,6 +9,7 @@ export const logIpcOutput = (message, verboseInfo) => { verboseLog({ type: 'ipc', logMessage, + fdNumber: 'ipc', verboseInfo, }); }; diff --git a/lib/verbose/log.js b/lib/verbose/log.js index e67e6d41e..5d17f78a7 100644 --- a/lib/verbose/log.js +++ b/lib/verbose/log.js @@ -2,37 +2,60 @@ import {writeFileSync} from 'node:fs'; import {inspect} from 'node:util'; import {escapeLines} from '../arguments/escape.js'; import {defaultLogger} from './default.js'; +import {getLogger} from './info.js'; // Write synchronously to ensure lines are properly ordered and not interleaved with `stdout` -export const verboseLog = ({type, logMessage, verboseInfo, failed, piped}) => { +export const verboseLog = ({type, logMessage, fdNumber, verboseInfo, failed, piped}) => { const logObject = getLogObject({ type, failed, piped, verboseInfo, }); - const printedLines = getPrintedLines(logMessage, logObject); - writeFileSync(STDERR_FD, `${printedLines}\n`); + const logger = getLogger(verboseInfo, fdNumber); + const printedLines = getPrintedLines(logMessage, logObject, logger); + writeFileSync(STDERR_FD, printedLines); }; const getLogObject = ({ type, failed = false, piped = false, - verboseInfo: {commandId, rawOptions}, + verboseInfo: {escapedCommand, commandId, rawOptions}, }) => ({ type, timestamp: new Date(), failed, piped, + escapedCommand, commandId, options: rawOptions, }); -const getPrintedLines = (logMessage, logObject) => logMessage +const getPrintedLines = (logMessage, logObject, logger) => logMessage .split('\n') - .map(message => defaultLogger({...logObject, message})) - .join('\n'); + .map(message => getPrintedLine(message, logObject, logger)) + .filter(printedLine => printedLine !== undefined) + .map(printedLine => appendNewline(printedLine)) + .join(''); + +const getPrintedLine = (message, logObject, logger) => { + const lineLogObject = {...logObject, message}; + const logLine = defaultLogger(lineLogObject); + + if (logger === undefined) { + return logLine; + } + + const printedLine = logger(logLine, lineLogObject); + if (typeof printedLine === 'string') { + return printedLine; + } +}; + +const appendNewline = printedLine => printedLine.endsWith('\n') + ? printedLine + : `${printedLine}\n`; // Unless a `verbose` function is used, print all logs on `stderr` const STDERR_FD = 2; diff --git a/lib/verbose/output.js b/lib/verbose/output.js index 74a76678d..ea56accc2 100644 --- a/lib/verbose/output.js +++ b/lib/verbose/output.js @@ -24,18 +24,18 @@ const fdUsesVerbose = fdNumber => fdNumber === 1 || fdNumber === 2; const PIPED_STDIO_VALUES = new Set(['pipe', 'overlapped']); // `verbose: 'full'` printing logic with async methods -export const logLines = async (linesIterable, stream, verboseInfo) => { +export const logLines = async (linesIterable, stream, fdNumber, verboseInfo) => { for await (const line of linesIterable) { if (!isPipingStream(stream)) { - logLine(line, verboseInfo); + logLine(line, fdNumber, verboseInfo); } } }; // `verbose: 'full'` printing logic with sync methods -export const logLinesSync = (linesArray, verboseInfo) => { +export const logLinesSync = (linesArray, fdNumber, verboseInfo) => { for (const line of linesArray) { - logLine(line, verboseInfo); + logLine(line, fdNumber, verboseInfo); } }; @@ -49,11 +49,12 @@ export const logLinesSync = (linesArray, verboseInfo) => { const isPipingStream = stream => stream._readableState.pipes.length > 0; // When `verbose` is `full`, print stdout|stderr -const logLine = (line, verboseInfo) => { +const logLine = (line, fdNumber, verboseInfo) => { const logMessage = serializeLogMessage(line); verboseLog({ type: 'output', logMessage, + fdNumber, verboseInfo, }); }; diff --git a/lib/verbose/start.js b/lib/verbose/start.js index 526f23924..ccd2f6431 100644 --- a/lib/verbose/start.js +++ b/lib/verbose/start.js @@ -1,7 +1,7 @@ import {isVerbose} from './info.js'; import {verboseLog} from './log.js'; -// When `verbose` is `short|full`, print each command +// When `verbose` is `short|full|custom`, print each command export const logCommand = (escapedCommand, verboseInfo, piped) => { if (!isVerbose(verboseInfo)) { return; diff --git a/test/fixtures/nested/custom-event.js b/test/fixtures/nested/custom-event.js new file mode 100644 index 000000000..79fa05296 --- /dev/null +++ b/test/fixtures/nested/custom-event.js @@ -0,0 +1,3 @@ +export const getOptions = ({type, eventProperty}) => ({ + verbose: (logLine, logEvent) => logEvent.type === type ? `${logEvent[eventProperty]}` : undefined, +}); diff --git a/test/fixtures/nested/custom-print-multiple.js b/test/fixtures/nested/custom-print-multiple.js new file mode 100644 index 000000000..ccf8aa148 --- /dev/null +++ b/test/fixtures/nested/custom-print-multiple.js @@ -0,0 +1,8 @@ +export const getOptions = ({fdNumber, secondFdNumber}) => ({ + verbose: { + [fdNumber](logLine) { + console.warn(logLine); + }, + [secondFdNumber]() {}, + }, +}); diff --git a/test/fixtures/nested/custom-print.js b/test/fixtures/nested/custom-print.js new file mode 100644 index 000000000..fb3a6f610 --- /dev/null +++ b/test/fixtures/nested/custom-print.js @@ -0,0 +1,9 @@ +const setFdSpecific = (fdNumber, option) => fdNumber === undefined + ? option + : {[fdNumber]: option}; + +export const getOptions = ({fdNumber}) => ({ + verbose: setFdSpecific(fdNumber, logLine => { + console.warn(logLine); + }), +}); diff --git a/test/fixtures/nested/custom-return.js b/test/fixtures/nested/custom-return.js new file mode 100644 index 000000000..5b42ceb46 --- /dev/null +++ b/test/fixtures/nested/custom-return.js @@ -0,0 +1,5 @@ +export const getOptions = ({logOutput}) => ({ + verbose(logLine, {type}) { + return type === 'command' ? logOutput : undefined; + }, +}); diff --git a/test/fixtures/nested/custom-throw.js b/test/fixtures/nested/custom-throw.js new file mode 100644 index 000000000..0ca085625 --- /dev/null +++ b/test/fixtures/nested/custom-throw.js @@ -0,0 +1,5 @@ +export const getOptions = ({errorMessage}) => ({ + verbose() { + throw new Error(errorMessage); + }, +}); diff --git a/test/fixtures/nested/custom-uppercase.js b/test/fixtures/nested/custom-uppercase.js new file mode 100644 index 000000000..220d11377 --- /dev/null +++ b/test/fixtures/nested/custom-uppercase.js @@ -0,0 +1,5 @@ +export const getOptions = () => ({ + verbose(logLine, {type}) { + return type === 'command' ? logLine.replace('noop', 'NOOP') : undefined; + }, +}); diff --git a/test/helpers/early-error.js b/test/helpers/early-error.js index ced3752cc..22563c1e3 100644 --- a/test/helpers/early-error.js +++ b/test/helpers/early-error.js @@ -1,5 +1,7 @@ import {execa, execaSync} from '../../index.js'; +export const validationErrorOptions = {timeout: []}; + export const earlyErrorOptions = {detached: 'true'}; export const getEarlyErrorSubprocess = options => execa('empty.js', {...earlyErrorOptions, ...options}); export const earlyErrorOptionsSync = {maxBuffer: false}; diff --git a/test/verbose/custom.js b/test/verbose/custom.js new file mode 100644 index 000000000..81aa2a04e --- /dev/null +++ b/test/verbose/custom.js @@ -0,0 +1,33 @@ +import test from 'ava'; +import {setFixtureDirectory} from '../helpers/fixtures-directory.js'; +import {foobarString} from '../helpers/input.js'; +import {nestedSubprocess} from '../helpers/nested.js'; +import {getCommandLine, testTimestamp} from '../helpers/verbose.js'; + +setFixtureDirectory(); + +const testCustomReturn = async (t, logOutput, expectedOutput) => { + const {stderr} = await nestedSubprocess( + 'noop.js', + ['.'], + {optionsFixture: 'custom-return.js', optionsInput: {logOutput}}, + {stripFinalNewline: false}, + ); + t.is(stderr, expectedOutput); +}; + +test('"verbose" returning a string prints it', testCustomReturn, `${foobarString}\n`, `${foobarString}\n`); +test('"verbose" returning a string without a newline adds it', testCustomReturn, foobarString, `${foobarString}\n`); +test('"verbose" returning a string with multiple newlines keeps them', testCustomReturn, `${foobarString}\n\n`, `${foobarString}\n\n`); +test('"verbose" returning an empty string prints an empty line', testCustomReturn, '', '\n'); +test('"verbose" returning undefined ignores it', testCustomReturn, undefined, ''); +test('"verbose" returning a number ignores it', testCustomReturn, 0, ''); +test('"verbose" returning a bigint ignores it', testCustomReturn, 0n, ''); +test('"verbose" returning a boolean ignores it', testCustomReturn, true, ''); +test('"verbose" returning an object ignores it', testCustomReturn, {}, ''); +test('"verbose" returning an array ignores it', testCustomReturn, [], ''); + +test('"verbose" receives logLine string as first argument', async t => { + const {stderr} = await nestedSubprocess('noop.js', [foobarString], {optionsFixture: 'custom-uppercase.js'}); + t.is(getCommandLine(stderr), `${testTimestamp} [0] $ NOOP.js ${foobarString}`); +}); diff --git a/test/verbose/start.js b/test/verbose/start.js index 78f38d08a..56e8875c2 100644 --- a/test/verbose/start.js +++ b/test/verbose/start.js @@ -24,6 +24,11 @@ import { ipcShortOption, ipcFullOption, } from '../helpers/verbose.js'; +import { + validationErrorOptions, + earlyErrorOptions, + earlyErrorOptionsSync, +} from '../helpers/early-error.js'; setFixtureDirectory(); @@ -73,6 +78,37 @@ test('Prints command, verbose "full", fd-specific fd3, worker, sync', testPrintC test('Prints command, verbose "short", fd-specific ipc, worker, sync', testPrintCommand, ipcShortOption, true, true); test('Prints command, verbose "full", fd-specific ipc, worker, sync', testPrintCommand, ipcFullOption, true, true); +const testPrintCommandCustom = async (t, fdNumber, worker, isSync) => { + const {stderr} = await nestedSubprocess('noop.js', [foobarString], { + worker, + isSync, + optionsFixture: 'custom-print.js', + optionsInput: {fdNumber}, + }); + t.is(getCommandLine(stderr), `${testTimestamp} [0] $ noop.js ${foobarString}`); +}; + +test('Prints command, verbose custom', testPrintCommandCustom, undefined, false, false); +test('Prints command, verbose custom, fd-specific stdout', testPrintCommandCustom, 'stdout', false, false); +test('Prints command, verbose custom, fd-specific stderr', testPrintCommandCustom, 'stderr', false, false); +test('Prints command, verbose custom, fd-specific fd3', testPrintCommandCustom, 'fd3', false, false); +test('Prints command, verbose custom, fd-specific ipc', testPrintCommandCustom, 'ipc', false, false); +test('Prints command, verbose custom, sync', testPrintCommandCustom, undefined, false, true); +test('Prints command, verbose custom, fd-specific stdout, sync', testPrintCommandCustom, 'stdout', false, true); +test('Prints command, verbose custom, fd-specific stderr, sync', testPrintCommandCustom, 'stderr', false, true); +test('Prints command, verbose custom, fd-specific fd3, sync', testPrintCommandCustom, 'fd3', false, true); +test('Prints command, verbose custom, fd-specific ipc, sync', testPrintCommandCustom, 'ipc', false, true); +test('Prints command, verbose custom, worker', testPrintCommandCustom, undefined, true, false); +test('Prints command, verbose custom, fd-specific stdout, worker', testPrintCommandCustom, 'stdout', true, false); +test('Prints command, verbose custom, fd-specific stderr, worker', testPrintCommandCustom, 'stderr', true, false); +test('Prints command, verbose custom, fd-specific fd3, worker', testPrintCommandCustom, 'fd3', true, false); +test('Prints command, verbose custom, fd-specific ipc, worker', testPrintCommandCustom, 'ipc', true, false); +test('Prints command, verbose custom, worker, sync', testPrintCommandCustom, undefined, true, true); +test('Prints command, verbose custom, fd-specific stdout, worker, sync', testPrintCommandCustom, 'stdout', true, true); +test('Prints command, verbose custom, fd-specific stderr, worker, sync', testPrintCommandCustom, 'stderr', true, true); +test('Prints command, verbose custom, fd-specific fd3, worker, sync', testPrintCommandCustom, 'fd3', true, true); +test('Prints command, verbose custom, fd-specific ipc, worker, sync', testPrintCommandCustom, 'ipc', true, true); + const testNoPrintCommand = async (t, verbose, isSync) => { const {stderr} = await nestedSubprocess('noop.js', [foobarString], {verbose, isSync}); t.is(stderr, ''); @@ -93,6 +129,21 @@ test('Does not print command, verbose "none", fd-specific fd3, sync', testNoPrin test('Does not print command, verbose "none", fd-specific ipc, sync', testNoPrintCommand, ipcNoneOption, true); test('Does not print command, verbose default, fd-specific, sync', testNoPrintCommand, {}, true); +const testPrintCommandOrder = async (t, fdNumber, secondFdNumber) => { + const {stderr} = await nestedSubprocess('noop.js', [foobarString], { + optionsFixture: 'custom-print-multiple.js', + optionsInput: {fdNumber, secondFdNumber}, + }); + t.is(getCommandLine(stderr), `${testTimestamp} [0] $ noop.js ${foobarString}`); +}; + +test('Prints command, verbose custom, fd-specific stdout+stderr', testPrintCommandOrder, 'stdout', 'stderr'); +test('Prints command, verbose custom, fd-specific stdout+fd3', testPrintCommandOrder, 'stdout', 'fd3'); +test('Prints command, verbose custom, fd-specific stdout+ipc', testPrintCommandOrder, 'stdout', 'ipc'); +test('Prints command, verbose custom, fd-specific stderr+fd3', testPrintCommandOrder, 'stderr', 'fd3'); +test('Prints command, verbose custom, fd-specific stderr+ipc', testPrintCommandOrder, 'stderr', 'ipc'); +test('Prints command, verbose custom, fd-specific fd3+ipc', testPrintCommandOrder, 'stderr', 'ipc'); + const testPrintCommandError = async (t, isSync) => { const stderr = await runErrorSubprocess(t, 'short', isSync); t.is(getCommandLine(stderr), `${testTimestamp} [0] $ noop-fail.js 1 ${foobarString}`); @@ -160,3 +211,53 @@ test('Escapes control characters from command', async t => { const {stderr} = await nestedSubprocess('noop.js', ['\u0001'], {verbose: 'short'}); t.is(getCommandLine(stderr), `${testTimestamp} [0] $ noop.js ${QUOTE}\\u0001${QUOTE}`); }); + +test('"verbose" function receives logEvent.type "command"', async t => { + const {stderr} = await nestedSubprocess('noop.js', [foobarString], { + optionsFixture: 'custom-event.js', + optionsInput: {type: 'command', eventProperty: 'type'}, + }); + t.is(stderr, 'command'); +}); + +test('"verbose" function receives logEvent.message', async t => { + const {stderr} = await nestedSubprocess('noop.js', ['. .'], { + optionsFixture: 'custom-event.js', + optionsInput: {type: 'command', eventProperty: 'message'}, + }); + t.is(stderr, 'noop.js \'. .\''); +}); + +test('"verbose" function receives logEvent.timestamp', async t => { + const {stderr} = await nestedSubprocess('noop.js', [foobarString], { + optionsFixture: 'custom-event.js', + optionsInput: {type: 'command', eventProperty: 'timestamp'}, + }); + t.true(Number.isInteger(new Date(stderr).getTime())); +}); + +test('"verbose" function receives logEvent.failed always true', async t => { + const {stderr} = await nestedSubprocess('fail.js', { + optionsFixture: 'custom-event.js', + optionsInput: {type: 'command', eventProperty: 'failed'}, + }); + t.is(stderr, 'false'); +}); + +const testCommandThrow = async (t, options, isSync) => { + const {nestedResult} = await nestedSubprocess('noop.js', ['.'], { + optionsFixture: 'custom-throw.js', + optionsInput: {errorMessage: foobarString}, + isSync, + ...options, + }); + t.true(nestedResult instanceof Error); + t.is(nestedResult.message, foobarString); +}; + +test('Handle exceptions in "verbose" function', testCommandThrow, {}, false); +test('Handle exceptions during validation errors', testCommandThrow, validationErrorOptions, false); +test('Handle exceptions during spawn errors', testCommandThrow, earlyErrorOptions, false); +test('Handle exceptions in "verbose" function, sync', testCommandThrow, {}, true); +test('Handle exceptions during validation errors, sync', testCommandThrow, validationErrorOptions, true); +test('Handle exceptions during spawn errors, sync', testCommandThrow, earlyErrorOptionsSync, true);