chore(exit): log any un-ended timings

It will be helpful to us when debugging the "exit handler never called"
bugs to know which timings were started but not ended.

Tests moved to use real npm.

PR-URL: #3479
Credit: @wraithgar
Close: #3479
Reviewed-by: @ruyadorno

lib/base-command.js

@@ -75,7 +75,6 @@ class BaseCommand {
   }
 
   async setWorkspaces (filters) {
-    // TODO npm guards workspaces/global mode so we should use this.npm.prefix?
     const ws = await getWorkspaces(filters, { path: this.npm.localPrefix })
     this.workspaces = ws
     this.workspaceNames = [...ws.keys()]

lib/npm.js

@@ -50,7 +50,7 @@ const npm = module.exports = new class extends EventEmitter {
   constructor () {
     super()
     // TODO make this only ever load once (or unload) in tests
-    require('./utils/perf.js')
+    this.timers = require('./utils/perf.js').timers
     this.started = Date.now()
     this.command = null
     this.commands = proxyCmds

lib/utils/exit-handler.js

@@ -32,9 +32,14 @@ process.on('timing', (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()
-  if (npm.config && npm.config.loaded && npm.config.get('timing')) {
+  for (const [name, timers] of npm.timers)
+    log.verbose('unfinished npm timer', name, timers)
+
+  if (npm.config.loaded && npm.config.get('timing')) {
     try {
       const file = path.resolve(npm.config.get('cache'), '_timing.json')
       const dir = path.dirname(npm.config.get('cache'))
@@ -69,7 +74,7 @@ process.on('exit', code => {
     }
   }
   // In timing mode we always write the log file
-  if (npm.config && npm.config.loaded && npm.config.get('timing') && !wroteLogFile)
+  if (npm.config.loaded && npm.config.get('timing') && !wroteLogFile)
     writeLogFile()
   if (wroteLogFile) {
     // just a line break
@@ -113,7 +118,7 @@ const exit = (code, noLog) => {
 
 const exitHandler = (err) => {
   log.disableProgress()
-  if (!npm.config || !npm.config.loaded) {
+  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)
@@ -180,7 +185,7 @@ const exitHandler = (err) => {
   for (const errline of [...msg.summary, ...msg.detail])
     log.error(...errline)
 
-  if (npm.config && npm.config.get('json')) {
+  if (npm.config.loaded && npm.config.get('json')) {
     const error = {
       error: {
         code: err.code,

lib/utils/perf.js

@@ -1,20 +1,21 @@
 const log = require('npmlog')
-const timings = new Map()
+const timers = new Map()
 
 process.on('time', (name) => {
-  timings.set(name, Date.now())
+  timers.set(name, Date.now())
 })
 
 process.on('timeEnd', (name) => {
-  if (timings.has(name)) {
-    const ms = Date.now() - timings.get(name)
+  if (timers.has(name)) {
+    const ms = Date.now() - timers.get(name)
     process.emit('timing', name, ms)
     log.timing(name, `Completed in ${ms}ms`)
-    timings.delete(name)
+    timers.delete(name)
   } else
     log.silly('timing', "Tried to end timer that doesn't exist:", name)
 })
 
+exports.timers = timers
 // for tests
 /* istanbul ignore next */
 exports.reset = () => {

test/lib/utils/exit-handler.js

@@ -1,8 +1,10 @@
 /* eslint-disable no-extend-native */
 /* eslint-disable no-global-assign */
+const t = require('tap')
 const EventEmitter = require('events')
 const writeFileAtomic = require('write-file-atomic')
-const t = require('tap')
+
+const { real: mockNpm } = require('../../fixtures/mock-npm')
 
 // NOTE: Although these unit tests may look like the rest on the surface,
 // they are in fact very special due to the amount of things hooking directly
@@ -25,23 +27,14 @@ t.cleanSnapshot = (str) => redactCwd(str)
 
 // internal modules mocks
 const cacheFolder = t.testdir({})
-const config = {
-  values: {
-    cache: cacheFolder,
-    timing: true,
-  },
-  loaded: true,
-  updateNotification: null,
-  get (key) {
-    return this.values[key]
-  },
-}
 
-const npm = {
-  version: '1.0.0',
-  config,
-  shelloutCommands: ['exec', 'run-script'],
-}
+const { npm } = mockNpm(t)
+
+t.before(async () => {
+  npm.version = '1.0.0'
+  await npm.load()
+  npm.config.set('cache', cacheFolder)
+})
 
 const npmlog = {
   disableProgress: () => null,
@@ -190,9 +183,15 @@ t.test('handles unknown error', (t) => {
 t.test('npm.config not ready', (t) => {
   t.plan(1)
 
-  config.loaded = false
-
+  const { npm: unloaded } = mockNpm(t)
   const _error = console.error
+
+  t.teardown(() => {
+    console.error = _error
+    exitHandler.setNpm(npm)
+  })
+
+  exitHandler.setNpm(unloaded)
   console.error = (msg) => {
     t.match(
       msg,
@@ -202,25 +201,20 @@ t.test('npm.config not ready', (t) => {
   }
 
   exitHandler()
-
-  t.teardown(() => {
-    console.error = _error
-    config.loaded = true
-  })
 })
 
 t.test('fail to write logfile', (t) => {
   t.plan(1)
 
+  t.teardown(() => {
+    npm.config.set('cache', cacheFolder)
+  })
+
   const badDir = t.testdir({
     _logs: 'is a file',
   })
 
-  config.values.cache = badDir
-
-  t.teardown(() => {
-    config.values.cache = cacheFolder
-  })
+  npm.config.set('cache', badDir)
 
   t.doesNotThrow(
     () => exitHandler(err),
@@ -231,7 +225,11 @@ t.test('fail to write logfile', (t) => {
 t.test('console.log output using --json', (t) => {
   t.plan(1)
 
-  config.values.json = true
+  npm.config.set('json', true)
+  t.teardown(() => {
+    console.error = _error
+    npm.config.set('json', false)
+  })
 
   const _error = console.error
   console.error = (jsonOutput) => {
@@ -249,11 +247,6 @@ t.test('console.log output using --json', (t) => {
   }
 
   exitHandler(new Error('Error: EBADTHING Something happened'))
-
-  t.teardown(() => {
-    console.error = _error
-    delete config.values.json
-  })
 })
 
 t.test('throw a non-error obj', (t) => {
@@ -354,7 +347,12 @@ t.test('on exit handler', (t) => {
 t.test('it worked', (t) => {
   t.plan(2)
 
-  config.values.timing = false
+  npm.config.set('timing', false)
+
+  t.teardown(() => {
+    process.exit = _exit
+    npm.config.set('timing', true)
+  })
 
   const _exit = process.exit
   process.exit = (code) => {
@@ -370,11 +368,6 @@ t.test('it worked', (t) => {
     process.emit('exit', 0)
   }
 
-  t.teardown(() => {
-    process.exit = _exit
-    config.values.timing = true
-  })
-
   exitHandler()
 })
 
@@ -466,6 +459,14 @@ t.test('exit handler called twice', (t) => {
 t.test('defaults to log error msg if stack is missing', (t) => {
   t.plan(1)
 
+  const { npm: unloaded } = mockNpm(t)
+  const _error = console.error
+
+  t.teardown(() => {
+    console.error = _error
+    exitHandler.setNpm(npm)
+  })
+
   const noStackErr = Object.assign(
     new Error('Error with no stack'),
     {
@@ -475,15 +476,11 @@ t.test('defaults to log error msg if stack is missing', (t) => {
   )
   delete noStackErr.stack
 
-  npm.config.loaded = false
-
-  const _error = console.error
   console.error = (msg) => {
-    console.error = _error
-    npm.config.loaded = true
     t.equal(msg, 'Error with no stack', 'should use error msg')
   }
 
+  exitHandler.setNpm(unloaded)
   exitHandler(noStackErr)
 })