spawn with pipes

[elibarzilay]

• Version: v9.3.0
• Platform: mainly Linux, compared with Windows
• Subsystem: child_process

Disclaimer: the below is using my understanding of the docs which might
be wrong.

I'm trying to figure out the best way to create a pipeline of two
processes, and there seem to be some subtle issues that are either bugs
or maybe a result of under-documentation... I'll describe the three
variants that I tried below -- note that I'm trying to avoid the
explicit piping in JS that the "very elaborate" example in the docs is
doing, since my goal is to let the system do its thing when possible.

The main question here is whether the first code sample should work, and
if not, then what is the right way to do this.

0. Setup

In all of these examples the current directory has two files: foo.js
with the code, and a bar file. This is just an artificial setup to
make sure that the resulting output works.

1. Simple code

The first thing I tried is what I thought should work fine:

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

let p1 = spawn("find", [".", "-type", "f"],
               {stdio: [process.stdin, "pipe", process.stderr]});
p1.on("error", e => console.log("p1 error:", e));
p1.on("exit", (code, signal) => console.log("p1 done", code, signal));
// console.log("!!!");
let p2 = spawn("grep", ["foo"],
               {stdio: [p1.stdio[1], process.stdout, process.stdout]});
p2.on("error", e => console.log("p2 error:", e));
p2.on("exit", (code, signal) => console.log("p2 done", code, signal));

On Windows (using cygwin) this works as expected:

./foo.js
p1 done 0 null
p2 done 0 null

but on Linux it sometimes works fine (as above) and sometimes it fails
inexplicably:

p1 done 0 null
p2 done 1 null

To make things more weird, uncommenting the console.log("!!!") line
makes it work fine (on both platforms). This lead me to believe that
there might be some race condition somewhere.

2. Delayed start of the second process

Following the above guess, I tried to delay the second process to make
sure that the pipe gets generated in a consistent way:

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

let p1 = spawn("find", [".", "-type", "f"],
               {stdio: [process.stdin, "pipe", process.stderr]});
p1.on("error", e => console.log("p1 error:", e));
p1.on("exit", (code, signal) => console.log("p1 done", code, signal));

setImmediate(() => {
  let p2 = spawn("grep", ["foo"],
                 {stdio: [p1.stdio[1], process.stdout, process.stdout]});
  p2.on("error", e => console.log("p2 error:", e));
  p2.on("exit", (code, signal) => console.log("p2 done", code, signal));
});

This either fails as before (rarely), or (more commonly) fails with an error:

p1 done 0 null
internal/child_process.js:917
      throw new errors.TypeError('ERR_INVALID_OPT_VALUE', 'stdio',
      ^

TypeError [ERR_INVALID_OPT_VALUE]: The value "Socket {
  connecting: false, ... [Symbol(bytesRead)]: 15 }" is invalid for option "stdio"
    at internal/child_process.js:917:13
    at Array.reduce (<anonymous>)
    at _validateStdio (internal/child_process.js:843:17)
    at ChildProcess.spawn (internal/child_process.js:283:11)
    at exports.spawn (child_process.js:499:9)
    at Immediate.setImmediate (/home/eli/work/ms/x/foo.js:10:12)
    at runCallback (timers.js:773:18)
    at tryOnImmediate (timers.js:734:5)
    at processImmediate [as _immediateCallback] (timers.js:711:5)

This might be a different error where the stream gets into a state where
it cannot be used as an input. Note that:

1. Using setTimeout() leads to the same behavior
2. The failure is only on Linux -- on Windows it works fine as it did
   previously

3. Starting the processes from the end

I finally tried creating the processes going from the end. This was
close, but when the p1 process ends, it doesn't close its pre-existing
stdout, so I have to do that manually:

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

let p2 = spawn("grep", ["foo"],
               {stdio: ["pipe", process.stdout, process.stdout]});
p2.on("error", e => console.log("p2 error:", e));
p2.on("exit", (code, signal) => console.log("p2 done", code, signal));

let p1 = spawn("find", [".", "-type", "f"],
               {stdio: [process.stdin, p2.stdio[0], process.stderr]});
p1.on("error", e => console.log("p1 error:", e));
p1.on("exit", (code, signal) => {
  console.log("p1 done", code, signal);
  p2.stdio[0].end();
});

This seems like it works fine, but I dislike closing the pipe in my own
code, since it is a step towards doing more work in node, instead of
letting the OS manage the pipe in a more natural way.

[gireeshpunathil]

how about this:

'use strict'
const { spawn } = require('child_process')

let p1 = spawn('find', ['.', '-type', 'f'])
let p2 = spawn('grep', ['foo'], {stdio: [p1.stdout, 'pipe', process.error]})

p2.stdout.on('data', (d) => {
  console.log(d.toString())
})

p1.on('exit', (code, signal) => console.log('p1 done', code, signal))
p2.on('exit', (code, signal) => console.log('p2 done', code, signal))

[elibarzilay]

I'm not sure that I'm catching the difference here. The main thing that
I can see is that you're using pipe and a manual loop at the end of
the chain instead of just connecting it to process.stdout. If that's
the case, then I think that there is some problem with process.stdout.

I've tried to start with your bit, cleaning it up a little (I don't have
process.error, so replace it with process.stderr). I don't get the
previous process failures now (even with my original sample, and on the
same v9.3), but every once in a while it drops one line from the
expected output. This bogus dropping does not happen when I add the
manual printout that you do, which is why I suspect that there's some
problem with process.stdout. Maybe something with process output that
happens in a way that is not safe with the REPL.

Here's the current version I tried -- added a sed to ensure that the
printouts are all going through the chain and not getting printed
earlier somehow:

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

let p1 = spawn("find", [".", "-type", "f"], {stdio: [process.stdin, "pipe", process.stderr]});
p1.on("error", e => console.log("p1 error:", e));
p1.on("exit", (code, signal) => console.log("p1 done", code, signal));

let p2 = spawn("grep", ["foo"], {stdio: [p1.stdout, "pipe", process.stderr]});
p2.on("error", e => console.log("p2 error:", e));
p2.on("exit", (code, signal) => console.log("p2 done", code, signal));

let p3 = spawn("sed", ["-e","s/^/-/"], {stdio: [p2.stdout, process.stdout, process.stderr]});
p3.on("error", e => console.log("p3 error:", e));
p3.on("exit", (code, signal) => console.log("p3 done", code, signal));

// p3.stdout.on("data", d => console.log(d.toString()));

This skips a line as I described -- and if I change the last output to
"pipe" and un-comment the manual printout, it indeed works
consistently.

[gireeshpunathil]

can you share with me a failing scenario? I am not able observe the dropping stdout scenario.

[elibarzilay]

Sorry, I tried recreating it with a toy directory but it doesn't show the problem there. Above, I'm running it in a pretty big directory, which is where I see the problem.

[elibarzilay]

I tried it again on my home directory, and the discrepancies are very frequent, to the point that two consecutive runs rarely produce the same output. I also tried it without the direct process.stdout (with the manual output printing thing) and that fails to produce consistent results too.

I'm guessing that you should be able to see this if running in a big enough directory.

[gireeshpunathil]

yes, I tried quite a big one but could not see anything wrong. But as you state you are seeing it consistently, let me try again. Couple of sanity checks:

• hope you are not redirecting output to a file - in which case the process.stdout changes its identity.

• for that matter you are also not counting output lines through | wc -l etc.?

• hope you are not taking care of the re-ordering of file names that find command performs based on its internal logic.

[elibarzilay]

1. I am redirecting to a file, but like I said, the differences happen
   either way. (I also saw these differences without a redirection.)

2. Using wc would be a valid way to test it, since lines get ommitted.
   But I'm mainly comparing the files to verify that there are actual
   differences.

3. And yes, I do account for possible differences in ordering, it's not
   the problem.

[gireeshpunathil]

thanks for the clarification. Now the only differences would be:

• in terms of platform. Can you please confirm your complete OS version?
• the number of files : roughly how many files the find command brings forth?

[gireeshpunathil]

@elibarzilay - is this still outstanding?

[elibarzilay]

@gireeshpunathil Yes. In fact I just tested it again recently, and it is still very broken. To see it without scanning a directory tree with find, do this:

Save the following in b and chmod +x it:

#!/usr/bin/env bash
for (( x=0; x < $1; x++ )); do
  echo xxx $x xxx
done

And put this in x.js:

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

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

With this I'm getting:

$ ./b 10000 | grep 7 | wc -l               # shows the expected result
3439
$ node x.js; node x.js; node x.js; node x.js
2140
2146
2796
2143

[gireeshpunathil]

thanks, I understand what you are saying. And I am able to reproduce it too:

Can you try this?

$ cat 18016.js

"use strict";
const { spawn } = require("child_process");
let p1 = spawn("./b", ["10000"])
let p2 = spawn("grep", ["7"])
p1.stdout.pipe(p2.stdin);
let p3 = spawn("wc", ["-l"], {stdio: ['pipe', process.stdout, 'pipe']})
p2.stdout.pipe(p3.stdin);

[gireeshpunathil]

Explanation to the behavior we see:

1. When 'b' is spawned, a pipe is created for child's stdout.
2. As pipes would have it, it has 2 ends p1 and p2. p1 is with parent (x.js) and p2 with child, 'b'
3. When 'grep' is spawned, p1 is passed as stdin for it.
4. Expectation is that all data coming to p1 be routed to grep.
5. In reality, another pipe is created, say with ends q1 and q2. q1 will be controlled by parent, x.js
6. The forked child (grep) uses a copy of p1, say q2.
7. The parent x.js also has the original copy of p1 with it.
8. All p1, p2, q1, q2 are sockets.

With this setup when find start writing data, there are two potential consumers for it - q2 (p1.stdio[1] duplicated in grep) and original p1 that is still with parent. Depending on which one attempts a read when data is available, the data is bifurcated, and grep gets only a handlful of it!

When you do p1.stdout.pipe(p2.stdin) the missing pieces are returned to grep.

I am too puzzled to recommend anything. :)

/cc @nodejs/child_process @nodejs/streams