Emit timers via proc-log

DEPENDENCIES.md

@@ -211,6 +211,7 @@ graph LR;
   npmcli-metavuln-calculator-->cacache;
   npmcli-metavuln-calculator-->json-parse-even-better-errors;
   npmcli-metavuln-calculator-->pacote;
+  npmcli-metavuln-calculator-->proc-log;
   npmcli-metavuln-calculator-->semver;
   npmcli-mock-globals-->npmcli-eslint-config["@npmcli/eslint-config"];
   npmcli-mock-globals-->npmcli-template-oss["@npmcli/template-oss"];
@@ -676,6 +677,7 @@ graph LR;
   npmcli-metavuln-calculator-->cacache;
   npmcli-metavuln-calculator-->json-parse-even-better-errors;
   npmcli-metavuln-calculator-->pacote;
+  npmcli-metavuln-calculator-->proc-log;
   npmcli-metavuln-calculator-->semver;
   npmcli-mock-globals-->npmcli-eslint-config["@npmcli/eslint-config"];
   npmcli-mock-globals-->npmcli-template-oss["@npmcli/template-oss"];

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)
+        }
+      }
     }
   }
 }

node_modules/@npmcli/metavuln-calculator/lib/index.js

@@ -3,6 +3,7 @@
 // class handles all the IO with the registry and cache.
 const pacote = require('pacote')
 const cacache = require('cacache')
+const { time } = require('proc-log')
 const Advisory = require('./advisory.js')
 const { homedir } = require('os')
 const jsonParse = require('json-parse-even-better-errors')
@@ -48,34 +49,33 @@ class Calculator {
 
   async [_calculate] (name, source) {
     const k = `security-advisory:${name}:${source.id}`
-    const t = `metavuln:calculate:${k}`
-    process.emit('time', t)
+    const timeEnd = time.start(`metavuln:calculate:${k}`)
     const advisory = new Advisory(name, source, this[_options])
     // load packument and cached advisory
     const [cached, packument] = await Promise.all([
       this[_cacheGet](advisory),
       this[_packument](name),
     ])
-    process.emit('time', `metavuln:load:${k}`)
+    const timeEndLoad = time.start(`metavuln:load:${k}`)
     advisory.load(cached, packument)
-    process.emit('timeEnd', `metavuln:load:${k}`)
+    timeEndLoad()
     if (advisory.updated) {
       await this[_cachePut](advisory)
     }
     this[_advisories].set(k, advisory)
-    process.emit('timeEnd', t)
+    timeEnd()
     return advisory
   }
 
   async [_cachePut] (advisory) {
     const { name, id } = advisory
     const key = `security-advisory:${name}:${id}`
-    process.emit('time', `metavuln:cache:put:${key}`)
+    const timeEnd = time.start(`metavuln:cache:put:${key}`)
     const data = JSON.stringify(advisory)
     const options = { ...this[_options] }
     this[_cacheData].set(key, jsonParse(data))
     await cacache.put(this[_cache], key, data, options).catch(() => {})
-    process.emit('timeEnd', `metavuln:cache:put:${key}`)
+    timeEnd()
   }
 
   async [_cacheGet] (advisory) {
@@ -87,12 +87,12 @@ class Calculator {
       return this[_cacheData].get(key)
     }
 
-    process.emit('time', `metavuln:cache:get:${key}`)
+    const timeEnd = time.start(`metavuln:cache:get:${key}`)
     const p = cacache.get(this[_cache], key, { ...this[_options] })
       .catch(() => ({ data: '{}' }))
       .then(({ data }) => {
         data = jsonParse(data)
-        process.emit('timeEnd', `metavuln:cache:get:${key}`)
+        timeEnd()
         this[_cacheData].set(key, data)
         return data
       })
@@ -105,7 +105,7 @@ class Calculator {
       return this[_packuments].get(name)
     }
 
-    process.emit('time', `metavuln:packument:${name}`)
+    const timeEnd = time.start(`metavuln:packument:${name}`)
     const p = pacote.packument(name, { ...this[_options] })
       .catch((er) => {
         // presumably not something from the registry.
@@ -116,7 +116,7 @@ class Calculator {
         }
       })
       .then(paku => {
-        process.emit('timeEnd', `metavuln:packument:${name}`)
+        timeEnd()
         this[_packuments].set(name, paku)
         return paku
       })

node_modules/@npmcli/metavuln-calculator/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@npmcli/metavuln-calculator",
-  "version": "7.0.1",
+  "version": "7.1.0",
   "main": "lib/index.js",
   "files": [
     "bin/",
@@ -42,6 +42,7 @@
     "cacache": "^18.0.0",
     "json-parse-even-better-errors": "^3.0.0",
     "pacote": "^18.0.0",
+    "proc-log": "^4.1.0",
     "semver": "^7.3.5"
   },
   "engines": {