From fc68547eb9b06a1a6a2a0feb7e422accec50230d Mon Sep 17 00:00:00 2001 From: Luke Karrys Date: Mon, 22 Apr 2024 15:13:13 -0700 Subject: [PATCH] fix: remove some npm.load timers and exit earlier for --versions --- lib/cli/entry.js | 12 +- lib/npm.js | 103 ++++++--------- lib/utils/display.js | 32 ++++- lib/utils/log-file.js | 4 +- .../test/lib/cli/exit-handler.js.test.cjs | 66 ++++++++++ .../test/lib/utils/log-file.js.test.cjs | 119 +++++++++--------- test/lib/cli/entry.js | 16 ++- test/lib/{utils => cli}/exit-handler.js | 0 test/lib/npm.js | 16 +-- test/lib/utils/display.js | 9 +- 10 files changed, 208 insertions(+), 169 deletions(-) create mode 100644 tap-snapshots/test/lib/cli/exit-handler.js.test.cjs rename test/lib/{utils => cli}/exit-handler.js (100%) diff --git a/lib/cli/entry.js b/lib/cli/entry.js index 1c5f7e0dc1545..9b3e29ec336a6 100644 --- a/lib/cli/entry.js +++ b/lib/cli/entry.js @@ -40,20 +40,12 @@ module.exports = async (process, validateEngines) => { // Now actually fire up npm and run the command. // This is how to use npm programmatically: try { - await npm.load() + const { exec } = await npm.load() - // npm -v - if (npm.config.get('version', 'cli')) { - output.standard(npm.version) + if (!exec) { return exitHandler() } - // npm --versions - if (npm.config.get('versions', 'cli')) { - npm.argv = ['version'] - npm.config.set('usage', false, 'cli') - } - cmd = npm.argv.shift() if (!cmd) { output.standard(npm.usage) diff --git a/lib/npm.js b/lib/npm.js index d52f8bdc1c480..c801b33cf7adb 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -7,7 +7,7 @@ const usage = require('./utils/npm-usage.js') const LogFile = require('./utils/log-file.js') const Timers = require('./utils/timers.js') const Display = require('./utils/display.js') -const { log, time } = require('proc-log') +const { log, time, output } = require('proc-log') const { redactLog: replaceInfo } = require('@npmcli/redact') const pkg = require('../package.json') const { deref } = require('./utils/cmd-list.js') @@ -28,20 +28,14 @@ class Npm { } updateNotification = null - loadErr = null argv = [] #command = null #runId = new Date().toISOString().replace(/[.:]/g, '_') - #loadPromise = null #title = 'npm' #argvClean = [] #npmRoot = null - #chalk = null - #logChalk = null - #noColorChalk = null - #display = null #logFile = new LogFile() #timers = new Timers({ start: 'npm' }) @@ -107,13 +101,7 @@ class Npm { } async load () { - if (!this.#loadPromise) { - this.#loadPromise = time.start('npm:load', () => this.#load().catch((er) => { - this.loadErr = er - throw er - })) - } - return this.#loadPromise + return time.start('npm:load', () => this.#load().then(r => r || { exec: true })) } get loaded () { @@ -160,19 +148,24 @@ class Npm { await time.start('npm:load:configload', () => this.config.load()) - // get createSupportsColor from chalk directly if this lands - // https://github.com/chalk/chalk/pull/600 - const [{ Chalk }, { createSupportsColor }] = await Promise.all([ - import('chalk'), - import('supports-color'), - ]) - this.#noColorChalk = new Chalk({ level: 0 }) - // we get the chalk level based on a null stream meaning chalk will only use - // what it knows about the environment to get color support since we already - // determined in our definitions that we want to show colors. - const level = Math.max(createSupportsColor(null).level, 1) - this.#chalk = this.color ? new Chalk({ level }) : this.#noColorChalk - this.#logChalk = this.logColor ? new Chalk({ level }) : this.#noColorChalk + await this.#display.load({ + loglevel: this.config.get('loglevel'), + stdoutColor: this.color, + stderrColor: this.logColor, + timing: this.config.get('timing'), + unicode: this.config.get('unicode'), + progress: this.flatOptions.progress, + json: this.config.get('json'), + heading: this.config.get('heading'), + }) + process.env.COLOR = this.color ? '1' : '0' + + // npm -v + // return from here early so we dont create any caches/logfiles/timers etc + if (this.config.get('version', 'cli')) { + output.standard(this.version) + return { exec: false } + } // mkdir this separately since the logs dir can be set to // a different location. if this fails, then we don't have @@ -208,49 +201,29 @@ class Npm { log.verbose('argv', this.#argvClean.map(JSON.stringify).join(' ')) }) - time.start('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, - stderrColor: this.logColor, - timing: this.config.get('timing'), - unicode: this.config.get('unicode'), - progress: this.flatOptions.progress, - json: this.config.get('json'), - heading: this.config.get('heading'), - }) - process.env.COLOR = this.color ? '1' : '0' + this.#logFile.load({ + path: this.logPath, + logsMax: this.config.get('logs-max'), }) - time.start('npm:load:logFile', () => { - this.#logFile.load({ - path: this.logPath, - logsMax: this.config.get('logs-max'), - }) - log.verbose('logfile', this.#logFile.files[0] || 'no logfile created') + this.#timers.load({ + path: this.config.get('timing') ? this.logPath : null, }) - time.start('npm:load:timers', () => - this.#timers.load({ - path: this.config.get('timing') ? this.logPath : null, - }) - ) - - time.start('npm:load:configScope', () => { - const configScope = this.config.get('scope') - if (configScope && !/^@/.test(configScope)) { - this.config.set('scope', `@${configScope}`, this.config.find('scope')) - } - }) + const configScope = this.config.get('scope') + if (configScope && !/^@/.test(configScope)) { + this.config.set('scope', `@${configScope}`, this.config.find('scope')) + } if (this.config.get('force')) { log.warn('using --force', 'Recommended protections disabled.') } + + // npm --versions + if (this.config.get('versions', 'cli')) { + this.argv = ['version'] + this.config.set('usage', false, 'cli') + } } get isShellout () { @@ -283,15 +256,15 @@ class Npm { } get noColorChalk () { - return this.#noColorChalk + return this.#display.chalk.noColor } get chalk () { - return this.#chalk + return this.#display.chalk.stdout } get logChalk () { - return this.#logChalk + return this.#display.chalk.stderr } get global () { diff --git a/lib/utils/display.js b/lib/utils/display.js index d9642fa374adf..1cc906083b5a9 100644 --- a/lib/utils/display.js +++ b/lib/utils/display.js @@ -121,6 +121,7 @@ class Display { } // colors + #noColorChalk #stdoutChalk #stdoutColor #stderrChalk @@ -161,25 +162,44 @@ class Display { } } - load ({ + get chalk () { + return { + noColor: this.#noColorChalk, + stdout: this.#stdoutChalk, + stderr: this.#stderrChalk, + } + } + + async load ({ heading, json, loglevel, progress, - stderrChalk, stderrColor, - stdoutChalk, stdoutColor, timing, unicode, }) { + // get createSupportsColor from chalk directly if this lands + // https://github.com/chalk/chalk/pull/600 + const [{ Chalk }, { createSupportsColor }] = await Promise.all([ + import('chalk'), + import('supports-color'), + ]) + // we get the chalk level based on a null stream meaning chalk will only use + // what it knows about the environment to get color support since we already + // determined in our definitions that we want to show colors. + const level = Math.max(createSupportsColor(null).level, 1) + + this.#noColorChalk = new Chalk({ level: 0 }) + this.#stdoutColor = stdoutColor - this.#stdoutChalk = stdoutChalk + this.#stdoutChalk = stdoutColor ? new Chalk({ level }) : this.#noColorChalk this.#stderrColor = stderrColor - this.#stderrChalk = stderrChalk + this.#stderrChalk = stderrColor ? new Chalk({ level }) : this.#noColorChalk - this.#logColors = COLOR_PALETTE({ chalk: stderrChalk }) + this.#logColors = COLOR_PALETTE({ chalk: this.#stderrChalk }) this.#levelIndex = LEVEL_OPTIONS[loglevel].index this.#timing = timing diff --git a/lib/utils/log-file.js b/lib/utils/log-file.js index a3792abf91951..80fd9d9636dbc 100644 --- a/lib/utils/log-file.js +++ b/lib/utils/log-file.js @@ -72,6 +72,8 @@ class LogFiles { } } + log.verbose('logfile', this.files[0] || 'no logfile created') + // Kickoff cleaning process, even if we aren't writing a logfile. // This is async but it will always ignore the current logfile // Return the result so it can be awaited in tests @@ -234,7 +236,7 @@ class LogFiles { } catch (e) { // Disable cleanup failure warnings when log writing is disabled if (this.#logsMax > 0) { - log.warn('logfile', 'error cleaning log files', e) + log.verbose('logfile', 'error cleaning log files', e) } } finally { log.silly('logfile', 'done cleaning log files') diff --git a/tap-snapshots/test/lib/cli/exit-handler.js.test.cjs b/tap-snapshots/test/lib/cli/exit-handler.js.test.cjs new file mode 100644 index 0000000000000..3a510647ece8e --- /dev/null +++ b/tap-snapshots/test/lib/cli/exit-handler.js.test.cjs @@ -0,0 +1,66 @@ +/* IMPORTANT + * This snapshot file is auto-generated, but designed for humans. + * It should be checked into source control and tracked carefully. + * Re-generate by setting TAP_SNAPSHOT=1 and running tests. + * Make sure to inspect the output below. Do not ignore changes! + */ +'use strict' +exports[`test/lib/cli/exit-handler.js TAP handles unknown error with logs and debug file > debug file contents 1`] = ` +XX timing npm:load:whichnode Completed in {TIME}ms +XX silly config:load:file:{CWD}/npmrc +XX silly config:load:file:{CWD}/prefix/.npmrc +XX silly config:load:file:{CWD}/home/.npmrc +XX silly config:load:file:{CWD}/global/etc/npmrc +XX timing npm:load:configload Completed in {TIME}ms +XX timing npm:load:mkdirpcache Completed in {TIME}ms +XX timing npm:load:mkdirplogs Completed in {TIME}ms +XX verbose title npm +XX verbose argv "--fetch-retries" "0" "--cache" "{CWD}/cache" "--loglevel" "silly" "--color" "false" "--timing" "true" +XX timing npm:load:setTitle Completed in {TIME}ms +XX verbose logfile logs-max:10 dir:{CWD}/cache/_logs/{DATE}- +XX verbose logfile {CWD}/cache/_logs/{DATE}-debug-0.log +XX timing npm:load Completed in {TIME}ms +XX verbose stack Error: Unknown error +XX verbose cwd {CWD}/prefix +XX verbose {OS} +XX verbose {NODE-VERSION} +XX verbose npm {NPM-VERSION} +XX error code ECODE +XX error ERR SUMMARY Unknown error +XX error ERR DETAIL Unknown error +XX verbose exit 1 +XX timing npm Completed in {TIME}ms +XX verbose code 1 +XX error Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json +XX error A complete log of this run can be found in: {CWD}/cache/_logs/{DATE}-debug-0.log +` + +exports[`test/lib/cli/exit-handler.js TAP handles unknown error with logs and debug file > logs 1`] = ` +timing npm:load:whichnode Completed in {TIME}ms +silly config:load:file:{CWD}/npmrc +silly config:load:file:{CWD}/prefix/.npmrc +silly config:load:file:{CWD}/home/.npmrc +silly config:load:file:{CWD}/global/etc/npmrc +timing npm:load:configload Completed in {TIME}ms +timing npm:load:mkdirpcache Completed in {TIME}ms +timing npm:load:mkdirplogs Completed in {TIME}ms +verbose title npm +verbose argv "--fetch-retries" "0" "--cache" "{CWD}/cache" "--loglevel" "silly" "--color" "false" "--timing" "true" +timing npm:load:setTitle Completed in {TIME}ms +verbose logfile logs-max:10 dir:{CWD}/cache/_logs/{DATE}- +verbose logfile {CWD}/cache/_logs/{DATE}-debug-0.log +timing npm:load Completed in {TIME}ms +verbose stack Error: Unknown error +verbose cwd {CWD}/prefix +verbose {OS} +verbose {NODE-VERSION} +verbose npm {NPM-VERSION} +error code ECODE +error ERR SUMMARY Unknown error +error ERR DETAIL Unknown error +verbose exit 1 +timing npm Completed in {TIME}ms +verbose code 1 +error Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json +error A complete log of this run can be found in: {CWD}/cache/_logs/{DATE}-debug-0.log +` diff --git a/tap-snapshots/test/lib/utils/log-file.js.test.cjs b/tap-snapshots/test/lib/utils/log-file.js.test.cjs index 0a4af7cadf060..34002b8133e22 100644 --- a/tap-snapshots/test/lib/utils/log-file.js.test.cjs +++ b/tap-snapshots/test/lib/utils/log-file.js.test.cjs @@ -7,64 +7,65 @@ 'use strict' exports[`test/lib/utils/log-file.js TAP snapshot > must match snapshot 1`] = ` 0 verbose logfile logs-max:10 dir:{CWD}/{DATE}- -1 silly logfile done cleaning log files -2 error no prefix -3 error prefix with prefix -4 error prefix 1 2 3 -5 verbose { obj: { with: { many: [Object] } } } -6 verbose {"obj":{"with":{"many":{"props":1}}}} -7 verbose { -7 verbose "obj": { -7 verbose "with": { -7 verbose "many": { -7 verbose "props": 1 -7 verbose } -7 verbose } -7 verbose } -7 verbose } -8 verbose [ 'test', 'with', 'an', 'array' ] -9 verbose ["test","with","an","array"] -10 verbose [ -10 verbose "test", -10 verbose "with", -10 verbose "an", -10 verbose "array" -10 verbose ] -11 verbose [ 'test', [ 'with', [ 'an', [Array] ] ] ] -12 verbose ["test",["with",["an",["array"]]]] -13 verbose [ -13 verbose "test", -13 verbose [ -13 verbose "with", -13 verbose [ -13 verbose "an", -13 verbose [ -13 verbose "array" -13 verbose ] -13 verbose ] -13 verbose ] -13 verbose ] -14 error pre has many errors Error: message -14 error pre at stack trace line 0 -14 error pre at stack trace line 1 -14 error pre at stack trace line 2 -14 error pre at stack trace line 3 -14 error pre at stack trace line 4 -14 error pre at stack trace line 5 -14 error pre at stack trace line 6 -14 error pre at stack trace line 7 -14 error pre at stack trace line 8 -14 error pre at stack trace line 9 Error: message2 -14 error pre at stack trace line 0 -14 error pre at stack trace line 1 -14 error pre at stack trace line 2 -14 error pre at stack trace line 3 -14 error pre at stack trace line 4 -14 error pre at stack trace line 5 -14 error pre at stack trace line 6 -14 error pre at stack trace line 7 -14 error pre at stack trace line 8 -14 error pre at stack trace line 9 -15 error nostack [Error: message] +1 verbose logfile {CWD}/{DATE}-debug-0.log +2 silly logfile done cleaning log files +3 error no prefix +4 error prefix with prefix +5 error prefix 1 2 3 +6 verbose { obj: { with: { many: [Object] } } } +7 verbose {"obj":{"with":{"many":{"props":1}}}} +8 verbose { +8 verbose "obj": { +8 verbose "with": { +8 verbose "many": { +8 verbose "props": 1 +8 verbose } +8 verbose } +8 verbose } +8 verbose } +9 verbose [ 'test', 'with', 'an', 'array' ] +10 verbose ["test","with","an","array"] +11 verbose [ +11 verbose "test", +11 verbose "with", +11 verbose "an", +11 verbose "array" +11 verbose ] +12 verbose [ 'test', [ 'with', [ 'an', [Array] ] ] ] +13 verbose ["test",["with",["an",["array"]]]] +14 verbose [ +14 verbose "test", +14 verbose [ +14 verbose "with", +14 verbose [ +14 verbose "an", +14 verbose [ +14 verbose "array" +14 verbose ] +14 verbose ] +14 verbose ] +14 verbose ] +15 error pre has many errors Error: message +15 error pre at stack trace line 0 +15 error pre at stack trace line 1 +15 error pre at stack trace line 2 +15 error pre at stack trace line 3 +15 error pre at stack trace line 4 +15 error pre at stack trace line 5 +15 error pre at stack trace line 6 +15 error pre at stack trace line 7 +15 error pre at stack trace line 8 +15 error pre at stack trace line 9 Error: message2 +15 error pre at stack trace line 0 +15 error pre at stack trace line 1 +15 error pre at stack trace line 2 +15 error pre at stack trace line 3 +15 error pre at stack trace line 4 +15 error pre at stack trace line 5 +15 error pre at stack trace line 6 +15 error pre at stack trace line 7 +15 error pre at stack trace line 8 +15 error pre at stack trace line 9 +16 error nostack [Error: message] ` diff --git a/test/lib/cli/entry.js b/test/lib/cli/entry.js index 66a417e7d269a..feb6692704d2a 100644 --- a/test/lib/cli/entry.js +++ b/test/lib/cli/entry.js @@ -1,4 +1,5 @@ const t = require('tap') +const { dirname } = require('path') const { load: loadMockNpm } = require('../../fixtures/mock-npm.js') const tmock = require('../../fixtures/tmock.js') const validateEngines = require('../../../lib/cli/validate-engines.js') @@ -29,20 +30,17 @@ const cliMock = async (t, opts) => { t.test('print the version, and treat npm_g as npm -g', async t => { const { logs, cli, Npm, outputs, exitHandlerCalled } = await cliMock(t, { - globals: { 'process.argv': ['node', 'npm_g', '-v'] }, + globals: { 'process.argv': ['node', 'npm_g', 'root'] }, }) await cli(process) - t.strictSame(process.argv, ['node', 'npm', '-g', '-v'], 'system process.argv was rewritten') + t.strictSame(process.argv, ['node', 'npm', '-g', 'root'], 'system process.argv was rewritten') t.strictSame(logs.verbose.byTitle('cli'), ['cli node npm']) - t.strictSame(logs.verbose.byTitle('title'), ['title npm']) - t.match(logs.verbose.byTitle('argv'), ['argv "--global" "--version"']) - t.strictSame(logs.info, [ - `using npm@${Npm.version}`, - `using node@${process.version}`, - ]) + t.strictSame(logs.verbose.byTitle('title'), ['title npm root']) + t.match(logs.verbose.byTitle('argv'), ['argv "--global" "root"']) + t.strictSame(logs.info, [`using npm@${Npm.version}`, `using node@${process.version}`]) t.equal(outputs.length, 1) - t.strictSame(outputs, [Npm.version]) + t.match(outputs[0], dirname(process.cwd())) t.strictSame(exitHandlerCalled(), []) }) diff --git a/test/lib/utils/exit-handler.js b/test/lib/cli/exit-handler.js similarity index 100% rename from test/lib/utils/exit-handler.js rename to test/lib/cli/exit-handler.js diff --git a/test/lib/npm.js b/test/lib/npm.js index bc9042365abea..915e63d0060bc 100644 --- a/test/lib/npm.js +++ b/test/lib/npm.js @@ -26,25 +26,13 @@ t.test('not yet loaded', async t => { t.test('npm.load', async t => { await t.test('load error', async t => { const { npm } = await loadMockNpm(t, { load: false }) - const loadError = new Error('load error') npm.config.load = async () => { - throw loadError + throw new Error('load error') } await t.rejects( () => npm.load(), /load error/ ) - - t.equal(npm.loadErr, loadError) - npm.config.load = async () => { - throw new Error('different error') - } - await t.rejects( - () => npm.load(), - /load error/, - 'loading again returns the original error' - ) - t.equal(npm.loadErr, loadError) }) await t.test('basic loading', async t => { @@ -416,7 +404,7 @@ t.test('timings', async t => { t.match(logs.timing.byTitle('npm'), [ /Completed in [0-9]+ms/, ]) - t.match(logs.silly, [ + t.match(logs.silly.byTitle('timing'), [ `timing Tried to end timer that doesn't exist: baz`, ]) t.notOk(npm.unfinishedTimers.has('foo'), 'foo timer is gone') diff --git a/test/lib/utils/display.js b/test/lib/utils/display.js index 31ea7bbed8add..b05690ebd8179 100644 --- a/test/lib/utils/display.js +++ b/test/lib/utils/display.js @@ -5,23 +5,22 @@ 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) - const displayLoad = (opts) => display.load({ + const displayLoad = async (opts) => display.load({ loglevel: 'silly', - stderrChalk: new Chalk({ level: 0 }), stderrColor: false, + stdoutColot: false, heading: 'npm', ...opts, }) if (load !== false) { - displayLoad(load) + await displayLoad(load) } t.teardown(() => display.off()) @@ -68,7 +67,7 @@ t.test('can buffer output when paused', async t => { output.standard('Message 2') t.strictSame(outputs, []) - displayLoad() + await displayLoad() t.strictSame(outputs, ['Message 1', 'Message 2']) })