chore(refactor): refactor exit handler and tests

 * npm mock logger writes to npm.log.record too now
 * No more extra process.exit from within the process `exit` event handle.
 * No more `exit()` function.  Logic is rolled up into the exit handler.
 * Now there is only an exit handler and an exit event listener.
   `lib/utils/perf.js` was rolled up into npm.js itself.

Unfortunately the tests were written in such a way that any further
refactoring of the exit handler was going to require also rewriting the
tests.  Fortunately NOW the tests are interacting with the exit handler
in a way that shouldn't require them to be rewritten AGAIN if we change
the internals of the exit handler.

PR-URL: #3482
Credit: @wraithgar
Close: #3482
Reviewed-by: @nlf

Author: wraithgar

lib/npm.js

@@ -1,12 +1,7 @@
-// The order of the code in this file is relevant, because a lot of things
-// require('npm.js'), but also we need to use some of those modules.  So,
-// we define and instantiate the singleton ahead of loading any modules
-// required for its methods.
-
-// these are all dependencies used in the ctor
 const EventEmitter = require('events')
 const { resolve, dirname } = require('path')
 const Config = require('@npmcli/config')
+const log = require('npmlog')
 
 // Patch the global fs module here at the app level
 require('graceful-fs').gracefulify(require('fs'))
@@ -37,23 +32,51 @@ const proxyCmds = new Proxy({}, {
   },
 })
 
+// Timers in progress
+const timers = new Map()
+// Finished timers
+const timings = {}
+
+const processOnTimeHandler = (name) => {
+  timers.set(name, Date.now())
+}
+
+const processOnTimeEndHandler = (name) => {
+  if (timers.has(name)) {
+    const ms = Date.now() - timers.get(name)
+    log.timing(name, `Completed in ${ms}ms`)
+    timings[name] = ms
+    timers.delete(name)
+  } else
+    log.silly('timing', "Tried to end timer that doesn't exist:", name)
+}
+
 const { definitions, flatten, shorthands } = require('./utils/config/index.js')
 const { shellouts } = require('./utils/cmd-list.js')
 const usage = require('./utils/npm-usage.js')
 
+const which = require('which')
+
+const deref = require('./utils/deref-command.js')
+const setupLog = require('./utils/setup-log.js')
+const cleanUpLogFiles = require('./utils/cleanup-log-files.js')
+const getProjectScope = require('./utils/get-project-scope.js')
+
 let warnedNonDashArg = false
 const _runCmd = Symbol('_runCmd')
 const _load = Symbol('_load')
 const _tmpFolder = Symbol('_tmpFolder')
 const _title = Symbol('_title')
+
 const npm = module.exports = new class extends EventEmitter {
   constructor () {
     super()
-    // TODO make this only ever load once (or unload) in tests
-    this.timers = require('./utils/perf.js').timers
     this.started = Date.now()
     this.command = null
     this.commands = proxyCmds
+    this.timings = timings
+    this.timers = timers
+    this.perfStart()
     procLogListener()
     process.emit('time', 'npm')
     this.version = require('../package.json').version
@@ -67,6 +90,16 @@ const npm = module.exports = new class extends EventEmitter {
     this.updateNotification = null
   }
 
+  perfStart () {
+    process.on('time', processOnTimeHandler)
+    process.on('timeEnd', processOnTimeEndHandler)
+  }
+
+  perfStop () {
+    process.off('time', processOnTimeHandler)
+    process.off('timeEnd', processOnTimeEndHandler)
+  }
+
   get shelloutCommands () {
     return shellouts
   }
@@ -317,16 +350,5 @@ const npm = module.exports = new class extends EventEmitter {
   }
 }()
 
-// now load everything required by the class methods
-
-const log = require('npmlog')
-
-const which = require('which')
-
-const deref = require('./utils/deref-command.js')
-const setupLog = require('./utils/setup-log.js')
-const cleanUpLogFiles = require('./utils/cleanup-log-files.js')
-const getProjectScope = require('./utils/get-project-scope.js')
-
 if (require.main === module)
   require('./cli.js')(process)

lib/utils/exit-handler.js

@@ -1,4 +1,3 @@
-const log = require('npmlog')
 const os = require('os')
 const path = require('path')
 const writeFileAtomic = require('write-file-atomic')
@@ -13,8 +12,6 @@ let logFileName
 let npm // set by the cli
 let wroteLogFile = false
 
-const timings = {}
-
 const getLogFile = () => {
   // we call this multiple times, so we need to treat it as a singleton because
   // the date is part of the name
@@ -24,20 +21,13 @@ const getLogFile = () => {
   return logFileName
 }
 
-process.on('timing', (name, value) => {
-  if (timings[name])
-    timings[name] += value
-  else
-    timings[name] = value
-})
-
 process.on('exit', code => {
   // process.emit is synchronous, so the timeEnd handler will run before the
   // unfinished timer check below
   process.emit('timeEnd', 'npm')
-  log.disableProgress()
+  npm.log.disableProgress()
   for (const [name, timers] of npm.timers)
-    log.verbose('unfinished npm timer', name, timers)
+    npm.log.verbose('unfinished npm timer', name, timers)
 
   if (npm.config.loaded && npm.config.get('timing')) {
     try {
@@ -49,7 +39,7 @@ process.on('exit', code => {
         command: process.argv.slice(2),
         logfile: getLogFile(),
         version: npm.version,
-        ...timings,
+        ...npm.timings,
       }) + '\n')
 
       const st = fs.lstatSync(path.dirname(npm.config.get('cache')))
@@ -61,14 +51,14 @@ process.on('exit', code => {
   }
 
   if (!code)
-    log.info('ok')
+    npm.log.info('ok')
   else {
-    log.verbose('code', code)
+    npm.log.verbose('code', code)
     if (!exitHandlerCalled) {
-      log.error('', 'Exit handler never called!')
+      npm.log.error('', 'Exit handler never called!')
       console.error('')
-      log.error('', 'This is an error with npm itself. Please report this error at:')
-      log.error('', '    <https://github.com/npm/cli/issues>')
+      npm.log.error('', 'This is an error with npm itself. Please report this error at:')
+      npm.log.error('', '    <https://github.com/npm/cli/issues>')
       // TODO this doesn't have an npm.config.loaded guard
       writeLogFile()
     }
@@ -78,10 +68,10 @@ process.on('exit', code => {
     writeLogFile()
   if (wroteLogFile) {
     // just a line break
-    if (log.levels[log.level] <= log.levels.error)
+    if (npm.log.levels[npm.log.level] <= npm.log.levels.error)
       console.error('')
 
-    log.error(
+    npm.log.error(
       '',
       [
         'A complete log of this run can be found in:',
@@ -93,121 +83,114 @@ process.on('exit', code => {
   // these are needed for the tests to have a clean slate in each test case
   exitHandlerCalled = false
   wroteLogFile = false
-
-  // actually exit.
-  process.exit(code)
 })
 
-const exit = (code, noLog) => {
-  log.verbose('exit', code || 0)
-  if (log.level === 'silent')
-    noLog = true
-
-  // noLog is true if there was an error, including if config wasn't loaded, so
-  // this doesn't need a config.loaded guard
-  if (code && !noLog)
-    writeLogFile()
-
-  // Exit directly -- nothing in the CLI should still be running in the
-  // background at this point, and this makes sure anything left dangling
-  // for whatever reason gets thrown away, instead of leaving the CLI open
-  process.stdout.write('', () => {
-    process.exit(code)
-  })
-}
-
 const exitHandler = (err) => {
-  log.disableProgress()
+  npm.log.disableProgress()
   if (!npm.config.loaded) {
-    // logging won't work unless we pretend that it's ready
     err = err || new Error('Exit prior to config file resolving.')
     console.error(err.stack || err.message)
   }
 
-  if (exitHandlerCalled)
-    err = err || new Error('Exit handler called more than once.')
-
-  // only show the notification if it finished before the other stuff we
-  // were doing.  no need to hang on `npm -v` or something.
+  // only show the notification if it finished.
   if (typeof npm.updateNotification === 'string') {
-    const { level } = log
-    log.level = log.levels.notice
-    log.notice('', npm.updateNotification)
-    log.level = level
+    const { level } = npm.log
+    npm.log.level = 'notice'
+    npm.log.notice('', npm.updateNotification)
+    npm.log.level = level
   }
 
   exitHandlerCalled = true
-  if (!err)
-    return exit()
-
-  // if we got a command that just shells out to something else, then it
-  // will presumably print its own errors and exit with a proper status
-  // code if there's a problem.  If we got an error with a code=0, then...
-  // something else went wrong along the way, so maybe an npm problem?
-  const isShellout = npm.shelloutCommands.includes(npm.command)
-  const quietShellout = isShellout && typeof err.code === 'number' && err.code
-  if (quietShellout)
-    return exit(err.code, true)
-  else if (typeof err === 'string') {
-    log.error('', err)
-    return exit(1, true)
-  } else if (!(err instanceof Error)) {
-    log.error('weird error', err)
-    return exit(1, true)
-  }
 
-  if (!err.code) {
-    const matchErrorCode = err.message.match(/^(?:Error: )?(E[A-Z]+)/)
-    err.code = matchErrorCode && matchErrorCode[1]
-  }
-
-  for (const k of ['type', 'stack', 'statusCode', 'pkgid']) {
-    const v = err[k]
-    if (v)
-      log.verbose(k, replaceInfo(v))
+  let exitCode
+  let noLog
+
+  if (err) {
+    exitCode = 1
+    // if we got a command that just shells out to something else, then it
+    // will presumably print its own errors and exit with a proper status
+    // code if there's a problem.  If we got an error with a code=0, then...
+    // something else went wrong along the way, so maybe an npm problem?
+    const isShellout = npm.shelloutCommands.includes(npm.command)
+    const quietShellout = isShellout && typeof err.code === 'number' && err.code
+    if (quietShellout) {
+      exitCode = err.code
+      noLog = true
+    } else if (typeof err === 'string') {
+      noLog = true
+      npm.log.error('', err)
+    } else if (!(err instanceof Error)) {
+      noLog = true
+      npm.log.error('weird error', err)
+    } else {
+      if (!err.code) {
+        const matchErrorCode = err.message.match(/^(?:Error: )?(E[A-Z]+)/)
+        err.code = matchErrorCode && matchErrorCode[1]
+      }
+
+      for (const k of ['type', 'stack', 'statusCode', 'pkgid']) {
+        const v = err[k]
+        if (v)
+          npm.log.verbose(k, replaceInfo(v))
+      }
+
+      npm.log.verbose('cwd', process.cwd())
+
+      const args = replaceInfo(process.argv)
+      npm.log.verbose('', os.type() + ' ' + os.release())
+      npm.log.verbose('argv', args.map(JSON.stringify).join(' '))
+      npm.log.verbose('node', process.version)
+      npm.log.verbose('npm ', 'v' + npm.version)
+
+      for (const k of ['code', 'syscall', 'file', 'path', 'dest', 'errno']) {
+        const v = err[k]
+        if (v)
+          npm.log.error(k, v)
+      }
+
+      const msg = errorMessage(err, npm)
+      for (const errline of [...msg.summary, ...msg.detail])
+        npm.log.error(...errline)
+
+      if (npm.config.loaded && npm.config.get('json')) {
+        const error = {
+          error: {
+            code: err.code,
+            summary: messageText(msg.summary),
+            detail: messageText(msg.detail),
+          },
+        }
+        console.error(JSON.stringify(error, null, 2))
+      }
+
+      if (typeof err.errno === 'number')
+        exitCode = err.errno
+      else if (typeof err.code === 'number')
+        exitCode = err.code
+    }
   }
+  npm.log.verbose('exit', exitCode || 0)
 
-  log.verbose('cwd', process.cwd())
-
-  const args = replaceInfo(process.argv)
-  log.verbose('', os.type() + ' ' + os.release())
-  log.verbose('argv', args.map(JSON.stringify).join(' '))
-  log.verbose('node', process.version)
-  log.verbose('npm ', 'v' + npm.version)
-
-  for (const k of ['code', 'syscall', 'file', 'path', 'dest', 'errno']) {
-    const v = err[k]
-    if (v)
-      log.error(k, v)
-  }
+  if (npm.log.level === 'silent')
+    noLog = true
 
-  const msg = errorMessage(err, npm)
-  for (const errline of [...msg.summary, ...msg.detail])
-    log.error(...errline)
-
-  if (npm.config.loaded && npm.config.get('json')) {
-    const error = {
-      error: {
-        code: err.code,
-        summary: messageText(msg.summary),
-        detail: messageText(msg.detail),
-      },
-    }
-    console.error(JSON.stringify(error, null, 2))
-  }
+  // noLog is true if there was an error, including if config wasn't loaded, so
+  // this doesn't need a config.loaded guard
+  if (exitCode && !noLog)
+    writeLogFile()
 
-  exit(typeof err.errno === 'number' ? err.errno : typeof err.code === 'number' ? err.code : 1)
+  // explicitly call process.exit now so we don't hang on things like the
+  // update notifier, also flush stdout beforehand because process.exit doesn't
+  // wait for that to happen.
+  process.stdout.write('', () => process.exit(exitCode))
 }
 
 const messageText = msg => msg.map(line => line.slice(1).join(' ')).join('\n')
 
 const writeLogFile = () => {
-  if (wroteLogFile)
-    return
-
   try {
     let logOutput = ''
-    log.record.forEach(m => {
+    npm.log.record.forEach(m => {
       const p = [m.id, m.level]
       if (m.prefix)
         p.push(m.prefix)
@@ -230,7 +213,7 @@ const writeLogFile = () => {
     fs.chownSync(file, st.uid, st.gid)
 
     // truncate once it's been written.
-    log.record.length = 0
+    npm.log.record.length = 0
     wroteLogFile = true
   } catch (ex) {