Subprocess on windows unable to get stdout data #3871

Open
airportyh opened this Issue Aug 16, 2012 · 17 comments

Projects

None yet

7 participants

Simply creating a subprocess and reading data from its stdout fails on Windows. However, strangely, I was only able to reproduce this bug when running a test under mocha - not sure what mocha's doing that's so special. Here is the gist that demonstrates the problem

https://gist.github.com/3365454

I am running Windows 7 inside VMWare.

I think your main problem is that you're calling exec (which buffers data until the end) instead of spawn (which is what it looks like you intend to be calling. Also, side note, the "end" callback doesn't take any arguments (err and data).

I'm not sure why you'd be seeing differences between OS X and Windows though. Could be something about the way that mocha is implemented.

I just changed it to use spawn, but the exact same thing happened. Here's my new spawn.js

https://gist.github.com/3366250

Member

@airportyh Can you also log the stderr data? p.stderr.on('data', function() { etc.

@piscisaureus handling stderr actually uncovered a bug in my code on windows - that it couldn't find the mocha executable: thanks for the catch. I've fixed that in the new version.

https://gist.github.com/3372204

So does your script work now? Can this be closed?

@piscisaureus No, the problem persists. Same result. The next thing I can do is dig into what Mocha is doing to try to isolate.

@piscisaureus piscisaureus reopened this Aug 17, 2012
Member

airporthyr: so does mocha actually run or not? Because in that case, spawn() is working fine :-)

Spawn worked, but the stdout data event(s) didn't emit. See the results on Windows in the gist.

Member

One more suggestion: can you try to remove the p.on('exit', function() { listener?

Yeah, taking that out still doesn't let it receive any data events. It ends up hanging there with no data displayed.

Drilled down to the Mocha source and was able to get closer. It looks like calling process.exit() has the potential to muffle stdout messages to parent process on Windows. Here's my new test that demonstrates - now no longer depends on Mocha. I've also verified that you get the same results regardless of using spawn() or exec().

https://gist.github.com/3386599

This is still a major issue at least on my system (Windows 8). Calling process.exit on a spawned process will truncate the output, supposedly because stdout and stderr are not flushed before exiting.

The 'grunt' project (a task runner) uses this code snippet to guarantee that pipes are flushed before exiting, and I successfully patched other projects e.g. typescript and mocha that way and it solved the problem for me.

exports.exit = function exit(exitCode) {
  if (process.stdout._pendingWriteReqs || process.stderr._pendingWriteReqs) {
    process.nextTick(function() {
      exit(exitCode);
    });
  } else {
    process.exit(exitCode);
  }
};

see https://github.com/gruntjs/grunt/blob/master/lib/util/exit.js

To me it looks very much as if this should be handled at a lower level (in node), in order to improve reliability and stability of node as a platform on Windows.

+1 mistaecko

Mithgol commented Apr 1, 2013

After some recent API changes, as far as I see, the callback of process.nextTick is called before any input/output operations.

So in the above code setImmediate should probably be used instead of process.nextTick.

What do you think?

setImmediate didn't work for me, but waiting for the pipes to 'drain' did work with node 0.8 and 0.10:

function exit(code) {
    var draining = 0;
    var onDrain = function(){
        if (!draining--) process.exit(code);
    };
    if (process.stdout.bufferSize) {
        draining++;
        process.stdout.once('drain', onDrain);
    }
    if (process.stderr.bufferSize) {
        draining++;
        process.stderr.once('drain', onDrain);
    }
    if(!draining)
        process.exit(code);
}

see: mochajs/mocha#333 (comment)

Btw, the main ticket for this issue is #3584.

+1 mistaecko

@brzpegasus brzpegasus pushed a commit to brzpegasus/testem that referenced this issue May 31, 2015
@airportyh airportyh Merged in #242 to workaround subprocess output getting truncated beca…
…use of node core bug <nodejs/node-v0.x-archive#3871>. I removed the contributed tests because I don't think it adds a lot of value.
55cf3b5
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment