fix: remove some npm.load timers and exit earlier for --versions

Author: lukekarrys

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)

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 () {

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

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')

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
+`