feat(arborist): refactor arborist bin to use consistent 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.

17 files changed, 490 insertions, 359 deletions

diff --git a/package-lock.json b/package-lock.json
index 69a9daa86..fec11a53f 100644
--- a/package-lock.json
+++ b/package-lock.json
@@ -10434,6 +10434,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": "^9.0.0",
         "npm-pick-manifest": "^7.0.0",
@@ -11353,6 +11354,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": "^9.0.0",
         "npm-pick-manifest": "^7.0.0",
diff --git a/workspaces/arborist/README.md b/workspaces/arborist/README.md
index 8722b7a43..ee79a3bf2 100644
--- a/workspaces/arborist/README.md
+++ b/workspaces/arborist/README.md
@@ -333,3 +333,13 @@ pruning nodes from the tree.
 
 Note: `devOptional` is only set in the shrinkwrap/package-lock file if
 _neither_ `dev` nor `optional` are set, as it would be redundant.
+
+## BIN
+
+Arborist ships with a cli that can be used to run arborist specific commands outside of the context of the npm CLI. This script is currently not part of the public API and is subject to breaking changes outside of major version bumps.
+
+To see the usage run:
+
+```
+npx @npmcli/arborist --help
+```
diff --git a/workspaces/arborist/bin/actual.js b/workspaces/arborist/bin/actual.js
index eb0495997..866b2cd82 100644
--- a/workspaces/arborist/bin/actual.js
+++ b/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}`
+  })
diff --git a/workspaces/arborist/bin/audit.js b/workspaces/arborist/bin/audit.js
index d9ac532d3..0e32833d4 100644
--- a/workspaces/arborist/bin/audit.js
+++ b/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}`
+    })
+}
diff --git a/workspaces/arborist/bin/funding.js b/workspaces/arborist/bin/funding.js
index d0f4f3165..cf25976d9 100644
--- a/workspaces/arborist/bin/funding.js
+++ b/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}`
+    })
+}
diff --git a/workspaces/arborist/bin/ideal.js b/workspaces/arborist/bin/ideal.js
index 5d1ed0dcd..1dd206e81 100644
--- a/workspaces/arborist/bin/ideal.js
+++ b/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}`
+  })
diff --git a/workspaces/arborist/bin/index.js b/workspaces/arborist/bin/index.js
index 5449a50e6..0c1e98445 100755
--- a/workspaces/arborist/bin/index.js
+++ b/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()
 }
diff --git a/workspaces/arborist/bin/lib/logging.js b/workspaces/arborist/bin/lib/logging.js
index 8183ece1f..8b04d6370 100644
--- a/workspaces/arborist/bin/lib/logging.js
+++ b/workspaces/arborist/bin/lib/logging.js
@@ -1,42 +1,78 @@
-const options = require('./options.js')
-const { quiet = false } = options
-const { loglevel = quiet ? 'warn' : 'silly' } = options
+const log = require('proc-log')
+const mkdirp = require('mkdirp')
+const fs = require('fs')
+const { dirname } = require('path')
+const os = require('os')
+const { inspect, format } = require('util')
+
+const { bin: options } = require('./options.js')
 
-const levels = [
+// add a meta method to proc-log for passing optional
+// metadata through to log handlers
+const META = Symbol('meta')
+const parseArgs = (...args) => {
+  const { [META]: isMeta } = args[args.length - 1] || {}
+  return isMeta
+    ? [args[args.length - 1], ...args.slice(0, args.length - 1)]
+    : [{}, ...args]
+}
+log.meta = (meta = {}) => ({ [META]: true, ...meta })
+
+const levels = new Map([
   'silly',
   'verbose',
   'info',
-  'timing',
   'http',
   'notice',
   'warn',
   'error',
   'silent',
-]
+].map((level, index) => [level, index]))
 
-const levelMap = new Map(levels.reduce((set, level, index) => {
-  set.push([level, index], [index, level])
-  return set
-}, []))
+const addLogListener = (write, { eol = os.EOL, loglevel = 'silly', colors = false } = {}) => {
+  const levelIndex = levels.get(loglevel)
 
-const { inspect, format } = require('util')
-const colors = process.stderr.isTTY
-const magenta = colors ? msg => `\x1B[35m${msg}\x1B[39m` : m => m
-if (loglevel !== 'silent') {
-  process.on('log', (level, ...args) => {
-    if (levelMap.get(level) < levelMap.get(loglevel)) {
-      return
+  const magenta = m => colors ? `\x1B[35m${m}\x1B[39m` : m
+  const dim = m => colors ? `\x1B[2m${m}\x1B[22m` : m
+  const red = m => colors ? `\x1B[31m${m}\x1B[39m` : m
+
+  const formatter = (level, ...args) => {
+    const depth = level === 'error' && args[0] && args[0].code === 'ERESOLVE' ? Infinity : 10
+
+    if (level === 'info' && args[0] === 'timeEnd') {
+      args[1] = dim(args[1])
+    } else if (level === 'error' && args[0] === 'timeError') {
+      args[1] = red(args[1])
     }
+
+    const messages = args.map(a => typeof a === 'string' ? a : inspect(a, { depth, colors }))
     const pref = `${process.pid} ${magenta(level)} `
-    if (level === 'warn' && args[0] === 'ERESOLVE') {
-      args[2] = inspect(args[2], { depth: 10, colors })
-    } else {
-      args = args.map(a => {
-        return typeof a === 'string' ? a
-          : inspect(a, { depth: 10, colors })
-      })
+
+    return pref + format(...messages).trim().split('\n').join(`${eol}${pref}`) + eol
+  }
+
+  process.on('log', (...args) => {
+    const [meta, level, ...logArgs] = parseArgs(...args)
+
+    if (levelIndex <= levels.get(level) || meta.force) {
+      write(formatter(level, ...logArgs))
     }
-    const msg = pref + format(...args).trim().split('\n').join(`\n${pref}`)
-    console.error(msg)
   })
 }
+
+if (options.loglevel !== 'silent') {
+  addLogListener((v) => process.stderr.write(v), {
+    eol: '\n',
+    colors: options.colors,
+    loglevel: options.loglevel,
+  })
+}
+
+if (options.logfile) {
+  log.silly('logfile', options.logfile)
+  mkdirp.sync(dirname(options.logfile))
+  const fd = fs.openSync(options.logfile, 'a')
+  addLogListener((str) => fs.writeSync(fd, str))
+}
+
+module.exports = log
diff --git a/workspaces/arborist/bin/lib/options.js b/workspaces/arborist/bin/lib/options.js
index 23e89ddce..8dbaf13da 100644
--- a/workspaces/arborist/bin/lib/options.js
+++ b/workspaces/arborist/bin/lib/options.js
@@ -1,59 +1,123 @@
-const options = module.exports = {
-  path: undefined,
-  cache: `${process.env.HOME}/.npm/_cacache`,
-  _: [],
+const nopt = require('nopt')
+const path = require('path')
+
+const has = (o, k) => Object.prototype.hasOwnProperty.call(o, k)
+
+const cleanPath = (val) => {
+  const k = Symbol('key')
+  const data = {}
+  nopt.typeDefs.path.validate(data, k, val)
+  return data[k]
 }
 
-for (const arg of process.argv.slice(2)) {
-  if (/^--add=/.test(arg)) {
-    options.add = options.add || []
-    options.add.push(arg.substr('--add='.length))
-  } else if (/^--rm=/.test(arg)) {
-    options.rm = options.rm || []
-    options.rm.push(arg.substr('--rm='.length))
-  } else if (arg === '--global') {
-    options.global = true
-  } else if (arg === '--global-style') {
-    options.globalStyle = true
-  } else if (arg === '--prefer-dedupe') {
-    options.preferDedupe = true
-  } else if (arg === '--legacy-peer-deps') {
-    options.legacyPeerDeps = true
-  } else if (arg === '--force') {
-    options.force = true
-  } else if (arg === '--update-all') {
-    options.update = options.update || {}
-    options.update.all = true
-  } else if (/^--update=/.test(arg)) {
-    options.update = options.update || {}
-    options.update.names = options.update.names || []
-    options.update.names.push(arg.substr('--update='.length))
-  } else if (/^--omit=/.test(arg)) {
-    options.omit = options.omit || []
-    options.omit.push(arg.substr('--omit='.length))
-  } else if (/^--before=/.test(arg)) {
-    options.before = new Date(arg.substr('--before='.length))
-  } else if (/^-w.+/.test(arg)) {
-    options.workspaces = options.workspaces || []
-    options.workspaces.push(arg.replace(/^-w/, ''))
-  } else if (/^--workspace=/.test(arg)) {
-    options.workspaces = options.workspaces || []
-    options.workspaces.push(arg.replace(/^--workspace=/, ''))
-  } else if (/^--[^=]+=/.test(arg)) {
-    const [key, ...v] = arg.replace(/^--/, '').split('=')
-    const val = v.join('=')
-    options[key] = val === 'false' ? false : val === 'true' ? true : val
-  } else if (/^--.+/.test(arg)) {
-    options[arg.replace(/^--/, '')] = true
-  } else if (options.path === undefined) {
-    options.path = arg
-  } else {
-    options._.push(arg)
+const parse = (...noptArgs) => {
+  const binOnlyOpts = {
+    command: String,
+    loglevel: String,
+    colors: Boolean,
+    timing: ['always', Boolean],
+    logfile: String,
+  }
+
+  const arbOpts = {
+    add: Array,
+    rm: Array,
+    omit: Array,
+    update: Array,
+    workspaces: Array,
+    global: Boolean,
+    force: Boolean,
+    'global-style': Boolean,
+    'prefer-dedupe': Boolean,
+    'legacy-peer-deps': Boolean,
+    'update-all': Boolean,
+    before: Date,
+    path: path,
+    cache: path,
+    ...binOnlyOpts,
+  }
+
+  const short = {
+    quiet: ['--loglevel', 'warn'],
+    logs: ['--logfile', 'true'],
+    w: '--workspaces',
+    g: '--global',
+    f: '--force',
+  }
+
+  const defaults = {
+    // key order is important for command and path
+    // since they shift positional args
+    // command is 1st, path is 2nd
+    command: (o) => o.argv.remain.shift(),
+    path: (o) => cleanPath(o.argv.remain.shift() || '.'),
+    colors: has(process.env, 'NO_COLOR') ? false : !!process.stderr.isTTY,
+    loglevel: 'silly',
+    timing: (o) => o.loglevel === 'silly',
+    cache: `${process.env.HOME}/.npm/_cacache`,
+  }
+
+  const derived = [
+    // making update either `all` or an array of names but not both
+    ({ updateAll: all, update: names, ...o }) => {
+      if (all || names) {
+        o.update = all != null ? { all } : { names }
+      }
+      return o
+    },
+    ({ logfile, ...o }) => {
+      // logfile is parsed as a string so if its true or set but empty
+      // then set the default logfile
+      if (logfile === 'true' || logfile === '') {
+        logfile = `arb-log-${new Date().toISOString().replace(/[.:]/g, '_')}.log`
+      }
+      // then parse it the same as nopt parses other paths
+      if (logfile) {
+        o.logfile = cleanPath(logfile)
+      }
+      return o
+    },
+  ]
+
+  const transforms = [
+    // Camelcase all top level keys
+    (o) => {
+      const entries = Object.entries(o).map(([k, v]) => [
+        k.replace(/-./g, s => s[1].toUpperCase()),
+        v,
+      ])
+      return Object.fromEntries(entries)
+    },
+    // Set defaults on unset keys
+    (o) => {
+      for (const [k, v] of Object.entries(defaults)) {
+        if (!has(o, k)) {
+          o[k] = typeof v === 'function' ? v(o) : v
+        }
+      }
+      return o
+    },
+    // Set/unset derived values
+    ...derived.map((derive) => (o) => derive(o) || o),
+    // Separate bin and arborist options
+    ({ argv: { remain: _ }, ...o }) => {
+      const bin = { _ }
+      for (const k of Object.keys(binOnlyOpts)) {
+        if (has(o, k)) {
+          bin[k] = o[k]
+          delete o[k]
+        }
+      }
+      return { bin, arb: o }
+    },
+  ]
+
+  let options = nopt(arbOpts, short, ...noptArgs)
+  for (const t of transforms) {
+    options = t(options)
   }
-}
 
-if (options.path === undefined) {
-  options.path = '.'
+  return options
 }
 
-console.error(options)
+module.exports = parse()
diff --git a/workspaces/arborist/bin/lib/print-tree.js b/workspaces/arborist/bin/lib/print-tree.js
index 1ea2a7218..55398190b 100644
--- a/workspaces/arborist/bin/lib/print-tree.js
+++ b/workspaces/arborist/bin/lib/print-tree.js
@@ -1,5 +1,4 @@
 const { inspect } = require('util')
-const { quiet } = require('./options.js')
+const log = require('./logging.js')
 
-module.exports = quiet ? () => {}
-  : tree => console.log(inspect(tree.toJSON(), { depth: Infinity }))
+module.exports = tree => log.info(inspect(tree.toJSON(), { depth: Infinity }))
diff --git a/workspaces/arborist/bin/lib/timers.js b/workspaces/arborist/bin/lib/timers.js
index 242431980..586dee780 100644
--- a/workspaces/arborist/bin/lib/timers.js
+++ b/workspaces/arborist/bin/lib/timers.js
@@ -1,31 +1,33 @@
-const timers = Object.create(null)
-const { format } = require('util')
-const options = require('./options.js')
+const { bin: options } = require('./options.js')
+const log = require('./logging.js')
+
+const timers = new Map()
+const finished = new Map()
 
 process.on('time', name => {
-  if (timers[name]) {
+  if (timers.has(name)) {
     throw new Error('conflicting timer! ' + name)
   }
-  timers[name] = process.hrtime()
+  timers.set(name, process.hrtime.bigint())
 })
 
-const dim = process.stderr.isTTY ? msg => `\x1B[2m${msg}\x1B[22m` : m => m
-const red = process.stderr.isTTY ? msg => `\x1B[31m${msg}\x1B[39m` : m => m
 process.on('timeEnd', name => {
-  if (!timers[name]) {
+  if (!timers.has(name)) {
     throw new Error('timer not started! ' + name)
   }
-  const res = process.hrtime(timers[name])
-  delete timers[name]
-  const msg = format(`${process.pid} ${name}`, res[0] * 1e3 + res[1] / 1e6)
-  if (options.timers !== false) {
-    console.error(dim(msg))
+  const elapsed = Number(process.hrtime.bigint() - timers.get(name))
+  timers.delete(name)
+  finished.set(name, elapsed)
+  if (options.timing) {
+    log.info('timeEnd', `${name} ${elapsed / 1e9}s`, log.meta({ force: options.timing === 'always' }))
   }
 })
 
 process.on('exit', () => {
-  for (const name of Object.keys(timers)) {
-    console.error(red('Dangling timer:'), name)
+  for (const name of timers.keys()) {
+    log.error('timeError', 'Dangling timer:', name)
     process.exitCode = 1
   }
 })
+
+module.exports = finished
diff --git a/workspaces/arborist/bin/license.js b/workspaces/arborist/bin/license.js
index af34fece6..77d579679 100644
--- a/workspaces/arborist/bin/license.js
+++ b/workspaces/arborist/bin/license.js
@@ -1,39 +1,48 @@
-const Arborist = require('../')
 const localeCompare = require('@isaacs/string-locale-compare')('en')
-const options = require('./lib/options.js')
-require('./lib/logging.js')
-require('./lib/timers.js')
+const Arborist = require('../')
+const log = require('./lib/logging.js')
 
-const a = new Arborist(options)
-const query = options._.shift()
+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)) {
+        throw 'load actual'
+      } else {
+        return tree
+      }
+    }).catch((er) => {
+      log.error('loading actual tree', er)
+      return a.loadActual()
+    })
+    .then(time)
+    .then(({ result: tree }) => {
+      const output = []
+      if (!query) {
+        const set = []
+        for (const license of tree.inventory.query('license')) {
+          set.push([tree.inventory.query('license', license).size, license])
+        }
 
-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)) {
-    throw 'load actual'
-  } else {
-    return tree
-  }
-}).catch((er) => {
-  console.error('loading actual tree', er)
-  return a.loadActual()
-}).then(tree => {
-  if (!query) {
-    const set = []
-    for (const license of tree.inventory.query('license')) {
-      set.push([tree.inventory.query('license', license).size, license])
-    }
+        for (const [count, license] of set.sort((a, b) =>
+          a[1] && b[1] ? b[0] - a[0] || localeCompare(a[1], b[1])
+          : a[1] ? -1
+          : b[1] ? 1
+          : 0)) {
+          output.push(`${count} ${license}`)
+          log.info(count, license)
+        }
+      } else {
+        for (const node of tree.inventory.query('license', query === 'undefined' ? undefined : query)) {
+          const msg = `${node.name} ${node.location} ${node.package.description || ''}`
+          output.push(msg)
+          log.info(msg)
+        }
+      }
 
-    for (const [count, license] of set.sort((a, b) =>
-      a[1] && b[1] ? b[0] - a[0] || localeCompare(a[1], b[1])
-      : a[1] ? -1
-      : b[1] ? 1
-      : 0)) {
-      console.log(count, license)
-    }
-  } else {
-    for (const node of tree.inventory.query('license', query === 'undefined' ? undefined : query)) {
-      console.log(`${node.name} ${node.location} ${node.package.description || ''}`)
-    }
-  }
-})
+      return output.join('\n')
+    })
+}
diff --git a/workspaces/arborist/bin/prune.js b/workspaces/arborist/bin/prune.js
index e11858c20..3c52bc13a 100644
--- a/workspaces/arborist/bin/prune.js
+++ b/workspaces/arborist/bin/prune.js
@@ -1,9 +1,7 @@
 const Arborist = require('../')
 
-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 log = require('./lib/logging.js')
 
 const printDiff = diff => {
   const { depth } = require('treeverse')
@@ -15,13 +13,13 @@ const printDiff = diff => {
       }
       switch (d.action) {
         case 'REMOVE':
-          console.error('REMOVE', d.actual.location)
+          log.info('REMOVE', d.actual.location)
           break
         case 'ADD':
-          console.error('ADD', d.ideal.location, d.ideal.resolved)
+          log.info('ADD', d.ideal.location, d.ideal.resolved)
           break
         case 'CHANGE':
-          console.error('CHANGE', d.actual.location, {
+          log.info('CHANGE', d.actual.location, {
             from: d.actual.resolved,
             to: d.ideal.resolved,
           })
@@ -32,18 +30,19 @@ const printDiff = diff => {
   })
 }
 
-const start = process.hrtime()
-process.emit('time', 'install')
-const arb = new Arborist(options)
-arb.prune(options).then(tree => {
-  process.emit('timeEnd', 'install')
-  const end = process.hrtime(start)
-  print(tree)
-  if (options.dryRun) {
-    printDiff(arb.diff)
-  }
-  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(require('util').inspect(er, { depth: Infinity })))
+module.exports = (options, time) => {
+  const arb = new Arborist(options)
+  return arb
+    .prune(options)
+    .then(time)
+    .then(async ({ timing, result: tree }) => {
+      printTree(tree)
+      if (options.dryRun) {
+        printDiff(arb.diff)
+      }
+      if (tree.meta && options.save) {
+        await tree.meta.save()
+      }
+      return `resolved ${tree.inventory.size} deps in ${timing.seconds}`
+    })
+}
diff --git a/workspaces/arborist/bin/reify.js b/workspaces/arborist/bin/reify.js
index 9dc26d2b9..3f3aafe8a 100644
--- a/workspaces/arborist/bin/reify.js
+++ b/workspaces/arborist/bin/reify.js
@@ -1,9 +1,7 @@
 const Arborist = require('../')
 
-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 log = require('./lib/logging.js')
 
 const printDiff = diff => {
   const { depth } = require('treeverse')
@@ -15,13 +13,13 @@ const printDiff = diff => {
       }
       switch (d.action) {
         case 'REMOVE':
-          console.error('REMOVE', d.actual.location)
+          log.info('REMOVE', d.actual.location)
           break
         case 'ADD':
-          console.error('ADD', d.ideal.location, d.ideal.resolved)
+          log.info('ADD', d.ideal.location, d.ideal.resolved)
           break
         case 'CHANGE':
-          console.error('CHANGE', d.actual.location, {
+          log.info('CHANGE', d.actual.location, {
             from: d.actual.resolved,
             to: d.ideal.resolved,
           })
@@ -32,18 +30,19 @@ const printDiff = diff => {
   })
 }
 
-const start = process.hrtime()
-process.emit('time', 'install')
-const arb = new Arborist(options)
-arb.reify(options).then(tree => {
-  process.emit('timeEnd', 'install')
-  const end = process.hrtime(start)
-  print(tree)
-  if (options.dryRun) {
-    printDiff(arb.diff)
-  }
-  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(require('util').inspect(er, { depth: Infinity })))
+module.exports = (options, time) => {
+  const arb = new Arborist(options)
+  return arb
+    .reify(options)
+    .then(time)
+    .then(async ({ timing, result: tree }) => {
+      printTree(tree)
+      if (options.dryRun) {
+        printDiff(arb.diff)
+      }
+      if (tree.meta && options.save) {
+        await tree.meta.save()
+      }
+      return `resolved ${tree.inventory.size} deps in ${timing.seconds}`
+    })
+}
diff --git a/workspaces/arborist/bin/shrinkwrap.js b/workspaces/arborist/bin/shrinkwrap.js
index b40416b7b..56603224e 100644
--- a/workspaces/arborist/bin/shrinkwrap.js
+++ b/workspaces/arborist/bin/shrinkwrap.js
@@ -1,12 +1,7 @@
 const Shrinkwrap = require('../lib/shrinkwrap.js')
-const options = require('./lib/options.js')
-require('./lib/logging.js')
-require('./lib/timers.js')
 
-const { quiet } = options
-Shrinkwrap.load(options)
-  .then(s => quiet || console.log(JSON.stringify(s.commit(), 0, 2)))
-  .catch(er => {
-    console.error('shrinkwrap load failure', er)
-    process.exit(1)
-  })
+module.exports = (options, time) => Shrinkwrap
+  .load(options)
+  .then((s) => s.commit())
+  .then(time)
+  .then(({ result: s }) => JSON.stringify(s, 0, 2))
diff --git a/workspaces/arborist/bin/virtual.js b/workspaces/arborist/bin/virtual.js
index 457c945e7..95b1de282 100644
--- a/workspaces/arborist/bin/virtual.js
+++ b/workspaces/arborist/bin/virtual.js
@@ -1,18 +1,14 @@
 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 printTree = require('./lib/print-tree.js')
 
-const start = process.hrtime()
-new Arborist(options).loadVirtual().then(tree => {
-  const end = process.hrtime(start)
-  if (!options.quiet) {
-    print(tree)
-  }
-  if (options.save) {
-    tree.meta.save()
-  }
-  console.error(`read ${tree.inventory.size} deps in ${end[0] * 1000 + end[1] / 1e6}ms`)
-}).catch(er => console.error(er))
+module.exports = (options, time) => new Arborist(options)
+  .loadVirtual()
+  .then(time)
+  .then(async ({ timing, result: tree }) => {
+    printTree(tree)
+    if (options.save) {
+      await tree.meta.save()
+    }
+    return `read ${tree.inventory.size} deps in ${timing.ms}`
+  })
diff --git a/workspaces/arborist/package.json b/workspaces/arborist/package.json
index 3864d55d9..d8d27bcfc 100644
--- a/workspaces/arborist/package.json
+++ b/workspaces/arborist/package.json
@@ -19,6 +19,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": "^9.0.0",
     "npm-pick-manifest": "^7.0.0",