Analysis crashes with 'too many open files'

[alexvictoor]

Summary

When running stryker on my day job project, I get a "too many open files error"
This is a project using Flow (version 0.65). I have tested the config on a small hello world project, it worked fine.

Stryker config

module.exports = function(config){
  config.set({
      logLevel: 'debug',
      mutator: "javascript",
      packageManager: "yarn",
      reporters: ["html", "clear-text", "progress"],
      testRunner: "jest",
      transpilers: [],
      coverageAnalysis: "off",
      files: [
        "./subproject/**/*.*",
      ],
      mutate: [
        "./subproject/**/*.js",
        '!**/*.spec.js',
        '!**/*.test.js',
      ],
      jest: {
        config: require('./.jest.stryker.json'),
      },
  });
}

Stryker environment

├─┬ stryker@0.30.0
│ ├── @stryker-mutator/util@0.0.1
├─┬ stryker-api@0.21.4
├─┬ stryker-html-reporter@0.16.5
│ ├── @stryker-mutator/util@0.0.1 deduped
├─┬ stryker-javascript-mutator@0.11.2
├─┬ stryker-jest-runner@1.2.4 

"jest": "^23.6.0",

Your Environment

software	version(s)
node	8.10.0
yarn	1.5.1
Operating System
MacOs 10.14

Add stryker.log

stryker.too_many_files.log

[simondel]

Hi Alex! Thanks for letting us know. Could you test this using stryker@0.29.5? With 0.30.0 we changed the way we do file management and I'm wondering if we broke it with that change or if it was already broken.

[alexvictoor]

Hello again
With stryker@0.29.5 I get a different error message:

23:29:20 (15390) INFO Stryker 2237 Mutant(s) generated
23:29:21 (15390) INFO SandboxPool Creating 8 test runners (based on CPU count)
23:29:21 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox1403658
23:29:21 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox5909173
23:29:22 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox1426186
23:29:23 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox4515750
23:29:23 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox7293265
23:29:24 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox5967824
23:29:24 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox9602536
23:29:24 (15390) DEBUG Sandbox Creating a sandbox for files in /Users/avictoor/work/fluo/.stryker-tmp/sandbox2960436
23:29:35 (15390) DEBUG Sandbox Creating test runner 0 using settings {port: 9234}
23:29:35 (15390) DEBUG ChildProcessProxy Starting /Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/ChildProcessTestRunnerWorker.js in child process undefined
23:29:35 (15390) ERROR StrykerCli an error occurred TypeError: this.worker.send is not a function
    at ChildProcessProxy.send (/Users/avictoor/work/fluo/node_modules/stryker/src/child-proxy/ChildProcessProxy.js:53:21)
    at new ChildProcessProxy (/Users/avictoor/work/fluo/node_modules/stryker/src/child-proxy/ChildProcessProxy.js:25:14)
    at Function.ChildProcessProxy.create (/Users/avictoor/work/fluo/node_modules/stryker/src/child-proxy/ChildProcessProxy.js:50:16)
    at new ChildProcessTestRunnerDecorator (/Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/ChildProcessTestRunnerDecorator.js:15:51)
    at TimeoutDecorator.testRunnerProducer (/Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/ResilientTestRunnerFactory.js:14:76)
    at TimeoutDecorator.TestRunnerDecorator.createInnerRunner (/Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/TestRunnerDecorator.js:17:33)
    at TimeoutDecorator.TestRunnerDecorator (/Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/TestRunnerDecorator.js:6:14)
    at new TimeoutDecorator (/Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/TimeoutDecorator.js:14:47)
    at RetryDecorator.testRunnerProducer (/Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/ResilientTestRunnerFactory.js:14:24)
    at RetryDecorator.TestRunnerDecorator.createInnerRunner (/Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/TestRunnerDecorator.js:17:33)

Let me know if I should bring some other changes in my config

[simondel]

Unfortunately I'm not able to reproduce this locally.
Could you try downgrading stryker-api@0.21.4 to stryker-api@0.21.2? I just noticed that we also hit that package with our file system change for any-promise

[alexvictoor]

I have downgraded stryker-api but I get the exact same error :|

[nicojs]

This is a strange problem,

23:29:35 (15390) DEBUG ChildProcessProxy Starting /Users/avictoor/work/fluo/node_modules/stryker/src/test-runner/ChildProcessTestRunnerWorker.js in child process undefined

The undefined part in this log message should be filled with the child processes process id (PID). No wonder that send isn't defined on a child process that isn't spawned.

@alexvictoor
Just for debugging sake, could you try to reduce the amount of concurrent test runners? You can do this by setting maxConcurrentTestRunners to 1 in your stryker.conf.js file.

[alexvictoor]

@nicojs the crash does not happen when maxConcurrentTestRunners is set to 1 (or even 2)...
It happens when maxConcurrentTestRunners >= 4
Looks like a concurrent issue ;)

[nicojs]

Hmm that seems like an old fashion race condition.

This is the piece of compiled javascript code that gives the error:

this.worker = child_process_1.fork(require.resolve('./ChildProcessProxyWorker'), [messageProtocol_1.autoStart], { silent: true, execArgv: [] });
this.initTask = new Task_1.Task();
this.log.debug('Starting %s in child process %s', requirePath, this.worker.pid);
this.send({
  constructorArgs: constructorParams,
  kind: messageProtocol_1.WorkerMessageKind.Init,
  loggingContext: loggingContext,
  plugins: plugins,
  requirePath: requirePath,
  workingDirectory: workingDirectory
});

The send method is here is a pass through to worker.send. If send crashes with the given error, that would mean the child_process.fork failed somehow. I didn't know that could happen. We should figure out why and harden Stryker for this problem.

Thanks @alexvictoor for all your work so far. We'll continue to investigate.

[nicojs]

As part of the rewriting of #1514 I've fixed this issue in #2498 (I hope).