stream: writes can return false but forget to emit drain

[glasser]

If a write is above the high water mark but _write still manages to
fully send it synchronously, _writableState.length can be adjusted down
to 0 synchronously with the write that returns false, but 'drain' will
not be emitted until process.nextTick.

If you then issue another write before process.nextTick happens which is short, _writableState.needDrain will be reset to false, and the drain event will never fire.

Making matters worse, if you have a 0.8-style Stream piped into this writable stream, this means the source stream will get paused (due to a write returning false) and never resumed.

Eg, you would expect the following code to exit 0, not fail. It exits 0 if either of the two write calls are removed; you need the big one followed by the short one for the issue to occur.

var server = net.createServer();
server.listen(8000, function() {
  var client = net.createConnection(8000, function () {
    var big = new Buffer(16500);
    big.fill('x');
    assert(big.length > client._writableState.highWaterMark);
    assert(!client.write(big));
    assert(client.write('short'));
    client.on('drain', function () {
      process.exit(0);
    });
    setTimeout(function () {
      assert.fail();
    }, 100);
  });
});

[n1mmy]

I believe the issue is in lib/_stream_writeable.js in writeOrBuffer (https://github.com/joyent/node/blob/v0.10.22/lib/_stream_writable.js#L206). The needDrain flag is reset by the second write before the drain event is fired.

It looks like previously the code did the right thing by only setting the flag to true, never resetting to false: https://github.com/meteor/node/blob/v0.9.10/lib/_stream_writable.js#L162, changed in 049903e in what looks to be an unrelated refactoring.

[glasser]

By the way, the reason that this only affects piping from 0.8-style streams and not from 0.10-style streams (or, well, people doing their own flow control implementation) is that stream.Readable.prototype.pipe is careful to immediately stop writing to a stream after write returns false, whereas stream.Stream.prototype.pipe will happily send any incoming data along to the destination even if it thought that it already paused the source. That's why people who are only using 0.10-style streams and are only using pipe (ie, no manual handling of write return values) aren't seeing this.

But I think it actually can occur just using 0.10-style streams and pipe, if you have stranger topologies. For example, if you have TWO source stream.Readables s1 and s2 and one destination stream.Writable dest. And you run both s1.pipe(dest, {end: false}) and s2.pipe(dest, {end: false}).

Let's say that s1 sends a 16500 byte write to dest. This will cause dest.write to return false, so s1 increments its state.awaitDrain and won't send anything else to dest until it emits drain.

But since there's no event associated with dest.write returning false, s2 has no idea that there's anything wrong with writing to dest. If s2 happens to send a small write to dest before process.nextTick, dest will clear its needDrain flag and never notify s1 that it's time to continue. Clog!

[glasser]

Yeah, this shows how the bug affects you even with only 0.10-style streams and pipe.

If you run this with $UNBREAK set you'll see the small block of xs, the tiny, and the later.

Without $UNBREAK, you see the large block of xs, the tiny... and no later, because s1 never got drained.

var assert = require('assert');
var util = require('util');
var stream = require('stream');

function PassThrough () {
  stream.Transform.call(this);
};
util.inherits(PassThrough, stream.Transform);
PassThrough.prototype._transform = function (chunk, encoding, done) {
  this.push(chunk);
  done();
};

var s1 = new PassThrough;
s1.pipe(process.stdout);
var s2 = new PassThrough;
s2.pipe(process.stdout, {end: false});

var big = new Buffer(process.env.UNBREAK ? 16 : 16500);
big.fill('x');
big.write('\n', big.length - 1);

s1.write(big);
s2.write("tiny\n");
setTimeout(function () {
  s1.write("later\n");
}, 10);

[ayanamist]

I'm suffering from this issue when using node-mysql with LOAD DATA LOCAL INFILE sql query. The mysql connection is randomly hanged when querying but can got OkPacket which is verified by wireshark. Trace the whole process and find the problem as @glasser said.

[glasser]

Thanks @ayanamist and @indutny ! Looks like your PR fixed this issue.