diff --git a/lib/npm.js b/lib/npm.js index 0552acd8760c8..81b4dc6c408a3 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -244,7 +244,10 @@ class Npm { this.time('npm:load:display', () => { this.#display.load({ loglevel: this.config.get('loglevel'), - chalk: this.logChalk, // Use logChalk since that is based on stderr + stdoutChalk: this.#chalk, + stdoutColor: this.color, + stderrChalk: this.#logChalk, + stderrColor: this.logColor, timing: this.config.get('timing'), unicode: this.config.get('unicode'), progress: this.flatOptions.progress, diff --git a/lib/utils/display.js b/lib/utils/display.js index a6250b17f1c78..3621ebb3c0aef 100644 --- a/lib/utils/display.js +++ b/lib/utils/display.js @@ -1,7 +1,7 @@ const proggy = require('proggy') const { log } = require('proc-log') const { explain } = require('./explain-eresolve.js') -const { formatWithOptions, format } = require('./format') +const { formatWithOptions } = require('./format') const COLOR_PALETTE = ({ chalk: c }) => ({ heading: c.white.bgBlack, @@ -81,17 +81,30 @@ const setBlocking = (stream) => { return stream } +const getLevel = (stringOrLevelObject) => { + if (typeof stringOrLevelObject === 'string') { + return { level: stringOrLevelObject } + } + return stringOrLevelObject +} + class Display { - // pause by default until config is loaded - #paused = true + #logState = { + buffering: true, + buffer: [], + } - // buffers to store logs when paused - #logBuffer = [] - #outputBuffer = [] + #outputState = { + buffering: true, + buffer: [], + } // colors - #chalk - #colors + #stdoutChalk + #stdoutColor + #stderrChalk + #stderrColor + #logColors // progress #progress @@ -109,125 +122,163 @@ class Display { constructor ({ stdout, stderr }) { this.#stdout = setBlocking(stdout) this.#stderr = setBlocking(stderr) + // Handlers are set immediately so they can buffer all events process.on('log', this.#logHandler) process.on('output', this.#outputHandler) } off () { process.off('log', this.#logHandler) + this.#logState.buffer.length = 0 + process.off('output', this.#outputHandler) - this.#logBuffer.length = 0 + this.#outputState.buffer.length = 0 + if (this.#progress) { this.#progress.stop() } } - load ({ loglevel, chalk, timing, unicode, progress, json, heading }) { - this.#chalk = chalk - this.#colors = COLOR_PALETTE({ chalk }) + load ({ + loglevel, + stdoutColor, + stdoutChalk, + stderrColor, + stderrChalk, + timing, + unicode, + progress, + json, + heading, + }) { + this.#stdoutColor = stdoutColor + this.#stdoutChalk = stdoutChalk + + this.#stderrColor = stderrColor + this.#stderrChalk = stderrChalk + + this.#logColors = COLOR_PALETTE({ chalk: stderrChalk }) this.#levelIndex = LEVEL_OPTIONS[loglevel].index this.#timing = timing this.#json = json this.#heading = heading + // In silent mode we remove all the handlers if (this.#levelIndex <= 0) { this.off() - } else { - log.resume() - if (progress) { - this.#startProgress({ unicode }) - } + return } - } - forceLog (level, ...args) { - // This will show the log regardless of the current loglevel, except when silent - this.#logHandler({ level, force: true }, ...args) + // Emit resume event on the logs which will flush output + log.resume() + + // TODO: this should be a proc-log method `proc-log.output.flush`? + this.#outputHandler('flush') + + this.#startProgress({ progress, unicode }) } - #outputHandler = (level, ...args) => { - if (level === 'standard') { - this.#stdout.write(format(...args)) + // Public class field so it can be passed directly as a listener + #logHandler = (...args) => { + if (args[0] === LEVELS.resume) { + this.#logState.buffering = false + this.#logState.buffer.forEach((item) => this.#tryWriteLog(...item)) + this.#logState.buffer.length = 0 return } - /* istanbul ignore next - not implemented yet */ - if (level === 'error') { - this.#stderr.write(format(...args)) + if (args[0] === LEVELS.pause) { + this.#logState.buffering = true return } - /* istanbul ignore else - just to catch accidental errors */ - if (level === 'buffer') { - this.#outputBuffer.push(args[0]) + if (this.#logState.buffering) { + this.#logState.buffer.push(args) return } - /* istanbul ignore next - just to catch accidental errors */ - log.verbose('display', `Unknown output event ${level}`) + this.#tryWriteLog(...args) } - flushOutput (jsonError) { - if (!jsonError && !this.#outputBuffer.length) { + // Public class field so it can be passed directly as a listener + #outputHandler = (...args) => { + if (args[0] === 'flush') { + this.#outputState.buffering = false + if (args[1] && this.#json) { + const mergedJsonOutput = {} + for (const [, ...items] of this.#outputState.buffer) { + Object.assign(mergedJsonOutput, ...items.map(safeJsonParse)) + } + Object.assign(args[1]) + this.#writeOutput('standard', JSON.stringify(mergedJsonOutput, null, 2)) + } else { + this.#outputState.buffer.forEach((item) => this.#writeOutput(...item)) + } + this.#outputState.buffer.length = 0 return } - if (this.#json) { - const output = this.#outputBuffer.reduce((a, i) => ({ ...a, ...safeJsonParse(i) }), {}) - this.#stdout.write(format(JSON.stringify({ ...output, ...jsonError }, null, 2))) - } else { - this.#outputBuffer.forEach((item) => this.#stdout.write(format(item))) + if (args[0] === 'buffer') { + this.#outputState.buffer.push(['standard', ...args.slice(1)]) + return } - this.#outputBuffer.length = 0 + if (this.#outputState.buffering) { + this.#outputState.buffer.push(args) + return + } + + this.#writeOutput(...args) } - #write (...args) { - const { level: levelName, force = false } = typeof args[0] === 'string' - ? { level: args[0] } : args[0] + // OUTPUT - if (levelName === LEVELS.pause) { - this.#paused = true - return - } + #writeOutput (...args) { + const { level } = getLevel(args.shift()) - if (levelName === LEVELS.resume) { - this.#paused = false - this.#logBuffer.forEach((item) => this.#write(...item)) - this.#logBuffer.length = 0 + if (level === 'standard') { + this.#stdout.write(formatWithOptions({ colors: this.#stdoutColor }, ...args)) return } - if (this.#paused) { - this.#logBuffer.push(args) - return + if (level === 'error') { + this.#stderr.write(formatWithOptions({ colors: this.#stderrColor }, ...args)) } + } + + // TODO: move this to proc-log and remove this public method + flushOutput (jsonError) { + this.#outputHandler('flush', jsonError) + } - const level = LEVEL_METHODS[levelName] - const show = level.show ?? (({ index }) => level.index <= index) + // LOGS - if ((force && level.index !== 0) || show({ index: this.#levelIndex, timing: this.#timing })) { - // this mutates the array so we can pass args directly to format later - const [, title] = args.splice(0, 2) - const prefix = [ - this.#colors.heading(this.#heading), - this.#colors[levelName](level.label ?? levelName), - title ? this.#colors.title(title) : null, - ] - this.#stderr.write(formatWithOptions({ prefix }, ...args)) - } else if (this.#progress) { - // TODO: make this display a single log line of filtered messages + forceLog (level, ...args) { + // This will show the log regardless of the current loglevel + if (this.#levelIndex !== 0) { + this.#logHandler({ level, force: true }, ...args) } } - #logHandler = (level, ...args) => { + #tryWriteLog (...args) { try { - this.#log(level, ...args) + // Also (and this is a really inexcusable kludge), we patch the + // log.warn() method so that when we see a peerDep override + // explanation from Arborist, we can replace the object with a + // highly abbreviated explanation of what's being overridden. + // TODO: this could probably be moved to arborist now that display is refactored + const [level, heading, message, expl] = args + if (level === LEVELS.warn && heading === 'ERESOLVE' && expl && typeof expl === 'object') { + this.#writeLog(level, heading, message) + this.#writeLog(level, '', explain(expl, this.#stderrChalk, 2)) + return + } + this.#writeLog(...args) } catch (ex) { try { // if it crashed once, it might again! - this.#write(LEVELS.verbose, null, `attempt to log crashed`, ...args, ex) + this.#writeLog(LEVELS.verbose, null, `attempt to log crashed`, ...args, ex) } catch (ex2) { /* istanbul ignore next - this happens if the object has an inspect method that crashes */ // eslint-disable-next-line no-console @@ -236,22 +287,32 @@ class Display { } } - #log (...args) { - const [level, heading, message, expl] = args - if (level === LEVELS.warn && heading === 'ERESOLVE' && expl && typeof expl === 'object') { - // Also (and this is a really inexcusable kludge), we patch the - // log.warn() method so that when we see a peerDep override - // explanation from Arborist, we can replace the object with a - // highly abbreviated explanation of what's being overridden. - // TODO: this could probably be moved to arborist now that display is refactored - this.#write(level, heading, message) - this.#write(level, '', explain(expl, this.#chalk, 2)) - return + #writeLog (...args) { + const { level, force = false } = getLevel(args.shift()) + + const levelOpts = LEVEL_METHODS[level] + const show = levelOpts.show ?? (({ index }) => levelOpts.index <= index) + + if (force || show({ index: this.#levelIndex, timing: this.#timing })) { + // this mutates the array so we can pass args directly to format later + const title = args.shift() + const prefix = [ + this.#logColors.heading(this.#heading), + this.#logColors[level](levelOpts.label ?? level), + title ? this.#logColors.title(title) : null, + ] + this.#stderr.write(formatWithOptions({ prefix, colors: this.stderrColor }, ...args)) + } else if (this.#progress) { + // TODO: make this display a single log line of filtered messages } - this.#write(...args) } - #startProgress ({ unicode }) { + // PROGRESS + + #startProgress ({ progress, unicode }) { + if (!progress) { + return + } this.#progress = proggy.createClient({ normalize: true }) // TODO: implement proggy trackers in arborist/doctor // TODO: listen to progress events here and build progress UI diff --git a/lib/utils/exit-handler.js b/lib/utils/exit-handler.js index 3f2ffaaf0c807..e4d1325942e89 100644 --- a/lib/utils/exit-handler.js +++ b/lib/utils/exit-handler.js @@ -1,7 +1,6 @@ const os = require('os') const fs = require('fs') - -const { log } = require('proc-log') +const { log, output } = require('proc-log') const errorMessage = require('./error-message.js') const { redactLog: replaceInfo } = require('@npmcli/redact') @@ -9,6 +8,15 @@ let npm = null // set by the cli let exitHandlerCalled = false let showLogFileError = false +const outputError = (v) => { + if (npm) { + output.error(v) + } else { + // Use console for output if there is no npm + // eslint-disable-next-line no-console + console.error(v) + } +} process.on('exit', code => { // process.emit is synchronous, so the timeEnd handler will run before the // unfinished timer check below @@ -32,8 +40,7 @@ process.on('exit', code => { if (!exitHandlerCalled) { process.exitCode = code || 1 log.error('', 'Exit handler never called!') - // eslint-disable-next-line no-console - console.error('') + outputError('') log.error('', 'This is an error with npm itself. Please report this error at:') log.error('', ' ') showLogFileError = true @@ -62,8 +69,7 @@ process.on('exit', code => { if (logMethod) { if (!npm.silent) { // just a line break if not in silent mode - // eslint-disable-next-line no-console - console.error('') + outputError('') } const message = [] @@ -108,15 +114,15 @@ const exitHandler = err => { if (!npm) { err = err || new Error('Exit prior to setting npm in exit handler') + // Don't use proc-log here since npm was never set // eslint-disable-next-line no-console - console.error(err.stack || err.message) + outputError(err.stack || err.message) return process.exit(1) } if (!hasLoadedNpm) { err = err || new Error('Exit prior to config file resolving.') - // eslint-disable-next-line no-console - console.error(err.stack || err.message) + outputError(err.stack || err.message) } // only show the notification if it finished. diff --git a/test/lib/utils/exit-handler.js b/test/lib/utils/exit-handler.js index 8e218cb763429..95aefd9197aa6 100644 --- a/test/lib/utils/exit-handler.js +++ b/test/lib/utils/exit-handler.js @@ -53,7 +53,7 @@ mockGlobals(t, { }, { replace: true }) const mockExitHandler = async (t, { config, mocks, files, ...opts } = {}) => { - const errors = [] + const consoleErrors = [] const { npm, logMocks, ...rest } = await loadMockNpm(t, { ...opts, @@ -68,7 +68,7 @@ const mockExitHandler = async (t, { config, mocks, files, ...opts } = {}) => { ...(typeof config === 'function' ? config(dirs) : config), }), globals: { - 'console.error': (err) => errors.push(err), + 'console.error': (err) => consoleErrors.push(err), }, }) @@ -103,7 +103,7 @@ const mockExitHandler = async (t, { config, mocks, files, ...opts } = {}) => { return { ...rest, - errors, + consoleErrors, npm, // Make it async to make testing ergonomics a little easier so we dont need // to t.plan() every test to make sure we get process.exit called. @@ -170,52 +170,58 @@ t.test('handles unknown error with logs and debug file', async (t) => { }) t.test('exit handler never called - loglevel silent', async (t) => { - const { logs, errors } = await mockExitHandler(t, { + const { logs, outputErrors, consoleErrors } = await mockExitHandler(t, { config: { loglevel: 'silent' }, }) process.emit('exit', 1) t.strictSame(logs.error, []) - t.strictSame(errors, [''], 'logs one empty string to console.error') + t.strictSame(outputErrors, [''], 'logs one empty string to stderr') + t.strictSame(consoleErrors, []) }) t.test('exit handler never called - loglevel notice', async (t) => { - const { logs, errors } = await mockExitHandler(t) + const { logs, outputErrors, consoleErrors } = await mockExitHandler(t) process.emit('exit', 1) t.equal(process.exitCode, 1) t.match(logs.error, [ 'Exit handler never called!', /error with npm itself/, ]) - t.strictSame(errors, ['', ''], 'logs two empty strings to console.error') + t.strictSame(outputErrors, ['', ''], 'logs two empty strings to stderr') + t.strictSame(consoleErrors, []) }) t.test('exit handler never called - no npm', async (t) => { - const { logs, errors } = await mockExitHandler(t, { init: false }) + const { logs, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) process.emit('exit', 1) t.equal(process.exitCode, 1) t.strictSame(logs.error, []) - t.strictSame(errors, [''], 'logs one empty string to console.error') + t.strictSame(consoleErrors, [''], 'logs one empty string to stderr') + t.strictSame(outputErrors, []) }) t.test('exit handler called - no npm', async (t) => { - const { exitHandler, errors } = await mockExitHandler(t, { init: false }) + const { exitHandler, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) await exitHandler() t.equal(process.exitCode, 1) - t.match(errors, [/Error: Exit prior to setting npm in exit handler/]) + t.match(consoleErrors, [/Error: Exit prior to setting npm in exit handler/]) + t.strictSame(outputErrors, []) }) t.test('exit handler called - no npm with error', async (t) => { - const { exitHandler, errors } = await mockExitHandler(t, { init: false }) + const { exitHandler, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) await exitHandler(err('something happened')) t.equal(process.exitCode, 1) - t.match(errors, [/Error: something happened/]) + t.match(consoleErrors, [/Error: something happened/]) + t.strictSame(outputErrors, []) }) t.test('exit handler called - no npm with error without stack', async (t) => { - const { exitHandler, errors } = await mockExitHandler(t, { init: false }) + const { exitHandler, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) await exitHandler(err('something happened', {}, true)) t.equal(process.exitCode, 1) - t.match(errors, [/something happened/]) + t.match(consoleErrors, [/something happened/]) + t.strictSame(outputErrors, []) }) t.test('standard output using --json', async (t) => { @@ -320,17 +326,18 @@ t.test('update notification', async (t) => { }) t.test('npm.config not ready', async (t) => { - const { exitHandler, logs, errors } = await mockExitHandler(t, { + const { exitHandler, logs, outputErrors, consoleErrors } = await mockExitHandler(t, { load: false, }) await exitHandler() t.equal(process.exitCode, 1) - t.match(errors, [ + t.match(outputErrors, [ /Error: Exit prior to config file resolving./, ], 'should exit with config error msg') t.strictSame(logs, [], 'no logs if it doesnt load') + t.strictSame(consoleErrors, []) }) t.test('no logs dir', async (t) => { @@ -581,11 +588,14 @@ t.test('call exitHandler with no error', async (t) => { }) t.test('defaults to log error msg if stack is missing when unloaded', async (t) => { - const { exitHandler, logs, errors } = await mockExitHandler(t, { load: false }) + const { exitHandler, logs, outputErrors, consoleErrors } = await mockExitHandler(t, { + load: false, + }) await exitHandler(err('Error with no stack', { code: 'ENOSTACK', errno: 127 }, true)) t.equal(process.exitCode, 127) - t.same(errors, ['Error with no stack'], 'should use error msg') + t.strictSame(outputErrors, ['Error with no stack'], 'should use error msg') + t.strictSame(consoleErrors, []) t.strictSame(logs.error, []) }) @@ -609,25 +619,31 @@ t.test('do no fancy handling for shellouts', async t => { }) t.test('shellout with a numeric error code', async t => { - const { exitHandler, logs } = await mockShelloutExit(t) + const { exitHandler, logs, consoleErrors, outputErrors } = await mockShelloutExit(t) await exitHandler(err('', 5)) t.equal(process.exitCode, 5, 'got expected exit code') t.strictSame(logs.error, [], 'no noisy warnings') t.strictSame(logs.warn, [], 'no noisy warnings') + t.strictSame(consoleErrors, []) + t.strictSame(outputErrors, []) }) t.test('shellout without a numeric error code (something in npm)', async t => { - const { exitHandler, logs } = await mockShelloutExit(t) + const { exitHandler, logs, consoleErrors, outputErrors } = await mockShelloutExit(t) await exitHandler(err('', 'banana stand')) t.equal(process.exitCode, 1, 'got expected exit code') // should log some warnings and errors, because something weird happened t.strictNotSame(logs.error, [], 'bring the noise') + t.strictSame(consoleErrors, []) + t.strictSame(outputErrors, ['']) }) t.test('shellout with code=0 (extra weird?)', async t => { - const { exitHandler, logs } = await mockShelloutExit(t) + const { exitHandler, logs, consoleErrors, outputErrors } = await mockShelloutExit(t) await exitHandler(Object.assign(new Error(), { code: 0 })) t.equal(process.exitCode, 1, 'got expected exit code') t.strictNotSame(logs.error, [], 'bring the noise') + t.strictSame(consoleErrors, []) + t.strictSame(outputErrors, ['']) }) })