feat!: output using proc-log

BREAKING CHANGE: The existing banner is now emitted using `proc-log`
instead of `console.log`.  It is always emitted. Consuming libraries can
decide under which situations to show the banner.

Author: wraithgar

README.md

@@ -57,8 +57,6 @@ runScript({
   // print the package id and script, and the command to be run, like:
   // > somepackage@1.2.3 postinstall
   // > make all-the-things
-  // Defaults true when stdio:'inherit', otherwise suppressed
-  banner: true,
 })
   .then(({ code, signal, stdout, stderr, pkgid, path, event, script }) => {
     // do something with the results
@@ -99,6 +97,11 @@ terminal, then it is up to the user to end it, of course.
 - `event` Lifecycle event being run
 - `script` Command being run
 
+If stdio is `inherit` this package will emit a banner with the package
+name and version, event name, and script command to be run, and send it
+to [`proc-log.output.standard`](https://npm.im/proc-log).  Consuming
+libraries can decide whether or not to display this.
+
 ### Options
 
 - `path` Required.  The path to the package having its script run.
@@ -124,10 +127,6 @@ terminal, then it is up to the user to end it, of course.
 - `stdioString` Optional, passed directly to `@npmcli/promise-spawn` which
   defaults it to `true`.  Return string values for `stderr` and `stdout` rather
   than Buffers.
-- `banner` Optional, defaults to `true`.  If the `stdio` option is set to
-  `'inherit'`, then print a banner with the package name and version, event
-  name, and script command to be run.  Set explicitly to `false` to disable
-  for inherited stdio.
 
 Note that this does _not_ run pre-event and post-event scripts.  The
 caller has to manage that process themselves.

lib/run-script-pkg.js

@@ -5,19 +5,6 @@ const { isNodeGypPackage, defaultGypInstallScript } = require('@npmcli/node-gyp'
 const signalManager = require('./signal-manager.js')
 const isServerPackage = require('./is-server-package.js')
 
-// you wouldn't like me when I'm angry...
-const bruce = (id, event, cmd, args) => {
-  let banner = id
-    ? `\n> ${id} ${event}\n`
-    : `\n> ${event}\n`
-  banner += `> ${cmd.trim().replace(/\n/g, '\n> ')}`
-  if (args.length) {
-    banner += ` ${args.join(' ')}`
-  }
-  banner += '\n'
-  return banner
-}
-
 const runScriptPkg = async options => {
   const {
     event,
@@ -29,8 +16,6 @@ const runScriptPkg = async options => {
     pkg,
     args = [],
     stdioString,
-    // note: only used when stdio:inherit
-    banner = true,
     // how long to wait for a process.kill signal
     // only exposed here so that we can make the test go a bit faster.
     signalTimeout = 500,
@@ -59,9 +44,20 @@ const runScriptPkg = async options => {
     return { code: 0, signal: null }
   }
 
-  if (stdio === 'inherit' && banner !== false) {
-    // we're dumping to the parent's stdout, so print the banner
-    console.log(bruce(pkg._id, event, cmd, args))
+  if (stdio === 'inherit') {
+    let banner
+    if (pkg._id) {
+      banner = `\n> ${pkg._id} ${event}\n`
+    } else {
+      banner = `\n> ${event}\n`
+    }
+    banner += `> ${cmd.trim().replace(/\n/g, '\n> ')}`
+    if (args.length) {
+      banner += ` ${args.join(' ')}`
+    }
+    banner += '\n'
+    const { output } = require('proc-log')
+    output.standard(banner)
   }
 
   const [spawnShell, spawnArgs, spawnOpts] = makeSpawnArgs({

test/run-script-pkg.js

@@ -6,18 +6,19 @@ const isWindows = process.platform === 'win32'
 const emptyDir = t.testdir({})
 
 const pkill = process.kill
-const consoleLog = console.log
 
-const mockConsole = t => {
-  const logs = []
-  console.log = (...args) => logs.push(args)
-  t.teardown(() => console.log = consoleLog)
-  return logs
+const output = []
+const appendOutput = (level, ...args) => {
+  if (level === 'standard') {
+    output.push([...args])
+  }
 }
+process.on('output', appendOutput)
+t.afterEach(() => output.length = 0)
+t.teardown(() => process.removeListener('output', appendOutput))
 
 t.test('run-script-pkg', async t => {
-  await t.test('do the banner when stdio is inherited, handle line breaks', async t => {
-    const logs = mockConsole(t)
+  await t.test('stdio inherit no args and a pkgid', async t => {
     spawk.spawn('sh', a => a.includes('bar\nbaz\n'))
     await runScript({
       event: 'foo',
@@ -33,34 +34,11 @@ t.test('run-script-pkg', async t => {
         scripts: {},
       },
     })
-    t.strictSame(logs, [['\n> foo@1.2.3 foo\n> bar\n> baz\n']])
+    t.strictSame(output, [['\n> foo@1.2.3 foo\n> bar\n> baz\n']])
     t.ok(spawk.done())
   })
 
-  await t.test('do not show banner when stdio is inherited, if suppressed', async t => {
-    const logs = mockConsole(t)
-    spawk.spawn('sh', a => a.includes('bar'))
-    await runScript({
-      event: 'foo',
-      path: emptyDir,
-      scriptShell: 'sh',
-      env: {
-        environ: 'value',
-      },
-      stdio: 'inherit',
-      cmd: 'bar',
-      pkg: {
-        _id: 'foo@1.2.3',
-        scripts: {},
-      },
-      banner: false,
-    })
-    t.strictSame(logs, [])
-    t.ok(spawk.done())
-  })
-
-  await t.test('do the banner with no pkgid', async t => {
-    const logs = mockConsole(t)
+  await t.test('stdio inherit args and no pkgid', async t => {
     spawk.spawn('sh', a => a.includes('bar baz buzz'))
     await runScript({
       event: 'foo',
@@ -76,12 +54,11 @@ t.test('run-script-pkg', async t => {
         scripts: {},
       },
     })
-    t.strictSame(logs, [['\n> foo\n> bar baz buzz\n']])
+    t.strictSame(output, [['\n> foo\n> bar baz buzz\n']])
     t.ok(spawk.done())
   })
 
-  await t.test('pkg has foo script', async t => {
-    const logs = mockConsole(t)
+  await t.test('pkg has foo script, with stdio pipe', async t => {
     spawk.spawn('sh', a => a.includes('bar'))
     await runScript({
       event: 'foo',
@@ -98,12 +75,11 @@ t.test('run-script-pkg', async t => {
         },
       },
     })
-    t.strictSame(logs, [])
+    t.strictSame(output, [])
     t.ok(spawk.done())
   })
 
-  await t.test('pkg has foo script, with args', async t => {
-    const logs = mockConsole(t)
+  await t.test('pkg has foo script, with stdio pipe and args', async t => {
     spawk.spawn('sh', a => a.includes('bar a b c'))
     await runScript({
       event: 'foo',
@@ -122,16 +98,16 @@ t.test('run-script-pkg', async t => {
       args: ['a', 'b', 'c'],
       binPaths: false,
     })
-    t.strictSame(logs, [])
+    t.strictSame(output, [])
     t.ok(spawk.done())
   })
 
-  await t.test('pkg has no install or preinstall script, node-gyp files present', async t => {
+  /* eslint-disable-next-line max-len */
+  await t.test('pkg has no install or preinstall script, node-gyp files present, stdio pipe', async t => {
     const testdir = t.testdir({
       'binding.gyp': 'exists',
     })
 
-    const logs = mockConsole(t)
     spawk.spawn('sh', a => a.includes('node-gyp rebuild'))
     await runScript({
       event: 'install',
@@ -146,11 +122,11 @@ t.test('run-script-pkg', async t => {
         scripts: {},
       },
     })
-    t.strictSame(logs, [])
+    t.strictSame(output, [])
     t.ok(spawk.done())
   })
 
-  t.test('pkg has no install or preinstall script, but gypfile:false', async t => {
+  t.test('pkg has no install or preinstall script, but gypfile:false, stdio pipe', async t => {
     const testdir = t.testdir({
       'binding.gyp': 'exists',
     })
@@ -170,6 +146,7 @@ t.test('run-script-pkg', async t => {
         },
       },
     })
+    t.strictSame(output, [])
     t.strictSame(res, { code: 0, signal: null })
   })
 
@@ -190,7 +167,7 @@ t.test('run-script-pkg', async t => {
     t.ok(interceptor.calledWith.stdio[0].writableEnded, 'stdin was ended properly')
   })
 
-  await t.test('kill process when foreground process ends with signal', async t => {
+  await t.test('kill process when foreground process ends with signal, stdio inherit', async t => {
     t.teardown(() => {
       process.kill = pkill
     })
@@ -219,14 +196,15 @@ t.test('run-script-pkg', async t => {
         },
       },
     }))
+    t.strictSame(output, [['\n> husky@1.2.3 sleep\n> sleep 1000000\n']])
     t.ok(spawk.done())
     if (!isWindows) {
       t.equal(signal, 'SIGFOO', 'process.kill got expected signal')
       t.equal(pid, process.pid, 'process.kill got expected pid')
     }
   })
 
-  await t.test('kill process when foreground process ends with signal', async t => {
+  await t.test('kill process when foreground process ends with signal, stdio inherit', async t => {
     t.teardown(() => {
       process.kill = pkill
     })
@@ -255,14 +233,15 @@ t.test('run-script-pkg', async t => {
         },
       },
     }))
+    t.strictSame(output, [['\n> husky@1.2.3 sleep\n> sleep 1000000\n']])
     t.ok(spawk.done())
     if (!isWindows) {
       t.equal(signal, 'SIGFOO', 'process.kill got expected signal')
       t.equal(pid, process.pid, 'process.kill got expected pid')
     }
   })
 
-  t.test('rejects if process.kill fails to end process', async t => {
+  t.test('rejects if process.kill fails to end process, stdio inherit', async t => {
     t.teardown(() => {
       process.kill = pkill
     })
@@ -290,6 +269,7 @@ t.test('run-script-pkg', async t => {
         },
       },
     }))
+    t.strictSame(output, [['\n> husky@1.2.3 sleep\n> sleep 1000000\n']])
     t.ok(spawk.done())
     if (!isWindows) {
       t.equal(signal, 'SIGFOO', 'process.kill got expected signal')
@@ -314,6 +294,7 @@ t.test('run-script-pkg', async t => {
         },
       },
     }))
+    t.strictSame(output, [])
     t.ok(spawk.done())
   })
 })