From e6d35710ac794baf17d25073c11e125db5070035 Mon Sep 17 00:00:00 2001 From: Luke Karrys Date: Sat, 13 Apr 2024 16:47:21 -0700 Subject: [PATCH] fixup! feat: do all ouput over proc-log events --- lib/npm.js | 5 ++ lib/utils/display.js | 84 +++++++++++++++++++++------------- lib/utils/exit-handler.js | 28 +++++------- lib/utils/format.js | 4 +- test/lib/utils/display.js | 82 +++++++++++++++++++++++++-------- test/lib/utils/exit-handler.js | 81 +++++++++++++++++--------------- 6 files changed, 178 insertions(+), 106 deletions(-) diff --git a/lib/npm.js b/lib/npm.js index 81b4dc6c408a3..8449e2e2775a8 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -244,6 +244,9 @@ class Npm { this.time('npm:load:display', () => { this.#display.load({ loglevel: this.config.get('loglevel'), + // TODO: only pass in logColor and color and create chalk instances + // in display load method. Then remove chalk getters from npm and + // producers should emit chalk-templates (or something else). stdoutChalk: this.#chalk, stdoutColor: this.color, stderrChalk: this.#logChalk, @@ -436,10 +439,12 @@ class Npm { return usage(this) } + // TODO: move to proc-log and remove forceLog (...args) { this.#display.forceLog(...args) } + // TODO: move to proc-log and remove flushOutput (jsonError) { this.#display.flushOutput(jsonError) } diff --git a/lib/utils/display.js b/lib/utils/display.js index 3621ebb3c0aef..b1f4e11bc8f23 100644 --- a/lib/utils/display.js +++ b/lib/utils/display.js @@ -1,5 +1,5 @@ const proggy = require('proggy') -const { log } = require('proc-log') +const { log, output } = require('proc-log') const { explain } = require('./explain-eresolve.js') const { formatWithOptions } = require('./format') @@ -17,7 +17,13 @@ const COLOR_PALETTE = ({ chalk: c }) => ({ silly: c.inverse, }) -const LEVELS = log.LEVELS.reduce((acc, key) => { +const LOG_LEVELS = log.LEVELS.reduce((acc, key) => { + acc[key] = key + return acc +}, {}) + +// TODO: move flush to proc-log +const OUTPUT_LEVELS = ['flush', ...output.LEVELS].reduce((acc, key) => { acc[key] = key return acc }, {}) @@ -55,20 +61,20 @@ const LEVEL_OPTIONS = { const LEVEL_METHODS = { ...LEVEL_OPTIONS, - [LEVELS.timing]: { + [LOG_LEVELS.timing]: { show: ({ timing, index }) => !!timing && index !== 0, }, } -const safeJsonParse = (maybeJsonStr) => { - if (typeof maybeJsonStr !== 'string') { - return maybeJsonStr - } - try { - return JSON.parse(maybeJsonStr) - } catch { - return {} +const tryJsonParse = (value) => { + if (typeof value === 'string') { + try { + return JSON.parse(value) + } catch { + return {} + } } + return value } const setBlocking = (stream) => { @@ -122,6 +128,7 @@ 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) @@ -174,21 +181,34 @@ class Display { log.resume() // TODO: this should be a proc-log method `proc-log.output.flush`? - this.#outputHandler('flush') + this.#outputHandler(OUTPUT_LEVELS.flush) this.#startProgress({ progress, unicode }) } + // STREAM WRITES + + // Write formatted and (non-)colorized output to streams + #stdoutWrite (options, ...args) { + this.#stdout.write(formatWithOptions({ colors: this.#stdoutColor, ...options }, ...args)) + } + + #stderrWrite (options, ...args) { + this.#stderr.write(formatWithOptions({ colors: this.#stderrColor, ...options }, ...args)) + } + + // HANDLERS + // Public class field so it can be passed directly as a listener #logHandler = (...args) => { - if (args[0] === LEVELS.resume) { + if (args[0] === LOG_LEVELS.resume) { this.#logState.buffering = false this.#logState.buffer.forEach((item) => this.#tryWriteLog(...item)) this.#logState.buffer.length = 0 return } - if (args[0] === LEVELS.pause) { + if (args[0] === LOG_LEVELS.pause) { this.#logState.buffering = true return } @@ -203,15 +223,14 @@ class Display { // Public class field so it can be passed directly as a listener #outputHandler = (...args) => { - if (args[0] === 'flush') { + if (args[0] === OUTPUT_LEVELS.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)) + const json = {} + for (const [, item] of this.#outputState.buffer) { + Object.assign(json, tryJsonParse(item)) } - Object.assign(args[1]) - this.#writeOutput('standard', JSON.stringify(mergedJsonOutput, null, 2)) + this.#writeOutput('standard', JSON.stringify({ ...json, ...args[1] }, null, 2)) } else { this.#outputState.buffer.forEach((item) => this.#writeOutput(...item)) } @@ -219,7 +238,7 @@ class Display { return } - if (args[0] === 'buffer') { + if (args[0] === OUTPUT_LEVELS.buffer) { this.#outputState.buffer.push(['standard', ...args.slice(1)]) return } @@ -237,25 +256,27 @@ class Display { #writeOutput (...args) { const { level } = getLevel(args.shift()) - if (level === 'standard') { - this.#stdout.write(formatWithOptions({ colors: this.#stdoutColor }, ...args)) + if (level === OUTPUT_LEVELS.standard) { + this.#stdoutWrite({}, ...args) return } - if (level === 'error') { - this.#stderr.write(formatWithOptions({ colors: this.#stderrColor }, ...args)) + if (level === OUTPUT_LEVELS.error) { + this.#stderrWrite({}, ...args) } } // TODO: move this to proc-log and remove this public method flushOutput (jsonError) { - this.#outputHandler('flush', jsonError) + this.#outputHandler(OUTPUT_LEVELS.flush, jsonError) } // LOGS + // TODO: make proc-log able to send signal data like `force` + // when that happens, remove this public method forceLog (level, ...args) { - // This will show the log regardless of the current loglevel + // This will show the log regardless of the current loglevel except when silent if (this.#levelIndex !== 0) { this.#logHandler({ level, force: true }, ...args) } @@ -269,7 +290,7 @@ class Display { // 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') { + if (level === LOG_LEVELS.warn && heading === 'ERESOLVE' && expl && typeof expl === 'object') { this.#writeLog(level, heading, message) this.#writeLog(level, '', explain(expl, this.#stderrChalk, 2)) return @@ -278,9 +299,10 @@ class Display { } catch (ex) { try { // if it crashed once, it might again! - this.#writeLog(LEVELS.verbose, null, `attempt to log crashed`, ...args, ex) + this.#writeLog(LOG_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 */ + // This happens if the object has an inspect method that crashes so just console.error + // with the errors but don't do anything else that might error again. // eslint-disable-next-line no-console console.error(`attempt to log crashed`, ex, ex2) } @@ -301,7 +323,7 @@ class Display { this.#logColors[level](levelOpts.label ?? level), title ? this.#logColors.title(title) : null, ] - this.#stderr.write(formatWithOptions({ prefix, colors: this.stderrColor }, ...args)) + this.#stderrWrite({ prefix }, ...args) } else if (this.#progress) { // TODO: make this display a single log line of filtered messages } diff --git a/lib/utils/exit-handler.js b/lib/utils/exit-handler.js index e4d1325942e89..5b4087e913254 100644 --- a/lib/utils/exit-handler.js +++ b/lib/utils/exit-handler.js @@ -8,15 +8,6 @@ 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 @@ -40,9 +31,13 @@ process.on('exit', code => { if (!exitHandlerCalled) { process.exitCode = code || 1 log.error('', 'Exit handler never called!') - outputError('') log.error('', 'This is an error with npm itself. Please report this error at:') log.error('', ' ') + + // This gets logged regardless of silent mode + // eslint-disable-next-line no-console + console.error('') + showLogFileError = true } @@ -67,10 +62,7 @@ process.on('exit', code => { const logMethod = showLogFileError ? 'error' : timing ? 'info' : null if (logMethod) { - if (!npm.silent) { - // just a line break if not in silent mode - outputError('') - } + output.error('') const message = [] @@ -116,17 +108,20 @@ const exitHandler = err => { 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 - outputError(err.stack || err.message) + console.error(err.stack || err.message) return process.exit(1) } if (!hasLoadedNpm) { err = err || new Error('Exit prior to config file resolving.') - outputError(err.stack || err.message) + // Don't use proc-log here since npm was never loaded + // eslint-disable-next-line no-console + console.error(err.stack || err.message) } // only show the notification if it finished. if (typeof npm.updateNotification === 'string') { + // TODO: use proc-log to send `force: true` along with event npm.forceLog('notice', '', npm.updateNotification) } @@ -204,6 +199,7 @@ const exitHandler = err => { } if (hasLoadedNpm) { + // TODO: use proc-log.output.flush() once it exists npm.flushOutput(jsonError) } diff --git a/lib/utils/format.js b/lib/utils/format.js index 97f01996a2025..abfbf9e331704 100644 --- a/lib/utils/format.js +++ b/lib/utils/format.js @@ -47,6 +47,4 @@ const formatWithOptions = ({ prefix: prefixes = [], eol = '\n', ...options }, .. return lines.reduce((acc, l) => `${acc}${prefix}${prefix && l ? ' ' : ''}${l}${eol}`, '') } -const format = (...args) => formatWithOptions({}, ...args) - -module.exports = { format, formatWithOptions } +module.exports = { formatWithOptions } diff --git a/test/lib/utils/display.js b/test/lib/utils/display.js index ff8328f20d2ec..31ea7bbed8add 100644 --- a/test/lib/utils/display.js +++ b/test/lib/utils/display.js @@ -1,49 +1,77 @@ const t = require('tap') const tmock = require('../../fixtures/tmock') const mockLogs = require('../../fixtures/mock-logs') +const mockGlobals = require('@npmcli/mock-globals') const { inspect } = require('util') const mockDisplay = async (t, { mocks, load } = {}) => { const { Chalk } = await import('chalk') const { log, output } = require('proc-log') + const logs = mockLogs() + const Display = tmock(t, '{LIB}/utils/display', mocks) const display = new Display(logs.streams) - display.load({ + const displayLoad = (opts) => display.load({ loglevel: 'silly', - chalk: new Chalk({ level: 0 }), + stderrChalk: new Chalk({ level: 0 }), + stderrColor: false, heading: 'npm', - ...load, + ...opts, }) + + if (load !== false) { + displayLoad(load) + } + t.teardown(() => display.off()) return { + display, output, log, + displayLoad, ...logs.logs, } } t.test('can log cleanly', async (t) => { + const { log, logs } = await mockDisplay(t) + + log.error('', 'test\x00message') + t.match(logs.error, ['test^@message']) +}) + +t.test('can handle special eresolves', async (t) => { const explains = [] const { log, logs } = await mockDisplay(t, { mocks: { '{LIB}/utils/explain-eresolve.js': { explain: (...args) => { explains.push(args) - return 'explanation' + return 'EXPLAIN' }, }, }, }) - log.error('', 'test\x00message') - t.match(logs.error, ['test^@message']) - log.warn('ERESOLVE', 'hello', { some: 'object' }) - t.match(logs.warn, ['ERESOLVE hello']) + t.strictSame(logs.warn, ['ERESOLVE hello', 'EXPLAIN']) t.match(explains, [[{ some: 'object' }, Function, 2]]) }) +t.test('can buffer output when paused', async t => { + const { displayLoad, outputs, output } = await mockDisplay(t, { + load: false, + }) + + output.buffer('Message 1') + output.standard('Message 2') + + t.strictSame(outputs, []) + displayLoad() + t.strictSame(outputs, ['Message 1', 'Message 2']) +}) + t.test('can do progress', async (t) => { const { log, logs } = await mockDisplay(t, { load: { @@ -58,20 +86,34 @@ t.test('can do progress', async (t) => { }) t.test('handles log throwing', async (t) => { - const { log, logs } = await mockDisplay(t, { - mocks: { - '{LIB}/utils/explain-eresolve.js': { - explain: () => { - throw new Error('explain') - }, - }, - }, - }) + class ThrowInspect { + #crashes = 0; - log.warn('ERESOLVE', 'hello', { some: 'object' }) + [inspect.custom] () { + throw new Error(`Crashed ${++this.#crashes}`) + } + } + + const errors = [] + mockGlobals(t, { 'console.error': (...msg) => errors.push(msg) }) + + const { log, logs } = await mockDisplay(t) + + log.error('woah', new ThrowInspect()) + + t.strictSame(logs.error, []) + t.equal(errors.length, 1) + t.match(errors[0], [ + 'attempt to log crashed', + new Error('Crashed 1'), + new Error('Crashed 2'), + ]) +}) - t.match(logs.verbose[0], - `attempt to log crashed ERESOLVE hello { some: 'object' } Error: explain`) +t.test('incorrect levels', async t => { + const { outputs } = await mockDisplay(t) + process.emit('output', 'not a real level') + t.strictSame(outputs, [], 'output is ignored') }) t.test('Display.clean', async (t) => { diff --git a/test/lib/utils/exit-handler.js b/test/lib/utils/exit-handler.js index 95aefd9197aa6..2ac0c61ac0662 100644 --- a/test/lib/utils/exit-handler.js +++ b/test/lib/utils/exit-handler.js @@ -103,7 +103,10 @@ const mockExitHandler = async (t, { config, mocks, files, ...opts } = {}) => { return { ...rest, - consoleErrors, + errors: () => [ + ...rest.outputErrors, + ...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,58 +173,55 @@ t.test('handles unknown error with logs and debug file', async (t) => { }) t.test('exit handler never called - loglevel silent', async (t) => { - const { logs, outputErrors, consoleErrors } = await mockExitHandler(t, { + const { logs, errors } = await mockExitHandler(t, { config: { loglevel: 'silent' }, }) process.emit('exit', 1) t.strictSame(logs.error, []) - t.strictSame(outputErrors, [''], 'logs one empty string to stderr') - t.strictSame(consoleErrors, []) + t.strictSame(errors(), [''], 'one empty string') }) t.test('exit handler never called - loglevel notice', async (t) => { - const { logs, outputErrors, consoleErrors } = await mockExitHandler(t) + const { logs, errors } = 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(outputErrors, ['', ''], 'logs two empty strings to stderr') - t.strictSame(consoleErrors, []) + t.strictSame(errors(), ['', ''], 'two empty string on output') }) t.test('exit handler never called - no npm', async (t) => { - const { logs, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) + const { logs, errors } = await mockExitHandler(t, { init: false }) process.emit('exit', 1) t.equal(process.exitCode, 1) t.strictSame(logs.error, []) - t.strictSame(consoleErrors, [''], 'logs one empty string to stderr') - t.strictSame(outputErrors, []) + t.strictSame(errors(), [''], 'one empty string') }) t.test('exit handler called - no npm', async (t) => { - const { exitHandler, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) + const { exitHandler, errors } = await mockExitHandler(t, { init: false }) await exitHandler() t.equal(process.exitCode, 1) - t.match(consoleErrors, [/Error: Exit prior to setting npm in exit handler/]) - t.strictSame(outputErrors, []) + t.equal(errors().length, 1) + t.match(errors(), [/Error: Exit prior to setting npm in exit handler/]) }) t.test('exit handler called - no npm with error', async (t) => { - const { exitHandler, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) + const { exitHandler, errors } = await mockExitHandler(t, { init: false }) await exitHandler(err('something happened')) t.equal(process.exitCode, 1) - t.match(consoleErrors, [/Error: something happened/]) - t.strictSame(outputErrors, []) + t.equal(errors().length, 1) + t.match(errors(), [/Error: something happened/]) }) t.test('exit handler called - no npm with error without stack', async (t) => { - const { exitHandler, consoleErrors, outputErrors } = await mockExitHandler(t, { init: false }) + const { exitHandler, errors } = await mockExitHandler(t, { init: false }) await exitHandler(err('something happened', {}, true)) t.equal(process.exitCode, 1) - t.match(consoleErrors, [/something happened/]) - t.strictSame(outputErrors, []) + t.equal(errors().length, 1) + t.match(errors(), [/something happened/]) }) t.test('standard output using --json', async (t) => { @@ -314,8 +314,10 @@ t.test('throw a string error', async (t) => { ]) }) -t.test('update notification', async (t) => { - const { exitHandler, logs, npm } = await mockExitHandler(t) +t.test('update notification - shows even with loglevel error', async (t) => { + const { exitHandler, logs, npm } = await mockExitHandler(t, { + config: { loglevel: 'error' }, + }) npm.updateNotification = 'you should update npm!' await exitHandler() @@ -325,19 +327,30 @@ t.test('update notification', async (t) => { ]) }) +t.test('update notification - hidden with silent', async (t) => { + const { exitHandler, logs, npm } = await mockExitHandler(t, { + config: { loglevel: 'silent' }, + }) + npm.updateNotification = 'you should update npm!' + + await exitHandler() + + t.strictSame(logs.notice, []) +}) + t.test('npm.config not ready', async (t) => { - const { exitHandler, logs, outputErrors, consoleErrors } = await mockExitHandler(t, { + const { exitHandler, logs, errors } = await mockExitHandler(t, { load: false, }) await exitHandler() t.equal(process.exitCode, 1) - t.match(outputErrors, [ + t.equal(errors().length, 1) + t.match(errors(), [ /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) => { @@ -588,14 +601,13 @@ 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, outputErrors, consoleErrors } = await mockExitHandler(t, { + const { exitHandler, logs, errors } = await mockExitHandler(t, { load: false, }) await exitHandler(err('Error with no stack', { code: 'ENOSTACK', errno: 127 }, true)) t.equal(process.exitCode, 127) - t.strictSame(outputErrors, ['Error with no stack'], 'should use error msg') - t.strictSame(consoleErrors, []) + t.strictSame(errors(), ['Error with no stack'], 'should use error msg') t.strictSame(logs.error, []) }) @@ -619,31 +631,28 @@ t.test('do no fancy handling for shellouts', async t => { }) t.test('shellout with a numeric error code', async t => { - const { exitHandler, logs, consoleErrors, outputErrors } = await mockShelloutExit(t) + const { exitHandler, logs, errors } = 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.strictSame(errors(), []) }) t.test('shellout without a numeric error code (something in npm)', async t => { - const { exitHandler, logs, consoleErrors, outputErrors } = await mockShelloutExit(t) + const { exitHandler, logs, errors } = 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.strictSame(errors(), ['']) }) t.test('shellout with code=0 (extra weird?)', async t => { - const { exitHandler, logs, consoleErrors, outputErrors } = await mockShelloutExit(t) + const { exitHandler, logs, errors } = 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, ['']) + t.strictSame(errors(), ['']) }) })