Lost stdout output when executed through child_process.spawn

[simondean]

Hi. I'm writing a node module for executing cucumber-js features across multiple processes and multiple machines. I've hit an issue when executing cucumber-js via child_proces.spawn. 5-15% of the time, cucumber-js exits without outputting anything to stdout (normally I'm using the JSON formatter).

You can see the bug by running the following code (spawn_cucumber.js):

var ChildProcess = require('child_process');

var count = 1000;
var finishCount = 0;
var failCount = 0;

function test() {
  var child = ChildProcess.spawn('node', ['node_modules/cucumber/bin/cucumber.js', 'features'], {
    cwd: '.',
    stdio: ['ignore', 'pipe', process.stderr],
    env: process.env
  });

  var stdoutData = [];

  child.stdout.on('data', function(data) {
    stdoutData.push(data);
  });

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

  child.on('close', function(code, signal) {
    finishCount++;

    if (stdoutData.length == 0) {
      failCount++;
    }

    if (finishCount < count) {
      test();
    }
    else {
      console.log('Flush succeeded ' + (count - failCount) + ' times');
      console.log('Flush failed ' + failCount + ' times');
      console.log('Flush failed ' + (failCount / count * 100) + '% of the time');
    }
  });

  child.on('disconnect', function() {
    console.log('disconnect');
  });
}

test();

There's also a copy of the above code here: git://github.com/simondean/node-spawn-lost-output-bug.git

Here's some example ouput:

>node spawn_cucumber.js
Flush succeeded 929 times
Flush failed 71 times
Flush failed 7.1% of the time

The issue is in bin/cucumber.js:

  var code = succeeded ? 0 : 1;
  var exitFunction = function() {
    process.exit(code);
  };

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

If the above is replaced with the following it fixes the issue:

  var code = succeeded ? 0 : 1;

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

Thanks
Simon

[jbpros]

Could you make this a pull request?

[simondean]

Will do. Thanks

[simondean]

I've found that resource leaks (thinks that keep the event loop active) can cause cucumber-js to never exit. The fix is to replace

  var code = succeeded ? 0 : 1;

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

with

  var code = succeeded ? 0 : 1;

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

  var timeoutId = setTimeout(function () {
    console.error('Cucumber process timed out after waiting 60 seconds for the node.js event loop to empty.  There may be a resource leak.  Have all resources like database connections and network connections been closed properly?');
    process.exit(code);    
  }, 60 * 1000);

  if (timeoutId.unref) {
    timeoutId.unref();
  }
  else {
    clearTimeout(timeoutId);
  }

This is compatible with old and new versions of node but you only get the benefit of the timeout with node 0.10 onwards (see the if (timeoutId.unref) conditional above). See http://nodejs.org/api/timers.html#timers_unref for the documentation on the new unref method.

[jbpros]

Hi Simon,

Is this still relevant?

Also, I'm thinking the warning message and the timeout could become pretty annoying when testing applications with servers running. An express application, for example, will not let the event loop empty and forcing a process.exit() call right after the tests were run is a pretty efficient way of short-circuiting this.

WDYT?

[jbpros]

@simondean Please reopen if you still experience this issue.

[simonlampen]

Hi Simon and Julien,
This still seems relevant, I was experiencing a test failure running the cucumber-js tests themselves issue , (cli.features) because the stdout was not flushed, and Simon your patch does fix it.
I am on the latest node (v0.10.26) on Win7 64bit.

Cheers
Simon

[joshtombs]

I'm still experiencing this problem. When i run

require('cucumber').Cli(specs).run(function (succeeded) {
  var code = succeeded ? 0 : 1;

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

  var timeoutId = setTimeout(function () {
    console.error('Cucumber process timed out after waiting 60 seconds for the node.js event loop to empty.  There may be a resource leak.  Have all resources like database connections and network connections been closed properly?');
    process.exit(code);
  }, 60 * 1000);

  if (timeoutId.unref) {
    timeoutId.unref();
  }
  else {
    clearTimeout(timeoutId);
  }
});

And a test fails, nothing is logged. I am trying to log the duration of the tests right before process.exit but even the log "exiting" isnt being executed.

Not sure if this issue needs reopening, or if maybe theres a bug in my code but for whatever reason I can't catch process.on('exit')

[simondean]

@joshtombs Which version of node.js are you using?

[joshtombs]

@simondean v0.10.29

[simondean]

process.on('exit') will only fire when the node.js event loop is empty. Having something like an open database or HTTP connection will prevent the process from exiting. Does the timeout fire? Do you see the output from the console.error?

[joshtombs]

Above is what's being outputted from terminal. As you can see my test failed and the error was reported. The feature file finished, and this is at the end of the "(::) failed steps (::)" report. It displays the error and then exits. The log isnt being hit in

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

Then as shown when I check the status of the previous exit it is 0. Thanks!

[simondean]

Is spec your command line args for Cucumber?

Does it work properly if you use the offical bin for cucumber-js? E.g. ./node_modules/.bin/cucumber-js

[joshtombs]

Yeah, so I forked cucumber-js and ran the default cucumber-js features/ directory and everything works as expected. When I manipulated the ./bin/cucumber.js file and adjusted the "on exit" function, it worked as I would expect it to, logging "exiting" right before exiting the process. Also, when running a failing feature it exits with the correct exit code.

That said, I am using cucumber-js inside a project that I'm working on, which can just be thought of as a layer that sits on top of cucumber right now. specs is just an array that is passed instead of the true process.argv. We manipulate command line arguments and have created some of our own, so we groom them and then pass them in specs to cucumber in a way that cucumber understands.

I would like to be able to pass my own callback function to the runtime, so that is why I am just calling require('cucumber').Cli(specs).run(func...).

[simondean]

Does it sound like the bug is maybe in your code then? It's worth checking you don't have more than 1 listener for the process exit event. It's worth checking the docs for the exit event too: http://nodejs.org/api/process.html#process_event_exit It gives some guidance for things not to do in an exit listener.

Calling process.exit from the exit event is really trick. The process would have exited anyway, the trick just provides a way to change the exit code from the default of zero.

[joshtombs]

@simondean you were right! So after digging further into our code, I noticed that we were using our own

@registerHandler "AfterFeatures", (event, callback) =>
    # code

and not actually calling that callback function! so the tree walker wasn't actually finishing.

Thanks for the help

[kaworu]

Cucumber hanging 60sec is quite annoying, there is no way to know what ressource is keeping the event loop busy and a lot of modules (ex. connect-mongostore, zombiejs) don't provide a way to clean their ressource(s).

[bitplanets]

For mongoose you can do:

var hooks = function(){
    this.After(function(cb){
        this.mongoose.connection.close()
        cb();
    });
};
module.exports = hooks;

[zs-zs]

I also think that this 60 second exit timeout is very annoying, especially if you cannot tell what causes your resource leak.
Just for curiosity, why did you decide to use a timeout at all? You could simply call process.exit(code) without any timeout.
I mean by not subscribing to process exit as it was originally, but calling the process.exit(); right from the CucumberJS CLI's finished callback.

Or this would trace back to the original stdout lost issue?

[simondean]

@zs-zs node.js does not finish processing the event loop or flush any output to STDOUT or STDERR when you call process.exit();

I can't remember whether this is a Windows specific issue or affects other OSs too

See nodejs/node-v0.x-archive#3737 for more info

[jbpros]

@zs-zs The timeout seemed to be the best compromise, I'm not so sure anymore as it made Cucumber responsible for user land leaked resource management and that arbitrary timeout is indeed annoying.

I've reverted back to a non-timeout approach on master. @simondean @zs-zs @kaworu please give it a try and tell us if it awakes old demons.

@simondean I've used your flush test script against that new code:

arwen:tmp jbpros$ time node flush-test.js 
Run #1000
Flush succeeded 1000 times
Flush failed 0 times (0%)

real    5m33.214s
user    5m4.271s
sys 0m34.389s

[kaworu]

hi @jbpros,

I've tested master using npm install cucumber/cucumber-js and everything is running fine here.

As far as I can see 23ff860 solved the timeout issue we have in some projects where it's hard to know what ressources is leaking and/or which library.

[jbpros]

Thanks @kaworu. That's one happy person, right.

Who's next? :)

[charlierudolph]

Closing as this issue moves through a few different solutions that span over a couple years. If you are still experiencing this issue with the latest versions, please open a new issue

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.