Log script executions and exits

There have been a few reports from users who were concerned and
perplexed that their install scripts didn't seem to be run, looking at
the logs npm produces.  In fact, the install scripts WERE running, just
running quietly and successfully.

This logs the commands Arborist runs explicitly, along with exit code
and signal, so that it's more clear what ran when we look at the logs.

Close: #112

PR-URL: #123
Credit: @isaacs
Close: #123
Reviewed-by: @ruyadorno

lib/arborist/rebuild.js

@@ -184,14 +184,16 @@ module.exports = cls => class Builder extends cls {
         dev,
         devOptional,
         package: pkg,
+        location,
       } = node
 
       // skip any that we know we'll be deleting
       if (this[_trashList].has(path))
         return
 
-      const timer = `build:run:${event}:${node.location}`
+      const timer = `build:run:${event}:${location}`
       process.emit('time', timer)
+      this.log.info('run', pkg._id, event, location, pkg.scripts[event])
       const p = runScript({
         event,
         path,
@@ -208,11 +210,19 @@ module.exports = cls => class Builder extends cls {
             boolEnv(devOptional && !dev && !optional),
         },
         scriptShell: this[_scriptShell],
+      }).catch(er => {
+        const { code, signal } = er
+        this.log.info('run', pkg._id, event, {code, signal})
+        throw er
+      }).then(({code, signal}) => {
+        this.log.info('run', pkg._id, event, {code, signal})
       })
 
-      return (this[_doHandleOptionalFailure]
-        ? this[_handleOptionalFailure](node, p) : p)
-        .then(() => process.emit('timeEnd', timer))
+      await (this[_doHandleOptionalFailure]
+        ? this[_handleOptionalFailure](node, p)
+        : p)
+
+      process.emit('timeEnd', timer)
     }))
     process.emit('timeEnd', `build:run:${event}`)
   }

test/arborist/rebuild.js

@@ -22,6 +22,18 @@ t.test('setup explosive server', t => {
 const registry = `http://localhost:${PORT}`
 const newArb = opt => new Arborist({...opt, registry})
 
+// track the logs that are emitted.  returns a function that removes
+// the listener and provides the list of what it saw.
+const logTracker = () => {
+  const list = []
+  const onlog = (...msg) => list.push(msg)
+  process.on('log', onlog)
+  return () => {
+    process.removeListener('log', onlog)
+    return list
+  }
+}
+
 t.test('rebuild bin links for all nodes if no nodes specified', async t => {
   const path = fixture(t, 'dep-installed-without-bin-link')
   const semver = resolve(path, 'node_modules/.bin/semver')
@@ -150,6 +162,7 @@ t.test('dont blow up if package.json is borked', async t => {
 
 t.test('verify dep flags in script environments', async t => {
   const path = fixture(t, 'testing-rebuild-script-env-flags')
+  const checkLogs = logTracker()
 
   const expect = {
     devdep: ['npm_package_dev'],
@@ -166,4 +179,43 @@ t.test('verify dep flags in script environments', async t => {
     const file = resolve(path, 'node_modules', pkg, 'env')
     t.strictSame(flags, fs.readFileSync(file, 'utf8').split('\n'), pkg)
   }
+  t.strictSame(checkLogs().sort((a, b) =>
+    a[2].localeCompare(b[2]) || (typeof a[4] === 'string' ? -1 : 1)), [
+    ['info','run','[email protected]','postinstall','node_modules/devdep','node ../../env.js'],
+    ['info','run','[email protected]','postinstall',{code: 0, signal: null}],
+    ['info','run','[email protected]','postinstall','node_modules/devopt','node ../../env.js'],
+    ['info','run','[email protected]','postinstall',{code: 0, signal: null}],
+    ['info','run','[email protected]','postinstall','node_modules/opt-and-dev','node ../../env.js'],
+    ['info','run','[email protected]','postinstall',{code: 0, signal: null}],
+    ['info','run','[email protected]','postinstall','node_modules/optdep','node ../../env.js'],
+    ['info','run','[email protected]','postinstall',{code: 0, signal: null}],
+  ], 'logged script executions at info level')
+})
+
+t.test('log failed exit codes as well, even if we dont crash', async t => {
+  const path = t.testdir({
+    'package.json': JSON.stringify({
+      optionalDependencies: { optdep: '1' },
+    }),
+    node_modules: {
+      optdep: {
+        'package.json': JSON.stringify({
+          name: 'optdep',
+          version: '1.2.3',
+          scripts: {
+            preinstall: 'exit 1',
+          },
+        }),
+      }
+    }
+  })
+  const arb = new Arborist({path})
+  const checkLogs = logTracker()
+  await arb.rebuild({ handleOptionalFailure: true })
+  t.strictSame(checkLogs(), [
+    ['info', 'run', '[email protected]', 'preinstall', 'node_modules/optdep', 'exit 1'],
+    ['info', 'run', '[email protected]', 'preinstall', { code: 1, signal: null }],
+    ['verbose', 'reify', 'failed optional dependency', resolve(path, 'node_modules/optdep')],
+    ['silly', 'reify', 'mark', 'deleted', [resolve(path, 'node_modules/optdep')]]
+  ])
 })