Jest: EventEmitter memory leak

[morungos]

I've seen similar issues reported but without much explanation, and yet, this is manifesting as a Jest issue.

Basically, Jest tests:

• Start OK
• After about 8-9 files, throw the leak warning
• Usually run to completion, but fairly often crash out on a GC out of memory
• End with a process that won't ^C.

Watch mode seems to alleviate it as it often gets through a run on a subset of files. Then a re-run might well throw the leak warning.

The issue only manifests part way through a full test run. Partial tests complete OK, so something some of my tests are doing don't seem to be cleaned up right.

Versions:

• Jest - 2.0.4
• Node - v6.10.0
• npm - 3.10.10

Note that the code is very distantly linked to most of my testing, but it does appear to manifest in require calls around node-pre-gyp and signal-exit. So I'm wondering if there's some mock/require logic not handling the teardown in some cases. It happens at about nine test files, by which time DBs have been opened and closed a hundred or so times. The number of files is 11 +/- 3, hence my suspicion.

It could be it's not a Jest issue -- that has been said a few times on other issues -- but I've checked carefully, and (for example) the DB is being properly torn down after each test.

Hopefully this trace can help someone put me on the right track.

Full backtrace is as follows:

(node:59201) Warning: Possible EventEmitter memory leak detected. 11 SIGABRT listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:28:1)
    at process.addListener (events.js:28:1)
    at /Users/stuart/git/turalt-portal/node_modules/sqlite3/node_modules/node-pre-gyp/node_modules/npmlog/node_modules/gauge/node_modules/signal-exit/index.js:28:1
    at Array.filter (native)
    at load (/Users/stuart/git/turalt-portal/node_modules/sqlite3/node_modules/node-pre-gyp/node_modules/npmlog/node_modules/gauge/node_modules/signal-exit/index.js:28:1)
    at Object.<anonymous>.module.exports (/Users/stuart/git/turalt-portal/node_modules/sqlite3/node_modules/node-pre-gyp/node_modules/npmlog/node_modules/gauge/node_modules/signal-exit/index.js:26:5)
    at Object.Gauge (/Users/stuart/git/turalt-portal/node_modules/sqlite3/node_modules/node-pre-gyp/node_modules/npmlog/node_modules/gauge/index.js:28:1)
    at Object.<anonymous> (/Users/stuart/git/turalt-portal/node_modules/sqlite3/node_modules/node-pre-gyp/node_modules/npmlog/log.js:28:13)
    at Runtime._execModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModuleOrMock (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Object.<anonymous> (/Users/stuart/git/turalt-portal/node_modules/sqlite3/node_modules/node-pre-gyp/lib/node-pre-gyp.js:10:3)
    at Runtime._execModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModuleOrMock (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Object.<anonymous> (/Users/stuart/git/turalt-portal/node_modules/sqlite3/lib/sqlite3.js:1:1)
    at Runtime._execModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModuleOrMock (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Client_SQLite3._driver (/Users/stuart/git/turalt-portal/node_modules/knex/lib/dialects/sqlite3/index.js:28:1)
    at Client_SQLite3.initializeDriver (/Users/stuart/git/turalt-portal/node_modules/knex/lib/client.js:28:1)
    at Client_SQLite3.Client (/Users/stuart/git/turalt-portal/node_modules/knex/lib/client.js:28:1)
    at new Client_SQLite3 (/Users/stuart/git/turalt-portal/node_modules/knex/lib/dialects/sqlite3/index.js:28:1)
    at Knex (/Users/stuart/git/turalt-portal/node_modules/knex/lib/index.js:28:1)
    at Object.getDatabase (/Users/stuart/git/turalt-portal/src/service/lib/database.coffee:1:1)
    at Object.<anonymous> (/Users/stuart/git/turalt-portal/src/service/lib/application.coffee:30:3)
    at Runtime._execModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModuleOrMock (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Object.<anonymous> (/Users/stuart/git/turalt-portal/src/service/lib/routers/metrics-router.coffee:10:3)
    at Runtime._execModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModuleOrMock (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Object.<anonymous> (/Users/stuart/git/turalt-portal/jest/supports/agent.js:12:3)
    at Runtime._execModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModuleOrMock (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Object.<anonymous> (/Users/stuart/git/turalt-portal/__tests__/service/routers/response-router.js:2:17)
    at Runtime._execModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at Runtime.requireModule (/Users/stuart/git/turalt-portal/node_modules/jest-runtime/build/index.js:28:1)
    at jasmine2 (/Users/stuart/git/turalt-portal/node_modules/jest-jasmine2/build/index.js:28:1)
    at runTest (/Users/stuart/git/turalt-portal/node_modules/jest/node_modules/jest-cli/build/runTest.js:28:1)
    at promise.then (/Users/stuart/git/turalt-portal/node_modules/jest/node_modules/jest-cli/build/TestRunner.js:28:1)

Do you want to request a feature or report a bug?

What is the current behavior?

Jest tests run through, but throw a warning. Process then hangs on exit, won't respond to ^C. Jest also frequently runs out of memory in a GC (this might be unrelated).

If the current behavior is a bug, please provide the steps to reproduce and either a repl.it demo through https://repl.it/languages/jest or a minimal repository on GitHub that we can yarn install and yarn test.

Hard as it's non-public code, but I can assemble something if it'll take this forward.

[thymikee]

Can you provide a repro of this?

[morungos]

Okay, the repo to reproduce is at: https://github.com/morungos/jest-leak-test

The package.json shows a few commands, all of which fail. It's probably deep in SQLite, but the single-worker processes show the error above. The multiple worker version also fails with database lock issues. So right now, I can't test at all until I resolve one or both.

You can get a fuller trace with:

node --trace-warnings node_modules/.bin/jest -i

This is all on macOS Sierra by the way, and oddly, one of these is leaving borked node processes hanging outside my Terminal system.

A few thoughts.

• SQLite doesn't like two processes accessing a DB at the same time, unless you set journal_mode to WAL. Without that, one worker process is needed to avoid the tests failing with busy errors. Hence the -i
• With this added and using multiple workers, the EventEmitter error seems to go away, or at least be deferred so it doesn't happen in this small test.
• By and large -i and -w 1 seem to show identical warnings.

[shelldandy]

I'm having that same issue when running more than 4 tests at the same time, just some basic yeoman-assert tests :(((((

[morungos]

Anything I can do more to help on this?

[cpojer]

This is not a Jest bug, this is a bug with the library that is not tearing down event emitters after a successful test run. You need to make sure that you clean up any resources at the end of a run.

Note we have thousands of tests at FB that all run in a single run, and we aren't experiencing this issue. We did have a bug once with both the react-native and the Jest tests running into the same issue, and every time it was a leaky handler that wasn't removed properly.

[morungos]

Sorry to follow up late on this, but I could really use some assistance. Can you give me any clue at all as to how to identify which handler is responsible and how to remove it? As the example shows, even without any of my code in there, it jams up all the tests. I'm glad it works at FB, but that doesn't really help.

If you are confident it's an SQLite driver issue I am happy to follow it up there, but I don't want them to shout at me claiming it's a Jest issue.

[pupudu]

Hi @morungos
I had a similar issue today and here's how I debugged that.

First I enabled traces for warnings in node when running tests using jest. To do that, instead of running jest on the command line, I ran:
node --trace-warnings node_modules/.bin/jest

Doing this showed me where the events were being attached. In my case, newrelic was the culprit. But in your case, it would be something else. The solution I used for this is to completely disable newrelic for jest tests, by declaring a mock in the root __mocks__ directory.

[telpochyaotl]

I had a similar issue with jest today.... The solution: Unmount your component after each test.