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.

Sign up for GitHub

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

Jump to bottom

Warning: possible EventEmitter memory leak detected #144

Closed
stephanebruckert opened this issue Dec 8, 2016 · 9 comments
Closed

Warning: possible EventEmitter memory leak detected #144

stephanebruckert opened this issue Dec 8, 2016 · 9 comments

Comments

@stephanebruckert
Copy link

stephanebruckert commented Dec 8, 2016 •
edited
Loading

Hi,

In my tests, I'm creating more than 10 loggers, which leads to the warnings below.
I could easily hide them by setting process.stdout.setMaxListeners(Infinity) at the top of the file, but that would be only a workaround I believe.

What's your opinion on this guys as I might not want to setMaxListeners in production? Is this something Pino should handle or should we handle it ourselves? Any way to close a stream?

Thanks

(node) warning: possible EventEmitter memory leak detected. 11 finish listeners added. Use emitter.setMaxListeners() to increase limit.
Trace
    at WriteStream.addListener (events.js:252:17)
    at WriteStream.Readable.on (_stream_readable.js:673:33)
    at WriteStream.once (events.js:278:8)
    at DestroyableTransform.Readable.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/readable-stream/lib/_stream_readable.js:567:8)
    at DestroyableTransform.stream.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/pino/pretty.js:78:10)
    at _isPretty (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:37:12)
    at Object.module.exports.serviceLogger (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:75:18)
    at Context.<anonymous> (/Users/sbruckert/Code/sdk-helpers-module/test/unit/log.test.js:121:13)
    at callFn (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:343:21)
    at Hook.Runnable.run (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:335:7)
    at next (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:309:10)
    at Immediate._onImmediate (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:339:5)
    at tryOnImmediate (timers.js:534:15)
    at processImmediate [as _immediateCallback] (timers.js:514:5)
(node) warning: possible EventEmitter memory leak detected. 11 unpipe listeners added. Use emitter.setMaxListeners() to increase limit.
Trace
    at WriteStream.addListener (events.js:252:17)
    at WriteStream.Readable.on (_stream_readable.js:673:33)
    at DestroyableTransform.Readable.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/readable-stream/lib/_stream_readable.js:485:8)
    at DestroyableTransform.stream.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/pino/pretty.js:78:10)
    at _isPretty (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:37:12)
    at Object.module.exports.serviceLogger (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:75:18)
    at Context.<anonymous> (/Users/sbruckert/Code/sdk-helpers-module/test/unit/log.test.js:132:15)
    at callFn (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:343:21)
    at Test.Runnable.run (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:335:7)
    at Runner.runTest (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:444:10)
    at /Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:550:12
    at next (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:361:14)
    at /Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:371:7
    at next (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:295:14)
    at Immediate._onImmediate (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:339:5)
    at tryOnImmediate (timers.js:534:15)
    at processImmediate [as _immediateCallback] (timers.js:514:5)
(node) warning: possible EventEmitter memory leak detected. 11 drain listeners added. Use emitter.setMaxListeners() to increase limit.
Trace
    at WriteStream.addListener (events.js:252:17)
    at WriteStream.Readable.on (_stream_readable.js:673:33)
    at DestroyableTransform.Readable.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/readable-stream/lib/_stream_readable.js:503:8)
    at DestroyableTransform.stream.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/pino/pretty.js:78:10)
    at _isPretty (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:37:12)
    at Object.module.exports.serviceLogger (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:75:18)
    at Context.<anonymous> (/Users/sbruckert/Code/sdk-helpers-module/test/unit/log.test.js:132:15)
    at callFn (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:343:21)
    at Test.Runnable.run (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:335:7)
    at Runner.runTest (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:444:10)
    at /Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:550:12
    at next (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:361:14)
    at /Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:371:7
    at next (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:295:14)
    at Immediate._onImmediate (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:339:5)
    at tryOnImmediate (timers.js:534:15)
    at processImmediate [as _immediateCallback] (timers.js:514:5)
(node) warning: possible EventEmitter memory leak detected. 11 close listeners added. Use emitter.setMaxListeners() to increase limit.
Trace
    at WriteStream.addListener (events.js:252:17)
    at WriteStream.Readable.on (_stream_readable.js:673:33)
    at WriteStream.once (events.js:278:8)
    at DestroyableTransform.Readable.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/readable-stream/lib/_stream_readable.js:561:8)
    at DestroyableTransform.stream.pipe (/Users/sbruckert/Code/sdk-helpers-module/node_modules/pino/pretty.js:78:10)
    at _isPretty (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:37:12)
    at Object.module.exports.serviceLogger (/Users/sbruckert/Code/sdk-helpers-module/lib/log.js:75:18)
    at Context.<anonymous> (/Users/sbruckert/Code/sdk-helpers-module/test/unit/log.test.js:132:15)
    at callFn (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:343:21)
    at Test.Runnable.run (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runnable.js:335:7)
    at Runner.runTest (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:444:10)
    at /Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:550:12
    at next (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:361:14)
    at /Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:371:7
    at next (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:295:14)
    at Immediate._onImmediate (/Users/sbruckert/Code/sdk-helpers-module/node_modules/mocha/lib/runner.js:339:5)
    at tryOnImmediate (timers.js:534:15)
    at processImmediate [as _immediateCallback] (timers.js:514:5)
@stephanebruckert stephanebruckert changed the title warning: possible EventEmitter memory leak detected Warning: possible EventEmitter memory leak detected Dec 8, 2016
@mcollina
Copy link
Member

mcollina commented Dec 8, 2016

How are you creating these loggers? The best approach is to create a main one, and then create as many child as you need to.
This is not happening for us.

@stephanebruckert
Copy link
Author

True, that's the approach I'm using in my code. You made me realize only the tests would create multiple "main loggers". So I will just use process.stdout.setMaxListeners(Infinity) in my test.

Thanks, closing

@mcollina
Copy link
Member

mcollina commented Dec 8, 2016 via email

@robertrossmann
Copy link

I would like to resurrect this issue and provide more context:

This happens in my tests, too, even though I have only a single pino instance in my application. To successfully replicate the warning:

  • Use the pretty printer (via prettyPrint: true) configuration option
  • Run a test suite in --watch mode (ie. mocha --watch)
  • Cause the test runner to execute the test more than 10 times (usually by saving a file multiple times)
  • Observe memory leak warning

Seems like the log data is piped through a pretty-printer stream and then sent to stdout. The pump module adds a bunch of event listeners to the pretty-printer and stdout streams which in this case eventually causes a memory leak warning due to too many error, finish and end listeners being attached to the process.stdout stream.

I could call pino.stream.end() manually but that still does not clean up all the even listeners. I think the best solution would be to have a mechanism to undo the pump module's effects on process.stdout to really fix the memory leaks.

Please note that these are memory leaks; long-running --watch tasks will eventually blow up due to memory constraints.

For completeness, below you can find the stack trace, I think it's almost the same as the original one.

(node:10399) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 finish listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:223:19)
    at WriteStream.addListener (events.js:240:10)
    at WriteStream.Readable.on (_stream_readable.js:775:35)
    at WriteStream.once (events.js:271:8)
    at DestroyableTransform.Readable.pipe (/my-project/node_modules/readable-stream/lib/_stream_readable.js:650:8)
    at DestroyableTransform.stream.pipe (/my-project/node_modules/pino/pretty.js:86:17)
    at pipe (/my-project/node_modules/pump/index.js:54:15)
    at Array.reduce (<anonymous>)
    at pump (/my-project/node_modules/pump/index.js:77:18)
    at pino (/my-project/node_modules/pino/pino.js:282:5)
    at new Atlas (/my-project/node_modules/@atlas.js/atlas/src/atlas.mjs:223:16)
    at Function.init (/my-project/node_modules/@atlas.js/atlas/src/atlas.mjs:56:19)
    at Object.<anonymous> (/my-project/src/index.mjs:10:21)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Module.require (module.js:604:17)
    at require (internal/module.js:11:18)
    at Object.<anonymous> (/my-project/test/meta/global-hooks.test.mjs:2:1)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Module.require (module.js:604:17)
    at require (internal/module.js:11:18)
    at /my-project/node_modules/mocha/lib/mocha.js:231:27
    at Array.forEach (<anonymous>)
    at Mocha.loadFiles (/my-project/node_modules/mocha/lib/mocha.js:228:14)
    at Mocha.run (/my-project/node_modules/mocha/lib/mocha.js:514:10)
    at loadAndRun (/my-project/node_modules/mocha/bin/_mocha:441:22)
    at rerun (/my-project/node_modules/mocha/bin/_mocha:469:5)
    at /my-project/node_modules/mocha/bin/_mocha:444:11
    at done (/my-project/node_modules/mocha/lib/mocha.js:545:13)
    at Runner.<anonymous> (/my-project/node_modules/mocha/lib/runner.js:842:5)
    at Runner.emit (events.js:164:20)
    at /my-project/node_modules/mocha/lib/runner.js:829:12
    at /my-project/node_modules/mocha/lib/runner.js:677:9
    at next (/my-project/node_modules/mocha/lib/runner.js:290:14)
    at /my-project/node_modules/mocha/lib/runner.js:329:7
    at done (/my-project/node_modules/mocha/lib/runnable.js:301:5)
    at /my-project/node_modules/mocha/lib/runnable.js:359:11
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:160:7)

@mcollina
Copy link
Member

You should not use prettyPrint in tests, or print logs in there for that matter. Logs are for production code, not test code (unless you are testing logging, but then you will send logs somewhere else).

A completely different solution is to rework how prettyPrint works in a way that avoids pipe or pump. If you want to send a PR, feel free to do that!

@robertrossmann
Copy link

@mcollina The test suite is for a big backend server which logs request info and other stuff. Frequently that log info is important to find a bug or other undesired behaviour. Not having the logs next to the test suite's progress info the log data is almost useless as there would be no correlation between the log data and the test which generated the log message.

I guess it's fine not to use prettyPrint in tests, it just improves on the logs' readability a lot.

@mcollina
Copy link
Member

I think something like this should work or your usecase (pseudocode):

var pino = require('pino')

// test starts..
var pretty = pino.pretty()
pretty.pipe(process.stdout)
var log = pino(pretty)

// test ends
pretty.unpipe(process.stdout)

@robertrossmann
Copy link

Thanks, I'll try the idea of manually hooking up the pretty printer. Thanks! 👍

@github-actions
Copy link

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Feb 10, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mcollina @stephanebruckert @robertrossmann