feat: write eresolve error files to the logs directory

Also refactor all files written to the logs directory to use the same
code path for file name creation.

Author: lukekarrys

lib/npm.js

@@ -18,11 +18,9 @@ const replaceInfo = require('./utils/replace-info.js')
 const updateNotifier = require('./utils/update-notifier.js')
 const pkg = require('../package.json')
 const cmdList = require('./utils/cmd-list.js')
-const runId = require('./utils/run-id.js')
 
 let warnedNonDashArg = false
 const _load = Symbol('_load')
-const RUN_ID = runId()
 
 class Npm extends EventEmitter {
   static get version () {
@@ -34,16 +32,16 @@ class Npm extends EventEmitter {
   loadErr = null
   argv = []
 
+  #runId = new Date().toISOString().replace(/[.:]/g, '_')
   #loadPromise = null
   #tmpFolder = null
   #title = 'npm'
   #argvClean = []
   #chalk = null
 
-  #logFile = new LogFile({ id: RUN_ID })
+  #logFile = new LogFile()
   #display = new Display()
   #timers = new Timers({
-    id: RUN_ID,
     start: 'npm',
     listener: (name, ms) => {
       const args = ['timing', name, `Completed in ${ms}ms`]
@@ -209,6 +207,7 @@ class Npm extends EventEmitter {
 
   writeTimingFile () {
     this.#timers.writeFile({
+      id: this.#runId,
       command: this.#argvClean,
       logfiles: this.logFiles,
       version: this.version,
@@ -289,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.logsDir : null,
+        path: this.config.get('timing') ? this.logPath : null,
       })
     )
 
@@ -371,6 +370,10 @@ class Npm extends EventEmitter {
     return this.config.get('logs-dir') || join(this.cache, '_logs')
   }
 
+  get logPath () {
+    return resolve(this.logsDir, `${this.#runId}-`)
+  }
+
   get timingFile () {
     return this.#timers.file
   }

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 = {

lib/utils/log-file.js

@@ -7,16 +7,11 @@ const MiniPass = require('minipass')
 const fsMiniPass = require('fs-minipass')
 const fs = require('@npmcli/fs')
 const log = require('./log-shim')
-const runId = require('./run-id')
 
 const padZero = (n, length) => n.toString().padStart(length.toString().length, '0')
 const globify = pattern => pattern.split('\\').join('/')
 
 class LogFiles {
-  // If we write multiple log files we want them all to have the same
-  // identifier for sorting and matching purposes
-  #logId = null
-
   // Default to a plain minipass stream so we can buffer
   // initial writes before we know the cache location
   #logStream = null
@@ -34,16 +29,14 @@ class LogFiles {
 
   #fileLogCount = 0
   #totalLogCount = 0
-  #dir = null
+  #path = null
   #logsMax = null
   #files = []
 
   constructor ({
-    id = runId(),
     maxLogsPerFile = 50_000,
     maxFilesPerProcess = 5,
   } = {}) {
-    this.#logId = id
     this.#MAX_LOGS_PER_FILE = maxLogsPerFile
     this.#MAX_FILES_PER_PROCESS = maxFilesPerProcess
     this.on()
@@ -73,18 +66,18 @@ class LogFiles {
     this.#endStream()
   }
 
-  load ({ dir, logsMax = Infinity } = {}) {
+  load ({ path, logsMax = Infinity } = {}) {
     // dir is user configurable and is required to exist so
     // this can error if the dir is missing or not configured correctly
-    this.#dir = dir
+    this.#path = path
     this.#logsMax = logsMax
 
     // Log stream has already ended
     if (!this.#logStream) {
       return
     }
 
-    log.verbose('logfile', `logs-max:${logsMax} dir:${dir}`)
+    log.verbose('logfile', `logs-max:${logsMax} dir:${this.#path}`)
 
     // Pipe our initial stream to our new file stream and
     // set that as the new log logstream for future writes
@@ -164,7 +157,7 @@ class LogFiles {
   }
 
   #getLogFilePath (count = '') {
-    return path.resolve(this.#dir, `${this.#logId}-debug-${count}.log`)
+    return `${this.#path}debug-${count}.log`
   }
 
   #openLogFile () {

lib/utils/run-id.js

@@ -1,25 +1,21 @@
 const EE = require('events')
-const { resolve } = require('path')
 const fs = require('@npmcli/fs')
 const log = require('./log-shim')
-const runId = require('./run-id')
 
 // This is an event emiiter but on/off
 // only listen on a single internal event that gets
 // emitted whenever a timer ends
 class Timers extends EE {
   file = null
 
-  #id = null
   #unfinished = new Map()
   #finished = {}
   #onTimeEnd = Symbol('onTimeEnd')
   #initialListener = null
   #initialTimer = null
 
-  constructor ({ id = runId(), listener = null, start = 'npm' } = {}) {
+  constructor ({ listener = null, start = 'npm' } = {}) {
     super()
-    this.#id = id
     this.#initialListener = listener
     this.#initialTimer = start
     this.#init()
@@ -71,9 +67,9 @@ class Timers extends EE {
     return end
   }
 
-  load ({ dir } = {}) {
-    if (dir) {
-      this.file = resolve(dir, `${this.#id}-timing.json`)
+  load ({ path } = {}) {
+    if (path) {
+      this.file = `${path}timing.json`
     }
   }
 
@@ -86,10 +82,7 @@ class Timers extends EE {
       const globalStart = this.started
       const globalEnd = this.#finished.npm || Date.now()
       const content = {
-        metadata: {
-          id: this.#id,
-          ...metadata,
-        },
+        metadata,
         timers: this.#finished,
         // add any unfinished timers with their relative start/end
         unfinishedTimers: [...this.#unfinished.entries()].reduce((acc, [name, start]) => {