From 8f0a443e6c7d7a44dcb566d510096bf61cfe83fb Mon Sep 17 00:00:00 2001 From: Tobias Koppers Date: Sat, 27 Jul 2019 19:48:10 +0200 Subject: [PATCH] Colored console for node environment Status report in logger ProgressPlugins uses logger --- lib/ProgressPlugin.js | 83 +++-------- lib/Stats.js | 10 +- lib/logging/Logger.js | 7 +- lib/logging/createConsoleLogger.js | 71 ++++++---- lib/logging/runtime.js | 3 +- lib/logging/truncateArgs.js | 74 ++++++++++ lib/node/NodeEnvironmentPlugin.js | 4 +- lib/node/nodeConsole.js | 132 ++++++++++++++++++ .../__snapshots__/StatsTestCases.test.js.snap | 28 ++-- 9 files changed, 306 insertions(+), 106 deletions(-) create mode 100644 lib/logging/truncateArgs.js create mode 100644 lib/node/nodeConsole.js diff --git a/lib/ProgressPlugin.js b/lib/ProgressPlugin.js index 2f5c62ce64b..93a5830ba12 100644 --- a/lib/ProgressPlugin.js +++ b/lib/ProgressPlugin.js @@ -10,50 +10,14 @@ const schema = require("../schemas/plugins/ProgressPlugin.json"); /** @typedef {import("../declarations/plugins/ProgressPlugin").ProgressPluginArgument} ProgressPluginArgument */ /** @typedef {import("../declarations/plugins/ProgressPlugin").ProgressPluginOptions} ProgressPluginOptions */ -const createDefaultHandler = profile => { - let lineCaretPosition = 0; - let lastMessage = ""; +const createDefaultHandler = (profile, logger) => { let lastState; let lastStateTime; const defaultHandler = (percentage, msg, ...args) => { - let state = msg; - const details = args.filter(v => v.length); - const maxLineLength = process.stderr.columns || Infinity; - if (percentage < 1) { - percentage = Math.floor(percentage * 100); - msg = `${percentage}% ${msg}`; - if (percentage < 100) { - msg = ` ${msg}`; - } - if (percentage < 10) { - msg = ` ${msg}`; - } - - if (details.length) { - const maxTotalDetailsLength = maxLineLength - msg.length; - const totalDetailsLength = details.reduce( - (a, b) => a + b.length, - details.length // account for added space before each detail text - ); - const maxDetailLength = - totalDetailsLength < maxTotalDetailsLength - ? Infinity - : Math.floor(maxTotalDetailsLength / details.length); - - for (let detail of details) { - if (!detail) continue; - if (detail.length + 1 > maxDetailLength) { - const truncatePrefix = "..."; - detail = `${truncatePrefix}${detail.substr( - -(maxDetailLength - truncatePrefix.length - 1) - )}`; - } - msg += ` ${detail}`; - } - } - } + logger.status(`${Math.floor(percentage * 100)}%`, msg, ...args); if (profile) { + let state = msg; state = state.replace(/^\d+\/\d+\s+/, ""); if (percentage === 0) { lastState = null; @@ -61,33 +25,23 @@ const createDefaultHandler = profile => { } else if (state !== lastState || percentage === 1) { const now = Date.now(); if (lastState) { - const stateMsg = `${now - lastStateTime}ms ${lastState}`; - goToLineStart(stateMsg); - process.stderr.write(stateMsg + "\n"); - lineCaretPosition = 0; + const diff = now - lastStateTime; + const stateMsg = `${diff}ms ${lastState}`; + if (diff > 1000) { + logger.warn(stateMsg); + } else if (diff > 10) { + logger.info(stateMsg); + } else if (diff > 0) { + logger.log(stateMsg); + } else { + logger.debug(stateMsg); + } } lastState = state; lastStateTime = now; } } - if (lastMessage !== msg) { - goToLineStart(msg); - msg = msg.substring(0, maxLineLength); - process.stderr.write(msg); - lastMessage = msg; - } - }; - - const goToLineStart = nextMessage => { - let str = ""; - for (; lineCaretPosition > nextMessage.length; lineCaretPosition--) { - str += "\b \b"; - } - for (var i = 0; i < lineCaretPosition; i++) { - str += "\b"; - } - lineCaretPosition = nextMessage.length; - if (str) process.stderr.write(str); + if (percentage === 1) logger.status(); }; return defaultHandler; @@ -118,7 +72,12 @@ class ProgressPlugin { apply(compiler) { const { modulesCount } = this; - const handler = this.handler || createDefaultHandler(this.profile); + const handler = + this.handler || + createDefaultHandler( + this.profile, + compiler.getInfrastructureLogger("webpack.Progress") + ); const showEntries = this.showEntries; const showModules = this.showModules; const showActiveModules = this.showActiveModules; diff --git a/lib/Stats.js b/lib/Stats.js index 7a586cb4da7..40bfd9ba783 100644 --- a/lib/Stats.js +++ b/lib/Stats.js @@ -755,6 +755,7 @@ class Stats { LogType.profile, LogType.profileEnd, LogType.time, + LogType.status, LogType.clear ]); collapsedGroups = true; @@ -1442,7 +1443,7 @@ class Stats { let indent = ""; for (const entry of logData.entries) { let color = colors.normal; - let prefix = ""; + let prefix = " "; switch (entry.type) { case LogType.clear: colors.normal(`${indent}-------`); @@ -1467,6 +1468,10 @@ class Stats { case LogType.debug: color = colors.normal; break; + case LogType.status: + color = colors.magenta; + prefix = " "; + break; case LogType.profile: color = colors.magenta; prefix = "

"; @@ -1481,13 +1486,14 @@ class Stats { break; case LogType.group: color = colors.cyan; + prefix = "<-> "; break; case LogType.groupCollapsed: color = colors.cyan; prefix = "<+> "; break; case LogType.groupEnd: - if (indent.length > 2) + if (indent.length >= 2) indent = indent.slice(0, indent.length - 2); continue; } diff --git a/lib/logging/Logger.js b/lib/logging/Logger.js index 6bdaea0dbc3..e3101378dd4 100644 --- a/lib/logging/Logger.js +++ b/lib/logging/Logger.js @@ -26,7 +26,8 @@ const LogType = Object.freeze({ time: "time", // name, time as [seconds, nanoseconds] - clear: "clear" // no arguments + clear: "clear", // no arguments + status: "status" // message, arguments }); exports.LogType = LogType; @@ -78,6 +79,10 @@ class WebpackLogger { this[LOG_SYMBOL](LogType.clear); } + status(...args) { + this[LOG_SYMBOL](LogType.status, args); + } + group(...args) { this[LOG_SYMBOL](LogType.group, args); } diff --git a/lib/logging/createConsoleLogger.js b/lib/logging/createConsoleLogger.js index b6b49660d19..8835d261588 100644 --- a/lib/logging/createConsoleLogger.js +++ b/lib/logging/createConsoleLogger.js @@ -15,8 +15,9 @@ const { LogType } = require("./Logger"); /** * @typedef {Object} LoggerOptions - * @property {false|true|"none"|"error"|"warn"|"info"|"log"|"verbose"} options.level loglevel - * @property {FilterTypes|boolean} options.debug filter for debug logging + * @property {false|true|"none"|"error"|"warn"|"info"|"log"|"verbose"} level loglevel + * @property {FilterTypes|boolean} debug filter for debug logging + * @property {Console & { status?: Function, logTime?: Function }} console the console to log to */ /** @@ -62,7 +63,7 @@ const LogLevel = { * @param {LoggerOptions} options options object * @returns {function(string, LogTypeEnum, any[]): void} logging function */ -module.exports = ({ level = "info", debug = false }) => { +module.exports = ({ level = "info", debug = false, console }) => { const debugFilters = typeof debug === "boolean" ? [() => debug] @@ -79,12 +80,12 @@ module.exports = ({ level = "info", debug = false }) => { * @returns {void} */ const logger = (name, type, args) => { - const labeledArgs = (prefix = "") => { + const labeledArgs = () => { if (Array.isArray(args)) { if (args.length > 0 && typeof args[0] === "string") { - return [`${prefix}[${name}] ${args[0]}`, ...args.slice(1)]; + return [`[${name}] ${args[0]}`, ...args.slice(1)]; } else { - return [`${prefix}[${name}]`, ...args]; + return [`[${name}]`, ...args]; } } else { return []; @@ -108,20 +109,33 @@ module.exports = ({ level = "info", debug = false }) => { break; case LogType.info: if (!debug && loglevel > LogLevel.info) return; - console.info(...labeledArgs(" ")); + console.info(...labeledArgs()); break; case LogType.warn: if (!debug && loglevel > LogLevel.warn) return; - console.warn(...labeledArgs(" ")); + console.warn(...labeledArgs()); break; case LogType.error: if (!debug && loglevel > LogLevel.error) return; - console.error(...labeledArgs(" ")); + console.error(...labeledArgs()); break; case LogType.trace: if (!debug) return; console.trace(); break; + case LogType.groupCollapsed: + if (!debug && loglevel > LogLevel.log) return; + if (!debug && loglevel > LogLevel.verbose) { + // eslint-disable-next-line node/no-unsupported-features/node-builtins + if (typeof console.groupCollapsed === "function") { + // eslint-disable-next-line node/no-unsupported-features/node-builtins + console.groupCollapsed(...labeledArgs()); + } else { + console.log(...labeledArgs()); + } + break; + } + // falls through case LogType.group: if (!debug && loglevel > LogLevel.log) return; // eslint-disable-next-line node/no-unsupported-features/node-builtins @@ -132,32 +146,25 @@ module.exports = ({ level = "info", debug = false }) => { console.log(...labeledArgs()); } break; - case LogType.groupCollapsed: - if (!debug && loglevel > LogLevel.log) return; - // eslint-disable-next-line node/no-unsupported-features/node-builtins - if (typeof console.groupCollapsed === "function") { - // eslint-disable-next-line node/no-unsupported-features/node-builtins - console.groupCollapsed(...labeledArgs()); - } else { - console.log(...labeledArgs(" ")); - } - break; case LogType.groupEnd: if (!debug && loglevel > LogLevel.log) return; // eslint-disable-next-line node/no-unsupported-features/node-builtins if (typeof console.groupEnd === "function") { // eslint-disable-next-line node/no-unsupported-features/node-builtins console.groupEnd(); - } else { - console.log(...labeledArgs(" ")); } break; - case LogType.time: + case LogType.time: { if (!debug && loglevel > LogLevel.log) return; - console.log( - `[${name}] ${args[0]}: ${args[1] * 1000 + args[2] / 1000000}ms` - ); + const ms = args[1] * 1000 + args[2] / 1000000; + const msg = `[${name}] ${args[0]}: ${ms}ms`; + if (typeof console.logTime === "function") { + console.logTime(msg); + } else { + console.log(msg); + } break; + } case LogType.profile: // eslint-disable-next-line node/no-unsupported-features/node-builtins if (typeof console.profile === "function") { @@ -180,6 +187,20 @@ module.exports = ({ level = "info", debug = false }) => { console.clear(); } break; + case LogType.status: + if (!debug && loglevel > LogLevel.info) return; + if (typeof console.status === "function") { + if (args.length === 0) { + console.status(); + } else { + console.status(...labeledArgs()); + } + } else { + if (args.length !== 0) { + console.info(...labeledArgs()); + } + } + break; default: throw new Error(`Unexpected LogType ${type}`); } diff --git a/lib/logging/runtime.js b/lib/logging/runtime.js index 7b4bbf7b22f..18e2148bec3 100644 --- a/lib/logging/runtime.js +++ b/lib/logging/runtime.js @@ -5,7 +5,8 @@ const createConsoleLogger = require("./createConsoleLogger"); /** @type {createConsoleLogger.LoggerOptions} */ let currentDefaultLoggerOptions = { level: "info", - debug: false + debug: false, + console }; let currentDefaultLogger = createConsoleLogger(currentDefaultLoggerOptions); diff --git a/lib/logging/truncateArgs.js b/lib/logging/truncateArgs.js new file mode 100644 index 00000000000..714e4624cb1 --- /dev/null +++ b/lib/logging/truncateArgs.js @@ -0,0 +1,74 @@ +/* + MIT License http://www.opensource.org/licenses/mit-license.php + Author Tobias Koppers @sokra + */ + +"use strict"; + +/** + * @param {any[]} args items to be truncated + * @param {number} maxLength maximum length of args including spaces between + * @returns {string[]} truncated args + */ +const truncateArgs = (args, maxLength) => { + const lengths = args.map(a => `${a}`.length); + const availableLength = maxLength - lengths.length + 1; + + if (availableLength > 0 && args.length === 1) { + if (availableLength > 3) { + return ["..." + args[0].slice(-availableLength + 3)]; + } else { + return [args[0].slice(-availableLength)]; + } + } + + // Check if there is space for at least 4 chars per arg + if (availableLength < lengths.reduce((s, i) => s + Math.min(i, 4), 0)) { + // remove args + if (args.length > 1) + return truncateArgs(args.slice(0, args.length - 1), maxLength); + return []; + } + + let currentLength = lengths.reduce((a, b) => a + b, 0); + + // Check if all fits into maxLength + if (currentLength <= availableLength) return args; + + // Try to remove chars from the longest items until it fits + while (currentLength > availableLength) { + const maxLength = Math.max(...lengths); + const shorterItems = lengths.filter(l => l !== maxLength); + const nextToMaxLength = + shorterItems.length > 0 ? Math.max(...shorterItems) : 0; + const maxReduce = maxLength - nextToMaxLength; + let maxItems = lengths.length - shorterItems.length; + let overrun = currentLength - availableLength; + for (let i = 0; i < lengths.length; i++) { + if (lengths[i] === maxLength) { + const reduce = Math.min(Math.floor(overrun / maxItems), maxReduce); + lengths[i] -= reduce; + currentLength -= reduce; + overrun -= reduce; + maxItems--; + } + } + } + + // Return args reduced to length in lengths + return args.map((a, i) => { + const str = `${a}`; + const length = lengths[i]; + if (str.length === length) { + return str; + } else if (length > 6) { + return "..." + str.slice(-length + 3); + } else if (length > 0) { + return str.slice(-length); + } else { + return ""; + } + }); +}; + +module.exports = truncateArgs; diff --git a/lib/node/NodeEnvironmentPlugin.js b/lib/node/NodeEnvironmentPlugin.js index 8a236ea85a5..98c7985e9e5 100644 --- a/lib/node/NodeEnvironmentPlugin.js +++ b/lib/node/NodeEnvironmentPlugin.js @@ -9,6 +9,7 @@ const NodeOutputFileSystem = require("./NodeOutputFileSystem"); const NodeJsInputFileSystem = require("enhanced-resolve/lib/NodeJsInputFileSystem"); const CachedInputFileSystem = require("enhanced-resolve/lib/CachedInputFileSystem"); const createConsoleLogger = require("../logging/createConsoleLogger"); +const nodeConsole = require("./nodeConsole"); class NodeEnvironmentPlugin { constructor(options) { @@ -20,7 +21,8 @@ class NodeEnvironmentPlugin { Object.assign( { level: "info", - debug: false + debug: false, + console: nodeConsole }, this.options.infrastructureLogging ) diff --git a/lib/node/nodeConsole.js b/lib/node/nodeConsole.js new file mode 100644 index 00000000000..016bbf2b9ac --- /dev/null +++ b/lib/node/nodeConsole.js @@ -0,0 +1,132 @@ +/* + MIT License http://www.opensource.org/licenses/mit-license.php + Author Tobias Koppers @sokra +*/ + +"use strict"; + +const truncateArgs = require("../logging/truncateArgs"); +const util = require("util"); + +const tty = process.stderr.isTTY && process.env.TERM !== "dumb"; + +let currentStatusMessage = undefined; +let hasStatusMessage = false; +let currentIndent = ""; +let currentCollapsed = 0; + +const indent = (str, prefix, colorPrefix, colorSuffix) => { + if (str === "") return str; + prefix = currentIndent + prefix; + if (tty) { + return ( + prefix + + colorPrefix + + str.replace(/\n/g, colorSuffix + "\n" + prefix + colorPrefix) + + colorSuffix + ); + } else { + return prefix + str.replace(/\n/g, "\n" + prefix); + } +}; + +const clearStatusMessage = () => { + if (hasStatusMessage) { + process.stderr.write("\x1b[2K\r"); + hasStatusMessage = false; + } +}; + +const writeStatusMessage = () => { + if (!currentStatusMessage) return; + const l = process.stderr.columns; + const args = l ? truncateArgs(currentStatusMessage, l) : currentStatusMessage; + const str = args.join(" "); + const coloredStr = `\u001b[1m${str}\u001b[39m\u001b[22m`; + process.stderr.write(`\x1b[2K\r${coloredStr}`); + hasStatusMessage = true; +}; + +const writeColored = (prefix, colorPrefix, colorSuffix) => { + return (...args) => { + if (currentCollapsed > 0) return; + clearStatusMessage(); + // @ts-ignore + const str = indent(util.format(...args), prefix, colorPrefix, colorSuffix); + process.stderr.write(str + "\n"); + writeStatusMessage(); + }; +}; + +const writeGroupMessage = writeColored( + "<-> ", + "\u001b[1m\u001b[36m", + "\u001b[39m\u001b[22m" +); + +const writeGroupCollapsedMessage = writeColored( + "<+> ", + "\u001b[1m\u001b[36m", + "\u001b[39m\u001b[22m" +); + +module.exports = { + log: writeColored(" ", "\u001b[1m", "\u001b[22m"), + debug: writeColored(" ", "", ""), + trace: writeColored(" ", "", ""), + info: writeColored(" ", "\u001b[1m\u001b[32m", "\u001b[39m\u001b[22m"), + warn: writeColored(" ", "\u001b[1m\u001b[33m", "\u001b[39m\u001b[22m"), + error: writeColored(" ", "\u001b[1m\u001b[31m", "\u001b[39m\u001b[22m"), + logTime: writeColored(" ", "\u001b[1m\u001b[35m", "\u001b[39m\u001b[22m"), + group: (...args) => { + writeGroupMessage(...args); + if (currentCollapsed > 0) { + currentCollapsed++; + } else { + currentIndent += " "; + } + }, + groupCollapsed: (...args) => { + writeGroupCollapsedMessage(...args); + currentCollapsed++; + }, + groupEnd: () => { + if (currentCollapsed > 0) currentCollapsed--; + else if (currentIndent.length >= 2) + currentIndent = currentIndent.slice(0, currentIndent.length - 2); + }, + // eslint-disable-next-line node/no-unsupported-features/node-builtins + profile: console.profile && (name => console.profile(name)), + // eslint-disable-next-line node/no-unsupported-features/node-builtins + profileEnd: console.profileEnd && (name => console.profileEnd(name)), + clear: + tty && + // eslint-disable-next-line node/no-unsupported-features/node-builtins + console.clear && + (() => { + clearStatusMessage(); + // eslint-disable-next-line node/no-unsupported-features/node-builtins + console.clear(); + writeStatusMessage(); + }), + status: tty + ? (name, ...args) => { + if (name === undefined && args.length === 0) { + clearStatusMessage(); + currentStatusMessage = undefined; + } else if ( + typeof name === "string" && + name.startsWith("[webpack.Progress] ") + ) { + currentStatusMessage = [name.slice(19), ...args]; + writeStatusMessage(); + } else if (name === "[webpack.Progress]") { + currentStatusMessage = [...args]; + writeStatusMessage(); + } else { + currentStatusMessage = [name, ...args]; + writeStatusMessage(); + } + } + : writeColored(" ", "", "") +}; diff --git a/test/__snapshots__/StatsTestCases.test.js.snap b/test/__snapshots__/StatsTestCases.test.js.snap index 3e3fb1f582a..130be5be105 100644 --- a/test/__snapshots__/StatsTestCases.test.js.snap +++ b/test/__snapshots__/StatsTestCases.test.js.snap @@ -1254,21 +1254,21 @@ Entrypoint main = main.js | at Object..module.exports (Xdir/logging/node_modules/custom-loader/index.js:5:9) A warning | at Object..module.exports (Xdir/logging/node_modules/custom-loader/index.js:6:9) -Unimportant +<-> Unimportant Info message - Just log - Just debug + Just log + Just debug Measure: Xms - Nested - Log inside collapsed group - Trace + <-> Nested + Log inside collapsed group + Trace | at Object..module.exports (Xdir/logging/node_modules/custom-loader/index.js:15:9) Measure: Xms ------- - After clear + After clear DEBUG LOG from node_modules/custom-loader/index.js Named Logger node_modules/custom-loader/index.js!index.js -Message with named logger" + Message with named logger" `; exports[`StatsTestCases should print correct stats for max-modules 1`] = ` @@ -1942,11 +1942,11 @@ chunk {3} 3.js 54 bytes <{0}> >{1}< [rendered] ModuleConcatenation bailout: Module is not an ECMAScript module LOG from MyPlugin -Group +<-> Group Error Warning Info - Log + Log <+> Collaped group + 3 hidden lines" `; @@ -2125,13 +2125,13 @@ chunk {3} 3.js 54 bytes <{0}> >{1}< [rendered] [0] Xms -> factory:Xms building:Xms = Xms LOG from MyPlugin -Group +<-> Group Error Warning Info - Log - Collaped group - Log inside collapsed group + Log + <-> Collaped group + Log inside collapsed group + 1 hidden lines LOG from webpack.buildChunkGraph.visitModules