Jest: Hanging Before Coverage Output on "Running 1 test suite..."

[cpinnix]

I've been running jest tests for several versions now and I am seeing an intermittent issue where the script hangs at "Running 1 test suite..." just before printing coverage. I'm running in verbose mode with the hope of catching the error. But nothing prints.

This is my package.json config:

{
  "scripts": {
    "test": "./node_modules/jest-cli/bin/jest.js --verbose"
  },
  "jest": {
    "scriptPreprocessor": "../preprocessor.js",
    "rootDir": "src",
    "testPathIgnorePatterns": [
      "/node_modules/",
      "<rootDir>/node_modules/"
    ],
    "unmockedModulePathPatterns": [
      "react"
    ],
    "collectCoverage": true
  }
}

This is my preprocessor.js file:

var babelJest = require('babel-jest');

module.exports = {
  process: function(src, filename) {
    return babelJest.process(src, filename)
    .replace(/require\(\s*\'.*\.(css|scss|less)\'\);/gm, '');
  }
};

And some version numbers:
npm 2.14.7
node 4.2.1
jest-cli 0.6.1
babel-jest 5.3.0

[cpinnix]

Ah. Just after I wrote that. I get this output:

<--- Last few GCs --->

  176805 ms: Scavenge 1388.1 (1453.1) -> 1388.1 (1453.1) MB, 0.7 / 0 ms (+ 0.9 ms in 1 steps since last GC) [allocation failure] [incremental marking delaying mark-sweep].
  179099 ms: Mark-sweep 1388.1 (1453.1) -> 1386.8 (1453.1) MB, 2294.2 / 0 ms (+ 2.0 ms in 2 steps since start of marking, biggest step 1.1 ms) [last resort gc].
  181320 ms: Mark-sweep 1386.8 (1453.1) -> 1387.2 (1453.1) MB, 2220.5 / 0 ms [last resort gc].


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 0x2c066437399 <JS Object>
    1: SimpleSlice(aka SimpleSlice) [native array.js:~250] [pc=0x2f61c41df835] (this=0x2c066404131 <undefined>,o=0x3dad2b4ffbb9 <an Arguments with map 0x2826324cecf9>,Q=0,R=3,A=3,S=0x3dad2b4ffb99 <JS Array[1]>)
    2: ArraySlice [native array.js:~550] [pc=0x2f61c41e1dc1] (this=0x3dad2b4ffbb9 <an Arguments with map 0x2826324cecf9>,au=0x2c066404131 <undefined>,av=0x2c066404131 <undefined>)
    3: ...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory

[cpojer]

That's not good. We certainly need to get better around memory usage, something I'll be focusing on in the future but not currently, unfortunately. Do you know which test consistently hangs and whether its only one or always a different test?

[cpojer]

Can you repro this at all when you aren't using coverage? Coverage is way more expensive, so I'm wondering whether the issue is because it tries to generate coverage for a large app and it somehow fails.

[cpinnix]

Just ran twenty more tests with no coverage. The script hung twice on two different tests. To clarify, this means that the script hung after printing results for two different tests. Each test runs in parallel correct? If so, then how can we be sure it's actually hanging on two different tests, based on the console output?

I did recover one more stack trace:

<--- Last few GCs --->

  325992 ms: Scavenge 1388.1 (1453.1) -> 1388.1 (1453.1) MB, 0.2 / 0 ms (+ 0.6 ms in 1 steps since last GC) [allocation failure] [incremental marking delaying mark-sweep].
  328254 ms: Mark-sweep 1388.1 (1453.1) -> 1387.8 (1453.1) MB, 2262.2 / 0 ms (+ 1.6 ms in 2 steps since start of marking, biggest step 0.9 ms) [last resort gc].
  330474 ms: Mark-sweep 1387.8 (1453.1) -> 1388.1 (1453.1) MB, 2220.6 / 0 ms [last resort gc].


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 0x3bbec6b37399 <JS Object>
    1: create(aka create) [native v8natives.js:~754] [pc=0x3462990a177b] (this=0x3bbec6b04131 <undefined>,am=0xc95d1988f39 <an Object with map 0x208d749bca29>,aC=0x3bbec6b04131 <undefined>)
    2: arguments adaptor frame: 1->2
    3: defer(aka defer) [.../node_modules/q/q.js:545] [pc=0x3462990b9baa] (this=0x3bbec6b04131 <undefined>)
    4: then [.../git...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory

Also, to give you an idea of the amount of tests being executed:

299 tests passed (299 total in 72 test suites, run time 331.595s)

[cpojer]

oh yeah you got a lot of tests there. I also had an internal report of this and I'm hoping to find a fix for this soon but as always, these things are a bit hard to track down.

You can run your tests in the main thread using --runInBand, maybe try that together with --verbose.

[cpinnix]

Actually, I am getting another failure on another box. This one is similar to the last one. Having to deal with the q library maybe https://github.com/kriskowal/q.

<--- Last few GCs --->
FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory

  306312 ms: Scavenge 1388.4 (1453.1) -> 1388.4 (1453.1) MB, 0.2 / 0 ms (+ 2.0 ms in 1 steps since last GC) [allocation failure] [incremental marking delaying mark-sweep].
  308864 ms: Mark-sweep 1388.4 (1453.1) -> 1023.0 (1453.1) MB, 2551.7 / 0 ms (+ 3.2 ms in 2 steps since start of marking, biggest step 2.0 ms) [last resort gc].
  311601 ms: Mark-sweep 1023.0 (1453.1) -> 1023.0 (1453.1) MB, 2737.1 / 0 ms [last resort gc].


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 0x3c42a4736ae1 <JS Object>
    2: success(aka success) [.../src/main/js/stores/SessionStore.js:9] [pc=0x3f356bbeff4] (this=0x3c42a4704131 <undefined>)
    3: arguments adaptor frame: 1->0
    4: _fulfilled(aka _fulfilled) [.../node_modules/q/q.js:834] [pc=0x3f356bbee43] (this=0x3c42a4704131 <undefined>,value=...

[cpojer]

There is also node-heapdump which allows to create a heapdump of the current state of a node process that you can then open and inspect in node. I built a service at FB that used multiple contexts and had a circular reference from inside a context to the parent and it was just a mess to debug :(

[cpinnix]

I got another error around q. My theory at the moment is that one of my tests is trying to do an http request and that request is pending. The request is handled via a promise. So maybe when a promise never resolves it just sits...

My tests shouldn't be doing requests at all though. So going to dig further and make sure that isn't happening.

[cpojer]

If you do want to test Promises you can return a promise from a test (change it to pit) and it will have a 5 second timer for that promise to resolve.

[cpojer]

Feel free to ping me on the reactiflux channel for jest, as well: https://facebook.github.io/react/blog/2015/10/19/reactiflux-is-moving-to-discord.html

[cpinnix]

Got to the bottom of this issue. Basically one of my tests was doing a request, and with no internet connection, the request would just pend in a promise and eventually jest just fails.

The request was done in a flux store in response to a request data action. The problem originated from a container component test that was firing a request data action. The action hit the store and triggered the request. With the jest.autoMockOff() line at the top of the container component test. Nothing was mocked and the request was made. Simply mocking the flux store solved the issue.

All this explains the intermittent failure on machines. It was only really failing on a bad connection or when a service went down.

This is a case where I wasn't testing a promise directly, but rather indirectly through the require chain. Not sure how jest would catch something like this in the future. Perhaps this is a place where I could stub out my Api module (which does all the requests) with the moduleNameMapper option?

[cpojer]

Thanks @cpinnix for tracking this down. We have had a similar issue at FB recently so I'm wondering if they are related. @jmorrell

[anback]

For all you bright devs coming all the way to the bottom of this thread, in jest 18 the newly introduced flag --forceExit solved this for me. Install latest jest and run jest --help to see info

[cpojer]

@anback Note that use of --forceExit is discouraged and means that your tests are not cleaning up resources (like db connections etc.) and cause memory leaks while the test is run. You should use afterAll or afterEach to disconnect and tear down things.