Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stryker returns only timeouts (mostly when using Jest) #613

Closed
ronderksen opened this issue Feb 7, 2018 · 27 comments
Closed

Stryker returns only timeouts (mostly when using Jest) #613

ronderksen opened this issue Feb 7, 2018 · 27 comments
Assignees
Labels
🐛 Bug Something isn't working

Comments

@ronderksen
Copy link

Summary

When I run stryker on Jest tests, I get only timeout results.
Running with logLevel: 'trace' gives this output:

[2018-02-07 08:56:27.944] [TRACE] TestRunnerChildProcessAdapter - [2018-02-07 08:56:27.943] [DEBUG] IsolatedTestRunnerAdapterWorker - UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): error

[2018-02-07 08:56:28.040] [TRACE] TestRunnerChildProcessAdapter - [2018-02-07 08:56:28.040] [DEBUG] IsolatedTestRunnerAdapterWorker - UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 2): Error: timeout

[2018-02-07 08:56:28.044] [TRACE] TestRunnerChildProcessAdapter - [2018-02-07 08:56:28.044] [DEBUG] IsolatedTestRunnerAdapterWorker - UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 3): Error: timeout

[2018-02-07 08:56:28.636] [TRACE] TestRunnerChildProcessAdapter - [2018-02-07 08:56:28.635] [DEBUG] IsolatedTestRunnerAdapterWorker - UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 4): Error: User unknown

Stryker config

const path = require('path');

module.exports = function(config) {
  config.set({
    files: [
      {
        pattern: 'src/app/AppRoot.js',
        mutated: true,
        included: false,
      },
      'src/public/**/*',
      'src/app/**/*.scss',
      'src/app/**/AppRoot.spec.js',
      'src/app/**/AppRoot.spec.js.snap',
      'src/**/*',
      'test/*',
      'development/*',
    ],
    testRunner: 'jest',
    mutator: 'javascript',
    transpilers: ['babel'],
    reporter: ['html', 'clear-text', 'progress'],
    coverageAnalysis: 'off',
    babelrcFile: '.babelrc',
    jest: {
      config: require(path.resolve(__dirname, './test/jest.config.json')),
    },
  });
};

Stryker environment

├─┬ stryker@0.18.2
├─┬ stryker-api@0.12.0
├─┬ stryker-babel-transpiler@0.2.4
├─┬ stryker-html-reporter@0.11.5
├─┬ stryker-javascript-mutator@0.3.3
├─┬ stryker-jest-runner@0.4.0
├─┬ stryker-webpack-transpiler@0.1.2

Your Environment

software version(s)
node v8.9.4
npm v.5.5.1
Operating System macOS v10.13.2
@simondel
Copy link
Member

simondel commented Feb 7, 2018

Thanks for reporting this! I have three questions so far:

  1. Is this during the initial test run or have the mutants been generated and are they being tested (causing timeouts)?
  2. Is this a React project? If so, has it been created using create-react-app?
  3. Could you try running stryker without the transpiler array in your config? Does that make a difference?

@ronderksen
Copy link
Author

  1. The mutants have been generated and they are causing timeouts.
  2. It is a React project, but it's a custom build. No create-react-app has been harmed ;).
  3. That makes no difference

@automeow
Copy link

automeow commented Feb 8, 2018

I have the same issue (every mutant is TimedOut) but I don't have any errors when I run it with trace.

My config:

    files: [
      'src/assets/**/*',
      'src/**/*.test.js',
      'src/**/*.story.js',
      'src/**/__snapshots__/*.snap',
      '.storybook/*.js',
      'jest-results.json',
      { pattern: 'src/**/*.js', included: false, mutated: true }
    ],
    logLevel: 'all',
    timeoutMs: 20000,
    testRunner: 'jest',
    mutator: 'javascript',
    reporter: ['dots', 'html'],
    htmlReporter: {
      baseDir: 'test/results/mutation/html'
    },
    coverageAnalysis: 'off',
    plugins: [
      'stryker-jest-runner',
      'stryker-html-reporter',
      'stryker-babel-transpiler',
      'stryker-javascript-mutator'
    ],
    babelrcFile: '.babelrc',
    transpilers: ['babel'],
    jest: {
      project: 'react'
    }

My info level output:

$ node_modules/.bin/stryker run

[2018-02-08 12:01:22.600] [INFO] ConfigReader - Using stryker.conf.js in the current working directory.
[2018-02-08 12:01:22.827] [INFO] InputFileResolver - Found 1 of 159 file(s) to be mutated.
[2018-02-08 12:01:22.829] [INFO] InitialTestExecutor - Starting initial test run. This may take a while.
[2018-02-08 12:01:22.830] [INFO] BabelConfigReader - Reading .babelrc file from path "~/react/.babelrc"
[2018-02-08 12:01:47.543] [INFO] InitialTestExecutor - Initial test run succeeded. Ran 606 tests in 24 seconds.
[2018-02-08 12:01:47.617] [INFO] Stryker - 91 Mutant(s) generated
[2018-02-08 12:01:48.030] [INFO] BabelConfigReader - Reading .babelrc file from path "~/react/.babelrc"
[2018-02-08 12:01:50.717] [INFO] SandboxPool - Creating 7 test runners (based on CPU count)
TTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTT
[2018-02-08 12:07:40.898] [INFO] HtmlReporter - Your report can be found at: file://~/react/test/results/mutation/html/index.html
[2018-02-08 12:07:41.303] [INFO] Stryker - Done in 6 minutes 18 seconds.

Any trace/debug output just looks like this:

T[2018-02-08 12:14:02.409] [TRACE] TestRunnerChildProcessAdapter - [2018-02-08 12:14:02.409] [DEBUG] PluginLoader - Loading plugins stryker-javascript-mutator

[2018-02-08 12:14:02.420] [TRACE] TestRunnerChildProcessAdapter - [2018-02-08 12:14:02.420] [DEBUG] IsolatedTestRunnerAdapterWorker - Changing current working directory for this process to ~/react/.stryker-tmp/sandbox4220055

Results are a score of 100%, as every mutation times out.

I would really like to use this library, so any help is much appreciated 😄

@nicojs
Copy link
Member

nicojs commented Feb 8, 2018

@ronderksen @automeow could you share your code in any way? If not, could you create a small repo that reproduces the problem and publish that somewhere? That would help us a lot debugging this issue. Thanks in advance!

@automeow
Copy link

automeow commented Feb 8, 2018

FYI I have now fixed this by setting the timeoutMs to 60000. My tests take 26 seconds to run so maybe this was the issue (5000ms not enough)? This might be different to @ronderksen's issue as I had no errors.

New output:

$ node_modules/.bin/stryker run

[2018-02-08 12:29:28.939] [INFO] ConfigReader - Using stryker.conf.js in the current working directory.
[2018-02-08 12:29:29.176] [INFO] InputFileResolver - Found 48 of 159 file(s) to be mutated.
[2018-02-08 12:29:29.177] [INFO] InitialTestExecutor - Starting initial test run. This may take a while.
[2018-02-08 12:29:29.178] [INFO] BabelConfigReader - Reading .babelrc file from path "~/react/.babelrc"
[2018-02-08 12:29:55.613] [INFO] InitialTestExecutor - Initial test run succeeded. Ran 606 tests in 26 seconds.
[2018-02-08 12:29:55.858] [INFO] Stryker - 182 Mutant(s) generated
[2018-02-08 12:29:56.311] [INFO] BabelConfigReader - Reading .babelrc file from path "~/react/.babelrc"
[2018-02-08 12:29:59.249] [INFO] SandboxPool - Creating 7 test runners (based on CPU count)
SSS.ES..S.S.SSSSSSSSSS.S..S.S..ES.S....TTT.S.TTTT.S.S.S.......S..SS..SS..SS..SSSS.ST.S..TTT....STTT..S......S.......................TSSSTTTTSS...S.S..T.T.....S.SSSSS.S.S............T
[2018-02-08 12:45:13.749] [INFO] HtmlReporter - Your report can be found at: file://~/react/test/results/mutation/html/index.html
[2018-02-08 12:45:14.192] [INFO] Stryker - Done in 15 minutes 45 seconds.

Hope this can help others

Cheers!

@nicojs
Copy link
Member

nicojs commented Feb 8, 2018

Glad to hear it @automeow. 26 seconds is a lot of quite a lot of time :)

(5000ms not enough)?

Well.. the timeout used by stryker is not 5000ms. Rather, it is the result of this calculation:

timeoutForTestRunMs = timeOfTheInitialTestRunMs * timeoutFactor + timeoutMs

Here the timeoutMs is set to 5000 by default.

@Archcry could there be a problem with the timeOfTheInitialTestRunMs reported by the jest runner? That would explain why people are forced to override the timeoutMs value.

@automeow
Copy link

automeow commented Feb 9, 2018

@nicojs Could it be that jest parallelises test runs? Given the initial test run will be able to use all the cores, but subsequent runs can only use 1, the subsequent runs should take far longer?

EDIT: running jest with --maxWorkers=1 makes my tests take ~60 seconds instead of <30 seconds

@nicojs
Copy link
Member

nicojs commented Feb 9, 2018

EDIT: running jest with --maxWorkers=1 makes my tests take ~60 seconds instead of <30 seconds

We use the runInBand option to mitigate that problem. That should force the maxWorkers to 1 by default, but apparently not?
@Archcry do you know if can be the problem?

An other issue might be that our formula was originally designed for pretty fasts tests, in that the 5 second offset is already pretty long. But on a max time of 26 second, 5 seconds is pretty much an after thought. Combine that with the max concurrent test runners and you can get a lot of timeouts potentially.

@automeow could you slice the maxConcurrentTestRunners in half and see if that solves the problem for you? (leave the timeoutMs at 5s)

@automeow
Copy link

automeow commented Feb 9, 2018

@nicojs I have tried with 3 concurrent runners and 1, but I have the same issue:

[2018-02-09 14:06:15.087] [INFO] ConfigReader - Using stryker.conf.js in the current working directory.
[2018-02-09 14:06:15.375] [INFO] InputFileResolver - Found 84 of 149 file(s) to be mutated.
[2018-02-09 14:06:15.376] [INFO] InitialTestExecutor - Starting initial test run. This may take a while.
[2018-02-09 14:06:15.377] [INFO] BabelConfigReader - Reading .babelrc file from path "~/.babelrc"
[2018-02-09 14:06:39.812] [INFO] InitialTestExecutor - Initial test run succeeded. Ran 606 tests in 24 seconds.
[2018-02-09 14:06:40.684] [INFO] Stryker - 842 Mutant(s) generated
[2018-02-09 14:06:41.568] [INFO] BabelConfigReader - Reading .babelrc file from path "~/.babelrc"
[2018-02-09 14:06:44.719] [INFO] SandboxPool - Creating 1 test runners (based on maxConcurrentTestRunners config)
TTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTT

@nicojs
Copy link
Member

nicojs commented Feb 9, 2018

@automeow thanks for your reply. For now, you can increase the timeoutMs setting. We will continue investigating this issue.

@sanderkoenders
Copy link
Member

sanderkoenders commented Feb 9, 2018

We use the runInBand option to mitigate that problem. That should force the maxWorkers to 1 by default, but apparently not?
@Archcry do you know if can be the problem?

Runinband

Alias: -i. Run all tests serially in the current process, rather than creating a worker pool of child processes that run tests. This can be useful for debugging. (https://facebook.github.io/jest/docs/en/cli.html#runinband).

It should only use one worker when using runinband.

@Archcry could there be a problem with the timeOfTheInitialTestRunMs reported by the jest runner? That would explain why people are forced to override the timeoutMs value.

The Jest runner now returns the duration of each individual test as seen here.

@nicojs
Copy link
Member

nicojs commented Feb 9, 2018

Ok, so we're missing the overhead of the start and end of a test run. Right now, we don't really have a way of factoring in that overhead into the calculation. Our assumption is that the overhead should be caught with the timeoutMs. @simondel do you think we should change our calculation?

@simondel
Copy link
Member

@nicojs I don't think we should change our calculation just yet. We don't change the Jest config in any way right now I recall it correctly. So if someone turns on code coverage using Jest, it will always run with code coverage on, making it slow on every run and increasing the chance of having this issue.

@automeow @ronderksen Could you two create reproduction repositories for the issue to help us figure out if we could perhaps speed up the Jest runner? Perhaps there's also something else that we can do.

@lunafi-dorian
Copy link

lunafi-dorian commented Feb 11, 2018

👍 for similar issue. will follow the thread 💯 I get timeout results when the report finishes, but I don't get any timeouts on console when I am running in trace or all. Note: My code is almost all try/catch and async/await (if that helps)

jest config:

module.exports = {
  rootDir: './',
  verbose: true,
  collectCoverage: true,
  testEnvironment: 'node',
  collectCoverageFrom: [
    '**/*.js',
    '!build/**',
    '!coverage/**',
    '!jest-config.js',
    '!rollup.config.js',
    '!.styker-tmp/**',
    '!reports/**'
  ],
  coverageDirectory: '<rootDir>/coverage',
  testResultsProcessor: './node_modules/jest-junit'
};

stryker config

module.exports = function (config) {
  config.set({
    files: [
      {
        pattern: '**/!(*.test).js',
        mutated: true,
        included: false
      },
      {
        pattern: '**/*.test.js',
        mutated: false,
        included: true
      },
      '!node_modules/**/*.js',
      'node_modules/jest-junit/**/*',
      '!node_modules/jest-junit/node_modules/**/*',
      '!coverage/**/*',
      '!build/**/*',
      '!reports/**/*',
    ],
    testRunner: 'jest',
    mutator: 'javascript',
    transpilers: ['babel'],
    reporter: ['html', 'clear-text', 'progress'],
    coverageAnalysis: 'off',
    babelrcFile: '.babelrc',
    jest: {
      config: require('./jest-config.js')
    },
    logLevel: "all"
  });
};

.babelrc

{
  "presets": [
    [
      "env",
      {
        "modules": false,
        "targets": {
          "node": "8"
        }
      }
    ]
  ],
  "plugins": ["transform-object-rest-spread"],
  "env": {
    "test": {
      "presets": [
        [
          "env",
          {
            "modules": "commonjs",
            "targets": {
              "node": "8"
            }
          }
        ]
      ]
    }
  }
}

@simondel
Copy link
Member

@lunafi-dorian Thanks for posting your setup!

How long does a regular test run take? (With coverage and without coverage)
Could you see what happens if you:

  1. Turn off code coverage
  2. Turn off verbose in the jest config
  3. Turn off code coverage and verbose

Is the jest-junit node_modules folder in your Stryker config because of the testResultsProcessor config in your jest config? Can you run it without that setting? If that's the case, we could override the property in the stryker-jest-runner so you won't have to put it in your files.

@lunafi-dorian
Copy link

lunafi-dorian commented Feb 11, 2018

14 test suites and 107 tests:

  1. running NODE_ENV=test && jest --config jest-config.js without coverage turned off it takes: 4.6 seconds (with verbose off its: 3.04 seconds).
  2. running NODE_ENV=test && jest --config jest-config.js with coverage turned on it takes: 10.83 seconds (with verbose off its: 5.82 esconds)

For stryker (Found 39 of 61 file(s) to be mutated and 914 mutations with 3 test runners, just using dots and no loglevel. Intitial test run finds all tests in 15 seconds):
3. running stryker run without coverage and with verbose turned off: still gets timeouts and test takes greater than 10 minutes to run. With coverage and verbose on and loglevel all with 3 test runners it takes over 40 minutes.

Yes the jest-junit node_modules in the stryker config is because of testResultsProcessor. I get an error that it can't find jest-junit when trying to run. I can remove that since I turned off coverage

Note: I have tried increasing timeoutMS and it doesn't help.

Hope this information helps!

@simondel
Copy link
Member

Awesome, so your regular test run takes 10 seconds. Since Stryker generates 900 mutants and runs with 3 test runners, we can say that each test runner handles 300 mutants. If all test runners can run without slowing down your system, stryker would be done after 50 minutes (300 mutants * 10 seconds / 60).

If each test run is 3 seconds (coverage and verbose off), stryker would be done after about 15 minutes (300 mutants * 3 seconds / 60). If stryker is done on your system in 10 and 40 minutes, that's not too bad given this use case.

What is the final report by stryker? How many timeouts do you get?

@lunafi-dorian
Copy link

lunafi-dorian commented Feb 12, 2018

@simondel - only 1 did not timeout. All the rest did.

I thought I would add that I do get a few of the [WARN] TestRunnerChildProcessAdapter - Received unexpected message from test runner worker process: "result" while current task is dispose. Ignoring this message. but nothing else with the "dots" reporter

@nicojs
Copy link
Member

nicojs commented Feb 14, 2018

@lunafi-dorian

The warning [WARN] TestRunnerChildProcessAdapter - Received unexpected message from test runner... is consistent with the problem we're facing. Stryker already decided that it should kill the test process, but the test process returns with a test result later on (thus unexpected).

If anyone can provide a small repo which reproduces the problem we would be very grateful

@khujo
Copy link

khujo commented Mar 30, 2018

@nicojs I'm facing the same issue when running Stryker on Windows. You can to reproduce this using this repo: https://github.com/khujo/stryker-on-mac. I'm having another issue on my MacBook (hence the name of the repo), see #291.

Setting timeoutMs to 60000 solves the issue for me.

@simondel simondel added 🐛 Bug Something isn't working backlog labels Apr 6, 2018
@nicojs
Copy link
Member

nicojs commented Apr 20, 2018

I've got an idea. During initial test run we can calculate the overhead the test runner took (total initial test run time - time for all tests to run). We can use that to add to the timeout. That way the default timeout (of 5s) should be far more than sufficient.

This can be solved by stryker and should not be implemented in test runners.

I've discussed this with @Archcry and @simondel and we're taking this into sprint.

@nicojs nicojs changed the title Stryker returns only timeouts Stryker returns only timeouts (mostly when using Jest) May 11, 2018
@nicojs nicojs added comitted and removed backlog labels May 11, 2018
@ghost ghost assigned nicojs May 11, 2018
@ghost ghost added 🛠 In progress and removed comitted labels May 11, 2018
simondel pushed a commit that referenced this issue May 18, 2018
Take test runner overhead into account when calculating the
timeout of a single mutant.

The formula is now:

```
timeoutForTestRunMs = netTimeMs * timeoutFactor + timeoutMs + overheadMs
```

Check readme for more information.

Fixes #613
@ghost ghost removed the 🔎 Needs review label May 18, 2018
@sswales
Copy link

sswales commented Aug 13, 2019

What's the current situation with this as we are running 2.0.2 and still getting this issue.

@andreadellacorte
Copy link

Would also love an update - I am running into the same issue

@jimmyandrade
Copy link

I'd also love an update. Running into the same issue 😢

@andreadellacorte
Copy link

@jimmyandrade I solved it on my side - I think the issue was I wasn't using the "smart" jest runner but just running jest directly as a command, which caused all kind of issues.

@jimmyandrade
Copy link

jimmyandrade commented Mar 11, 2020

@andreadellacorte thanks for your answer. Sorry for the delay on answering it.

Because Stryker 3.0 was released (#1983 (comment)), I updated my project dependencies and now timeouts are gone 🎉 on https://github.com/multei/openalpr/issues/4

@brodycj
Copy link

brodycj commented May 6, 2020

I think the option in stryker.conf.js was renamed to timeoutMS, wasted a few minutes before I checked it in README.md. Just a drive-by comment in case it may help someone else, landed here with help from Google.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
🐛 Bug Something isn't working
Projects
None yet
Development

No branches or pull requests