fixup! feat: do all ouput over proc-log events

lib/npm.js

@@ -244,7 +244,10 @@ class Npm {
     this.time('npm:load:display', () => {
       this.#display.load({
         loglevel: this.config.get('loglevel'),
-        chalk: this.logChalk, // Use logChalk since that is based on stderr
+        stdoutChalk: this.#chalk,
+        stdoutColor: this.color,
+        stderrChalk: this.#logChalk,
+        stderrColor: this.logColor,
         timing: this.config.get('timing'),
         unicode: this.config.get('unicode'),
         progress: this.flatOptions.progress,

lib/utils/display.js

@@ -1,7 +1,7 @@
 const proggy = require('proggy')
 const { log } = require('proc-log')
 const { explain } = require('./explain-eresolve.js')
-const { formatWithOptions, format } = require('./format')
+const { formatWithOptions } = require('./format')
 
 const COLOR_PALETTE = ({ chalk: c }) => ({
   heading: c.white.bgBlack,
@@ -81,17 +81,30 @@ const setBlocking = (stream) => {
   return stream
 }
 
+const getLevel = (stringOrLevelObject) => {
+  if (typeof stringOrLevelObject === 'string') {
+    return { level: stringOrLevelObject }
+  }
+  return stringOrLevelObject
+}
+
 class Display {
-  // pause by default until config is loaded
-  #paused = true
+  #logState = {
+    buffering: true,
+    buffer: [],
+  }
 
-  // buffers to store logs when paused
-  #logBuffer = []
-  #outputBuffer = []
+  #outputState = {
+    buffering: true,
+    buffer: [],
+  }
 
   // colors
-  #chalk
-  #colors
+  #stdoutChalk
+  #stdoutColor
+  #stderrChalk
+  #stderrColor
+  #logColors
 
   // progress
   #progress
@@ -109,125 +122,163 @@ class Display {
   constructor ({ stdout, stderr }) {
     this.#stdout = setBlocking(stdout)
     this.#stderr = setBlocking(stderr)
+    // Handlers are set immediately so they can buffer all events
     process.on('log', this.#logHandler)
     process.on('output', this.#outputHandler)
   }
 
   off () {
     process.off('log', this.#logHandler)
+    this.#logState.buffer.length = 0
+
     process.off('output', this.#outputHandler)
-    this.#logBuffer.length = 0
+    this.#outputState.buffer.length = 0
+
     if (this.#progress) {
       this.#progress.stop()
     }
   }
 
-  load ({ loglevel, chalk, timing, unicode, progress, json, heading }) {
-    this.#chalk = chalk
-    this.#colors = COLOR_PALETTE({ chalk })
+  load ({
+    loglevel,
+    stdoutColor,
+    stdoutChalk,
+    stderrColor,
+    stderrChalk,
+    timing,
+    unicode,
+    progress,
+    json,
+    heading,
+  }) {
+    this.#stdoutColor = stdoutColor
+    this.#stdoutChalk = stdoutChalk
+
+    this.#stderrColor = stderrColor
+    this.#stderrChalk = stderrChalk
+
+    this.#logColors = COLOR_PALETTE({ chalk: stderrChalk })
 
     this.#levelIndex = LEVEL_OPTIONS[loglevel].index
     this.#timing = timing
     this.#json = json
     this.#heading = heading
 
+    // In silent mode we remove all the handlers
     if (this.#levelIndex <= 0) {
       this.off()
-    } else {
-      log.resume()
-      if (progress) {
-        this.#startProgress({ unicode })
-      }
+      return
     }
-  }
 
-  forceLog (level, ...args) {
-    // This will show the log regardless of the current loglevel, except when silent
-    this.#logHandler({ level, force: true }, ...args)
+    // Emit resume event on the logs which will flush output
+    log.resume()
+
+    // TODO: this should be a proc-log method `proc-log.output.flush`?
+    this.#outputHandler('flush')
+
+    this.#startProgress({ progress, unicode })
   }
 
-  #outputHandler = (level, ...args) => {
-    if (level === 'standard') {
-      this.#stdout.write(format(...args))
+  // Public class field so it can be passed directly as a listener
+  #logHandler = (...args) => {
+    if (args[0] === LEVELS.resume) {
+      this.#logState.buffering = false
+      this.#logState.buffer.forEach((item) => this.#tryWriteLog(...item))
+      this.#logState.buffer.length = 0
       return
     }
 
-    /* istanbul ignore next - not implemented yet */
-    if (level === 'error') {
-      this.#stderr.write(format(...args))
+    if (args[0] === LEVELS.pause) {
+      this.#logState.buffering = true
       return
     }
 
-    /* istanbul ignore else - just to catch accidental errors */
-    if (level === 'buffer') {
-      this.#outputBuffer.push(args[0])
+    if (this.#logState.buffering) {
+      this.#logState.buffer.push(args)
       return
     }
 
-    /* istanbul ignore next - just to catch accidental errors */
-    log.verbose('display', `Unknown output event ${level}`)
+    this.#tryWriteLog(...args)
   }
 
-  flushOutput (jsonError) {
-    if (!jsonError && !this.#outputBuffer.length) {
+  // Public class field so it can be passed directly as a listener
+  #outputHandler = (...args) => {
+    if (args[0] === 'flush') {
+      this.#outputState.buffering = false
+      if (args[1] && this.#json) {
+        const mergedJsonOutput = {}
+        for (const [, ...items] of this.#outputState.buffer) {
+          Object.assign(mergedJsonOutput, ...items.map(safeJsonParse))
+        }
+        Object.assign(args[1])
+        this.#writeOutput('standard', JSON.stringify(mergedJsonOutput, null, 2))
+      } else {
+        this.#outputState.buffer.forEach((item) => this.#writeOutput(...item))
+      }
+      this.#outputState.buffer.length = 0
       return
     }
 
-    if (this.#json) {
-      const output = this.#outputBuffer.reduce((a, i) => ({ ...a, ...safeJsonParse(i) }), {})
-      this.#stdout.write(format(JSON.stringify({ ...output, ...jsonError }, null, 2)))
-    } else {
-      this.#outputBuffer.forEach((item) => this.#stdout.write(format(item)))
+    if (args[0] === 'buffer') {
+      this.#outputState.buffer.push(['standard', ...args.slice(1)])
+      return
     }
 
-    this.#outputBuffer.length = 0
+    if (this.#outputState.buffering) {
+      this.#outputState.buffer.push(args)
+      return
+    }
+
+    this.#writeOutput(...args)
   }
 
-  #write (...args) {
-    const { level: levelName, force = false } = typeof args[0] === 'string'
-      ? { level: args[0] } : args[0]
+  // OUTPUT
 
-    if (levelName === LEVELS.pause) {
-      this.#paused = true
-      return
-    }
+  #writeOutput (...args) {
+    const { level } = getLevel(args.shift())
 
-    if (levelName === LEVELS.resume) {
-      this.#paused = false
-      this.#logBuffer.forEach((item) => this.#write(...item))
-      this.#logBuffer.length = 0
+    if (level === 'standard') {
+      this.#stdout.write(formatWithOptions({ colors: this.#stdoutColor }, ...args))
       return
     }
 
-    if (this.#paused) {
-      this.#logBuffer.push(args)
-      return
+    if (level === 'error') {
+      this.#stderr.write(formatWithOptions({ colors: this.#stderrColor }, ...args))
     }
+  }
+
+  // TODO: move this to proc-log and remove this public method
+  flushOutput (jsonError) {
+    this.#outputHandler('flush', jsonError)
+  }
 
-    const level = LEVEL_METHODS[levelName]
-    const show = level.show ?? (({ index }) => level.index <= index)
+  // LOGS
 
-    if ((force && level.index !== 0) || show({ index: this.#levelIndex, timing: this.#timing })) {
-      // this mutates the array so we can pass args directly to format later
-      const [, title] = args.splice(0, 2)
-      const prefix = [
-        this.#colors.heading(this.#heading),
-        this.#colors[levelName](level.label ?? levelName),
-        title ? this.#colors.title(title) : null,
-      ]
-      this.#stderr.write(formatWithOptions({ prefix }, ...args))
-    } else if (this.#progress) {
-      // TODO: make this display a single log line of filtered messages
+  forceLog (level, ...args) {
+    // This will show the log regardless of the current loglevel
+    if (this.#levelIndex !== 0) {
+      this.#logHandler({ level, force: true }, ...args)
     }
   }
 
-  #logHandler = (level, ...args) => {
+  #tryWriteLog (...args) {
     try {
-      this.#log(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.
+      // TODO: this could probably be moved to arborist now that display is refactored
+      const [level, heading, message, expl] = args
+      if (level === LEVELS.warn && heading === 'ERESOLVE' && expl && typeof expl === 'object') {
+        this.#writeLog(level, heading, message)
+        this.#writeLog(level, '', explain(expl, this.#stderrChalk, 2))
+        return
+      }
+      this.#writeLog(...args)
     } catch (ex) {
       try {
         // if it crashed once, it might again!
-        this.#write(LEVELS.verbose, null, `attempt to log crashed`, ...args, ex)
+        this.#writeLog(LEVELS.verbose, null, `attempt to log crashed`, ...args, ex)
       } catch (ex2) {
         /* istanbul ignore next - this happens if the object has an inspect method that crashes */
         // eslint-disable-next-line no-console
@@ -236,22 +287,32 @@ class Display {
     }
   }
 
-  #log (...args) {
-    const [level, heading, message, expl] = args
-    if (level === LEVELS.warn && heading === 'ERESOLVE' && expl && typeof expl === 'object') {
-      // 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.
-      // TODO: this could probably be moved to arborist now that display is refactored
-      this.#write(level, heading, message)
-      this.#write(level, '', explain(expl, this.#chalk, 2))
-      return
+  #writeLog (...args) {
+    const { level, force = false } = getLevel(args.shift())
+
+    const levelOpts = LEVEL_METHODS[level]
+    const show = levelOpts.show ?? (({ index }) => levelOpts.index <= index)
+
+    if (force || show({ index: this.#levelIndex, timing: this.#timing })) {
+      // this mutates the array so we can pass args directly to format later
+      const title = args.shift()
+      const prefix = [
+        this.#logColors.heading(this.#heading),
+        this.#logColors[level](levelOpts.label ?? level),
+        title ? this.#logColors.title(title) : null,
+      ]
+      this.#stderr.write(formatWithOptions({ prefix, colors: this.stderrColor }, ...args))
+    } else if (this.#progress) {
+      // TODO: make this display a single log line of filtered messages
     }
-    this.#write(...args)
   }
 
-  #startProgress ({ unicode }) {
+  // PROGRESS
+
+  #startProgress ({ progress, unicode }) {
+    if (!progress) {
+      return
+    }
     this.#progress = proggy.createClient({ normalize: true })
     // TODO: implement proggy trackers in arborist/doctor
     // TODO: listen to progress events here and build progress UI

lib/utils/exit-handler.js

@@ -1,14 +1,22 @@
 const os = require('os')
 const fs = require('fs')
-
-const { log } = require('proc-log')
+const { log, output } = require('proc-log')
 const errorMessage = require('./error-message.js')
 const { redactLog: replaceInfo } = require('@npmcli/redact')
 
 let npm = null // set by the cli
 let exitHandlerCalled = false
 let showLogFileError = false
 
+const outputError = (v) => {
+  if (npm) {
+    output.error(v)
+  } else {
+    // Use console for output if there is no npm
+    // eslint-disable-next-line no-console
+    console.error(v)
+  }
+}
 process.on('exit', code => {
   // process.emit is synchronous, so the timeEnd handler will run before the
   // unfinished timer check below
@@ -32,8 +40,7 @@ process.on('exit', code => {
   if (!exitHandlerCalled) {
     process.exitCode = code || 1
     log.error('', 'Exit handler never called!')
-    // eslint-disable-next-line no-console
-    console.error('')
+    outputError('')
     log.error('', 'This is an error with npm itself. Please report this error at:')
     log.error('', '    <https://github.com/npm/cli/issues>')
     showLogFileError = true
@@ -62,8 +69,7 @@ process.on('exit', code => {
     if (logMethod) {
       if (!npm.silent) {
         // just a line break if not in silent mode
-        // eslint-disable-next-line no-console
-        console.error('')
+        outputError('')
       }
 
       const message = []
@@ -108,15 +114,15 @@ const exitHandler = err => {
 
   if (!npm) {
     err = err || new Error('Exit prior to setting npm in exit handler')
+    // Don't use proc-log here since npm was never set
     // eslint-disable-next-line no-console
-    console.error(err.stack || err.message)
+    outputError(err.stack || err.message)
     return process.exit(1)
   }
 
   if (!hasLoadedNpm) {
     err = err || new Error('Exit prior to config file resolving.')
-    // eslint-disable-next-line no-console
-    console.error(err.stack || err.message)
+    outputError(err.stack || err.message)
   }
 
   // only show the notification if it finished.