wip: get new way to mock logs working in tests

Author: lukekarrys

lib/cli-entry.js

@@ -1,6 +1,3 @@
-/* eslint-disable max-len */
-
-// Separated out for easier unit testing
 module.exports = async (process, validateEngines) => {
   // set it here so that regardless of what happens later, we don't
   // leak any private CLI configs to other programs
@@ -17,18 +14,25 @@ module.exports = async (process, validateEngines) => {
   const npm = new Npm()
   exitHandler.setNpm(npm)
 
-  // only log node and npm paths in argv initially since argv can contain sensitive info. a cleaned version will be logged later
+  // only log node and npm paths in argv initially since argv can contain
+  // sensitive info. a cleaned version will be logged later
   const log = require('proc-log')
   log.verbose('cli', process.argv.slice(0, 2).join(' '))
   log.info('using', 'npm@%s', npm.version)
   log.info('using', 'node@%s', process.version)
 
-  // At this point we've required a few files and can be pretty sure we dont contain invalid syntax for this version of node. It's possible a lazy require would, but that's unlikely enough that it's not worth catching anymore and we attach the more important exit handlers.
+  // At this point we've required a few files and can be pretty sure we dont
+  // contain invalid syntax for this version of node. It's possible a lazy
+  // require would, but that's unlikely enough that it's not worth catching
+  // anymore and we attach the more important exit handlers.
   validateEngines.off()
   process.on('uncaughtException', exitHandler)
   process.on('unhandledRejection', exitHandler)
 
-  // It is now safe to log a warning if they are using a version of node that is not going to fail on syntax errors but is still unsupported and untested and might not work reliably. This is safe to use the logger now which we want since this will show up in the error log too.
+  // It is now safe to log a warning if they are using a version of node that is
+  // not going to fail on syntax errors but is still unsupported and untested
+  // and might not work reliably. This is safe to use the logger now which we
+  // want since this will show up in the error log too.
   if (!satisfies(validateEngines.node, validateEngines.engines)) {
     log.warn('cli', validateEngines.unsupportedMessage)
   }

lib/commands/init.js

@@ -60,7 +60,7 @@ class Init extends BaseCommand {
     // to create a workspace package.json file or its folders
     const { content: pkg } = await PackageJson.normalize(this.npm.localPrefix).catch(err => {
       if (err.code === 'ENOENT') {
-        log.warn('Missing package.json. Try with `--include-workspace-root`.')
+        log.warn('', 'Missing package.json. Try with `--include-workspace-root`.')
       }
       throw err
     })

lib/commands/ping.js

@@ -12,7 +12,8 @@ class Ping extends BaseCommand {
     const cleanRegistry = cleanUrl(this.npm.config.get('registry'))
     log.notice('PING', cleanRegistry)
     const start = Date.now()
-    const details = await pingUtil({ ...this.npm.flatOptions })
+    let details = await pingUtil({ ...this.npm.flatOptions })
+    details = { a: 1, b: 2 }
     const time = Date.now() - start
     log.notice('PONG', `${time}ms`)
     if (this.npm.config.get('json')) {
@@ -22,7 +23,7 @@ class Ping extends BaseCommand {
         details,
       }, null, 2))
     } else if (Object.keys(details).length) {
-      log.notice('PONG', `${JSON.stringify(details, null, 2)}`)
+      log.notice('PONG', JSON.stringify(details, null, 2))
     }
   }
 }

lib/npm.js

@@ -48,8 +48,8 @@ class Npm {
   #logChalk = null
   #noColorChalk = null
 
+  #display = null
   #logFile = new LogFile()
-  #display = new Display()
   #timers = new Timers({
     start: 'npm',
     listener: (name, ms) => {
@@ -71,7 +71,14 @@ class Npm {
   //     allows tests created by tap inside this repo to not set the local
   //     prefix to `npmRoot` since that is the first dir it would encounter when
   //     doing implicit detection
-  constructor ({ npmRoot = dirname(__dirname), argv = [], excludeNpmCwd = false } = {}) {
+  constructor ({
+    stdout = process.stdout,
+    stderr = process.stderr,
+    npmRoot = dirname(__dirname),
+    argv = [],
+    excludeNpmCwd = false,
+  } = {}) {
+    this.#display = new Display({ stdout, stderr })
     this.#npmRoot = npmRoot
     this.config = new Config({
       npmPath: this.#npmRoot,
@@ -446,7 +453,7 @@ class Npm {
   }
 
   outputBuffer (arg) {
-    this.#display.outputBuffer.push(arg)
+    this.#display.outputBuffer(arg)
   }
 
   flushOutput (jsonError) {

lib/utils/display.js

@@ -57,7 +57,7 @@ const LEVEL_OPTIONS = {
 const LEVEL_METHODS = {
   ...LEVEL_OPTIONS,
   [LEVELS.timing]: {
-    show: ({ index, timing }) => timing && index !== 0,
+    show: ({ timing, index }) => !!timing && index !== 0,
   },
 }
 
@@ -68,7 +68,7 @@ const safeJsonParse = (maybeJsonStr) => {
   try {
     return JSON.parse(maybeJsonStr)
   } catch {
-    return maybeJsonStr
+    return {}
   }
 }
 
@@ -93,7 +93,12 @@ class Display {
   #json = false
   #heading = 'npm'
 
-  constructor () {
+  #stdout = null
+  #stderr = null
+
+  constructor ({ stdout, stderr }) {
+    this.#stdout = stdout
+    this.#stderr = stderr
     process.on('log', this.#logHandler)
   }
 
@@ -135,11 +140,11 @@ class Display {
 
   output (...args) {
     // TODO: make this respect silent option
-    process.stdout.write(format(...args))
+    this.#stdout.write(format(...args))
   }
 
   outputError (...args) {
-    process.stderr.write(format(...args))
+    this.#stderr.write(format(...args))
   }
 
   outputBuffer (item) {
@@ -193,7 +198,7 @@ class Display {
         this.#colors[levelName](level.label ?? levelName),
         title ? this.#colors.title(title) : null,
       ]
-      process.stderr.write(formatWithOptions({ prefix }, ...args))
+      this.#stderr.write(formatWithOptions({ prefix }, ...args))
     } else if (this.#progress) {
       // TODO: make this display a single log line of filtered messages
     }

lib/utils/exit-handler.js

@@ -57,7 +57,7 @@ process.on('exit', code => {
 
     // Determine whether to show log file message and why it is
     // being shown since in timing mode we always show the log file message
-    const logMethod = showLogFileError ? 'error' : timing ? 'info' : null
+    const logMethod = showLogFileError ? 'error' : timing ? 'notice' : null
 
     if (logMethod) {
       if (!npm.silent) {
@@ -121,7 +121,7 @@ const exitHandler = err => {
 
   // only show the notification if it finished.
   if (typeof npm.updateNotification === 'string') {
-    npm.forcceLog('notice', '', npm.updateNotification)
+    npm.forceLog('notice', '', npm.updateNotification)
   }
 
   let exitCode = process.exitCode || 0

lib/utils/format.js

@@ -85,15 +85,11 @@ const cleanControl = createCleaner((output) => {
 })
 
 const formatWithOptions = ({ prefix = [], eol = '\n', ...options }, ...args) => {
-  const prefixStr = prefix.filter(p => p != null).join(' ')
+  const pre = prefix.filter(p => p != null).join(' ')
   return baseFormatWithOptions(options, ...args)
-    .trim()
     .split(/\r?\n/)
     .map(cleanControl)
-    .reduce((lines, line) =>
-      lines += prefixStr + (prefixStr && line ? ' ' : '') + line + eol,
-    ''
-    )
+    .reduce((acc, l) => `${acc}${pre}${pre && l ? ' ' : ''}${l}${eol}`, '')
 }
 
 const format = (...args) => formatWithOptions({}, ...args)

lib/utils/log-file.js

@@ -41,11 +41,6 @@ class LogFiles {
     this.on()
   }
 
-  static format (count, level, title, ...args) {
-    const prefix = [count, level, title || null]
-    return formatWithOptions({ prefix, eol: os.EOL, colors: false }, ...args)
-  }
-
   on () {
     this.#logStream = new Minipass()
     process.on('log', this.#logHandler)
@@ -141,9 +136,10 @@ class LogFiles {
     }
   }
 
-  #formatLogItem (...args) {
+  #formatLogItem (level, title, ...args) {
     this.#fileLogCount += 1
-    return LogFiles.format(this.#totalLogCount++, ...args)
+    const prefix = [this.#totalLogCount++, level, title || null]
+    return formatWithOptions({ prefix, eol: os.EOL, colors: false }, ...args)
   }
 
   #getLogFilePath (count = '') {

tap-snapshots/test/lib/commands/audit.js.test.cjs

@@ -45,7 +45,6 @@ exports[`test/lib/commands/audit.js TAP audit signatures ignores optional depend
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures json output with invalid and missing signatures > must match snapshot 1`] = `
@@ -131,14 +130,12 @@ exports[`test/lib/commands/audit.js TAP audit signatures multiple registries wit
 audited 2 packages in xxx
 
 2 packages have verified registry signatures
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures omit dev dependencies with missing signature > must match snapshot 1`] = `
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures output details about missing signatures > must match snapshot 1`] = `
@@ -157,7 +154,6 @@ audited 1 package in xxx
 @npmcli/arborist@1.0.14 (https://verdaccio-clone.org/)
 
 Someone might have tampered with this package since it was published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures third-party registry with keys and missing signatures errors > must match snapshot 1`] = `
@@ -172,21 +168,18 @@ exports[`test/lib/commands/audit.js TAP audit signatures third-party registry wi
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures third-party registry with sub-path (trailing slash) > must match snapshot 1`] = `
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures third-party registry with sub-path > must match snapshot 1`] = `
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with both invalid and missing signatures > must match snapshot 1`] = `
@@ -201,14 +194,12 @@ async@1.1.1 (https://registry.npmjs.org/)
 kms-demo@1.0.0 (https://registry.npmjs.org/)
 
 Someone might have tampered with this package since it was published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with bundled and peer deps and no signatures > must match snapshot 1`] = `
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with invalid attestations > must match snapshot 1`] = `
@@ -219,7 +210,6 @@ audited 1 package in xxx
 sigstore@1.0.0 (https://registry.npmjs.org/)
 
 Someone might have tampered with this package since it was published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with invalid signatures > must match snapshot 1`] = `
@@ -230,7 +220,6 @@ audited 1 package in xxx
 kms-demo@1.0.0 (https://registry.npmjs.org/)
 
 Someone might have tampered with this package since it was published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with invalid signtaures and color output enabled > must match snapshot 1`] = `
@@ -241,14 +230,12 @@ audited 1 package in xxx
 kms-demo@1.0.0 (https://registry.npmjs.org/)
 
 Someone might have tampered with this package since it was published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with key fallback to legacy API > must match snapshot 1`] = `
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with keys but missing signature > must match snapshot 1`] = `
@@ -268,7 +255,6 @@ sigstore@1.0.0 (https://registry.npmjs.org/)
 tuf-js@1.0.0 (https://registry.npmjs.org/)
 
 Someone might have tampered with these packages since they were published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with multiple invalid signatures > must match snapshot 1`] = `
@@ -280,7 +266,6 @@ async@1.1.1 (https://registry.npmjs.org/)
 kms-demo@1.0.0 (https://registry.npmjs.org/)
 
 Someone might have tampered with these packages since they were published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with multiple missing signatures > must match snapshot 1`] = `
@@ -302,7 +287,6 @@ audited 3 packages in xxx
 node-fetch@1.6.0 (https://registry.npmjs.org/)
 
 Someone might have tampered with this package since it was published on the registry!
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with valid and missing signatures > must match snapshot 1`] = `
@@ -321,35 +305,30 @@ audited 1 package in xxx
 1 package has a verified registry signature
 
 1 package has a verified attestation
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with valid signatures > must match snapshot 1`] = `
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures with valid signatures using alias > must match snapshot 1`] = `
 audited 1 package in xxx
 
 1 package has a verified registry signature
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures workspaces verifies registry deps and ignores local workspace deps > must match snapshot 1`] = `
 audited 3 packages in xxx
 
 3 packages have verified registry signatures
-
 `
 
 exports[`test/lib/commands/audit.js TAP audit signatures workspaces verifies registry deps when filtering by workspace name > must match snapshot 1`] = `
 audited 2 packages in xxx
 
 2 packages have verified registry signatures
-
 `
 
 exports[`test/lib/commands/audit.js TAP fallback audit > must match snapshot 1`] = `