Winston: Got MaxListenersExceededWarning while using winston.

[LvChengbin]

I got a warning message while using [email protected] after calling the createLogger function multiple times in my test cases.

(node:28754) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 end listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:280:19)
    at DerivedLogger.addListener (events.js:297:10)
    at DerivedLogger.Readable.on (_stream_readable.js:772:35)
    at DerivedLogger.once (events.js:341:8)
    at DerivedLogger.Readable.pipe (_stream_readable.js:580:9)
    at DerivedLogger.add (/Users/NS/yk/node_modules/winston/lib/winston/logger.js:299:8)
    at DerivedLogger.<anonymous> (/Users/NS/yk/node_modules/winston/lib/winston/logger.js:82:12)
    at Array.forEach (<anonymous>)
    at DerivedLogger.Logger.configure (/Users/NS/yk/node_modules/winston/lib/winston/logger.js:81:24)
    at DerivedLogger.Logger (/Users/NS/yk/node_modules/winston/lib/winston/logger.js:22:8)
    at new DerivedLogger (/Users/NS/yk/node_modules/winston/lib/winston/create-logger.js:24:44)
    at Object.module.exports [as createLogger] (/Users/NS/yk/node_modules/winston/lib/winston/create-logger.js:58:10)

[ChrisAlderson]

Could you provide an example on how to reproduce this issue on master?

[DABH]

FWIW I'm also seeing this on the file stress test on master with npm run test, something like
(node:32041) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 drain listeners added. Use emitter.setMaxListeners() to increase limit
Not sure exactly what's going on yet but would be good to get to the bottom of this...

[LvChengbin]

I found it would happen if using an instance of transport in createLogger more than maybe 10 times, for example:

const winston = require( 'winston' );

const transports = [
    new winston.transports.Console(),
];

for( let i = 0, l = 10; i < l; i += 1 ) {
    winston.createLogger( { transports } );
}

After running the code above, I got this result:

$node winston.js
(node:39048) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 unpipe listeners added. Use emitter.setMaxListeners() to increase limit
(node:39048) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit

@DABH don't reuse transport instance if you are doing that.

But in my project, I don't think I did anything like this, so I am still trying to find out what makes this issue in my code.

[mempf]

This is almost certainly being caused by the number of log events waiting for the stream buffer to drain exceeds the default max limit for event listeners. (See Node.js documentation here)

In winston2 there was code that used the "setMaxListeners()" function to Infinity for the file transport, we should consider increasing the limit passed the default value of 10 for the stream used in the file transport.

Edit: Just noticed the test case mentioned here uses the console transport only but the same problem can occur in the file transport. @LvChengbin Are use using a file transport in your testing while seeing this?

@ChrisAlderson I see what your doing with your fix/gh-1334 branch but I have some concerns about that solution. Once again referring to the Node.js documentation on streams. Once a call to .write returns false we should prevent further writes from occurring until the buffer clears on its own due to the operating system accepting the data. In your solution you are setting up a one time event to listen for the drain event but then immediately and forcibly emitting the drain event. I can't see how this would be the intended way to use node streams and I fear while it allows the current test cases to pass we are would then be writing to the buffer of the stream before its actually drained and creating further backup.

[DABH]

Thanks @mempf for the insights. We came to some similar conclusions chatting in our gitter channel.

If we just do something like this https://github.com/winstonjs/winston/compare/master...DABH:no-max-listeners?expand=1 , it does seem to silence those warnings. But I wonder whether we are masking a bug in that case? Or if we should somehow warn the user about the potential performance degradation? etc. I do think we want to avoid e.g. calling stream.emit('drain') as I think that is the stream's job to emit that event (we should just listen for it).

[mempf]

"By default EventEmitters will print a warning if more than 10 listeners are added for a particular event. This is a useful default that helps finding memory leaks. Obviously, not all events should be limited to just 10 listeners."

So to me this means we have at least 10 log messages potentially waiting for the stream buffer to drain when we start to see this message. So I guess the real question is how many log messages should be allowed to wait for the buffer to drain before warnings and performance become a concern. The fact that we are getting into this condition in the first place means we are failing to keep up with OS level disk writes already (hopefully only temporarily). So what is the right call here? Not sure, but probably not an event limit of 10.

Edit: In my worst case testing I have found that a event limit of 16 seems to be where the warnings go away. So maybe a good suggestion would be to set the limit to 20-30 instead of Infinity? (This number is likely to vary from system to system with slower systems requiring a higher value because it has even more difficulty keeping up

[DABH]

Sounds reasonable to me, will let @indexzero weigh in and see if just setting the limit to something like 30 sounds like the right call here...

[indexzero]

Hmmm ... seems somewhat reasonable to increase the limit, but I'm not sure if this warning will still be present because it's from node itself iirc.

[mempf]

The warning is emitted purely to help a developer identify a potential memory leak. In this case we are not leaking memory so much as falling behind the file system writes but it seems to cause the default maximum (where it starts to warn) to be exceeded during the file stress test and seemingly its possible to occur in more innocent scenarios but in my most extreme of testing (attempting to write multiple GB of log data in just a few seconds) only attached a maximum of 16 drain listeners.

The original cause of this bug report doesn't even stem from the file transport but from possible reusing transports in a way that was unintended. I was more concerned with @DABH mention that he saw similar errors in the file stress test.

Finally if we refer back to winston2 code we see that these listener limits were set to Infinity.

[DABH]

Yeah, it's just an efficiency thing really as @mempf notes. If the transport falls sufficiently behind then it creates "too many" (>10) listeners waiting for the drain event to fire so writing can continue. Or, in the OP's case, if you setup a bunch of loggers all sharing the same transport, then that will also create (I guess) some listeners on the transport per logger, which add up (whether that is a usage anti-pattern is another story -- if you are creating many loggers all with the same transport, shouldn't you just be sharing one singleton logger across your code...).

I've opened #1344 which bumps the limit to 30 and should silence these warnings, at least in the winston test cases. If the OP's issues persists, maybe there is another transport where the limit should be bumped, but I'd be a little skeptical of doing so per the above discussion.

[indexzero]

Fixed in #1344

[Acionyx]

Problem still exists for DailyRotateFile. Code above is enough to reproduce issue.

[DABH]

The snippet above where a bunch of transports are created? If so, why are you creating so many transports? It would be great to understand your use case better, maybe there is a better usage pattern. The max listeners thing is just a warning, so it shouldn't break anything, but performance could degrade with a bunch of listeners (e.g. many transports).

[Acionyx]

Yep. My case: I'm trying to label messages from different modules with winston 3.0, e.g.
[DB] Connected ok, [Main] Server started ok.
So what i want to do, is simple call on the top of file, like this: const logger = createNamedLogger('Main');, where createNamedLogger is my wrapper to create logger with labeled Console and File transports.

I tried to find easy way to do such trivial thing, but i did not found it in docs.

[Acionyx]

Interesting thing is that Console transport doesn't cause such error, only File. I did not compared source code of both transports, but it seems like potential bug.

[DABH]

Yeah, the Console transport is less complex and has fewer event emitters/listeners.

A better (more efficient) design for your use case is to use a singleton logger+transport plus a custom formatter, something like

// logger.js
export const namedFormatter = (info, opts) => {
  info.message = `[${opts.name}] ${info.message}`; 
  return info;
};

export const globalLogger = winston.createLogger({
  level: 'info',
  format: namedFormatter,
  transports: [
    new winston.transports.File({ filename: 'combined.log' })
  ]
});

export const namedLog = (name) => {
    return (level, message, meta?) => globalLogger.log({name: name, level, message, meta});
};

// DB.js
import namedLog from 'logger.js';

const log = namedLog('DB');

// ...

log('info', 'Connected ok');

It is slightly awkward to pass arguments to formatters at log-time, but that is one potential solution (note: untested, there may be syntax errors etc.!). But the overall point is that you probably only need one Logger, and probably only one Transport per logging destination (file, console, etc.).

[Acionyx]

@DABH, thank you for your example. It pushed me to combine few solutions of my own and yours and to get result i need. Let me show how i did it, i think some of that ideas can be included in winston or winston modules because they are very common for users.

Goals:

1. Allow >1 arguments to all logging methods
2. Formatter that will print full stack of Error of any type
3. Wrapper for labeling (our first issue)
4. Colorize only Level in message

All above should work together. Here is my current realization:

const loggerParams = {
  level: process.env.NODE_ENV === 'development' ? 'info' : 'info',
  transports: [
    new winston.transports.Console({
      format: winston.format.combine(
        winston.format.timestamp({
          format: 'YYYY-MM-DD HH:mm:ss'
        }),
        winston.format.printf(
          info =>
            `${info.timestamp} [${winston.format
              .colorize()
              .colorize(info.level, info.level.toUpperCase())}]: ${
              info.group ? `[${info.group}]` : ``
            } ${info.message}`
        )
      )
    }),
    new DailyRotateFile({
      filename: config.logFileName,
      dirname: config.logFileDir,
      maxsize: 2097152, //2MB
      maxFiles: 25
    })
  ]
};

const cleverConcatenate = args =>
  args.reduce((accum, current) => {
    if (current && current.stack) {
      return process.env.NODE_ENV === 'development'
        ? `${accum}
        ${current.stack}
        `
        : `${accum} ${current.message}`;
    } else if (current === undefined) {
      return `${accum} undefined`;
    } else {
      return `${accum} ${current.toString()}`;
    }
  }, '');

const proxify = (logger, group) =>
  new Proxy(logger, {
    get(target, propKey) {
      if (
        ['error', 'warn', 'info', 'http', 'verbose', 'debug', 'silly'].indexOf(
          propKey
        ) > -1
      ) {
        return (...args) => {
          if (args.length > 1) {
            args = cleverConcatenate(args);
          }
          return target.log({ group, message: args, level: propKey });
        };
      } else {
        return target[propKey];
      }
    }
  });

const simpleLogger = winston.createLogger(loggerParams);
const logger = proxify(simpleLogger, null);
const createNamedLogger = group => proxify(simpleLogger, group);

export default logger;
export { createNamedLogger };

There are few things to polish in future (and remove hardcode), of course .

[daniyel]

Hi.

I was also having problems with my app. I started to get this warnings Possible EventEmitter memory leak detected. 16 unpipe listeners added. Use emitter.setMaxListeners() to increase limit. After installing this module max-listeners-exceeded-warning, I found out it was something wrong with winston. After searching for the fix, I found this issue and solution from @DABH helped me get rid of the warning.

We were using Console transport in such way:

...
const transports = [new winston.transports.Console()];

function logger(name: string, level?: string): Logger {
    if (!level) {
        level = getLoggingLevel();
    }
    return createLogger({
        format: createLogFormat(name),
        transports,
        level
    });
}
...

After removing const transports = [new winston.transports.Console()]; and putting it directly into transports, the warnings were gone. Now I do it this way:

...
function logger(name: string, level?: string): Logger {
    if (!level) {
        level = getLoggingLevel();
    }
    return createLogger({
        format: createLogFormat(name),
        transports: [
            new winston.transports.Console()
        ],
        level
    });
}
...

[radiumrasheed]

@DABH, thank you for your example. It pushed me to combine few solutions of my own and yours and to get result i need. Let me show how i did it, i think some of that ideas can be included in winston or winston modules because they are very common for users.

Goals:

1. Allow >1 arguments to all logging methods
2. Formatter that will print full stack of Error of any type
3. Wrapper for labeling (our first issue)
4. Colorize only Level in message

All above should work together. Here is my current realization:

const loggerParams = {
  level: process.env.NODE_ENV === 'development' ? 'info' : 'info',
  transports: [
    new winston.transports.Console({
      format: winston.format.combine(
        winston.format.timestamp({
          format: 'YYYY-MM-DD HH:mm:ss'
        }),
        winston.format.printf(
          info =>
            `${info.timestamp} [${winston.format
              .colorize()
              .colorize(info.level, info.level.toUpperCase())}]: ${
              info.group ? `[${info.group}]` : ``
            } ${info.message}`
        )
      )
    }),
    new DailyRotateFile({
      filename: config.logFileName,
      dirname: config.logFileDir,
      maxsize: 2097152, //2MB
      maxFiles: 25
    })
  ]
};

const cleverConcatenate = args =>
  args.reduce((accum, current) => {
    if (current && current.stack) {
      return process.env.NODE_ENV === 'development'
        ? `${accum}
        ${current.stack}
        `
        : `${accum} ${current.message}`;
    } else if (current === undefined) {
      return `${accum} undefined`;
    } else {
      return `${accum} ${current.toString()}`;
    }
  }, '');

const proxify = (logger, group) =>
  new Proxy(logger, {
    get(target, propKey) {
      if (
        ['error', 'warn', 'info', 'http', 'verbose', 'debug', 'silly'].indexOf(
          propKey
        ) > -1
      ) {
        return (...args) => {
          if (args.length > 1) {
            args = cleverConcatenate(args);
          }
          return target.log({ group, message: args, level: propKey });
        };
      } else {
        return target[propKey];
      }
    }
  });

const simpleLogger = winston.createLogger(loggerParams);
const logger = proxify(simpleLogger, null);
const createNamedLogger = group => proxify(simpleLogger, group);

export default logger;
export { createNamedLogger };

There are few things to polish in future (and remove hardcode), of course .

see my updated gist below...
https://gist.github.com/radiumrasheed/9dafdadabd1674b8f9ea967acfbd3947

[iranianpep]

I had the same issue, it got fixed by calling winstonLoggerInstance.clear() which clears all the transports

[RikdeVos]

I had the same issue, and it was because I was using ts-node-dev to run my TypeScript node app on my local machine. When building the TS app and running node ./dist hereafter, Winston wouldn't crash.

[trykers]

I had the same issue, I resolved using method https://github.com/winstonjs/winston/issues/1334#issuecomment-399634717 (with Proxy) like this :

const myCustomLevels = {
  levels: {
    error: 0,
    warn: 1,
    info: 2,
    success: 3,
    debug: 4,
    silly: 5
  } as config.AbstractConfigSetLevels,
  colors: {
    error: 'bold red',
    warn: 'bold yellow',
    info: 'bold magenta',
    success: 'bold green',
    debug: 'bold blue',
    silly: 'bold gray'
  } as config.AbstractConfigSetColors
};

interface CustomLevels extends Logger {
  success: LeveledLogMethod;
}

const dailyRotateFileTransport = new (transports.DailyRotateFile)({
  filename: 'logs/application-%DATE%.log',
  datePattern: 'YYYY-MM-DD-HH',
  zippedArchive: true,
  maxSize: '20m',
  maxFiles: '30d'
});

const transportsConfig = [
  new transports.Console({ level: 'silly' }),
  dailyRotateFileTransport
];

const myFormat = printf(({ level, message, label, timestamp, ms, showMs }) => {
  return `${timestamp} [${label}] ${level}: ${message} ${showMs ? `==> (\u001b[33m${ms}\u001b[39m)` : ''}`;
});

const logger = <CustomLevels>createLogger({
  transports: transportsConfig,
  levels: myCustomLevels.levels,
  format: combine(
    timestamp(),
    colorize(),
    ms(),
    myFormat)
});

addColors(myCustomLevels.colors);

const subLogger = (label: string = 'APP', showMs: boolean = false) => new Proxy(logger, {
  get(target, propKey) {
    if (Object.keys(myCustomLevels.levels).includes(String(propKey))) {
      return (...args) => target.log({ label, group: null, message: args.join(' '), level: String(propKey), showMs })
    } else {
      return target[propKey];
    }
  }
});

export { subLogger };

Now I can call like this :

import subLogger from './logger';
const log = subLogger(`BDD`, true); // true will ask to show ms()
log.debug('Hello');

Produce :

2020-03-28T18:21:01.955Z [BDD] debug: Hello ==> (+0ms)

with no MaxListenersExceededWarning 😄