fix: use proc-log for all timers

lib/commands/ci.js

@@ -1,7 +1,7 @@
 const reifyFinish = require('../utils/reify-finish.js')
 const runScript = require('@npmcli/run-script')
 const fs = require('fs/promises')
-const { log } = require('proc-log')
+const { log, time } = require('proc-log')
 const validateLockfile = require('../utils/validate-lockfile.js')
 
 const ArboristWorkspaceCmd = require('../arborist-cmd.js')
@@ -79,7 +79,7 @@ class CI extends ArboristWorkspaceCmd {
     if (!dryRun) {
       // Only remove node_modules after we've successfully loaded the virtual
       // tree and validated the lockfile
-      await this.npm.time('npm-ci:rm', async () => {
+      await time.start('npm-ci:rm', async () => {
         const path = `${where}/node_modules`
         // get the list of entries so we can skip the glob for performance
         const entries = await fs.readdir(path, null).catch(er => [])

lib/npm.js

@@ -11,7 +11,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 } = require('proc-log')
+const { log, time } = require('proc-log')
 const { redactLog: replaceInfo } = require('@npmcli/redact')
 const updateNotifier = require('./utils/update-notifier.js')
 const pkg = require('../package.json')
@@ -110,7 +110,7 @@ class Npm {
   async exec (cmd, args = this.argv) {
     const command = this.setCmd(cmd)
 
-    const timeEnd = this.time(`command:${cmd}`)
+    const timeEnd = time.start(`command:${cmd}`)
 
     // this is async but we dont await it, since its ok if it doesnt
     // finish before the command finishes running. it uses command and argv
@@ -137,7 +137,7 @@ class Npm {
 
   async load () {
     if (!this.#loadPromise) {
-      this.#loadPromise = this.time('npm:load', () => this.#load().catch((er) => {
+      this.#loadPromise = time.start('npm:load', () => this.#load().catch((er) => {
         this.loadErr = er
         throw er
       }))
@@ -158,10 +158,6 @@ class Npm {
     this.#logFile.off()
   }
 
-  time (name, fn) {
-    return this.#timers.time(name, fn)
-  }
-
   writeTimingFile () {
     this.#timers.writeFile({
       id: this.#runId,
@@ -181,7 +177,7 @@ class Npm {
   }
 
   async #load () {
-    await this.time('npm:load:whichnode', async () => {
+    await time.start('npm:load:whichnode', async () => {
       // TODO should we throw here?
       const node = await which(process.argv[0]).catch(() => {})
       if (node && node.toUpperCase() !== process.execPath.toUpperCase()) {
@@ -191,7 +187,7 @@ class Npm {
       }
     })
 
-    await this.time('npm:load:configload', () => this.config.load())
+    await time.start('npm:load:configload', () => this.config.load())
 
     // get createSupportsColor from chalk directly if this lands
     // https://github.com/chalk/chalk/pull/600
@@ -211,21 +207,21 @@ class Npm {
     // a different location. if this fails, then we don't have
     // a cache dir, but we don't want to fail immediately since
     // the command might not need a cache dir (like `npm --version`)
-    await this.time('npm:load:mkdirpcache', () =>
+    await time.start('npm:load:mkdirpcache', () =>
       fs.mkdir(this.cache, { recursive: true })
         .catch((e) => log.verbose('cache', `could not create cache: ${e}`)))
 
     // it's ok if this fails. user might have specified an invalid dir
     // which we will tell them about at the end
     if (this.config.get('logs-max') > 0) {
-      await this.time('npm:load:mkdirplogs', () =>
+      await time.start('npm:load:mkdirplogs', () =>
         fs.mkdir(this.logsDir, { recursive: true })
           .catch((e) => log.verbose('logfile', `could not create logs-dir: ${e}`)))
     }
 
     // note: this MUST be shorter than the actual argv length, because it
     // uses the same memory, so node will truncate it if it's too long.
-    this.time('npm:load:setTitle', () => {
+    time.start('npm:load:setTitle', () => {
       const { parsedArgv: { cooked, remain } } = this.config
       this.argv = remain
       // Secrets are mostly in configs, so title is set using only the positional args
@@ -241,7 +237,7 @@ class Npm {
       log.verbose('argv', this.#argvClean.map(JSON.stringify).join(' '))
     })
 
-    this.time('npm:load:display', () => {
+    time.start('npm:load:display', () => {
       this.#display.load({
         loglevel: this.config.get('loglevel'),
         // TODO: only pass in logColor and color and create chalk instances
@@ -260,21 +256,21 @@ class Npm {
       process.env.COLOR = this.color ? '1' : '0'
     })
 
-    this.time('npm:load:logFile', () => {
+    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.time('npm:load:timers', () =>
+    time.start('npm:load:timers', () =>
       this.#timers.load({
         path: this.config.get('timing') ? this.logPath : null,
       })
     )
 
-    this.time('npm:load:configScope', () => {
+    time.start('npm:load:configScope', () => {
       const configScope = this.config.get('scope')
       if (configScope && !/^@/.test(configScope)) {
         this.config.set('scope', `@${configScope}`, this.config.find('scope'))

lib/utils/exit-handler.js

@@ -1,6 +1,6 @@
 const os = require('os')
 const fs = require('fs')
-const { log, output } = require('proc-log')
+const { log, output, time } = require('proc-log')
 const errorMessage = require('./error-message.js')
 const { redactLog: replaceInfo } = require('@npmcli/redact')
 
@@ -11,14 +11,14 @@ let showLogFileError = false
 process.on('exit', code => {
   // process.emit is synchronous, so the timeEnd handler will run before the
   // unfinished timer check below
-  process.emit('timeEnd', 'npm')
+  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.verbose('unfinished npm timer', name, timer)
+      log.silly('unfinished npm timer', name, timer)
     }
   }
 

lib/utils/timers.js

@@ -1,6 +1,6 @@
 const EE = require('events')
 const fs = require('fs')
-const { log } = require('proc-log')
+const { log, time } = require('proc-log')
 
 const INITIAL_TIMER = 'npm'
 
@@ -13,7 +13,7 @@ class Timers extends EE {
   constructor () {
     super()
     this.on()
-    process.emit('time', INITIAL_TIMER)
+    time.start(INITIAL_TIMER)
     this.started = this.#unfinished.get(INITIAL_TIMER)
   }
 
@@ -26,23 +26,11 @@ class Timers extends EE {
   }
 
   on () {
-    process.on('time', this.#timeListener)
-    process.on('timeEnd', this.#timeEndListener)
+    process.on('time', this.#timeHandler)
   }
 
   off () {
-    process.off('time', this.#timeListener)
-    process.off('timeEnd', this.#timeEndListener)
-  }
-
-  time (name, fn) {
-    process.emit('time', name)
-    const end = () => process.emit('timeEnd', name)
-    if (typeof fn === 'function') {
-      const res = fn()
-      return res && res.finally ? res.finally(end) : (end(), res)
-    }
-    return end
+    process.off('time', this.#timeHandler)
   }
 
   load ({ path } = {}) {
@@ -75,18 +63,22 @@ class Timers extends EE {
     }
   }
 
-  #timeListener = (name) => {
-    this.#unfinished.set(name, Date.now())
-  }
-
-  #timeEndListener = (name) => {
-    if (this.#unfinished.has(name)) {
-      const ms = Date.now() - this.#unfinished.get(name)
-      this.#finished[name] = ms
-      this.#unfinished.delete(name)
-      log.timing(name, `Completed in ${ms}ms`)
-    } else {
-      log.silly('timing', "Tried to end timer that doesn't exist:", name)
+  #timeHandler = (level, name) => {
+    const now = Date.now()
+    switch (level) {
+      case time.KEYS.start:
+        this.#unfinished.set(name, now)
+        break
+      case time.KEYS.end: {
+        if (this.#unfinished.has(name)) {
+          const ms = now - this.#unfinished.get(name)
+          this.#finished[name] = ms
+          this.#unfinished.delete(name)
+          log.timing(name, `Completed in ${ms}ms`)
+        } else {
+          log.silly('timing', "Tried to end timer that doesn't exist:", name)
+        }
+      }
     }
   }
 }

test/lib/npm.js

@@ -1,6 +1,7 @@
 const t = require('tap')
 const { resolve, dirname, join } = require('path')
 const fs = require('fs')
+const { time } = require('proc-log')
 const { load: loadMockNpm } = require('../fixtures/mock-npm.js')
 const mockGlobals = require('@npmcli/mock-globals')
 const { commands } = require('../../lib/utils/cmd-list.js')
@@ -398,15 +399,15 @@ t.test('timings', async t => {
         timing: true,
       },
     })
-    process.emit('time', 'foo')
-    process.emit('time', 'bar')
+    time.start('foo')
+    time.start('bar')
     t.match(npm.unfinishedTimers.get('foo'), Number, 'foo timer is a number')
     t.match(npm.unfinishedTimers.get('bar'), Number, 'foo timer is a number')
-    process.emit('timeEnd', 'foo')
-    process.emit('timeEnd', 'bar')
-    process.emit('timeEnd', 'baz')
+    time.end('foo')
+    time.end('bar')
+    time.end('baz')
     // npm timer is started by default
-    process.emit('timeEnd', 'npm')
+    time.end('npm')
     t.match(logs.timing.byTitle('foo'), [
       /Completed in [0-9]+ms/,
     ])
@@ -428,9 +429,9 @@ t.test('timings', async t => {
     const { npm, cache, timingFile } = await loadMockNpm(t, {
       config: { timing: true },
     })
-    process.emit('time', 'foo')
-    process.emit('timeEnd', 'foo')
-    process.emit('time', 'bar')
+    time.start('foo')
+    time.end('foo')
+    time.start('bar')
     npm.writeTimingFile()
     t.match(npm.timingFile, cache)
     t.match(npm.timingFile, /-timing.json$/)

test/lib/utils/exit-handler.js

@@ -3,7 +3,7 @@ const fs = require('fs')
 const fsMiniPass = require('fs-minipass')
 const { join, resolve } = require('path')
 const EventEmitter = require('events')
-const { output } = require('proc-log')
+const { output, time } = require('proc-log')
 const { load: loadMockNpm } = require('../../fixtures/mock-npm')
 const mockGlobals = require('@npmcli/mock-globals')
 const { cleanCwd, cleanDate } = require('../../fixtures/clean-snapshot')
@@ -517,8 +517,8 @@ t.test('unfinished timers', async (t) => {
     config: { timing: true },
   })
 
-  process.emit('time', 'foo')
-  process.emit('time', 'bar')
+  time.start('foo')
+  time.start('bar')
 
   await exitHandler()
   const timingFileData = await timingFile()

test/lib/utils/timers.js

@@ -1,7 +1,7 @@
 const t = require('tap')
 const { resolve, join } = require('path')
 const fs = require('graceful-fs')
-const { log } = require('proc-log')
+const { log, time } = require('proc-log')
 const tmock = require('../../fixtures/tmock')
 
 const mockTimers = (t, options) => {
@@ -24,57 +24,46 @@ const mockTimers = (t, options) => {
 
 t.test('listens/stops on process', async (t) => {
   const { timers } = mockTimers(t)
-  process.emit('time', 'foo')
-  process.emit('time', 'bar')
-  process.emit('timeEnd', 'bar')
+  time.start('foo')
+  time.start('bar')
+  time.end('bar')
   t.match(timers.unfinished, new Map([['foo', Number]]))
   t.match(timers.finished, { bar: Number })
   timers.off()
-  process.emit('time', 'baz')
+  time.start('baz')
   t.notOk(timers.unfinished.get('baz'))
 })
 
-t.test('convenience time method', async (t) => {
-  const { timers } = mockTimers(t)
-
-  const end = timers.time('later')
-  timers.time('sync', () => {})
-  await timers.time('async', () => new Promise(r => setTimeout(r, 10)))
-  end()
-
-  t.match(timers.finished, { later: Number, sync: Number, async: Number })
-})
-
 t.test('initial timer is named npm', async (t) => {
   const { timers } = mockTimers(t)
-  process.emit('timeEnd', 'npm')
+  time.end('npm')
   t.match(timers.finished, { npm: Number })
 })
 
 t.test('logs timing events', async (t) => {
   const events = []
   const listener = (...args) => events.push(args)
   const { timers, logs } = mockTimers(t, { listener })
-  process.emit('time', 'foo')
-  process.emit('time', 'bar')
-  process.emit('timeEnd', 'bar')
+  time.start('foo')
+  time.start('bar')
+  time.end('bar')
   timers.off(listener)
-  process.emit('timeEnd', 'foo')
+  time.end('foo')
   t.equal(logs.timing.length, 1)
   t.match(logs.timing[0], /^bar Completed in [0-9]ms/)
 })
 
 t.test('finish unstarted timer', async (t) => {
   const { logs } = mockTimers(t)
-  process.emit('timeEnd', 'foo')
+  time.end('foo')
   t.match(logs.silly, ["timing Tried to end timer that doesn't exist: foo"])
 })
 
 t.test('writes file', async (t) => {
   const { timers } = mockTimers(t)
   const dir = t.testdir()
-  process.emit('time', 'foo')
-  process.emit('timeEnd', 'foo')
+  time.start('foo')
+  time.end('foo')
   timers.load({ path: resolve(dir, `TIMING_FILE-`) })
   timers.writeFile({ some: 'data' })
   const data = JSON.parse(fs.readFileSync(resolve(dir, 'TIMING_FILE-timing.json')))