gyp: send spawned output to logger

[cinderblock]

Checklist

• npm install && npm test passes
• tests are included
• documentation is changed or added
• commit message follows commit guidelines

Description of change

As discussed in #532, might be nice to allow capturing of spawned output. This is my first stab at an implementation. Seems to work so far as I've tested.

[rvagg]

can we see a screenshot of what this looks line in action?

[rvagg]

This is probably OK but it's nice to make a habit of avoiding using 'data' events so you can set up proper backpressure (not really a requirement here because npmlog doesn't give us a mechanism for it), usually done by implementing a custom stream.

maybe something like this

const { Transform } = require('stream')

...

function outLogger (prefix, log) {
  return new Transform({
    transform: (chunk, enc, callback) {
      log(prefix, chunk.toString())
      callback()
    }
  })
}

cp.stdout.pipe(split()).pipe(outLogger('spawn stdout', log.notice)) // does it need to be `log.notice.bind(log)`?
cp.stderr.pipe(split()).pipe(outLogger('spawn stderr', log.error))

[cinderblock]

Hmmm. I was wondering why you were suggesting this route in the original issue. I hadn't heard of a reason to not just use the data event. I didn't see an advantage to using a Transform stream but makes sense.

To be clear, this is the data event from split() and not from stdout/stderr.

I wonder if there are any possible improvements from using a Writable stream instead of a Transform since there is no data coming out of the logger (as far as the stream api is concerned).

[TooTallNate]

One problem that I see with this is that the subprocess loses the "TTY-ness" which many programs use to determine whether or not to out put output colors to the terminal.

[cinderblock]

@TooTallNate This seems like a reason to add an "opt-in" option.

[rvagg]

Labeleling this semver-major for now, we can discuss if anyone disagrees or if this evolves in a different direction. For now I'm leaning on the assumption that there are use-cases in existence that parse output to look for certain things and that by changing the loglevel at which they show up might break that.

[richardlau]

Labeleling this semver-major for now, we can discuss if anyone disagrees or if this evolves in a different direction. For now I'm leaning on the assumption that there are use-cases in existence that parse output to look for certain things and that by changing the loglevel at which they show up might break that.

If I understand the code correctly the current code doesn't log the output from spawned processes at any loglevel (which is probably why errors from make don't show up in the npm-debug.log files) and this PR changes it so the output will now be in the logs. It's definitely at least semver-minor -- I've no objections with semver-major for now.

[cinderblock]

@rvagg Has node-gyp made any guarantees to the outside world about what is printed? If the world is using undocumented behaviors, and those undocumented behaviors change, I don't think that necessitates a major semver change.

Alternatively, instead of prefixing spawned outputs with spawn stdxxx, they could be passed on unmodified. Those using default configurations would still get the same outputs. People using loglevel would be the only ones affected. However they are the ones that would be more likely to have custom parsing of this output...

An extra option could be added to opt into this capturing of spawned output making it completely non-api changing.

@richardlau The current code just passes the spawned IO to node-gyp's IO files. [0, 1, 2] is equivalent to stdin, stdout, and stderr.

This just made me think of one other breaking change in what I'm currently proposing:
stdin file from make is no longer piped. While I'm not aware of anyone using stdin during a build script, technically it's possible to prompt for user input and this change, as is, breaks that. Do we want to keep support for that?

[rvagg]

@cinderblock there are not written guarantees but output tends to be treated as an API and with the massive deployment base of node-gyp we need to be a bit sensitive to such things because they break in surprising ways. We've learnt this the hard way with Node.js itself.

Maybe the best way to deal with this, and the comment about stdout losing its TTY status is to add this as an opt-in and then we could consider making it opt-out in the future, more gentle and a good way to experiment. Opt-in via environment variable might be a good start, and that can be inherited from npm too so an npm config set can work on this.

[cinderblock]

I understand the implications of many people using such a big package. That's why it needs to be opt-in.

I'll take a stab at improving the PR to make it opt in.

The opt-in option name should probably include verbiage to indicate the stricter operating environment (no stdin), buffered stdout. Maybe captured-streams or strict-io-streams? Would love input here.

[rvagg]

--log-stdio, NODE_GYP_LOG_STDIO=true, npm config set node_gyp_log_stdio true ?