child_process spawn missing stdout on Ubuntu 20.04

[doubleswirve]

• Version: v12.16.1
• Platform: Linux ${edited_hostname} 5.4.0-769-generic openssl-cli.exe child process stdin problem on Windows #12157774391120.04~05e6ba8-Ubuntu SMP Tue Dec 31 00:30:08 UTC x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: child_process

What steps will reproduce the bug?

Note: Test code here as well.

Create an executable a.js:

#!/usr/bin/env node
const { spawn } = require("child_process");

spawn("echo", ["-n", "hello, world"], { stdio: "inherit" });

When I run ./a.js, I receive the hello, world output I'm expecting.

Then I create another JavaScript file b.js that calls ./a.js:

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

let data = "";
let proc = spawn("./a.js", [], { cwd: process.env.PWD });
proc.stdout.on("data", chunk => data += chunk);
proc.on("close", code => console.log(`Code: ${code}\nData: ${data}`));

On Linux (unlike macOS), data remains an empty string within the close event handler.

How often does it reproduce? Is there a required condition?

I receive the same output for every run on Linux.

What is the expected behavior?

I expected to receive the same output as macOS (Catalina 10.15.3), i.e.,

Code: 0
Data: hello, world

What do you see instead?

On Linux, I receive:

Code: 0
Data: 

Additional information

Thanks for all the help!

[mscdex]

I'm not able to reproduce the issue (on Ubuntu 18.04 FWIW) with node v10.x, v12.x, or master.

[gireeshpunathil]

@doubleswirve - do you have node in your PATH? what does which node show?

[doubleswirve]

Thanks for double-checking me @mscdex. I should've mentioned it, but I had installed node via a Snap package.

To make sure I had originally installed it correctly, I removed the snap package and ran:

sudo snap install node --classic --channel=12

When running node b.js, I still do not see the expected output.

After testing the snap package installation, I removed the snap package and followed the binary archive installation directions. Running node b.js does print the expected output.

Additionally, I tested this via Docker in the linked test repo and that does work as well.

So maybe I was having an issue with my snap installation. Feel free to close. Let me know if it would be helpful to post this elsewhere re: snap. Thanks again!

[gireeshpunathil]

the reason why I ask (which node) is: I am able to reproduce your problem, if I take out node from the standard PATH variable. when directly executing a.js via node, no problem, because we are feeding the required path. Whereas for the second method (via b.js), there is no way to deduct the PATH other than through env.

[pid 50844] write(2, "./a.js: line 1: syntax error near unexpected token `('\n", 55) = 55
[pid 50835] <... epoll_wait resumed> [{EPOLLIN, {u32=22, u64=22}}], 1024, 8100) = 1
[pid 50844] write(2, "./a.js: line 1: `const { spawn } = require(\"child_process\");'\n", 62 <unfinished ...>

as you can see, the script is attempted to be interpreted by bash, not by node - as it is not in the PATH.

I am not saying this IS your problem too, but this MAY be.

[gireeshpunathil]

if you can check, we can close this gracefully, with clear inference.

[doubleswirve]

Howdy @gireeshpunathil, with the snap installation (when I'm not receiving the expected output), which node prints out /snap/bin/node. To clarify further, /snap/bin is in PATH.

When the output does work as expected (via the binary archive installation), which node prints out /usr/local/lib/nodejs/node-v12.16.1-linux-x64/bin/node.

Hope that helps; let me know if I missed anything.

[gireeshpunathil]

@doubleswirve - thanks. that means your PATH looks all right. To be double sure, can you see if /snap/bin/node -v works?

Either way, I would be very interested to see strace -f -s 1024 node b.js output. This will tell us precisely what happened in the child, whether it wrote the data and why the parent could not read it etc.

[doubleswirve]

@gireeshpunathil, I reinstalled node via snap, so that which node prints /snap/bin/node. Running /snap/bin/node -v prints v12.16.1.

Re: the strace command, I haven't used it before; am I safe to share the output here via a gist for example? Thanks.

[gireeshpunathil]

@doubleswirve - as strace works at the lowest possible level of an application, its output is generally unsafe to share in public as is without sanitization. But since you are running a small test case (rather than production code) we are good. I just went through my output and did not see any parts that can cause unwanted exposure.

[doubleswirve]

@gireeshpunathil, thanks for the info. When running the strace command, sometimes it would complete and other times it would hang. I've made a gist for both cases:

• "Hanging" call
• Completed

In both cases, I ran strace -f -s 1024 node b.js &> debug.log.

[gireeshpunathil]

@doubleswirve - looks like you are running some other program? I am unable to match the context in the strace with the above sample code. For example, execve("./a.js", ["./a.js"], ...) is not present in the trace - this is important, as it represents the spawn.

Can you also try adding an error callback for the child process? (I tried but did not catch anything in my side)

proc.on('error', (e) => {
  console.log(e)
})

[doubleswirve]

@gireeshpunathil, strange, I thought I was running the right command. I've updated the test repo just in case it helps. I added a shell script for the strace call here. I ran grep on the output locally and I also did not see a reference to a.js.

Running strace -f -s 1024 node b.js (outside of the script) still hangs for me most of the time (and I have to kill the process).

I also added the error event handler; the current test code is on master here. Let me know if I'm missing something. Thanks!

[gireeshpunathil]

@doubleswirve - with the supplied Dockerfile, I am unable to recreate the issue.

there are a lot of (48) EPERM on many syscalls in the log, and this:

write(2, "need to run as root or suid", 27need to run as root or suid) = 27
write(2, ": Operation not permitted\n", 26: Operation not permitted

there is no evidence of the child process being invoked, while /usr/sbin/apparmor_parser, /usr/lib/snapd/snap-seccomp, /usr/lib/snapd/snap-confine these processes are being spawned - probably indicative of container's security controls coming into action, and failing some of the user requests?

[doubleswirve]

@gireeshpunathil, the docker version (which installs node via binary archive) is working for me as well. Installing node on my host via binary archive also works for me.

I'm only seeing the unexpected output when running node b.js on my host (i.e., not using docker) via the snap installation. I also tried running sudo node b.js; however, I receive the same unexpected output.

I couldn't find a good way to install node via snap within docker, but maybe I'll poke around later and see if I can recreate in that environment.

[jehon]

As far as I can understand those very tough discussions about Snap, I looks like the file descriptor can not be passed from snap to snap.
Something technical is around those links:
https://bugs.launchpad.net/ubuntu/+source/snapd/+bug/1849753
https://bugs.launchpad.net/snapd/+bug/1835805
nodesource/distributions#663

The only solution I did find is... not to use snap for nodejs.

[giner]

Temporary workaround #37982 (comment)

[bnoordhuis]

I'm closing this as it's not a node bug, it's a snap issue.