uv_spawn() erroneously closes stream fds when fork() fails

[davepacheco]

The "Child Process" documentation for the stdio file descriptors says that the value can be:

4. Stream object - Share a readable or writable stream that refers
to a tty, file, socket, or a pipe with the child process. The stream's
underlying file descriptor is duplicated in the child process to the
fd that corresponds to the index in the stdio array.

I assume based on this that the underlying stream is untouched in the parent process, regardless of whether fork succeeds or fails. However, if the fork fails, the stream actually gets closed.

You can simulate a fork failure on OS X using "ulimit -u" to set a process count to something way below the current number of processes. Like this:

dap@sharptooth ~ $ ps -A | wc -l
     170
dap@sharptooth ~ $ ulimit -u 10
dap@sharptooth ~ $ ls
-bash: fork: Resource temporarily unavailable
dap@sharptooth ~ $ 

This doesn't affect other terminals you have open.

Now, here's a test program that demonstrates that the fd is being closed by spawn:

var child = require('child_process');
var fs = require('fs');

var out = fs.createWriteStream('/var/tmp/out');
out.on('open', function () {
    try {
        child.spawn('echo', [ 'hello' ], { 'stdio': [ null, out, null ] });
    } catch (ex) {
        console.log('error!', ex);
        setTimeout(function () {
            out.end('test content');
        }, 1000);
    }
});

Here's what happens when I run it normally, without inducing a fork() failure:

dap@sharptooth ~ $ uname -a
Darwin sharptooth.local 12.5.0 Darwin Kernel Version 12.5.0: Mon Jul 29 16:33:49 PDT 2013; root:xnu-2050.48.11~1/RELEASE_X86_64 x86_64
dap@sharptooth ~ $ node -v
v0.10.18
dap@sharptooth ~ $ ls -l /var/tmp/out
ls: /var/tmp/out: No such file or directory
dap@sharptooth ~ $ node spawntest-write.js 
dap@sharptooth ~ $ cat /var/tmp/out 
hello
test content

As expected, the output file is created, and contains the output of both the "echo hello" child command and the "test content" write, which happens one second later in the parent process.

Now, if I induce a fork failure:

dap@sharptooth ~ $ rm -f /var/tmp/out 
dap@sharptooth ~ $ bash   # spawn second shell, since the test will exit the first one
dap@sharptooth ~ $ ulimit -u 10
dap@sharptooth ~ $ exec node spawntest-write.js 
error! { [Error: spawn EAGAIN] code: 'EAGAIN', errno: 'EAGAIN', syscall: 'spawn' }

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: EBADF, write
dap@sharptooth ~ $ ls -l /var/tmp/out 
-rw-r--r--  1 dap  wheel  0 Oct  1 18:31 /var/tmp/out
dap@sharptooth ~ $ cat /var/tmp/out 
dap@sharptooth ~ $ 

In this case, the write() failed with EBADF. This is not expected -- the documentation doesn't say anything about closing the Stream on failure.

I hit this initially with a different case, shown in this program:

var child = require('child_process');
var fs = require('fs');

var out = fs.createWriteStream('/var/tmp/out');
out.on('open', function () {
    try {
        child.spawn('echo', [ 'hello' ], { 'stdio': [ null, out, null ] });
    } catch (ex) {
        console.log('error!', ex);
    }

    out.destroy();
});

In this simplified case taken from my actual code, I destroy the stream after opening it. The logic is that in the success case, the stream was duplicated in the child, and I don't need another copy. In the failure case, the stream is no longer needed, and I still don't need it. So I destroy it in both cases. That fails similarly:

dap@sharptooth ~ $ bash
dap@sharptooth ~ $ ulimit -u 10
dap@sharptooth ~ $ exec node spawntest-destroy.js 
error! { [Error: spawn EAGAIN] code: 'EAGAIN', errno: 'EAGAIN', syscall: 'spawn' }

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: EBADF, close

Using DTrace and reproducing on SmartOS, I stopped the process at the moment close() returned EBADF, and caught this stack trace:

> ::jsstack
8047728 libc.so.1`__close+0x15
8047798 uv_spawn+0x5c9
8047878 node::ProcessWrap::Spawn+0x694
8047928 
_ZN2v88internalL21Builtin_HandleApiCallENS0_12_GLOBAL__N_116BuiltinArgumentsILNS0_21B
uiltinExtraArgumentsE1EEEPNS0_7IsolateE+0x157
804794c 0xa780a336 internal (Code: a780a2c1)
8047970 0xb46aec3b <anonymous> (as ChildProcess.spawn) (bd82ec05)
8047998 0xb46ada0a <anonymous> (as exports.spawn) (bd82ebb1)
...
8047a5c 0x8080c42e <anonymous> (as Barrier.done) (ab735431)
8047a80 0xa782951c <anonymous> (as startup.processNextTick.process._tickCallback) (
8a7439dd)
8047a9c 0xa7821bb9 <InternalFrame>
8047ad8 0xa7812b4a <EntryFrame>
8047b58 
_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x
101
8047b98 v8::internal::Execution::Call+0xc9
8047bf8 v8::Function::Call+0xf0
8047c78 _ZN4nodeL4TickEv+0xae
8047ca8 uv__run_check+0x47
8047ce8 uv__run+0x9c
8047cf8 uv_run+0x17
8047d58 node::Start+0x1c7
8047d78 main+0x1b
8047d94 _start+0x83

In this case close() was given -1 for an argument:

> ::stack ! head -1
libc.so.1`__close+0x15(ffffffff, 1, ffffffff, 86ac008, 86ac008, 804780c)

While that close() isn't the one that's wrong, it pointed me to this code in uv_spawn:

https://github.com/joyent/node/blob/v0.10.18/deps/uv/src/unix/process.c#L415-L421

which jumps here when fork fails:

https://github.com/joyent/node/blob/v0.10.18/deps/uv/src/unix/process.c#L463-L469

In the error case, we're closing all of the stdio file descriptors. This looks like leftover code from the time before Node supported anything other than pipes for the stdio fds. The initialization code (uv__process_init_stdio) was updated to not always create the pipe fds, but this cleanup code does not appear to have been updated to avoid closing the fds that were not created in uv_spawn() in the failure case.

[davepacheco]

I forgot to mention: EBADF is the absolute best thing that can happen in this case. A much worse possibility is that something else opens another file descriptor in the meantime and both streams now point to that fd. Here's a test program that shows that case:

var child = require('child_process');
var fs = require('fs');

var out = fs.createWriteStream('/var/tmp/out');
out.on('open', function () {
    try {
        child.spawn('echo', [ 'hello' ], { 'stdio': [ null, out, null ] });
    } catch (ex) {
        console.log('error!', ex);
    var err = fs.createWriteStream('/var/tmp/err');
    err.on('open', function () {
            out.end('test content\n');
        process.exit(0);
    });
    }
});

When I run this, I get this:

dap@Dave-Pachecos-Macbook $ ls -l /var/tmp/out /var/tmp/err
ls: /var/tmp/err: No such file or directory
ls: /var/tmp/out: No such file or directory
dap@Dave-Pachecos-Macbook $ bash
dap@Dave-Pachecos-Macbook $ ulimit -u 10
dap@Dave-Pachecos-Macbook $ exec node spawn-write-wrongfd.js 
error! { [Error: spawn EAGAIN] code: 'EAGAIN', errno: 'EAGAIN', syscall: 'spawn' }
dap@Dave-Pachecos-Macbook $ cat /var/tmp/out
dap@Dave-Pachecos-Macbook $ cat /var/tmp/err
test content
dap@Dave-Pachecos-Macbook $ 

In this case, the output intended for one stream went to the wrong stream.

[bnoordhuis]

@davepacheco Does joyent/libuv#945 fix it for you?

[davepacheco]

Thanks for the quick response! Yes, the patch (applied to node 0.10.20) works. Both of my original test programs run without the EBADF error on both OS X and SmartOS. Thanks!

[bnoordhuis]

Thanks Dave. Landed in libuv, will be in the next v0.10 release.