Piping w/ spawn is broken in Node 11 / 12

[arcanis]

• Version: 11.13
• Platform: OSX
• Subsystem: child_process

Ref #18016, ping @elibarzilay and @gireeshpunathil

It seems that Node 11's behavior changed compared to Node 10, and pipes are now automatically closed after being used as output stream from a process. I think this is a bug, because it makes it impossible to use the same pipe as output from two different processes (which would be the case if I was to implement (foo; bar) | cat - both foo and bar would write into the cat process).

Additionally, it causes previously working code to "randomly" throw internal exceptions. The random part is likely caused by a race condition, since perl throws consistently while rev doesn't cause problems. The exception is as such:

const {spawn} = require(`child_process`);

const p2 = spawn(`perl`, [`-ne`, `print uc`], {
  stdio: [`pipe`, process.stdout, process.stderr],
});

const p1 = spawn(`node`, [`-p`, `"hello world"`], {
  stdio: [process.stdin, p2.stdin, process.stderr],
});

p1.on(`exit`, code => {
  p2.stdin.end();
});

❯ [mael-mbp?] /Users/mael ❯ node test

HELLO WORLD
internal/validators.js:130
    throw new ERR_INVALID_ARG_TYPE(name, 'number', value);
    ^

TypeError [ERR_INVALID_ARG_TYPE]: The "err" argument must be of type number. Received type undefined
    at validateNumber (internal/validators.js:130:11)
    at Object.getSystemErrorName (util.js:231:3)
    at errnoException (internal/errors.js:383:21)
    at Socket._final (net.js:371:25)
    at callFinal (_stream_writable.js:617:10)
    at processTicksAndRejections (internal/process/task_queues.js:81:17)

As you can see the code executed fine (HELLO WORLD got printed), but during cleanup an internal assertion failed and Node crashed.

[gireeshpunathil]

@arcanis - thanks for reporting this, I will have a look

[gireeshpunathil]

I just confirmed that b1f82e4 (#21209) is NOT the reason for this behavior; with and without that the behavior is observed to be same.

will dig further tomorrow!

[arcanis]

Fwiw from my experiments the problems appeared in 11.10 - my tests pass in 11.9. Looking at the diff between the two, the only change in child_process is #21209.

[BridgeAR]

To me it seems to either be streams or libuv related.

[richardlau]

Git bisect between v11.9.0 (good) and v11.10.0 (bad) points to 197efb7

197efb7f846e14bdb3002f5ff7528d4070880328 is the first bad commit
commit 197efb7f846e14bdb3002f5ff7528d4070880328
Author: Gireesh Punathil <gpunathi@in.ibm.com>
Date:   Fri Jun 8 08:33:37 2018 -0400

    child_process: close pipe ends that are re-piped

    when t0 and t1 are spawned with t0's outputstream [1, 2] is piped into
    t1's input, a new pipe is created which uses a copy of the t0's fd.
    This leaves the original copy in Node parent, unattended. Net result is
    that when t0 produces data, it gets bifurcated into both the copies

    Detect the passed handle to be of 'wrap' type and close after the
    native spawn invocation by which time piping would have been over.

    Fixes: https://github.com/nodejs/node/issues/9413
    Fixes: https://github.com/nodejs/node/issues/18016

    PR-URL: https://github.com/nodejs/node/pull/21209
    Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
    Reviewed-By: James M Snell <jasnell@gmail.com>
    Reviewed-By: Anna Henningsen <anna@addaleax.net>

-bash-4.2$ git bisect log
git bisect start
# good: [8e24451439a9abbc1cd99b42066eec65473e781c] 2019-01-30, Version 11.9.0 (Current)
git bisect good 8e24451439a9abbc1cd99b42066eec65473e781c
# bad: [6e56771f2a9707ddf769358a4338224296a6b5fe] 2018-02-14, Version 11.10.0 (Current)
git bisect bad 6e56771f2a9707ddf769358a4338224296a6b5fe
# bad: [2b1f88185fca2bc73ef8f6d09422626e9e237636] benchmark: remove unreachable return
git bisect bad 2b1f88185fca2bc73ef8f6d09422626e9e237636
# good: [e28d891788069732d6e37a00459812bee02910fc] src: fix race condition in `~NodeTraceBuffer`
git bisect good e28d891788069732d6e37a00459812bee02910fc
# bad: [353de0f7520bce50b490f367048ee1e58894a784] doc: fix err_synthetic issue on v11.x
git bisect bad 353de0f7520bce50b490f367048ee1e58894a784
# good: [b5a8376ffe2f380103ebe7f7314d5c7a12500084] src: organize TLSWrap declarations by parent
git bisect good b5a8376ffe2f380103ebe7f7314d5c7a12500084
# good: [1c6fadea3135e5f95f3042cf06cd71de49a33e8f] meta: clarify EoL platform support
git bisect good 1c6fadea3135e5f95f3042cf06cd71de49a33e8f
# good: [2c737a89d59a0c3fa471d36031c64550607fc367] repl: remove obsolete buffer clearing
git bisect good 2c737a89d59a0c3fa471d36031c64550607fc367
# bad: [197efb7f846e14bdb3002f5ff7528d4070880328] child_process: close pipe ends that are re-piped
git bisect bad 197efb7f846e14bdb3002f5ff7528d4070880328
# good: [c866b52942b326674e9ab2adf52467d5f27cdf53] test: remove obsolete code
git bisect good c866b52942b326674e9ab2adf52467d5f27cdf53
# first bad commit: [197efb7f846e14bdb3002f5ff7528d4070880328] child_process: close pipe ends that are re-piped
-bash-4.2$

[gireeshpunathil]

thanks @richardlau - I dont know what mistake I was doing yesterday, but now I confirm that the behavior difference is caused by 197efb7

will analyze the test and and the failure to see what this means.

[gireeshpunathil]

ok, here is a deadlock situation:

$ cat true.js

const {spawn} = require(`child_process`);
const p3 = spawn('cat', {stdio: ['pipe', process.stdout, process.stderr]});
const p1 = spawn('./foo.sh', {stdio: ['pipe', p3.stdin, process.stderr]});
const p2 = spawn('./bar.sh', {stdio: ['pipe', p3.stdin, process.stderr]});

$ cat false.js

const { spawn } = require("child_process");
let p3 = spawn('wc', ['-l'], {stdio: ['pipe', process.stdout, process.stderr]})
let p2 = spawn('grep', ['spawn'],  {stdio: ['pipe', p3.stdin, process.stderr]})
let p1 = spawn('cat', [__filename],  {stdio: ['pipe', p2.stdin,  process.stderr]})

without 197efb7 true.js passes while false.js fails
with 197efb7 true.js fails while falsse.js passes

the rationale for 197efb7 is that pipe ends when re-piped were loosing data at either of the destination becaue of the bifurcation, making re-piping a meaningless use case. At the same time, looks like that is breaking the accumulation scenario.

I am not sure what is wrong with 197efb7 . The piping is good, as the data is correctly delivered (in true.js) but looks like something went wrong that led to the error.

pinging @nodejs/child_process to get an advice, while investigating further.

[arcanis]

the rationale for 197efb7 is that pipe ends when re-piped were loosing data at either of the destination becaue of the bifurcation, making re-piping a meaningless use case. At the same time, looks like that is breaking the accumulation scenario.

Have you checked my comment regarding (foo; bar) | cat? Isn't this change preventing to send the same process' stdin to multiple processes' stdout, since the stdin would get closed after being sent to the first process?

[gireeshpunathil]

yes, that is exactly true.js is doing right? (treat foo as 'echo hello' and bar as 'echo world')

if your question is whether the said commit has considered this use case, no, this was not considered.

[arcanis]

Ah indeed, I didn't check correctly!

if your question is whether the said commit has considered this use case, no, this was not considered.

Yep no worry I just wanted to be sure it was accounted now 😊 Given that, do you think there's a way to make both the original case and this new one work? Or should 197efb7 be reverted?

If I understand correctly, the original issue (#18016) referenced in option 3 what seemed to be a satisfying behavior: require the pipes to be manually closed by the user. Any improvement can then be implemented in userland via tools like execa, without compromising child_process' capabilities.

[elibarzilay]

@arcanis, are you saying that the problem in this comment should be considered satisfying? Which pipes should have been closed to make it work?

[arcanis]

I believe the problem in your post is due to an incorrect execution order (I mentioned it in my comment from the other thread but the exact ramifications didn't occur to me until I got to experience the bug first hand). Here is your example with two alternative fixes (I've put comments to detail my thoughts for each of them):

"use strict";

switch (process.argv[2]) {

  default: {

    console.log("Usage: ./x.js <0|1>");

  } break;

  case "0": {

    // The case that doesn't work; the pipes are left open in the current process, so some
    // data can be lost between the time "p1" spawns and the time "p2" spawns

    const { spawn } = require("child_process");

    let p1 = spawn("./b", ["10000"], {stdio: [process.stdin, "pipe", process.stderr]});
    let p2 = spawn("grep", ["7"], {stdio: [p1.stdio[1], "pipe", process.stdout]});
    let p3 = spawn("wc", ["-l"], {stdio: [p2.stdio[1], process.stdout, process.stdout]});

  } break;

  case "1": {

    // This is the same thing, except that we now close the pipes on our hand after spawning
    // the processes. It seems that calling "p.stdout.end()" doesn't work for some reason
    // (it throws a ENOTCONN exception), so we need to close the handle itself (basically
    // manually do what 197efb7 automatically does). That makes me think that we're not
    // supposed to do this.

    const { spawn } = require("child_process");

    let p1 = spawn("./b", ["10000"], {stdio: [process.stdin, "pipe", process.stderr]});

    let p2 = spawn("grep", ["7"], {stdio: [p1.stdio[1], "pipe", process.stdout]});
    p1.stdout._handle.close();

    let p3 = spawn("wc", ["-l"], {stdio: [p2.stdio[1], process.stdout, process.stdout]});
    p2.stdout._handle.close();

  } break;

  case "2": {

    // This is imo the best solution. Instead of spawning the data producers first, we start
    // by spawning the consumers first (right-to-left). After we spawned the process, we
    // close our side of the pipe so that it becomes clear that no data is to be expected
    // from us. Curiously this time we can use "p.stdin.end()", even though the previous
    // example showed that we couldn't call "p.stdout.end()".
    //
    // This approach also makes it possible to configure multiple subprocesses to write in
    // the same pipe, something which isn't possible with left-to-right execution (since you
    // don't know what pipe the left process should write into until after you've spawn the
    // right process).

    const { spawn } = require("child_process");

    let p3 = spawn("wc", ["-l"], {stdio: ["pipe", process.stdout, process.stdout]});

    let p2 = spawn("grep", ["7"], {stdio: ["pipe", p3.stdin, process.stdout]});
    p3.stdin.end();

    let p1 = spawn("./b", ["10000"], {stdio: [process.stdin, p2.stdin, process.stderr]});
    p2.stdin.end();

  } break;

}

[elibarzilay]

Thanks for the code, which I'll use if the commit is reverted, but I
still thing that something is wrong.

First, as I also replied in the other thread, the order should not
matter, and I've had tried it in both directions (but see below).
Second, there is the suspicious fact that the probelm didn't happen on
Windows.

Now, looking at your two solutions I get a vague feeling that the
problem is that a pipe is generated in any case, but when the output of
one process is used as the input of another (regardless of order), then
the connection is done on the underlying FD, and therefore the pipe is
now redundant, and having it around might lead to the race condition
that lead to the problem I've had. But this is all guessing based on
the fact that both of your solutions work via closing the pipe object.

One more comment is that things are still broken (ping
@gireeshpunathil). This variant of the code on Windows (with binaries
that are found on cygwin):

let p3 = spawn("wc.exe", ["-l"], {stdio: ["pipe", process.stdout, process.stdout]});
let p2 = spawn("grep.exe", ["7"], {stdio: ["pipe", p3.stdin, process.stdout]});
// p3.stdin.end();
let p1 = spawn("bash.exe", ["./b", "10000"], {stdio: [process.stdin, p2.stdin, process.stderr]});
// p2.stdin.end();

fails now, and works on linux. It looks like a read is initiated which
causes the failure. Uncommenting the two end lines makes it work on
windows and fail on linux (probably because they're already closed?).

If my guess is correct, then I see three conclusions:

1. It is indeed better to stick to starting processes right-to-left, but
   for a different reason -- because otherwise there might be some
   data that is lost into the pipe's buffer before it is closed.

2. But the flip side of that is the problem that I've seen above without
   calling ends: if for whatever reason a read is initiated, then
   things get broken. (No data is lost, but redundant data can be
   read.)

3. A proper way to resolve this is to avoid creating a pipe in the first
   place, as a new kind value to be used in options.stdio. Again, I'm
   not sure about all of this since I didn't read the code, but if it's
   close to true, then there should be some way to avoid creating a pipe
   when one is not needed (when two processes are piped), since
   otherwise one of the two problems above is likely.

(Regardless, something should be documented, especially if the commit
is reverted, since this closing thing is not something that I can guess
should be used from the docs.)