search

pact-foundation / pact-js

JS version of Pact. Pact is a contract testing framework for HTTP APIs and non-HTTP asynchronous messaging systems.
https://pact.io
Other
1.63k stars 346 forks source link

EventEmitter memory leak warning in jest #397

Open ertrzyiks opened 4 years ago

ertrzyiks commented 4 years ago

Software versions

Expected behaviour

No memory leak warning in jest

Actual behaviour

Serial spec execution with jest is accompanied with the warning:

(node:99515) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 drain listeners added to [WriteStream]. Use emitter.setMaxListeners() to increase limit
(node:99515) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added to [WriteStream]. Use emitter.setMaxListeners() to increase limit
(node:99515) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [WriteStream]. Use emitter.setMaxListeners() to increase limit

Steps to reproduce

https://github.com/ertrzyiks/jest-pact-memory-leak-example

Let me copy-paste the findings from the repo for easier access:

The problem

The internal logger pipes to stdout stream as a side effect of importing the file: https://github.com/pact-foundation/pact-js/blob/842185388ce1449c7cd47a51f5c44b80a4cc6771/src/common/logger.ts#L6

When using jest in band mode (--runInBand param) files are imported separately for each test file in the same process. That means stdout stream is piped repeatedly depending on the number of test files.

Steps to reproduce

yarn test
Screenshot 2019-12-08 at 08 14 15

Steps to get rid of the warning

Dive into ./node_modules/@pact-foundation/pact/common/logger.js and comment out the mentioned line:

prettyStdOut.pipe(process.stdout);

re-run yarn test and see no warning.

mefellows commented 4 years ago

Thanks @ertrzyiks, appreciate the detailed feedback. I'll add this to the backlog for review and update. If you're interested, I'd happily accept a PR for the fix.

ertrzyiks commented 4 years ago

@mefellows I could give it a shot, I just need some more time to wrap my head around the codebase. I suppose the fix would be to avoid the side effects of require.

Meanwhile, I find this issue as an extra motivator to go for parallel testing which would be faster and free from the warning.

TimothyJones commented 4 years ago

You might also be interested in some of the work @YOU54F and I have been doing with Jest and Pact here - this allows parallel tests.

sankalan-sharechat commented 4 years ago

Hey @ertrzyiks I would also love to help/tag along to understand how you fix this so that I can also start contributing to pact. Lemme know if I can help :) I could also help you document the changes you make.

ertrzyiks commented 4 years ago

@sankalan-sharechat I created a work in progress branch https://github.com/pact-foundation/pact-js/pull/399

I realized that removing .pipe() call eliminates the memory leak. Given that last release of https://www.npmjs.com/package/bunyan-prettystream happened 6 years ago before jumping into fixing the issue on its own I consider migrating away from it first. To do that I need to:

If the plan above fails, I would see what happens to the stream param we pass to the logger since passing stdout string directly doesn't cause the memory leak and if possible replicate that with prettystream instead of piping.

ertrzyiks commented 4 years ago

What I found is that:

I added pact-js setup to https://github.com/ertrzyiks/jest-pact-memory-leak-example so we can see logs during yarn test command execution. To keep bunyan and eliminate memory leaks from sequential jest run I submitted https://github.com/pact-foundation/pact-js/pull/399 but I believe the current bunyan setup requires too much hassle and it could be replaced with another logging library that does not require JSON to text transformation.

Please let me know what are your thoughts on that @mefellows

YOU54F commented 4 years ago

Pink looks good and is actively maintained. I am looking at migrating our work projects to use this logger as you have noted, Bunyan is no longer maintained

https://github.com/pinojs/pino

TimothyJones commented 4 years ago

Very happy to replace Bunyan in both pact-node and pact-js - we probably should make an issue for it to track the todo.

TimothyJones commented 4 years ago

figure out what is the purpose of this library and what is the behavior we expect from it

I'm afraid I can't shed any light on this - @mefellows ?

mefellows commented 4 years ago

Thanks for your research and careful response @ertrzyiks.

There is no attachment from my end to Bunyan. To be honest, it's been a pain in the neck for a while now (particularly the bloody native dependency it tries to install).

The particular library was introduced as it was a stream based implementation of the pretty printing capabilities, but also to be kept in line with Pact Nodes logging.

Not that I want to make this PR too big but, it would also be nice to be able to configure the logging to write to disk at some point too, so the stdout isn't so polluted for those who want it.

But a good first step would be fixing this issue, which is a genuine problem.

but I believe the current bunyan setup requires too much hassle and it could be replaced with another logging library that does not require JSON to text transformation.

100%. As long as the DSL is backwards compatible (read logLevel doesn't change) I don't see a huge set of requirements for this. A bonus would be a drop in replacement of the interface in the code base without requiring a replace all for the logger.info type statements.

Pino looks good, I'd be happy to see that given a go. The smaller the better, we really don't take advantage of anything fancy.

neezer commented 4 years ago

Any update on this? I'm encountering the same MaxListenersExceededWarning as @ertrzyiks

mefellows commented 4 years ago

No update sorry, PR's welcome.

neezer commented 4 years ago

AFAYK is the work just "fix the issue" or "migrate from Bunyan to Pino"? Wasn't completely clear reading through the history where y'all ended up on this.

ertrzyiks commented 4 years ago

We had one attempt with #399 but it did not get too much attention. Without any suggestion on what kind of contribution is expected instead I gave up on fixing it.

mefellows commented 4 years ago

Thanks @ertrzyiks, from memory (pun not intended) it didn't fix the problem, so that's why it wasn't merged. I could be wrong about it not working.

neezer commented 4 years ago

The repo @ertrzyiks provided shows warnings as previously described that concern WriteStream. Turning on --trace-warnings points directly to the Bunyan line previously mentioned. Editing those lines as was proposed in #399 fixes the issue... partially: #399 only edits @pact-foundation/pact-js and not @pact-foundation/pact-node, where the same line & library are present. I'm presuming this might be one reason @TimothyJones encountered the issue on his test repo with the changes from #399.

Alternatively, @TimothyJones 's example repo prints out the same warnings as @ertrzyiks 's example repo as well as two additional warnings for process concerning exit and SIGINT, so it's also possible that the WriteStream errors were eliminated(ish) but nearly identical warnings were still present.

I ran both repos locally unmodified, then did the following:

  1. Ran a local instance of verdaccio — using yarn/npm link was insufficient to accurately test this in my experience
  2. Compiled and published https://github.com/pact-foundation/pact-node/pull/238 to my local repository
  3. Installed newly-published package into @pact-foundation/pact locally
  4. Compiled and published [as yet unpublished changes meant as an update to #489 in order to complement https://github.com/pact-foundation/pact-node/pull/238, wherein I use the logger defined by @pact-foundation/pact-node and eliminate src/common/logger.ts completely from this repo] to my local repository
  5. Installed newly-published package into both test repositories mentioned above
  6. Ran both test suites with & without --trace-warnings enabled
    • the warnings never appeared in @ertrzyiks 's example repo
    • the warnings for WriteStream never appeared in @TimothyJones 's example repo, but warnings for process remained

The warnings for process: exit/SIGINT trace back to here: https://github.com/pact-foundation/pact-node/blob/master/src/pact.ts#L42-L43. I'm about to dive in there to see what those are about.

I find it interesting @ertrzyiks 's example repo did not produce the same warnings for process: exit/SIGINT, which might be a hint at the nature of the underlying problem. Lacking any additional insight or corrections, I feel confident that retiring Bunyan in both https://github.com/pact-foundation/pact-node/pull/238 and #489 should fix (exactly) issue described here—accepting that a very similar issue might still exist in a part of Pact not related to logging.

cc @mefellows