feat(arborist): refactor arborist bin to use consisten timing/logging

This attempts to make the arborist bin script behave more like the npm
cli with regards to the handing of timing and logging.

It also adds the a `logfile` argument to write logs to a file instead of
(or in addition to) stderr. This can be helpful for benchmarking
performance of loggins or terminal display.

package-lock.json

@@ -10544,6 +10544,7 @@
         "json-stringify-nice": "^1.1.4",
         "mkdirp": "^1.0.4",
         "mkdirp-infer-owner": "^2.0.0",
+        "nopt": "^5.0.0",
         "npm-install-checks": "^4.0.0",
         "npm-package-arg": "^8.1.5",
         "npm-pick-manifest": "^6.1.0",
@@ -11460,6 +11461,7 @@
         "mkdirp": "^1.0.4",
         "mkdirp-infer-owner": "^2.0.0",
         "nock": "^13.2.0",
+        "nopt": "^5.0.0",
         "npm-install-checks": "^4.0.0",
         "npm-package-arg": "^8.1.5",
         "npm-pick-manifest": "^6.1.0",

workspaces/arborist/bin/actual.js

@@ -1,23 +1,19 @@
 const Arborist = require('../')
-const print = require('./lib/print-tree.js')
-const options = require('./lib/options.js')
-require('./lib/logging.js')
-require('./lib/timers.js')
 
-const start = process.hrtime()
-new Arborist(options).loadActual(options).then(tree => {
-  const end = process.hrtime(start)
-  if (!process.argv.includes('--quiet')) {
-    print(tree)
-  }
+const printTree = require('./lib/print-tree.js')
 
-  console.error(`read ${tree.inventory.size} deps in ${end[0] * 1000 + end[1] / 1e6}ms`)
-  if (options.save) {
-    tree.meta.save()
-  }
-  if (options.saveHidden) {
-    tree.meta.hiddenLockfile = true
-    tree.meta.filename = options.path + '/node_modules/.package-lock.json'
-    tree.meta.save()
-  }
-}).catch(er => console.error(er))
+module.exports = (options, time) => new Arborist(options)
+  .loadActual(options)
+  .then(time)
+  .then(async ({ timing, result: tree }) => {
+    printTree(tree)
+    if (options.save) {
+      await tree.meta.save()
+    }
+    if (options.saveHidden) {
+      tree.meta.hiddenLockfile = true
+      tree.meta.filename = options.path + '/node_modules/.package-lock.json'
+      await tree.meta.save()
+    }
+    return `read ${tree.inventory.size} deps in ${timing.ms}`
+  })

workspaces/arborist/bin/audit.js

@@ -1,19 +1,17 @@
 const Arborist = require('../')
 
-const print = require('./lib/print-tree.js')
-const options = require('./lib/options.js')
-require('./lib/timers.js')
-require('./lib/logging.js')
+const printTree = require('./lib/print-tree.js')
+const log = require('./lib/logging.js')
 
 const Vuln = require('../lib/vuln.js')
 const printReport = report => {
   for (const vuln of report.values()) {
-    console.log(printVuln(vuln))
+    log.info(printVuln(vuln))
   }
   if (report.topVulns.size) {
-    console.log('\n# top-level vulnerabilities')
+    log.info('\n# top-level vulnerabilities')
     for (const vuln of report.topVulns.values()) {
-      console.log(printVuln(vuln))
+      log.info(printVuln(vuln))
     }
   }
 }
@@ -33,22 +31,21 @@ const printVuln = vuln => {
 
 const printAdvisory = a => `${a.title}${a.url ? ' ' + a.url : ''}`
 
-const start = process.hrtime()
-process.emit('time', 'audit script')
-const arb = new Arborist(options)
-arb.audit(options).then(tree => {
-  process.emit('timeEnd', 'audit script')
-  const end = process.hrtime(start)
-  if (options.fix) {
-    print(tree)
-  }
-  if (!options.quiet) {
-    printReport(arb.auditReport)
-  }
-  if (options.fix) {
-    console.error(`resolved ${tree.inventory.size} deps in ${end[0] + end[1] / 1e9}s`)
-  }
-  if (tree.meta && options.save) {
-    tree.meta.save()
-  }
-}).catch(er => console.error(er))
+module.exports = (options, time) => {
+  const arb = new Arborist(options)
+  return arb
+    .audit(options)
+    .then(time)
+    .then(async ({ timing, result: tree }) => {
+      if (options.fix) {
+        printTree(tree)
+      }
+      printReport(arb.auditReport)
+      if (tree.meta && options.save) {
+        await tree.meta.save()
+      }
+      return options.fix
+        ? `resolved ${tree.inventory.size} deps in ${timing.seconds}`
+        : `done in ${timing.seconds}`
+    })
+}

workspaces/arborist/bin/funding.js

@@ -1,34 +1,38 @@
-const options = require('./lib/options.js')
-require('./lib/logging.js')
-require('./lib/timers.js')
-
 const Arborist = require('../')
-const a = new Arborist(options)
-const query = options._.shift()
-const start = process.hrtime()
-a.loadVirtual().then(tree => {
-  // only load the actual tree if the virtual one doesn't have modern metadata
-  if (!tree.meta || !(tree.meta.originalLockfileVersion >= 2)) {
-    console.error('old metadata, load actual')
-    throw 'load actual'
-  } else {
-    console.error('meta ok, return virtual tree')
-    return tree
-  }
-}).catch(() => a.loadActual()).then(tree => {
-  const end = process.hrtime(start)
-  if (!query) {
-    for (const node of tree.inventory.values()) {
-      if (node.package.funding) {
-        console.log(node.name, node.location, node.package.funding)
+
+const log = require('./lib/logging.js')
+
+module.exports = (options, time) => {
+  const query = options._.shift()
+  const a = new Arborist(options)
+  return a
+    .loadVirtual()
+    .then(tree => {
+      // only load the actual tree if the virtual one doesn't have modern metadata
+      if (!tree.meta || !(tree.meta.originalLockfileVersion >= 2)) {
+        log.error('old metadata, load actual')
+        throw 'load actual'
+      } else {
+        log.error('meta ok, return virtual tree')
+        return tree
       }
-    }
-  } else {
-    for (const node of tree.inventory.query('name', query)) {
-      if (node.package.funding) {
-        console.log(node.name, node.location, node.package.funding)
+    })
+    .catch(() => a.loadActual())
+    .then(time)
+    .then(({ timing, result: tree }) => {
+      if (!query) {
+        for (const node of tree.inventory.values()) {
+          if (node.package.funding) {
+            log.info(node.name, node.location, node.package.funding)
+          }
+        }
+      } else {
+        for (const node of tree.inventory.query('name', query)) {
+          if (node.package.funding) {
+            log.info(node.name, node.location, node.package.funding)
+          }
+        }
       }
-    }
-  }
-  console.error(`read ${tree.inventory.size} deps in ${end[0] * 1000 + end[1] / 1e6}ms`)
-})
+      return `read ${tree.inventory.size} deps in ${timing.ms}`
+    })
+}

workspaces/arborist/bin/ideal.js

@@ -1,21 +1,14 @@
 const Arborist = require('../')
 
-const { inspect } = require('util')
-const options = require('./lib/options.js')
-const print = require('./lib/print-tree.js')
-require('./lib/logging.js')
-require('./lib/timers.js')
+const printTree = require('./lib/print-tree.js')
 
-const start = process.hrtime()
-new Arborist(options).buildIdealTree(options).then(tree => {
-  const end = process.hrtime(start)
-  print(tree)
-  console.error(`resolved ${tree.inventory.size} deps in ${end[0] + end[1] / 10e9}s`)
-  if (tree.meta && options.save) {
-    tree.meta.save()
-  }
-}).catch(er => {
-  const opt = { depth: Infinity, color: true }
-  console.error(er.code === 'ERESOLVE' ? inspect(er, opt) : er)
-  process.exitCode = 1
-})
+module.exports = (options, time) => new Arborist(options)
+  .buildIdealTree(options)
+  .then(time)
+  .then(async ({ timing, result: tree }) => {
+    printTree(tree)
+    if (tree.meta && options.save) {
+      await tree.meta.save()
+    }
+    return `resolved ${tree.inventory.size} deps in ${timing.seconds}`
+  })

workspaces/arborist/bin/index.js

@@ -1,81 +1,110 @@
 #!/usr/bin/env node
-const [cmd] = process.argv.splice(2, 1)
 
-const usage = () => `Arborist - the npm tree doctor
+const fs = require('fs')
+const path = require('path')
 
-Version: ${require('../package.json').version}
+const { bin, arb: options } = require('./lib/options')
+const version = require('../package.json').version
 
+const usage = (message = '') => `Arborist - the npm tree doctor
+
+Version: ${version}
+${message && '\n' + message + '\n'}
 # USAGE
   arborist <cmd> [path] [options...]
 
 # COMMANDS
 
-* reify: reify ideal tree to node_modules (install, update, rm, ...)
-* prune: prune the ideal tree and reify (like npm prune)
-* ideal: generate and print the ideal tree
-* actual: read and print the actual tree in node_modules
-* virtual: read and print the virtual tree in the local shrinkwrap file
-* shrinkwrap: load a local shrinkwrap and print its data
-* audit: perform a security audit on project dependencies
-* funding: query funding information in the local package tree.  A second
-  positional argument after the path name can limit to a package name.
-* license: query license information in the local package tree.  A second
-  positional argument after the path name can limit to a license type.
-* help: print this text
+  * reify: reify ideal tree to node_modules (install, update, rm, ...)
+  * prune: prune the ideal tree and reify (like npm prune)
+  * ideal: generate and print the ideal tree
+  * actual: read and print the actual tree in node_modules
+  * virtual: read and print the virtual tree in the local shrinkwrap file
+  * shrinkwrap: load a local shrinkwrap and print its data
+  * audit: perform a security audit on project dependencies
+  * funding: query funding information in the local package tree.  A second
+    positional argument after the path name can limit to a package name.
+  * license: query license information in the local package tree.  A second
+    positional argument after the path name can limit to a license type.
+  * help: print this text
+  * version: print the version
 
 # OPTIONS
 
-Most npm options are supported, but in camelCase rather than css-case.  For
-example, instead of '--dry-run', use '--dryRun'.
+  Most npm options are supported, but in camelCase rather than css-case.  For
+  example, instead of '--dry-run', use '--dryRun'.
 
-Additionally:
+  Additionally:
 
-* --quiet will supppress the printing of package trees
-* Instead of 'npm install <pkg>', use 'arborist reify --add=<pkg>'.
-  The '--add=<pkg>' option can be specified multiple times.
-* Instead of 'npm rm <pkg>', use 'arborist reify --rm=<pkg>'.
-  The '--rm=<pkg>' option can be specified multiple times.
-* Instead of 'npm update', use 'arborist reify --update-all'.
-* 'npm audit fix' is 'arborist audit --fix'
+  * --loglevel=warn|--quiet will supppress the printing of package trees
+  * --logfile <file|bool> will output logs to a file
+  * --timing will show timing information
+  * Instead of 'npm install <pkg>', use 'arborist reify --add=<pkg>'.
+    The '--add=<pkg>' option can be specified multiple times.
+  * Instead of 'npm rm <pkg>', use 'arborist reify --rm=<pkg>'.
+    The '--rm=<pkg>' option can be specified multiple times.
+  * Instead of 'npm update', use 'arborist reify --update-all'.
+  * 'npm audit fix' is 'arborist audit --fix'
 `
 
-const help = () => console.log(usage())
-
-switch (cmd) {
-  case 'actual':
-    require('./actual.js')
-    break
-  case 'virtual':
-    require('./virtual.js')
-    break
-  case 'ideal':
-    require('./ideal.js')
-    break
-  case 'prune':
-    require('./prune.js')
-    break
-  case 'reify':
-    require('./reify.js')
-    break
-  case 'audit':
-    require('./audit.js')
-    break
-  case 'funding':
-    require('./funding.js')
-    break
-  case 'license':
-    require('./license.js')
-    break
-  case 'shrinkwrap':
-    require('./shrinkwrap.js')
-    break
-  case 'help':
-  case '-h':
-  case '--help':
-    help()
-    break
-  default:
+const commands = {
+  version: () => console.log(version),
+  help: () => console.log(usage()),
+  exit: () => {
     process.exitCode = 1
-    console.error(usage())
-    break
+    console.error(
+      usage(`Error: command '${bin.command}' does not exist.`)
+    )
+  },
+}
+
+const commandFiles = fs.readdirSync(__dirname).filter((f) => path.extname(f) === '.js' && f !== __filename)
+
+for (const file of commandFiles) {
+  const command = require(`./${file}`)
+  const name = path.basename(file, '.js')
+  const totalTime = `bin:${name}:init`
+  const scriptTime = `bin:${name}:script`
+
+  commands[name] = () => {
+    const timers = require('./lib/timers')
+    const log = require('./lib/logging')
+
+    log.info(name, options)
+
+    process.emit('time', totalTime)
+    process.emit('time', scriptTime)
+
+    return command(options, (result) => {
+      process.emit('timeEnd', scriptTime)
+      return {
+        result,
+        timing: {
+          seconds: `${timers.get(scriptTime) / 1e9}s`,
+          ms: `${timers.get(scriptTime) / 1e6}ms`,
+        },
+      }
+    })
+      .then((result) => {
+        log.info(result)
+        return result
+      })
+      .catch((err) => {
+        process.exitCode = 1
+        log.error(err)
+        return err
+      })
+      .then((r) => {
+        process.emit('timeEnd', totalTime)
+        if (bin.loglevel !== 'silent') {
+          console[process.exitCode ? 'error' : 'log'](r)
+        }
+      })
+  }
+}
+
+if (commands[bin.command]) {
+  commands[bin.command]()
+} else {
+  commands.exit()
 }