Nested child_processes piping to stdout cause freeze

[isaacs]

Test script:

;(function () {

var gen = +(process.argv[2] || 0);
var maxGen = 5;


if (gen === maxGen) {
  console.log("hit maxGen, exiting", maxGen);
  return;
}

var ch = require("child_process");
var cp = ch.spawn("node", [__filename, gen + 1]);

console.log("gen=%d", gen);

var timer = setTimeout(function () {
  throw new Error("timeout! gen="+gen);
}, 1000);

cp.on("exit", function (code) {
  console.error("exit %d from gen %d", code, gen + 1);
  clearTimeout(timer);
})

cp.stdout.pipe(process.stdout);
cp.stderr.pipe(process.stderr);

})();

Output:

$ node no-exit.js 
gen=0
gen=1
gen=2
gen=3
gen=4
hit maxGen, exiting 5
exit 0 from gen 5
exit 0 from gen 4

/Users/isaacs/dev-src/js/semver/no-exit.js:19
  throw new Error("timeout! gen="+gen);
        ^
Error: timeout! gen=0
    at Object._onTimeout (/Users/isaacs/dev-src/js/semver/no-exit.js:19:9)
    at Timer.ontimeout (timers_uv.js:84:39)

[felixge]

Which node version is this?

[isaacs]

Sorry, forgot that. Master branch, 0.5.8-pre, 243c218.

[ry]

definitely a bug. the test has been landed in master but is broken.

works in windows!

[ry]

Root cause:

https://github.com/joyent/node/blob/3aa1975c5837a160b849d2b81fc7a4bcd7870155/src/node.js#L232

This is decreasing the libev loop reference count, uv_default_loop()->ev->activecnt, below zero. libev keeps looping on non-zero activecnt see
https://github.com/joyent/node/blob/040cf0272429547a09a1d6bb1efebe5b613e8c2a/deps/uv/src/unix/ev/ev.c#L2453
https://github.com/joyent/node/blob/040cf0272429547a09a1d6bb1efebe5b613e8c2a/deps/uv/src/unix/ev/ev.c#L2522

libev has asserts to check for this (at least when the activecnt is below -1, which wouldn't have caught it in this case) but they are compiled out by default. I changed the uv gyp build to use EV_VERIFY=2 which should avoid this sort of problem in the future here joyent/libuv@2c01791
deps/uv/src/win/core.c has a similar assert.

This example is illustrative:

console.error("process.stdout._type = " + process.stdout._type);
process.stdout.write('hello world\n');
process.stdout.end();

After process.stdout is closed, the reference count in the loop is -1. There is another bug I had to first uncover which is that half-duplex streams are having uv_shutdown() called on them. https://gist.github.com/1244448 fixes this.

Probably we need to stop using libev's reference counter. This has been a long time in the coming. I landed some tests in libuv in preparation for this switch
joyent/libuv@2ebb227
joyent/libuv@3e5aa06

[ry]

The above hack is pretty awful. It would be nice have the ability to "unref" a whole handle in libuv.

[koichik]

@ry - process.stdout is not defined with legacy backend.

$ ./node --use-legacy -e 'process.stdout.write("a")'

node.js:238
          stdout._handle.unref();
                         ^
TypeError: Cannot call method 'unref' of undefined
    at EventEmitter.stdout (node.js:238:26)
    at Object.<anonymous> (eval at <anonymous> (eval:1:75))
    at Object.<anonymous> (eval:1:63)
    at Module._compile (module.js:432:26)
    at startup (node.js:96:14)
    at node.js:559:3