feat: streaming debug logfile

This decouples the log file writing from the terminal logging. We now open an append only file at the start of the process and stream logs to it. We still only display the log file message in timing mode or if there is an error, but the file is still written regardless. All logging now goes through `proc-log` and this is the first step to removing `npmlog`. For now `npmlog` is still used for the terminal logging but with a shim in front of it to make it easier to test and use in conjunction with `proc-log`. Ref: npm/statusboard#366 This also refactors many of the tests to always use an explicit `t.testdir` for their cache since the file is opened on each `new Npm()`. Tests are also refactored to use more of `MockNpm` with behavior to add config items and load `npm` if necessary. A new fixture `mockGlobals` was also added to make much of this more ergonomic. Ref: npm/statusboard#410 Closes npm/statusboard#411 Closes npm/statusboard#367 PR-URL: #4062 Credit: @lukekarrys Close: #4062 Reviewed-by: @wraithgar
npm · Dec 2, 2021 · 6734ba36dd6e07a859ab4d6eb4f264d2c0022276 · 6734ba3
1 parent 037f2cc
commit 6734ba36dd6e07a859ab4d6eb4f264d2c0022276
diff --git a/.eslintrc.json b/.eslintrc.json
@@ -1,3 +1,15 @@
 {
-  "extends": ["@npmcli"]
+  "extends": ["@npmcli"],
+  "overrides": [{
+    "files": "test/**",
+    "rules": {
+      "no-extend-native": "off",
+      "no-global-assign": "off"
+    }
+  }, {
+    "files": ["lib/**"],
+    "rules": {
+      "no-console": "warn"
+    }
+  }]
 }
diff --git a/lib/auth/legacy.js b/lib/auth/legacy.js
@@ -1,15 +1,12 @@
-const log = require('npmlog')
 const profile = require('npm-profile')
-
+const log = require('../utils/log-shim')
 const openUrl = require('../utils/open-url.js')
 const read = require('../utils/read-user-info.js')
 
 const loginPrompter = async (creds) => {
-  const opts = { log: log }
-
-  creds.username = await read.username('Username:', creds.username, opts)
+  creds.username = await read.username('Username:', creds.username)
   creds.password = await read.password('Password:', creds.password)
-  creds.email = await read.email('Email: (this IS public) ', creds.email, opts)
+  creds.email = await read.email('Email: (this IS public) ', creds.email)
 
   return creds
 }

diff --git a/lib/auth/sso.js b/lib/auth/sso.js
@@ -7,10 +7,9 @@
 // CLI, we can remove this, and fold the lib/auth/legacy.js back into
 // lib/adduser.js
 
-const log = require('npmlog')
 const profile = require('npm-profile')
 const npmFetch = require('npm-registry-fetch')
-
+const log = require('../utils/log-shim')
 const openUrl = require('../utils/open-url.js')
 const otplease = require('../utils/otplease.js')
 

diff --git a/lib/cli.js b/lib/cli.js
@@ -4,20 +4,23 @@ module.exports = async process => {
   // leak any private CLI configs to other programs
   process.title = 'npm'
 
-  const { checkForBrokenNode, checkForUnsupportedNode } = require('../lib/utils/unsupported.js')
-
+  // We used to differentiate between known broken and unsupported
+  // versions of node and attempt to only log unsupported but still run.
+  // After we dropped node 10 support, we can use new features
+  // (like static, private, etc) which will only give vague syntax errors,
+  // so now both broken and unsupported use console, but only broken
+  // will process.exit. It is important to now perform *both* of these
+  // checks as early as possible so the user gets the error message.
+  const { checkForBrokenNode, checkForUnsupportedNode } = require('./utils/unsupported.js')
   checkForBrokenNode()
-
-  const log = require('npmlog')
-  // pause it here so it can unpause when we've loaded the configs
-  // and know what loglevel we should be printing.
-  log.pause()
-
   checkForUnsupportedNode()
 
-  const Npm = require('../lib/npm.js')
+  const exitHandler = require('./utils/exit-handler.js')
+  process.on('uncaughtException', exitHandler)
+  process.on('unhandledRejection', exitHandler)
+
+  const Npm = require('./npm.js')
   const npm = new Npm()
-  const exitHandler = require('../lib/utils/exit-handler.js')
   exitHandler.setNpm(npm)
 
   // if npm is called as "npmg" or "npm_g", then
@@ -26,16 +29,14 @@ module.exports = async process => {
     process.argv.splice(1, 1, 'npm', '-g')
   }
 
-  const replaceInfo = require('../lib/utils/replace-info.js')
+  const log = require('./utils/log-shim.js')
+  const replaceInfo = require('./utils/replace-info.js')
   log.verbose('cli', replaceInfo(process.argv))
 
   log.info('using', 'npm@%s', npm.version)
   log.info('using', 'node@%s', process.version)
 
-  process.on('uncaughtException', exitHandler)
-  process.on('unhandledRejection', exitHandler)
-
-  const updateNotifier = require('../lib/utils/update-notifier.js')
+  const updateNotifier = require('./utils/update-notifier.js')
 
   let cmd
   // now actually fire up npm and run the command.
@@ -63,7 +64,7 @@ module.exports = async process => {
     }
 
     await npm.exec(cmd, npm.argv)
-    exitHandler()
+    return exitHandler()
   } catch (err) {
     if (err.code === 'EUNKNOWNCOMMAND') {
       const didYouMean = require('./utils/did-you-mean.js')

diff --git a/lib/commands/adduser.js b/lib/commands/adduser.js
@@ -1,4 +1,4 @@
-const log = require('npmlog')
+const log = require('../utils/log-shim.js')
 const replaceInfo = require('../utils/replace-info.js')
 const BaseCommand = require('../base-command.js')
 const authTypes = {
@@ -31,6 +31,7 @@ class AddUser extends BaseCommand {
       creds,
       registry,
       scope,
+      log,
     })
 
     await this.updateConfig({

diff --git a/lib/commands/bin.js b/lib/commands/bin.js
@@ -10,6 +10,7 @@ class Bin extends BaseCommand {
     const b = this.npm.bin
     this.npm.output(b)
     if (this.npm.config.get('global') && !envPath.includes(b)) {
+      // XXX: does this need to be console?
       console.error('(not in PATH env variable)')
     }
   }

diff --git a/lib/commands/bugs.js b/lib/commands/bugs.js
@@ -1,5 +1,5 @@
-const log = require('npmlog')
 const pacote = require('pacote')
+const log = require('../utils/log-shim')
 const openUrl = require('../utils/open-url.js')
 const hostedFromMani = require('../utils/hosted-git-info-from-manifest.js')
 const BaseCommand = require('../base-command.js')

diff --git a/lib/commands/cache.js b/lib/commands/cache.js
@@ -1,6 +1,5 @@
 const cacache = require('cacache')
 const { promisify } = require('util')
-const log = require('npmlog')
 const pacote = require('pacote')
 const path = require('path')
 const rimraf = promisify(require('rimraf'))
@@ -9,6 +8,7 @@ const BaseCommand = require('../base-command.js')
 const npa = require('npm-package-arg')
 const jsonParse = require('json-parse-even-better-errors')
 const localeCompare = require('@isaacs/string-locale-compare')('en')
+const log = require('../utils/log-shim')
 
 const searchCachePackage = async (path, spec, cacheKeys) => {
   const parsed = npa(spec)
@@ -141,7 +141,7 @@ class Cache extends BaseCommand {
       try {
         entry = await cacache.get(cachePath, key)
       } catch (err) {
-        this.npm.log.warn(`Not Found: ${key}`)
+        log.warn(`Not Found: ${key}`)
         break
       }
       this.npm.output(`Deleted: ${key}`)

diff --git a/lib/commands/ci.js b/lib/commands/ci.js
@@ -5,8 +5,7 @@ const reifyFinish = require('../utils/reify-finish.js')
 const runScript = require('@npmcli/run-script')
 const fs = require('fs')
 const readdir = util.promisify(fs.readdir)
-
-const log = require('npmlog')
+const log = require('../utils/log-shim.js')
 
 const removeNodeModules = async where => {
   const rimrafOpts = { glob: false }
@@ -39,7 +38,7 @@ class CI extends ArboristWorkspaceCmd {
     const opts = {
       ...this.npm.flatOptions,
       path: where,
-      log: this.npm.log,
+      log,
       save: false, // npm ci should never modify the lockfile or package.json
       workspaces: this.workspaceNames,
     }

diff --git a/lib/commands/config.js b/lib/commands/config.js
@@ -11,6 +11,7 @@ const { spawn } = require('child_process')
 const { EOL } = require('os')
 const ini = require('ini')
 const localeCompare = require('@isaacs/string-locale-compare')('en')
+const log = require('../utils/log-shim.js')
 
 // take an array of `[key, value, k2=v2, k3, v3, ...]` and turn into
 // { key: value, k2: v2, k3: v3 }
@@ -87,12 +88,12 @@ class Config extends BaseCommand {
   }
 
   async execWorkspaces (args, filters) {
-    this.npm.log.warn('config', 'This command does not support workspaces.')
+    log.warn('config', 'This command does not support workspaces.')
     return this.exec(args)
   }
 
   async exec ([action, ...args]) {
-    this.npm.log.disableProgress()
+    log.disableProgress()
     try {
       switch (action) {
         case 'set':
@@ -117,7 +118,7 @@ class Config extends BaseCommand {
           throw this.usageError()
       }
     } finally {
-      this.npm.log.enableProgress()
+      log.enableProgress()
     }
   }
 
@@ -128,10 +129,10 @@ class Config extends BaseCommand {
 
     const where = this.npm.flatOptions.location
     for (const [key, val] of Object.entries(keyValues(args))) {
-      this.npm.log.info('config', 'set %j %j', key, val)
+      log.info('config', 'set %j %j', key, val)
       this.npm.config.set(key, val || '', where)
       if (!this.npm.config.validate(where)) {
-        this.npm.log.warn('config', 'omitting invalid config values')
+        log.warn('config', 'omitting invalid config values')
       }
     }
 

diff --git a/lib/commands/dedupe.js b/lib/commands/dedupe.js
@@ -1,6 +1,7 @@
 // dedupe duplicated packages, or find them in the tree
 const Arborist = require('@npmcli/arborist')
 const reifyFinish = require('../utils/reify-finish.js')
+const log = require('../utils/log-shim.js')
 
 const ArboristWorkspaceCmd = require('../arborist-cmd.js')
 
@@ -32,7 +33,7 @@ class Dedupe extends ArboristWorkspaceCmd {
     const where = this.npm.prefix
     const opts = {
       ...this.npm.flatOptions,
-      log: this.npm.log,
+      log,
       path: where,
       dryRun,
       workspaces: this.workspaceNames,

diff --git a/lib/commands/diff.js b/lib/commands/diff.js
@@ -1,13 +1,11 @@
 const { resolve } = require('path')
-
 const semver = require('semver')
 const libnpmdiff = require('libnpmdiff')
 const npa = require('npm-package-arg')
 const Arborist = require('@npmcli/arborist')
-const npmlog = require('npmlog')
 const pacote = require('pacote')
 const pickManifest = require('npm-pick-manifest')
-
+const log = require('../utils/log-shim')
 const readPackageName = require('../utils/read-package-name.js')
 const BaseCommand = require('../base-command.js')
 
@@ -57,7 +55,7 @@ class Diff extends BaseCommand {
     }
 
     const [a, b] = await this.retrieveSpecs(specs)
-    npmlog.info('diff', { src: a, dst: b })
+    log.info('diff', { src: a, dst: b })
 
     const res = await libnpmdiff([a, b], {
       ...this.npm.flatOptions,
@@ -83,7 +81,7 @@ class Diff extends BaseCommand {
     try {
       name = await readPackageName(this.prefix)
     } catch (e) {
-      npmlog.verbose('diff', 'could not read project dir package.json')
+      log.verbose('diff', 'could not read project dir package.json')
     }
 
     if (!name) {
@@ -116,7 +114,7 @@ class Diff extends BaseCommand {
     try {
       pkgName = await readPackageName(this.prefix)
     } catch (e) {
-      npmlog.verbose('diff', 'could not read project dir package.json')
+      log.verbose('diff', 'could not read project dir package.json')
       noPackageJson = true
     }
 
@@ -154,7 +152,7 @@ class Diff extends BaseCommand {
           actualTree.inventory.query('name', spec.name)
             .values().next().value
       } catch (e) {
-        npmlog.verbose('diff', 'failed to load actual install tree')
+        log.verbose('diff', 'failed to load actual install tree')
       }
 
       if (!node || !node.name || !node.package || !node.package.version) {
@@ -227,7 +225,7 @@ class Diff extends BaseCommand {
       try {
         pkgName = await readPackageName(this.prefix)
       } catch (e) {
-        npmlog.verbose('diff', 'could not read project dir package.json')
+        log.verbose('diff', 'could not read project dir package.json')
       }
 
       if (!pkgName) {
@@ -261,7 +259,7 @@ class Diff extends BaseCommand {
       const arb = new Arborist(opts)
       actualTree = await arb.loadActual(opts)
     } catch (e) {
-      npmlog.verbose('diff', 'failed to load actual install tree')
+      log.verbose('diff', 'failed to load actual install tree')
     }
 
     return specs.map(i => {

diff --git a/lib/commands/dist-tag.js b/lib/commands/dist-tag.js
@@ -1,8 +1,7 @@
-const log = require('npmlog')
 const npa = require('npm-package-arg')
 const regFetch = require('npm-registry-fetch')
 const semver = require('semver')
-
+const log = require('../utils/log-shim')
 const otplease = require('../utils/otplease.js')
 const readPackageName = require('../utils/read-package-name.js')
 const BaseCommand = require('../base-command.js')

diff --git a/lib/commands/docs.js b/lib/commands/docs.js
@@ -1,8 +1,7 @@
-const log = require('npmlog')
 const pacote = require('pacote')
 const openUrl = require('../utils/open-url.js')
 const hostedFromMani = require('../utils/hosted-git-info-from-manifest.js')
-
+const log = require('../utils/log-shim')
 const BaseCommand = require('../base-command.js')
 class Docs extends BaseCommand {
   static description = 'Open documentation for a package in a web browser'