Thrown readable stream error while uncorking

[jfhbrook]

• Version: 4.4.1 (currently upgrading to 4.4.2 to see what's good)
• Platform: Linux ip-10-90-38-23 3.10.0-123.8.1.el7.x86_64 deps: update openssl to 1.0.1j #1 SMP Mon Sep 22 19:06:58 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: _stream_writable.js

I have some production services that are throwing a pretty crazy error:

TypeError: Cannot set property 'entry' of null
    at clearBuffer (_stream_writable.js:379:18)
    at Socket.Writable.uncork (_stream_writable.js:238:7)
    at RedisClient.uncork (/cn/runtime/epi-services/nodejs/releases/current/node_modules/@condenast/tsugu-service/node_modules/redis/index.js:361:25)
    at Multi.exec_transaction (/cn/runtime/epi-services/nodejs/releases/current/node_modules/@condenast/tsugu-service/node_modules/redis/index.js:1171:18)

For some background: We're using redis as a caching layer, and this code is getting triggered while writing to redis with its 'multi' helper. We're using v2.4.2 of the redis module but I'm gonna upgrade to 2.5.3 just in case it helps.

As far as I can tell, what's happening here is that the redis client creates a net stream and at various points in time might call uncork on it, including inside the multi exec handler. For some reason, only sometimes, when this happens, trying to clear the buffer throws because state.corkedRequestsFree is null.

I did look at net and Duplex code paths, as well as the redis code, and didn't see anything touching internal stream state, but maybe I missed something?

Unfortunately, I don't have a reproducing case beyond the production code. I tried triggering this with a naive fuzzer on a writable stream, no dice.

@mcollina tagging you because we talked about this on irc a little bit, and because you have the git blame for CorkedRequest.

Thanks!

EDIT: Also created an issue on the redis project just in case

[mcollina]

I am sorry this happened. This commit has been around in node v5 and readable-stream for months. Unfortunately, nobody catched this very particular behavior before it was backported.

I can reproduce it with the following two scripts, the server and the client:

'use strict'

const net = require('net')
let chunks = 0
net.createServer((stream) => {
  stream.on('data', () => chunks++)
}).listen(4242)

setInterval(() => {
  console.log('received', chunks, 'chunks')
  chunks = 0
}, 1000)

'use strict'

const net = require('net')
const stream = net.connect(4242)
const buf = new Buffer('42')

function doWrite () {
  console.log('doWrite')
  let tooMuch = 0
  while (tooMuch < 10) {
    stream.cork()
    stream.write(buf)
    stream.write(buf) || tooMuch++ // we need two writes to trigger the bug
    stream.uncork()
  }
  console.log('break', tooMuch)
}

stream.setNoDelay(true)
stream.on('drain', doWrite)

doWrite()

The behavior of this script is to leverage the OS tcp buffering, and write synchronously. This come from this line: https://github.com/nodejs/node/blob/master/lib/net.js#L690. The normal output of this script is:

$ node bug-client.js
doWrite
break 10
doWrite

As you can immagine, this script keeps writing in a completely synchronous manner. This technique is used to demonstrate the bug. My example is a corner case which will lead (after a very long period) as a memory leak, because the buffer will never be collected (a reference to the callback will be held in the process.nextTick queue):

node/lib/_stream_writable.js

Line 344 in 5368455

process.nextTick(afterWrite, stream, state, finished, cb);

.

I am already working on a fix that does not lead to a slowdown of any sort.

I missed this because I have always tested cork/uncork behavior following this pattern:

node/lib/_http_outgoing.js

Lines 467 to 470 in be68b68

	if (this.connection && !this.connection.corked) {
	this.connection.cork();
	process.nextTick(connectionCorkNT, this.connection);
	}

. Which does not trigger the issue.I am sorry this happened. This commit has been around in node v5 and readable-stream for months. Unfortunately, nobody catched this very particular behavior before it was backported.

[mcollina]

cc @nodejs/streams

[jfhbrook]

@mcollina thanks for the quick work on this!

[mcollina]

No worries, I'm responsible for this, and I have bandwidth... as of yesterday :D.