This repository has been archived by the owner. It is now read-only.

child_process stdio doesn't flush before exiting #3737

Closed
seanmonstar opened this Issue Jul 19, 2012 · 13 comments

Comments

Projects
None yet
7 participants
@seanmonstar
Copy link

seanmonstar commented Jul 19, 2012

Example:

test.js:

var child_process = require('child_process');

var child = child_process.spawn('node', ['child.js']);
child.stdout.on('data', function(d) {
  console.log(String(d));
});
child.stderr.on('data', function(d) {
  console.error(String(d));
});

child.js

console.log('derp');
process.exit(1); // derp wont get flushed
setTimeout(function() {
  process.exit(1); // wait a bit, and it will
}, 500);
@bnoordhuis

This comment has been minimized.

Copy link
Member

bnoordhuis commented Jul 19, 2012

That's not a bug - process.exit() is an imperative that says "exit now!".

When stdout/stderr is a pipe (as is the case with child processes) and said pipe is full, pending data gets lost. Waiting until the pipe drains is not an option, that could hang the process indefinitely.

Software, it's all tradeoffs. :-/

@bnoordhuis bnoordhuis closed this Jul 19, 2012

@seanmonstar

This comment has been minimized.

Copy link

seanmonstar commented Jul 19, 2012

The same thing happens when there is an error.

In other cases, I've wanted to process.exit(1) to say that the end result was a failure, but not necessarily to QUIT NAOW!

It makes debugging infuriating, when I try to leave console.log('hi') at various lines to see how far the subprocess even got, but it doesn't get flushed.

@bnoordhuis

This comment has been minimized.

Copy link
Member

bnoordhuis commented Jul 19, 2012

I don't know if it helps your particular case but pass {stdio:['pipe','pipe','ignore']} to child_process.spawn() and log errors with console.error() instead of console.log(). That'll make errors get logged to a tty instead of a pipe (provided you don't pipe or redirect the stderr output of the parent process, of course).

@isaacs

This comment has been minimized.

Copy link

isaacs commented Jul 19, 2012

@bnoordhuis did you mean ['pipe','pipe','inherit']?

@seanmonstar Maybe you want to listen to the close event instead of the exit event?

@isaacs

This comment has been minimized.

Copy link

isaacs commented Jul 19, 2012

@seanmonstar Maybe you want to listen to the close event instead of the exit event?

Oh, wait, I see. Never mind.

@seanmonstar

This comment has been minimized.

Copy link

seanmonstar commented Jul 19, 2012

I'm currently converting a couple bash scripts we have to nodejs, so they can be cross platform. This is what tripped me up:

if [ ! -x "$CERTIFY"] ; then
  echo "cant find certify"
  exit 1
fi

I wrote this for the nodejs version:

if (!existsSync(CERTIFY)) {
  console.error('cannot find certify');
  process.exit(1);
}

Then, when I group up several of the scripts into a single deploy script, using child_process, I won't get the error messages. What's the better way to do this in node?

@matthiasg

This comment has been minimized.

Copy link

matthiasg commented Jan 18, 2013

obviously we would not want to hang the process on process.exit but giving it a 'reasonable' amount of time to flush buffers (a few dozen ms) in case anything has not been drained yet might make sense.

alternatively what is the best practice to check on whether all console streams have indeed been drained? several people are trying but not really making much progress here..

@simondean

This comment has been minimized.

Copy link

simondean commented May 31, 2013

@matthiasg I've seen the following code used to wait for stdout to empty. However having come across a bug caused by it, I've done some testing and found the code doesn't actually work. See below for the code the demonstrates the bug.

var waitingIO = false;
process.stdout.on('drain', function() {
  if (waitingIO) {
    // the kernel buffer is now empty
    process.exit(0);
  }
});
if (process.stdout.write("")) {
  // no buffer left, exit now:
  process.exit(0);
} else {
  // write() returned false, kernel buffer is not empty yet...
  waitingIO = true;
}

Here's the code to demonstrate the bug: git://github.com/simondean/node-spawn-lost-output-bug.git

>git clone git://github.com/simondean/node-spawn-lost-output-bug.git
>cd node-spawn-lost-output-bug

Testing the above code for draining stdout:

>node spawn_console.js bin/console_drain
bin: bin/console_drain
Flush succeeded 861 times
Flush failed 139 times
Flush failed 13.900000000000002% of the time

Here's the same test ran against a console app that makes no attempt to drain stdout:

>node spawn_console.js bin/console
bin: bin/console
Flush succeeded 866 times
Flush failed 134 times
Flush failed 13.4% of the time

I've worked out another way to drain stdout:

var code = 0;

process.on('exit', function() {
  process.exit(code);
});

Here's the test for the new approach:

>node spawn_console.js bin/console_on_e
xit
bin: bin/console_on_exit
Flush succeeded 1000 times
Flush failed 0 times
Flush failed 0% of the time
@matthiasg

This comment has been minimized.

Copy link

matthiasg commented Jun 6, 2013

@simondean thanks for your input ... that looks interesting and quite counterintuitive :) especially since it could be misunderstood as an endless loop. I will give it a try ...

if it works though, one should really dive into the code and investigate the root cause and the root reason as to why this fixes anything ;)

@simondean

This comment has been minimized.

Copy link

simondean commented Jun 8, 2013

@matthiasg I wonder if it would help if node provided another way to set the process exit code without having to call process.exit(code);

Then you could do something like:

process.setExitCode(1);

instead of:

var code = 1;

process.on('exit', function() {
  process.exit(code);
});
@am11

This comment has been minimized.

Copy link

am11 commented Dec 29, 2013

Is this issue still under consideration?

We are having a same problem with IcedCoffeeScript npm, when the process is executed from .NET's System.Diagnostics.Process. madskristensen/WebEssentials2013#358 (we fixed it with a very ugly hack -> using cmd /c redirect stdOut to a temporary file, read error message from file and delete the temp file. i.e. unnecessary overhead).

It looks like the StdOut gets the EXITLEVEL before the sub-process has returned the output message. However, the exit cod is always correct (0 for success and non-zero for failure).

@StephaneHeav

This comment has been minimized.

Copy link

StephaneHeav commented Jun 25, 2014

I am a bit late but yesterday, i met the same problem.
To solve the problem (not totally), i used spawn with fs.pipe like this :

    var outFile = __dirname+'/out.log';
    var errFile = __dirname+'/err.log';
    var out = fs.openSync(outFile, 'a');
    var err = fs.openSync(errFile, 'a');

    var init = spawn('dir', [ '.' ], {stdio: [ 'ignore', out, err ]});
    init.on('stdout', function(data) {
         //DO SOMETHING
    });
    init.on('stderr',function (err) {
         //DO SOMETHING
    });
    init.on('close', function (code) {
        try {
            if (fs.existsSync(errFile)) {
                init.emit('stderr', fs.readFileSync(errFile));
                fs.closeSync(err);
                fs.unlinkSync(errFile)
            }
            if (fs.existsSync(outFile)) {
                init.emit('stdout', code, fs.readFileSync(outFile));
                fs.closeSync(out);
                fs.unlinkSync(outFile)
            }
        } catch (err) {
            //DO SOMETHING
        }
    })

Don't forget to close pipes / remove files when you have finish.

@matthiasg

This comment has been minimized.

Copy link

matthiasg commented Jun 8, 2015

@simondean so it seems the process exit event is raised only when the entire event loop has been processed and thus all pending ops been processed. So at least the data would be in the hands of the OS.

FYI: all the console tests in your project currently return a 0% failure rate on my machine but that doesnt negate your findings of course.

I understand why @bnoordhuis closed this and i would concur generally, but there should be an easy and documented way to exit the process (stop timers and pending request handlers, data input etc, while still allowing outgoing buffers to flush) or at the very least a simple way to check for any pending outgoing data so the code might decide to go into a waiting mode (whether that results in an infinite loop is up to that coder in app space then)

denebolar pushed a commit to denebolar/jsdoc that referenced this issue Jul 14, 2017

Hendrik Millner
Deferred process.exit() to allow STDOUT pipe to flush
Since process.exit() is an imperative that exits immediately, pending
contents written to STDOUT is lost, if STDOUT is connected to a pipe
(as it is, for example, when used by sphinx-js to generate automatic
class descriptions).

The deferred exit in this commit allows STDOUT to flush its full
contents, before the jsdoc process exits with the designated exit code.

Please see
nodejs/node-v0.x-archive#3737 (comment)
for details.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.