fix(refactor): move timer and error logfile messages to lib/npm

lib/cli/exit-handler.js

@@ -1,4 +1,4 @@
-const { log, output, time, META } = require('proc-log')
+const { log, output, META } = require('proc-log')
 const errorMessage = require('../utils/error-message.js')
 const { redactLog: replaceInfo } = require('@npmcli/redact')
 
@@ -7,19 +7,8 @@ let exitHandlerCalled = false
 let showLogFileError = false
 
 process.on('exit', code => {
-  // process.emit is synchronous, so the timeEnd handler will run before the
-  // unfinished timer check below
-  time.end('npm')
-
   const hasLoadedNpm = npm?.config.loaded
 
-  // Unfinished timers can be read before config load
-  if (npm) {
-    for (const [name, timer] of npm.unfinishedTimers) {
-      log.silly('unfinished npm timer', name, timer)
-    }
-  }
-
   if (!code) {
     log.info('ok')
   } else {
@@ -31,65 +20,14 @@ process.on('exit', code => {
     log.error('', 'Exit handler never called!')
     log.error('', 'This is an error with npm itself. Please report this error at:')
     log.error('', '    <https://github.com/npm/cli/issues>')
-
-    if (!npm || !npm.silent) {
-      // eslint-disable-next-line no-console
-      console.error('')
-    }
-
+    // eslint-disable-next-line no-console
+    console.error('')
     showLogFileError = true
   }
 
   // npm must be loaded to know where the log file was written
   if (hasLoadedNpm) {
-    // write the timing file now, this might do nothing based on the configs set.
-    // we need to call it here in case it errors so we dont tell the user
-    // about a timing file that doesn't exist
-    npm.finish()
-
-    const logsDir = npm.logsDir
-    const logFiles = npm.logFiles
-
-    const timingDir = npm.timingDir
-    const timingFile = npm.timingFile
-
-    const timing = npm.config.get('timing')
-    const logsMax = npm.config.get('logs-max')
-
-    // Determine whether to show log file message and why it is
-    // being shown since in timing mode we always show the log file message
-    const logMethod = showLogFileError ? 'error' : timing ? 'info' : null
-
-    if (logMethod) {
-      // just a line break, will be ignored in silent mode
-      output.error('')
-
-      const message = []
-
-      if (timingFile) {
-        message.push(`Timing info written to: ${timingFile}`)
-      } else if (timing) {
-        message.push(
-          `The timing file was not written due to an error writing to the directory: ${timingDir}`
-        )
-      }
-
-      if (logFiles.length) {
-        message.push(`A complete log of this run can be found in: ${logFiles}`)
-      } else if (logsMax <= 0) {
-        // user specified no log file
-        message.push(`Log files were not written due to the config logs-max=${logsMax}`)
-      } else {
-        // could be an error writing to the directory
-        message.push(
-          `Log files were not written due to an error writing to the directory: ${logsDir}`,
-          'You can rerun the command with `--loglevel=verbose` to see the logs in your terminal'
-        )
-      }
-
-      log[logMethod]('', message.join('\n'))
-    }
-
+    npm.finish({ showLogFileError })
     // This removes any listeners npm setup, mostly for tests to avoid max listener warnings
     npm.unload()
   }

lib/npm.js

@@ -117,13 +117,35 @@ class Npm {
     this.#logFile.off()
   }
 
-  finish () {
+  finish ({ showLogFileError } = {}) {
     this.#timers.finish({
       id: this.#runId,
       command: this.#argvClean,
       logfiles: this.logFiles,
       version: this.version,
     })
+
+    if (showLogFileError) {
+      if (!this.silent) {
+        // just a line break if not in silent mode
+        output.error('')
+      }
+
+      const logsMax = this.config.get('logs-max')
+
+      if (this.logFiles.length) {
+        log.error('', `A complete log of this run can be found in: ${this.logFiles}`)
+      } else if (logsMax <= 0) {
+        // user specified no log file
+        log.error('', `Log files were not written due to the config logs-max=${logsMax}`)
+      } else {
+        // could be an error writing to the directory
+        log.error('',
+          `Log files were not written due to an error writing to the directory: ${this.#logsDir}` +
+          '\nYou can rerun the command with `--loglevel=verbose` to see the logs in your terminal'
+        )
+      }
+    }
   }
 
   get title () {
@@ -179,7 +201,7 @@ class Npm {
     // which we will tell them about at the end
     if (this.config.get('logs-max') > 0) {
       await time.start('npm:load:mkdirplogs', () =>
-        fs.mkdir(this.logsDir, { recursive: true })
+        fs.mkdir(this.#logsDir, { recursive: true })
           .catch((e) => log.verbose('logfile', `could not create logs-dir: ${e}`)))
     }
 
@@ -208,7 +230,7 @@ class Npm {
     })
 
     this.#timers.load({
-      path: this.config.get('timing') ? this.logPath : null,
+      path: this.logPath,
       timing: this.config.get('timing'),
     })
 
@@ -281,14 +303,6 @@ class Npm {
     return 2
   }
 
-  get unfinishedTimers () {
-    return this.#timers.unfinished
-  }
-
-  get finishedTimers () {
-    return this.#timers.finished
-  }
-
   get started () {
     return this.#timers.started
   }
@@ -297,16 +311,12 @@ class Npm {
     return this.#logFile.files
   }
 
-  get logsDir () {
+  get #logsDir () {
     return this.config.get('logs-dir') || join(this.cache, '_logs')
   }
 
   get logPath () {
-    return resolve(this.logsDir, `${this.#runId}-`)
-  }
-
-  get timingFile () {
-    return this.#timers.file
+    return resolve(this.#logsDir, `${this.#runId}-`)
   }
 
   get npmRoot () {

tap-snapshots/test/lib/cli/exit-handler.js.test.cjs

@@ -29,9 +29,9 @@ 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 timing npm Completed in {TIME}ms
+XX info timing 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
 `
 
@@ -59,8 +59,8 @@ 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
+timing npm Completed in {TIME}ms
+info timing 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
 `

test/lib/cli/exit-handler.js

@@ -382,7 +382,7 @@ t.test('timers fail to write', async (t) => {
 
   await exitHandler(new Error())
 
-  t.match(logs.error[2], `error writing to the directory`)
+  t.match(logs.warn[0], `timing could not write timing file: Error: err`)
 })
 
 t.test('log files fail to write', async (t) => {
@@ -455,33 +455,25 @@ t.test('files from error message with error', async (t) => {
 
 t.test('timing with no error', async (t) => {
   const { exitHandler, timingFile, npm, logs } = await mockExitHandler(t, {
-    config: { timing: true, loglevel: 'info' },
+    config: { timing: true, loglevel: 'silly' },
   })
 
   await exitHandler()
   const timingFileData = await timingFile()
 
   t.equal(process.exitCode, 0)
 
-  const msg = logs.info[1]
-  t.match(msg, /A complete log of this run can be found in:/)
+  const msg = logs.info.byTitle('timing')[0]
   t.match(msg, /Timing info written to:/)
 
-  t.match(
-    timingFileData.timers,
-    Object.keys(npm.finishedTimers).reduce((acc, k) => {
-      acc[k] = Number
-      return acc
-    }, {})
-  )
-  t.strictSame(npm.unfinishedTimers, new Map())
   t.match(timingFileData, {
     metadata: {
       command: [],
       version: npm.version,
       logfiles: [String],
     },
     timers: {
+      'npm:load': Number,
       npm: Number,
     },
   })
@@ -511,7 +503,6 @@ t.test('unfinished timers', async (t) => {
   const timingFileData = await timingFile()
 
   t.equal(process.exitCode, 0)
-  t.match(npm.unfinishedTimers, new Map([['foo', Number], ['bar', Number]]))
   t.match(timingFileData, {
     metadata: {
       command: [],