Streams Regression in v4.x

[MylesBorins]

We landed nodejs/node#6023 to fix nodejs/node#5820

This has created a regression that has had two different issues opened

nodejs/node#7159
nodejs/node#7278

There is a potential fix, but it has not yet lived in a release, and may not covered one of the edge cases mentioned in nodejs/node#7278

I think that it might be wise to revert nodejs/node#6023 in the next release.

[addaleax]

It might be worth noting that nodejs/node#7278 is distinct (although not unrelated) from nodejs/node#7159, will need its own bugfix and also existed in all Node.js versions prior to 4.2.0.

[addaleax]

As promised, a bit of writeup of the issues/PRs involved in this situation, as a general overview and also for myself to keep track of things (sorry if it’s a bit messy/unreadable/overlong, I’m tired and going to sleep now. 😄):

awaitDrain background

When using pipes in Node, there is a mechanism for handling backpressure: When one of the destination streams has a buffer that currently exceeds its highWaterMark, e.g. because it consumes the data slower than it is being produced, calling .write() on it will return false. Once this buffer is emptied and all data has been consumed in the destination stream, the 'drain' event is emitted.

The readable stream (where pipe is implemented) acts upon such a false write response by increasing a counter, awaitDrain, that represents the number of piping destinations that currently have full buffers. Once a 'drain' event on any of the pipes is emitted, this counter is decreased again, and once it hits 0, data is written to the destination streams again.

This should imply that 0 <= awaitDrain <= pipesCount always holds (it currently does not).

It also means that occasionally underestimating awaitDrain is unproblematic and only affects performance – if piping is continued too early, the destination streams will indicate having full buffers and the readable stream is paused again.

Issues/PRs Group 1

• Issue Redirecting from socket hangs with large data node#2323: When .unpipe() was called during a .write() call to the destination stream, which also returned false due to an exceeded highWaterMark, the awaitDrain counter was increased, but would never be decreased again because the .unpipe() call removed the 'drain' listener.

• PR stream: avoid pause with unpipe in buffered write node#2325 (included in v4.2.0): While this PR was supposed to fix Redirecting from socket hangs with large data node#2323 (it kind of did), it inadvertently disabled the awaitDrain mechanism altogether, as it put awaitDrain++ inside what was effectively if (false) { ... }. (Edit for clarification: This is basically only a problem when piping to multiple destinations, as the call to src.pause() was unaffected.)

  The broken backpressure handling support was only caught by tests in test/pummel and thus was not detected by the CI runs.

• Issues test pummel/test-stream2-basic.js failing since v4.2.0 node#5257, Piping readable stream to multiple writeable streams results in crash node#5820, Pipe to multiple writable streams doesn't throttle and may blow the memory (v4) node#6491: Reports of the broken backpressure support, both for the broken pummel test and the case of a slow and a fast piping destination getting so far out of sync that the accumulated Buffer of the slower destination stream exceeded memory allocations limits.

• PR stream: Fix readableState.awaitDrain mechanism node#6023 (included in v4.4.5): Fixed the changes from stream: avoid pause with unpipe in buffered write node#2325 in the way they seemed to have been intended. This largely re-instantiated the awaitDrain mechanism in the way it worked before stream: avoid pause with unpipe in buffered write node#2325.

Issues/PRs Group 2

• Issue Child process/streams memory leak node#4049: Child processes for which some of the output data has been consumed would not be garbage collected, because more output data would be available.

• PR child_process.flushStdio: resume _consuming streams node#4071 (included in v4.2.5): A solution for Child process/streams memory leak node#4049 that worked by calling .resume() on the stdio streams after the process finished (which was already done in some situations, but not when some data had already been read using .read()).

  This would have interfered with the backpressure handling mechanism in some cases, but since that did not work at the time, no problems showed up.

• Issues 'close' event for spawn() isn't emitted under unknown conditions node#7159, child-process: data loss with piped stdout node#7184: The .resume() call introduced in child_process.flushStdio: resume _consuming streams node#4071 was leading to trouble now that stream: Fix readableState.awaitDrain mechanism node#6023 had landed in releases: When a slow consumer of a processes standard output (e.g. a zlib stream) would indicate that its buffer was full, the awaitDrain was increased by one. However, the manual .resume() lead to the pipe passing data along again, with the result that a second call to .write() would also return false and awaitDrain would be increased again. Since awaitDrain was 2 now, no 'drain' event would have been able to decrease it back to zero and thus the pipe got permanently stuck, leading to data loss.

• PR stream: reset awaitDrain after manual .resume() node#7160 (landed, not released yet v6.2.2): Fixes 'close' event for spawn() isn't emitted under unknown conditions node#7159 by resetting awaitDrain to 0 in .resume(). If some of the following .write()s to destinations would return false, the value of awaitDrain would become correct again. The broken previous behaviour existed since 0.12.

• PR Fix child process stdio data loss with slow piped consumers node#7185 (closed): Alternative fix for 'close' event for spawn() isn't emitted under unknown conditions node#7159 that solves the problem at the child_process level by not calling .resume() on any stdio readable streams that are using pipes.

• PR Add two child-process stdio flush tests node#7257: Add a test for 'close' event for spawn() isn't emitted under unknown conditions node#7159 on the child_process level, extracted from Fix child process stdio data loss with slow piped consumers node#7185.

  It’s very likely unrelated to the rest of the issues here, but it also includes a fix for the test case from child_process: fix data loss with readable event node#5036 that did not test what it was supposed to test anymore, as unix: delay signal handling until after normal i/o libuv/libuv#611 changed the timing for some child_process stdio-related stream events.

Issues/PRs Group 3

• Issue Change in stream behaviour in Node 4.4.5 node#7278: Making more data on the source stream of a pipe using .push() during a write to the destination stream could also lead to stalling the pipe, with similar effect as the 'close' event for spawn() isn't emitted under unknown conditions node#7159 bug. Multiple recursive calls to dest.write() could return false and thus increase awaitDrain multiple times for a single destination stream.

  This behaviour also existed since 0.12, but would also not show up from 4.2.0 to 4.4.5.

  stream: reset awaitDrain after manual .resume() node#7160 would also fix this in a specific case because .pipe() schedules a resume using process.nextTick(), and thus could unclog the pipe once by over-eagerly resetting the awaitDrain counter to 0 instead of 1. In general, however, this bug needs its own fix.

• PR stream: only increase awaitDrain once for each pipe destination node#7292 (landed, not released yet v6.2.2): A proposed solution to Change in stream behaviour in Node 4.4.5 node#7278 that seeks to identify recursive calls to dest.write() and increase awaitDrain at most once for such a set of calls.

[rvagg]

Beautifully illustrates the problems we have with Streams in core, an endless game of wac-a-mole where most people eventually decide that it's too risky to touch anything so stay right away from it.

tbh I can't spare enough brain space to get fully around this issue to express much of an opinion on the best way forward: wait, backport, revert — each of these has risks so someone has to make a call on which is the least risky path. I would prefer if @addaleax and @thealphanerd could come up with a shared perspective on an appropriate path forward for LTS and tell the rest of us what to think!

[mcollina]

A couple of notes:

1. we should do a full post-mortem on this, and put failsafes in place to avoid this in the future
2. the situation is really complex, and I agree we should do nothing until we agree on a course of action
3. the bug stream: only increase awaitDrain once for each pipe destination node#7292 is "fixed" from [email protected] to [email protected], where 2.0.3 and 2.1.3 are broken.

The situation is actually made worse by readable-stream, we should push out a release there soon (we can even test there). We should use that to test this, I'll look for a module that was broken by this.

[addaleax]

The fixes for the bugs listed here have lived in 6.2.2 for almost a week, and I’d feel comfortable seeing them included in one of the next v4 releases.

If they don’t, reverting nodejs/node#6023 temporarily should also be okay – the problem it solved is, for the most part, a performance issue, so that should be safe, too.

I don’t know how exactly this interacts with the security releases; the decision is yours (@rvagg’s? @thealphanerd’s?) anyway, but both options seem better than “just waiting” to me.

[MylesBorins]

I've landed the fixes from nodejs/node#7292 and nodejs/node#7160 in v4.x-staging as nodejs/node@47f82cd...0dae3ca

The plan right now is to release the security update tomorrow as v4.4.6 and have a patch release v4.4.7 next Tuesday.

[MylesBorins]

fixed in v4.4.7

[addaleax]

@mcollina I don’t know, what’s the process for getting the fixes here out in a readable-stream release?