EventEmitter memory leak warning in jest

[ertrzyiks]

Software versions

• OS: Mac OSX 10.14
• Consumer Pact library: Pact JS v9.5.0
• Provider Pact library: none
• Node Version: v12.10.0

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

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]

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]

@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]

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]

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]

@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:

• figure out what is the purpose of this library and what is the behavior we expect from it
• expand the example to actually use Pact in order to see the logger in action
• look for alternatives, maybe the functionality we are looking for is already available in bunyan core

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]

What I found is that:

• bunyan itself provides logging with JSON messages and prettystream is used to replace JSON with human-readable message.
• bunyan-prettystream was introduced https://github.com/pact-foundation/pact-js/commit/57f7352bb6eedddc211e0f7b3d75d6c1ffcd0825 for consistency with pact-node.
• The node version is not really happy about using bunyan though https://github.com/pact-foundation/pact-node/blob/8e904a402a28c4e4a7924b48c4413c93f92bdb8c/src/logger.ts#L11

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]

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]

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]

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]

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]

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

[mefellows]

No update sorry, PR's welcome.

[neezer]

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]

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]

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]

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