Nested child_processes piping to stdout cause freeze #1726

Closed
isaacs opened this Issue Sep 17, 2011 · 6 comments

Projects

None yet

4 participants

@isaacs
isaacs commented Sep 17, 2011

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
felixge commented Sep 19, 2011

Which node version is this?

@isaacs
isaacs commented Sep 19, 2011

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

@isaacs isaacs added a commit that referenced this issue Sep 23, 2011
@isaacs @ry isaacs + ry Add broken test for #1726. 74c0206
@ry
ry commented Sep 26, 2011

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

works in windows!

@ry
ry commented Sep 27, 2011

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 ry closed this in 0f8f863 Sep 27, 2011
@ry
ry commented Sep 27, 2011

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

@ry ry added a commit that referenced this issue Sep 27, 2011
@ry ry Move process.stdout unref hack to handle_wrap.cc
See #1726
7e62bc9
@koichik
koichik commented Sep 28, 2011

@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
@indutny indutny added a commit that referenced this issue Jul 13, 2014
@indutny indutny test: fix regress-GH-1726 b692493
@sam-github sam-github pushed a commit to sam-github/node-v0.x-archive that referenced this issue Jul 18, 2015
@brendanashworth brendanashworth src: remove old code
The Socket writable only change was added and implemented in the
constructor around 5885f46, but this was never removed.

The libev counter issue is no longer prudent; the test remains in
test/sequential/test-regress-GH-1726.

PR-URL: nodejs/node#1819
Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>
a65762c
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment