Winston 3.0.0 still halts logging in high stress. Makes it unusable for us.

[kramer65]

Please tell us about your environment:

• version winston@3.0.0
• node -v outputs: v8.10.0
• Operating System: Ubuntu 18.04
• Language: ES6

This issue has been closed, but running the following code (which I also posted here) still stops Winston logs from working within a second or so:

"use strict";

let winston = require('winston');

const myFormat = winston.format.printf(info => {
    return `${info.timestamp} ${info.level}: ${info.message}`;
});
const logger = winston.createLogger({
    level: 'info',
    format: winston.format.timestamp(),
    transports: [
        new winston.transports.File({filename: 'logs/combined.log'}),
        new winston.transports.Console({format: winston.format.combine(winston.format.timestamp(), myFormat), level: 'debug'})
    ]
});

while (true) {
    let random_string = Math.random().toString(36).substring(7);
    logger.info(random_string);  // This one stops after a while
    console.log(random_string);  // while this one continues to function properly
}

[mempf]

Using while(true) in this example is going to starve the event loop and prevent asynchronous code (writing to your log file) from running. A modified version of this that is more node friendly could look something like this:

const winston = require('winston');

const myFormat = winston.format.printf(info => {
    return `${info.timestamp} ${info.level}: ${info.message}`;
});
const logger = winston.createLogger({
    level: 'info',
    format: winston.format.timestamp(),
    transports: [
        new winston.transports.File({filename: 'logs/combined.log'}),
        new winston.transports.Console({format: winston.format.combine(winston.format.timestamp(), myFormat), level: 'debug'})
    ]
});

function main() {
  let random_string = Math.random().toString(36).substring(7);
  logger.info(random_string);  // This one stops after a while (this call executes asynchronous code)
  console.log(random_string);  // while this one continues to function properly (I believe this is a synchronous function in node)
  setImmediate(main);
}

main();

[DABH]

@mempf is right, if you block the event loop like with while(true) then any async node code (not winston-specific) will eventually hang. Does his^ example above work fine for you?

@mempf We had the same problem within our project. We use "bottleneck" to prevent the problem. In our case, we sometimes log a bunch of entries at once and winston hung up in the past. We use bottleneck to "queue" calls of the log function. This fixed our problem. Our LoggerService looks like this (typescript):

import * as winston from 'winston';
import * as bottleneck from 'bottleneck';

const { printf, combine, colorize } = winston.format;

const logLevels = {
  levels: {
    error: 0,
    warn: 1,
    info: 2,
    http: 3,
    sql: 4,
    debug: 5
  },
  colors: {
    error: 'red',
    warn: 'yellow',
    info: 'green',
    http: 'blue',
    sql: 'blue',
    debug: 'gray'
  }
};
winston.addColors(logLevels);

export const jsonFormatter = (logEntry: any) => {
  const base = { timestamp: new Date() };
  const json = Object.assign(base, logEntry);
  const today = new Date();
  const day = today.toISOString().split('T')[0];
  const hours = today.getUTCHours();
  const minutes = today.getUTCMinutes();
  logEntry['message'] = `[${day} ${hours}:${minutes} UTC]: ${json.message}`;
  return logEntry;
};

/**
 * Logger Service. Handles logging with winston. Service handles logging time intervals with bottleneck.
 * Bottleneck, because winston will hang up under heavy load.
 */
export const LoggerService = {
  /** "Bottleneck" Limiter for Logger */
  bottleneck: new bottleneck.default({
    maxConcurrent: 1,
    minTime: 5
  }),
  /** Winston logger. See https://github.com/winstonjs/winston#creating-your-own-logger for more details  */
  logger: winston.createLogger({
    level: 'info',
    format: combine(
      colorize(),
      winston.format(jsonFormatter)(),
      printf((info: any) => `${info.level}: ${info.message}`)
    ),
    transports: [
      new winston.transports.File({ filename: 'error.log', level: 'error' }),
      new winston.transports.File({ filename: 'combined.log' })
    ],
    exceptionHandlers: [
      new winston.transports.File({ filename: 'exceptions.log' })
    ]
  }),
  /** Returns winston logger */
  getLogger() {
    return LoggerService.logger;
  },
  /**
   * Logs an event with winston
   * @param param0.level Log level. e.g. warn, info, error
   * @param param0.message Log message
   */
  log({ level, message } : {level: string, message: string }) {
    LoggerService.bottleneck.schedule({}, () => {
      return Promise.resolve(LoggerService.getLogger().log({ level, message }));
    });
  }
};

LoggerService.logger.add(new winston.transports.Console({
  format: winston.format.simple()
}));

[gnorbsl]

We have the same problem, winston stops outputting after receiving a lot of input. I'm not familiar enough with node to implement the above example into my project. So any help would be appreciated.

[tonestrike]

This is our code:

'use strict'

const appRoot = require('app-root-path')
const winston = require('winston')
const { Papertrail } = require('winston-papertrail')
const moment = require('moment')
const serializerr = require('serializerr')


const format = winston.format.combine(
  winston.format.colorize({message: true, levels: true}),
  winston.format.timestamp(),
  winston.format.align(),
  winston.format.simple(),
  winston.format.printf((info) => {
    let { timestamp, level, message, error, data } = info
    if (error && error instanceof Error) {
      let serializedError = serializerr(error)
      if (serializedError) message += `\t${JSON.stringify(serializedError)}`
    } else if (error && typeof error === 'object') {
      message += `\t${JSON.stringify(error)}`
    } else if (error) {
      message += `\t${error}`
    }

    if (data && typeof data === 'object') {
      message += `\t${JSON.stringify(data)}`
    } else if (data) {
      message += ` ${data}`
    }
    const ts = moment.utc(timestamp).format('YYYY-MM-DD HH:mm:ss Z')

    return `${ts} [${level}]: ${message}`
  })
)

// Create the Papertrail Transport
const papertrail = new Papertrail({
  host: 'logs4.papertrailapp.com',
  port: 12910,
  hostname: process.env.PAPERTRAIL_HOSTNAME,
  handleExceptions: true,
  json: true,
  format: format,
  levels: {
    critical: 0,
    error: 1,
    warn: 2,
    info: 3,
    debug: 4
  },
})

// Like with the Logger error, just output error to
// stderr if there's an error with writing to Papertrail.
papertrail.on('error', (error) => {
  console.error('Error logging to Papertrail', {error})
})


const options = {
  file: {
    level: 'info',
    filename: `${appRoot}/logs/app.log`,
    handleExceptions: true,
    exitOnError: false,
    json: true,
    maxsize: 5242880, // 5MB file chunks
    maxFiles: 5,
    format: format
  },
  output: {
    level: 'debug',
    handleExceptions: true,
    json: false,
    align: true,
    exitOnError: false,
    format: format,
    levels: {
      critical: 0,
      error: 1,
      warn: 2,
      info: 3,
      debug: 4
    },
    colors: {
      critical: 'red bold',
      error: 'red italic',
      warn: 'yellow bold',
      info: 'green',
      debug: 'blue'
    }
  }
}

// Set transports
let transports = []

if (process.env.NODE_ENV !== 'local') {
  transports = [
    new winston.transports.File({ filename: `${appRoot}/logs/app.log`, level: 'error' }),
    papertrail
  ]
} else {
  transports = [
    new winston.transports.Console(options.output)
  ]
}

// Create Winston Logger instance.
const logger = winston.createLogger({
  level: 'info',
  levels: options.output.levels,
  transports: transports
})

winston.addColors(options.output.colors)

// If there is an error with the Winston logger,
// don't try to use the logger, just output to stderr.
logger.on('error', (error) => {
  console.error(error)
})


logger.streamError = {
  write (message) {
      logger.info(`Express Request Error: ${message}`)
  }
}

module.exports = logger

When we try to log anything, it causes a delay of multiple seconds which is unacceptable. Any thoughts?

[tonestrike]

It is interesting, because even if we remove all transports, this still causes a huge spike in CPU (90% vs 4%) and slows down our code substantially (less than a second to run a method vs over 10).

[samothx]

I am experiencing the same behaviour and I think it makes no sense to work around it.
A logger if it is to be taken seriously should not be the source of a system locking up. I can see that when a system goes into overload, so does the event queue. But it usually recovers. Winston in my case does not. It blocks the system even after the load is gone.
This might be due to stream buffers overflowing and there is nothing you can do against that, except wait for the drain event and drop all logs that arrive meanwhile. Maybe count them and then log a critical error saying 200 logs have been dropped due to congestion.
If winston cannot handle this then you can not use it in critical systems.

[kramer65]

@kollerebbe - Thanks for your tip on bottleneck. We've been testing it for a while now and it more or less solved all our problems. And using the actual working logging we were also able to fix a memory leak.. 👍

For me that solves the problem, which means I could close this issue. I've got the feeling that more people in here have the same issue though.

@the other people in here (@samothx , @tonestrike @gnorbsl ) did you guys also try the bottleneck code? If not, try it out and post here if that solves your problems.. or not

[tonestrike]

We have not tried the bottleneck code. A lot of our issues were based around the size of the logs. If a particular log had a large JSON, Winston would spike our CPU to 90%+. However, if we stringified the JSON prior to passing it into Winston, we do not see such a huge spike. If we run into further issues, we will check out the bottleneck code above.

[MerkAndreas]

Same here...
I tried the bottleneck without solving the problem.
If I log in a for-loop the index variable, after 14 entries logging with winston stops, console.log continues.

[mherger]

@kramer65 would you know what was bringing down your node instance? Memory use? CPU?

We're experiencing a memory leak with Winston 3.0.0. Unfortunately we cannot reproduce it. It just happens every now and then (see #1445). Therefore we cannot easily test whether Bottleneck would help us. Would be great if some of you could confirm it's helping with memory leaks, too. Thanks!

[zoellner]

Seeing the same issue in our application. Can't reproduce yet but do see the memory climb up and the CPU go to max right around the time when it stops logging.

[kramer65]

@mherger - We experienced high CPU (~100%) and when the CPU spiked, the memory would rise as well. If at some point the CPU lowered to less than 100% (due to temporary less logging demands), Winston would use that breathing time to store all the logs from the queue and the memory would also lower to the normal level. If the CPU spiked for too long however, the memory would rise until it would reach 100% and then node would stop because of a memory error.

Bottleneck solved it for us because the logging would not interfere with the normal running of the program. This did have the effect that in case of high CPU, the logs would be written way after they were initiated. I tested this by writing the moment the log was initiated as well as the moment the log was written. At some points I saw a half an hour delay between the moment the log was initiated and when it was written. Since our logs are normally used for analysis at a later point that is not a problem for us.

We've decided to rewrite our whole application into golang though, since we simply need higher performance.

I hope this helps you to find the problem in your application. Let me know if I can be of any more help.

[zoellner]

Another observation that might be related: Logging in long running processes eventually stops

We use winston together with express-winston. Some services run for days without restarting and we're now observing that there are no logs anymore after about 4-5 days or so even without a high load.

[paularmstrong]

This is still an issue with 3.1.0. I can actively reproduce it with apache bench after attempting to write just 10 log messages to a file.