feat: timings are now written alongside debug log files

docs/content/using-npm/config.md

@@ -1707,12 +1707,11 @@ particular, use care when overriding this setting for public packages.
 * Default: false
 * Type: Boolean
 
-If true, writes a debug log to `logs-dir` and timing information to
-`_timing.json` in the cache, even if the command completes successfully.
-`_timing.json` is a newline delimited list of JSON objects.
+If true, writes timing information to a process specific json file in the
+cache or `logs-dir`. The file name ends with `-timing.json`.
 
 You can quickly view it with this [json](https://npm.im/json) command line:
-`npm exec -- json -g < ~/.npm/_timing.json`.
+`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g`.
 
 <!-- automatically generated, do not edit manually -->
 <!-- see lib/utils/config/definitions.js -->

docs/content/using-npm/logging.md

@@ -12,8 +12,7 @@ The `npm` CLI has various mechanisms for showing different levels of information
 
 All logs are written to a debug log, with the path to that file printed if the execution of a command fails.
 
-The default location of the logs directory is a directory named `_logs` inside the npm cache. This can be changed
-with the `logs-dir` config option.
+The default location of the logs directory is a directory named `_logs` inside the npm cache. This can be changed with the `logs-dir` config option.
 
 Log files will be removed from the `logs-dir` when the number of log files exceeds `logs-max`, with the oldest logs being deleted first.
 
@@ -62,9 +61,10 @@ The [`--timing` config](/using-npm/config#timing) can be set which does two
 things:
 
 1. Always shows the full path to the debug log regardless of command exit status
-1. Write timing information to a timing file in the cache or `logs-dir`
+1. Write timing information to a process specific timing file in the cache or `logs-dir`
 
-This file is a newline delimited list of JSON  objects that can be inspected to see timing data for each task in a `npm` CLI run.
+This file contains a `timers` object where the keys are an identifier for the
+portion of the process being timed and the value is the number of milliseconds it took to complete.
 
 ### Registry Response Headers
 

lib/npm.js

@@ -32,6 +32,7 @@ class Npm extends EventEmitter {
   loadErr = null
   argv = []
 
+  #runId = new Date().toISOString().replace(/[.:]/g, '_')
   #loadPromise = null
   #tmpFolder = null
   #title = 'npm'
@@ -206,11 +207,8 @@ class Npm extends EventEmitter {
 
   writeTimingFile () {
     this.#timers.writeFile({
+      id: this.#runId,
       command: this.#argvClean,
-      // We used to only ever report a single log file
-      // so to be backwards compatible report the last logfile
-      // XXX: remove this in npm 9 or just keep it forever
-      logfile: this.logFiles[this.logFiles.length - 1],
       logfiles: this.logFiles,
       version: this.version,
     })
@@ -290,15 +288,15 @@ class Npm extends EventEmitter {
 
     this.time('npm:load:logFile', () => {
       this.#logFile.load({
-        dir: this.logsDir,
+        path: this.logPath,
         logsMax: this.config.get('logs-max'),
       })
       log.verbose('logfile', this.#logFile.files[0] || 'no logfile created')
     })
 
     this.time('npm:load:timers', () =>
       this.#timers.load({
-        dir: this.config.get('timing') ? this.timingDir : null,
+        path: this.config.get('timing') ? this.logPath : null,
       })
     )
 
@@ -372,13 +370,12 @@ class Npm extends EventEmitter {
     return this.config.get('logs-dir') || join(this.cache, '_logs')
   }
 
-  get timingFile () {
-    return this.#timers.file
+  get logPath () {
+    return resolve(this.logsDir, `${this.#runId}-`)
   }
 
-  get timingDir () {
-    // XXX(npm9): make this always in logs-dir
-    return this.config.get('logs-dir') || this.cache
+  get timingFile () {
+    return this.#timers.file
   }
 
   get cache () {

lib/utils/config/definitions.js

@@ -2062,13 +2062,11 @@ define('timing', {
   default: false,
   type: Boolean,
   description: `
-    If true, writes a debug log to \`logs-dir\` and timing information
-    to \`_timing.json\` in the cache, even if the command completes
-    successfully.  \`_timing.json\` is a newline delimited list of JSON
-    objects.
+    If true, writes timing information to a process specific json file in
+    the cache or \`logs-dir\`. The file name ends with \`-timing.json\`.
 
     You can quickly view it with this [json](https://npm.im/json) command
-    line: \`npm exec -- json -g < ~/.npm/_timing.json\`.
+    line: \`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g\`.
   `,
 })
 

lib/utils/display.js

@@ -3,11 +3,6 @@ const npmlog = require('npmlog')
 const log = require('./log-shim.js')
 const { explain } = require('./explain-eresolve.js')
 
-const _logHandler = Symbol('logHandler')
-const _eresolveWarn = Symbol('eresolveWarn')
-const _log = Symbol('log')
-const _npmlog = Symbol('npmlog')
-
 class Display {
   constructor () {
     // pause by default until config is loaded
@@ -16,11 +11,11 @@ class Display {
   }
 
   on () {
-    process.on('log', this[_logHandler])
+    process.on('log', this.#logHandler)
   }
 
   off () {
-    process.off('log', this[_logHandler])
+    process.off('log', this.#logHandler)
     // Unbalanced calls to enable/disable progress
     // will leave change listeners on the tracker
     // This pretty much only happens in tests but
@@ -72,44 +67,44 @@ class Display {
   }
 
   log (...args) {
-    this[_logHandler](...args)
+    this.#logHandler(...args)
   }
 
-  [_logHandler] = (level, ...args) => {
+  #logHandler = (level, ...args) => {
     try {
-      this[_log](level, ...args)
+      this.#log(level, ...args)
     } catch (ex) {
       try {
         // if it crashed once, it might again!
-        this[_npmlog]('verbose', `attempt to log ${inspect(args)} crashed`, ex)
+        this.#npmlog('verbose', `attempt to log ${inspect(args)} crashed`, ex)
       } catch (ex2) {
         // eslint-disable-next-line no-console
         console.error(`attempt to log ${inspect(args)} crashed`, ex, ex2)
       }
     }
   }
 
-  [_log] (...args) {
-    return this[_eresolveWarn](...args) || this[_npmlog](...args)
+  #log (...args) {
+    return this.#eresolveWarn(...args) || this.#npmlog(...args)
   }
 
   // Explicitly call these on npmlog and not log shim
   // This is the final place we should call npmlog before removing it.
-  [_npmlog] (level, ...args) {
+  #npmlog (level, ...args) {
     npmlog[level](...args)
   }
 
   // Also (and this is a really inexcusable kludge), we patch the
   // log.warn() method so that when we see a peerDep override
   // explanation from Arborist, we can replace the object with a
   // highly abbreviated explanation of what's being overridden.
-  [_eresolveWarn] (level, heading, message, expl) {
+  #eresolveWarn (level, heading, message, expl) {
     if (level === 'warn' &&
         heading === 'ERESOLVE' &&
         expl && typeof expl === 'object'
     ) {
-      this[_npmlog](level, heading, message)
-      this[_npmlog](level, '', explain(expl, log.useColor(), 2))
+      this.#npmlog(level, heading, message)
+      this.#npmlog(level, '', explain(expl, log.useColor(), 2))
       // Return true to short circuit other log in chain
       return true
     }

lib/utils/error-message.js

@@ -8,6 +8,7 @@ const log = require('./log-shim')
 module.exports = (er, npm) => {
   const short = []
   const detail = []
+  const files = []
 
   if (er.message) {
     er.message = replaceInfo(er.message)
@@ -17,14 +18,17 @@ module.exports = (er, npm) => {
   }
 
   switch (er.code) {
-    case 'ERESOLVE':
+    case 'ERESOLVE': {
       short.push(['ERESOLVE', er.message])
       detail.push(['', ''])
       // XXX(display): error messages are logged so we use the logColor since that is based
       // on stderr. This should be handled solely by the display layer so it could also be
       // printed to stdout if necessary.
-      detail.push(['', report(er, !!npm.logColor, resolve(npm.cache, 'eresolve-report.txt'))])
+      const { explanation, file } = report(er, !!npm.logColor)
+      detail.push(['', explanation])
+      files.push(['eresolve-report.txt', file])
       break
+    }
 
     case 'ENOLOCK': {
       const cmd = npm.command || ''
@@ -398,5 +402,5 @@ module.exports = (er, npm) => {
 
       break
   }
-  return { summary: short, detail: detail }
+  return { summary: short, detail, files }
 }

lib/utils/exit-handler.js

@@ -1,4 +1,5 @@
 const os = require('os')
+const fs = require('@npmcli/fs')
 
 const log = require('./log-shim.js')
 const errorMessage = require('./error-message.js')
@@ -18,11 +19,10 @@ process.on('exit', code => {
   // unfinished timer check below
   process.emit('timeEnd', 'npm')
 
-  const hasNpm = !!npm
-  const hasLoadedNpm = hasNpm && npm.config.loaded
+  const hasLoadedNpm = npm?.config.loaded
 
   // Unfinished timers can be read before config load
-  if (hasNpm) {
+  if (npm) {
     for (const [name, timer] of npm.unfinishedTimers) {
       log.verbose('unfinished npm timer', name, timer)
     }
@@ -111,10 +111,9 @@ const exitHandler = err => {
 
   log.disableProgress()
 
-  const hasNpm = !!npm
-  const hasLoadedNpm = hasNpm && npm.config.loaded
+  const hasLoadedNpm = npm?.config.loaded
 
-  if (!hasNpm) {
+  if (!npm) {
     err = err || new Error('Exit prior to setting npm in exit handler')
     // eslint-disable-next-line no-console
     console.error(err.stack || err.message)
@@ -181,17 +180,33 @@ const exitHandler = err => {
         }
       }
 
-      const msg = errorMessage(err, npm)
-      for (const errline of [...msg.summary, ...msg.detail]) {
+      const { summary, detail, files = [] } = errorMessage(err, npm)
+
+      for (let [file, content] of files) {
+        file = `${npm.logPath}${file}`
+        content = `'Log files:\n${npm.logFiles.join('\n')}\n\n${content.trim()}\n`
+        try {
+          fs.withOwnerSync(
+            file,
+            () => fs.writeFileSync(file, content),
+            { owner: 'inherit' }
+          )
+          detail.push(['', `\n\nFor a full report see:\n${file}`])
+        } catch (err) {
+          log.warn('', `Could not write error message to ${file} due to ${err}`)
+        }
+      }
+
+      for (const errline of [...summary, ...detail]) {
         log.error(...errline)
       }
 
       if (hasLoadedNpm && npm.config.get('json')) {
         const error = {
           error: {
             code: err.code,
-            summary: messageText(msg.summary),
-            detail: messageText(msg.detail),
+            summary: messageText(summary),
+            detail: messageText(detail),
           },
         }
         npm.outputError(JSON.stringify(error, null, 2))

lib/utils/explain-eresolve.js

@@ -1,7 +1,6 @@
 // this is called when an ERESOLVE error is caught in the exit-handler,
 // or when there's a log.warn('eresolve', msg, explanation), to turn it
 // into a human-intelligible explanation of what's wrong and how to fix.
-const { writeFileSync } = require('fs')
 const { explainEdge, explainNode, printNode } = require('./explain-dep.js')
 
 // expl is an explanation object that comes from Arborist.  It looks like:
@@ -45,27 +44,25 @@ const explain = (expl, color, depth) => {
 }
 
 // generate a full verbose report and tell the user how to fix it
-const report = (expl, color, fullReport) => {
-  const orNoStrict = expl.strictPeerDeps ? '--no-strict-peer-deps, ' : ''
-  const fix = `Fix the upstream dependency conflict, or retry
-this command with ${orNoStrict}--force, or --legacy-peer-deps
-to accept an incorrect (and potentially broken) dependency resolution.`
-
-  writeFileSync(fullReport, `# npm resolution error report
-
-${new Date().toISOString()}
-
-${explain(expl, false, Infinity)}
+const report = (expl, color) => {
+  const flags = [
+    expl.strictPeerDeps ? '--no-strict-peer-deps' : '',
+    '--force',
+    '--legacy-peer-deps',
+  ].filter(Boolean)
 
-${fix}
+  const or = (arr) => arr.length <= 2
+    ? arr.join(' or ') :
+    arr.map((v, i, l) => i + 1 === l.length ? `or ${v}` : v).join(', ')
 
-Raw JSON explanation object:
-
-${JSON.stringify(expl, null, 2)}
-`, 'utf8')
+  const fix = `Fix the upstream dependency conflict, or retry
+this command with ${or(flags)}
+to accept an incorrect (and potentially broken) dependency resolution.`
 
-  return explain(expl, color, 4) +
-    `\n\n${fix}\n\nSee ${fullReport} for a full report.`
+  return {
+    explanation: `${explain(expl, color, 4)}\n\n${fix}`,
+    file: `# npm resolution error report\n\n${explain(expl, false, Infinity)}\n\n${fix}`,
+  }
 }
 
 module.exports = {