Pino: Warning: possible EventEmitter memory leak detected

[stephanebruckert]

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)

[mcollina]

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]

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]

are you using extreme mode? Or a specific transform on top of
process.stdout?
Il giorno gio 8 dic 2016 alle 18:52 Stéphane Bruckert <
[email protected]> ha scritto:

Closed #144 https://github.com/pinojs/pino/issues/144.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/pinojs/pino/issues/144#event-887231431, or mute the
thread
https://github.com/notifications/unsubscribe-auth/AADL49wbCxQXDMqbI2DjAAI7ve12wj8Xks5rGEPPgaJpZM4LIEzD
.

[robertrossmann]

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]

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]

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

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]

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