From f9f1199f675be9972897135124e9d2947acdb093 Mon Sep 17 00:00:00 2001 From: ehmicky Date: Tue, 18 Jun 2024 23:58:42 +0100 Subject: [PATCH] Refactor `verbose` logic (#1126) --- lib/arguments/command.js | 7 ++-- lib/arguments/specific.js | 10 +++++- lib/io/contents.js | 60 +++++++++++++++++++++------------ lib/io/max-buffer.js | 6 ++-- lib/io/output-sync.js | 29 +++++++++++----- lib/ipc/buffer-messages.js | 5 +-- lib/ipc/outgoing.js | 3 +- lib/return/reject.js | 2 +- lib/stdio/handle.js | 2 +- lib/stdio/stdio-option.js | 9 ++--- lib/verbose/complete.js | 58 +++++++++++--------------------- lib/verbose/default.js | 46 +++++++++++++++++++++++++ lib/verbose/error.js | 15 +++++---- lib/verbose/info.js | 43 +++++++++++++++--------- lib/verbose/ipc.js | 12 +++++-- lib/verbose/log.js | 69 +++++++++++++++++--------------------- lib/verbose/output.js | 14 +++++--- lib/verbose/start.js | 13 ++++--- 18 files changed, 246 insertions(+), 157 deletions(-) create mode 100644 lib/verbose/default.js diff --git a/lib/arguments/command.js b/lib/arguments/command.js index 1aa3bb696e..774f13077e 100644 --- a/lib/arguments/command.js +++ b/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, diff --git a/lib/arguments/specific.js b/lib/arguments/specific.js index b56eabba0a..1238c0df50 100644 --- a/lib/arguments/specific.js +++ b/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]; diff --git a/lib/io/contents.js b/lib/io/contents.js index 3de53a2462..aaadf8b6c1 100644 --- a/lib/io/contents.js +++ b/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 diff --git a/lib/io/max-buffer.js b/lib/io/max-buffer.js index c9ae2d8466..1f4520a595 100644 --- a/lib/io/max-buffer.js +++ b/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. diff --git a/lib/io/output-sync.js b/lib/io/output-sync.js index 22f9120f22..508d647c92 100644 --- a/lib/io/output-sync.js +++ b/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))) { diff --git a/lib/ipc/buffer-messages.js b/lib/ipc/buffer-messages.js index 590a1417d4..c8ed3d583c 100644 --- a/lib/ipc/buffer-messages.js +++ b/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, diff --git a/lib/ipc/outgoing.js b/lib/ipc/outgoing.js index 03bd91c456..904f67dd73 100644 --- a/lib/ipc/outgoing.js +++ b/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; diff --git a/lib/return/reject.js b/lib/return/reject.js index f70e7b966f..284acea5bc 100644 --- a/lib/return/reject.js +++ b/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; diff --git a/lib/stdio/handle.js b/lib/stdio/handle.js index 77a3b8d985..eeeb220b04 100644 --- a/lib/stdio/handle.js +++ b/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, diff --git a/lib/stdio/stdio-option.js b/lib/stdio/stdio-option.js index cc174d48aa..4d52a351bc 100644 --- a/lib/stdio/stdio-option.js +++ b/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); diff --git a/lib/verbose/complete.js b/lib/verbose/complete.js index 00bc990fa2..dd6174057a 100644 --- a/lib/verbose/complete.js +++ b/lib/verbose/complete.js @@ -1,5 +1,4 @@ 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'; @@ -7,52 +6,33 @@ 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, + }); }; diff --git a/lib/verbose/default.js b/lib/verbose/default.js new file mode 100644 index 0000000000..0ee31a52a0 --- /dev/null +++ b/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, +}; diff --git a/lib/verbose/error.js b/lib/verbose/error.js index 64266ddf28..a3ca076afe 100644 --- a/lib/verbose/error.js +++ b/lib/verbose/error.js @@ -1,12 +1,13 @@ -import {redBright, yellowBright} from 'yoctocolors'; import {verboseLog} from './log.js'; // When `verbose` is `short|full`, print each command's error when it fails -export const logError = ({message, failed, reject, verboseId, icon}) => { - if (!failed) { - return; +export const logError = (logMessage, verboseInfo, failed) => { + if (failed) { + verboseLog({ + type: 'error', + logMessage, + verboseInfo, + failed, + }); } - - const color = reject ? redBright : yellowBright; - verboseLog(message, verboseId, icon, color); }; diff --git a/lib/verbose/info.js b/lib/verbose/info.js index 83ca82aa23..3623f6da64 100644 --- a/lib/verbose/info.js +++ b/lib/verbose/info.js @@ -1,40 +1,51 @@ -import {debuglog} from 'node:util'; - -// Default value for the `verbose` option -export const verboseDefault = debuglog('execa').enabled ? 'full' : 'none'; +import {getFdSpecificValue} from '../arguments/specific.js'; // Information computed before spawning, used by the `verbose` option -export const getVerboseInfo = verbose => { - const verboseId = isVerbose(verbose) ? VERBOSE_ID++ : undefined; +export const getVerboseInfo = (verbose, escapedCommand, rawOptions) => { validateVerbose(verbose); - return {verbose, verboseId}; + const commandId = getCommandId(verbose); + return { + verbose, + escapedCommand, + commandId, + rawOptions, + }; }; +const getCommandId = verbose => isVerbose({verbose}) ? COMMAND_ID++ : undefined; + // Prepending the `pid` is useful when multiple commands print their output at the same time. // However, we cannot use the real PID since this is not available with `child_process.spawnSync()`. // Also, we cannot use the real PID if we want to print it before `child_process.spawn()` is run. // As a pro, it is shorter than a normal PID and never re-uses the same id. // As a con, it cannot be used to send signals. -let VERBOSE_ID = 0n; - -// The `verbose` option can have different values for `stdout`/`stderr` -export const isVerbose = verbose => verbose.some(fdVerbose => fdVerbose !== 'none'); +let COMMAND_ID = 0n; const validateVerbose = verbose => { - for (const verboseItem of verbose) { - if (verboseItem === false) { + for (const fdVerbose of verbose) { + if (fdVerbose === false) { throw new TypeError('The "verbose: false" option was renamed to "verbose: \'none\'".'); } - if (verboseItem === true) { + if (fdVerbose === true) { throw new TypeError('The "verbose: true" option was renamed to "verbose: \'short\'".'); } - if (!VERBOSE_VALUES.has(verboseItem)) { + if (!VERBOSE_VALUES.has(fdVerbose)) { const allowedValues = [...VERBOSE_VALUES].map(allowedValue => `'${allowedValue}'`).join(', '); - throw new TypeError(`The "verbose" option must not be ${verboseItem}. Allowed values are: ${allowedValues}.`); + throw new TypeError(`The "verbose" option must not be ${fdVerbose}. Allowed values are: ${allowedValues}.`); } } }; const VERBOSE_VALUES = new Set(['none', 'short', 'full']); + +// The `verbose` option can have different values for `stdout`/`stderr` +export const isVerbose = ({verbose}) => getFdGenericVerbose(verbose) !== 'none'; + +// Whether IPC and output and logged +export const isFullVerbose = ({verbose}, fdNumber) => getFdSpecificValue(verbose, fdNumber) === 'full'; + +const getFdGenericVerbose = verbose => verbose.every(fdVerbose => fdVerbose === verbose[0]) + ? verbose[0] + : verbose.find(fdVerbose => fdVerbose !== 'none'); diff --git a/lib/verbose/ipc.js b/lib/verbose/ipc.js index 01e4763e63..01a690c463 100644 --- a/lib/verbose/ipc.js +++ b/lib/verbose/ipc.js @@ -1,8 +1,14 @@ import {verboseLog, serializeLogMessage} from './log.js'; +import {isFullVerbose} from './info.js'; // When `verbose` is `'full'`, print IPC messages from the subprocess -export const shouldLogIpc = ({verbose}) => verbose.at(-1) === 'full'; +export const shouldLogIpc = verboseInfo => isFullVerbose(verboseInfo, 'ipc'); -export const logIpcOutput = (message, {verboseId}) => { - verboseLog(serializeLogMessage(message), verboseId, 'ipc'); +export const logIpcOutput = (message, verboseInfo) => { + const logMessage = serializeLogMessage(message); + verboseLog({ + type: 'ipc', + logMessage, + verboseInfo, + }); }; diff --git a/lib/verbose/log.js b/lib/verbose/log.js index 03145dd776..e67e6d41ec 100644 --- a/lib/verbose/log.js +++ b/lib/verbose/log.js @@ -1,51 +1,42 @@ import {writeFileSync} from 'node:fs'; import {inspect} from 'node:util'; -import figures from 'figures'; -import {gray} from 'yoctocolors'; import {escapeLines} from '../arguments/escape.js'; +import {defaultLogger} from './default.js'; // Write synchronously to ensure lines are properly ordered and not interleaved with `stdout` -export const verboseLog = (string, verboseId, icon, color) => { - const prefixedLines = addPrefix(string, verboseId, icon, color); - writeFileSync(STDERR_FD, `${prefixedLines}\n`); +export const verboseLog = ({type, logMessage, verboseInfo, failed, piped}) => { + const logObject = getLogObject({ + type, + failed, + piped, + verboseInfo, + }); + const printedLines = getPrintedLines(logMessage, logObject); + writeFileSync(STDERR_FD, `${printedLines}\n`); }; +const getLogObject = ({ + type, + failed = false, + piped = false, + verboseInfo: {commandId, rawOptions}, +}) => ({ + type, + timestamp: new Date(), + failed, + piped, + commandId, + options: rawOptions, +}); + +const getPrintedLines = (logMessage, logObject) => logMessage + .split('\n') + .map(message => defaultLogger({...logObject, message})) + .join('\n'); + +// Unless a `verbose` function is used, print all logs on `stderr` const STDERR_FD = 2; -const addPrefix = (string, verboseId, icon, color) => string.includes('\n') - ? string - .split('\n') - .map(line => addPrefixToLine(line, verboseId, icon, color)) - .join('\n') - : addPrefixToLine(string, verboseId, icon, color); - -const addPrefixToLine = (line, verboseId, icon, color = identity) => [ - gray(`[${getTimestamp()}]`), - gray(`[${verboseId}]`), - color(ICONS[icon]), - color(line), -].join(' '); - -const identity = string => string; - -// Prepending the timestamp allows debugging the slow paths of a subprocess -const getTimestamp = () => { - const date = new Date(); - return `${padField(date.getHours(), 2)}:${padField(date.getMinutes(), 2)}:${padField(date.getSeconds(), 2)}.${padField(date.getMilliseconds(), 3)}`; -}; - -const padField = (field, padding) => String(field).padStart(padding, '0'); - -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); diff --git a/lib/verbose/output.js b/lib/verbose/output.js index 4307282461..74a76678de 100644 --- a/lib/verbose/output.js +++ b/lib/verbose/output.js @@ -1,14 +1,15 @@ import {BINARY_ENCODINGS} from '../arguments/encoding-option.js'; import {TRANSFORM_TYPES} from '../stdio/type.js'; import {verboseLog, serializeLogMessage} from './log.js'; +import {isFullVerbose} from './info.js'; // `ignore` opts-out of `verbose` for a specific stream. // `ipc` cannot use piping. // `inherit` would result in double printing. // They can also lead to double printing when passing file descriptor integers or `process.std*`. // This only leaves with `pipe` and `overlapped`. -export const shouldLogOutput = ({stdioItems, encoding, verboseInfo: {verbose}, fdNumber}) => fdNumber !== 'all' - && verbose[fdNumber] === 'full' +export const shouldLogOutput = ({stdioItems, encoding, verboseInfo, fdNumber}) => fdNumber !== 'all' + && isFullVerbose(verboseInfo, fdNumber) && !BINARY_ENCODINGS.has(encoding) && fdUsesVerbose(fdNumber) && (stdioItems.some(({type, value}) => type === 'native' && PIPED_STDIO_VALUES.has(value)) @@ -48,6 +49,11 @@ export const logLinesSync = (linesArray, verboseInfo) => { const isPipingStream = stream => stream._readableState.pipes.length > 0; // When `verbose` is `full`, print stdout|stderr -const logLine = (line, {verboseId}) => { - verboseLog(serializeLogMessage(line), verboseId, 'output'); +const logLine = (line, verboseInfo) => { + const logMessage = serializeLogMessage(line); + verboseLog({ + type: 'output', + logMessage, + verboseInfo, + }); }; diff --git a/lib/verbose/start.js b/lib/verbose/start.js index 63f8416b81..526f239243 100644 --- a/lib/verbose/start.js +++ b/lib/verbose/start.js @@ -1,13 +1,16 @@ -import {bold} from 'yoctocolors'; import {isVerbose} from './info.js'; import {verboseLog} from './log.js'; // When `verbose` is `short|full`, print each command -export const logCommand = (escapedCommand, {verbose, verboseId}, {piped = false}) => { - if (!isVerbose(verbose)) { +export const logCommand = (escapedCommand, verboseInfo, piped) => { + if (!isVerbose(verboseInfo)) { return; } - const icon = piped ? 'pipedCommand' : 'command'; - verboseLog(escapedCommand, verboseId, icon, bold); + verboseLog({ + type: 'command', + logMessage: escapedCommand, + verboseInfo, + piped, + }); };