Winston v3.0.0 rc1 hangs under stress when using file transport

[juanda99]

I'm using a watcher that fires an event per directory found in ./materials folder.
I create some directories for debug:

cd materials
for i in `seq 1 10000`; do mkdir $i; done

When I ran my script It hangs except if I remove file transport and use just the console.

// load dependencies
var chokidar = require('chokidar')
var fs = require('fs-extra')
var path = require('path')

const { createLogger, format, transports } = require('winston')
const { combine, timestamp, label, printf, colorize } = format

const MATERIALS = './materials'
const NODE_ENV = process.env.NODE_ENV || 'development'



// log configuration
const myFormat = printf(info => {
  return `${info.timestamp} ${info.level}: ${info.message}`
})


const logger = createLogger({
  format: combine(
    colorize(),
    timestamp(),
    myFormat
  ),
  transports: [
    new transports.File({
      filename: 'combined.log'
    })
  ]
})


//
// If we're not in production then log to the `console` with the format:
// `${info.level}: ${info.message} JSON.stringify({ ...rest }) `
// 
if (process.env.NODE_ENV !== 'production') {
  logger.add(new transports.Console({
    level: 'debug'
  }))
}

// Initialize watcher.
var watcher = chokidar.watch(MATERIALS)

// Add event listeners.
watcher
  .on('addDir', (dir) => {
    logger.info(`ADDED DIRECTORY: ${path.resolve(MATERIALS, dir)}`)
  })
  .on('error', error => logger.error(`WATCHER ERROR: ${error}`))
  .on('ready', () => logger.info('Initial scan complete, waiting for changes'))

[kramer65]

I just arrived here to report exactly this issue, but I see @juanda99 beat me to it.

So yes, I can confirm this bug.

[indexzero]

It would be really helpful if you could reproduce this in the existing stress test: https://github.com/winstonjs/winston/blob/master/test/transports/file-stress.test.js

[MeoMix]

Also occurring for me!

[indexzero]

Thanks folks. This is looking like a pretty large blocker – if you could reproduce it in the existing stress test that would be very helpful.

[kramer65]

@indexzero - Great to hear that it's a large blocker. I want to use WInstonjs in production within a week or two and I would love to start with v3 from the start, but if this problem persists I have to backport my (quite extensive) logging code to v2. So I would love to help out.

I checked out the test-code, but I don't really know how to extend that with this problem. What I can do however is give you a small example with which you can reproduce this problem:

"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
}

As commented in the last lines, the console.log() keeps functioning properly while the logger.info() stops after a second or so.

Can this help you find the issue?

[kramer65]

@indexzero - Any news on this one?

[kramer65]

@indexzero - Has there been any progress on this?

I would love to help to resolve this one, but I'm unsure how else than providing the example code I did. Maybe if you give me some guidance I can be of any more help..

[sgilligan]

This looks related to my observation. First time with winston I implemented with 3.0.0-rc1 but soon found under long running regression tests that winston would stop logging without error (or I don't know how to expose the error). I've two File transports and Winston-elasticlogger transport configured. I finally reverted to 2.4 and so far, everything behaves as expected and keeps logging.

[ericdrobinson]

This could be the same thing as that described in #1194. People using the File() or DailyRotateFile() transports appear to be affected. Could it be an issue with the underlying stream handling perhaps? Is there some common functionality between the File transport and the Daily Rotate File transport? Perhaps this is an issue with winston-transport?

[phoenix741]

Hi,

I have some similar problem. When i'm writing log of configuration, winston stop writing log without error :

I don't have daily-rotate-file.

this.logger = winston.createLogger({
  level: 'info',
  format: combine(
    timestamp(),
    loggerFormat
  ),
  transports: [
    new winston.transports.File({ filename: path.join(task.logsDirectory, `backup-${backupNumber}.errors.log`), level: 'error', tailable: true }),
    new winston.transports.File({ filename: path.join(task.logsDirectory, `backup-${backupNumber}.log`), tailable: true })
  ]
})

[drventure]

I have the same problem. I've got a console and file logger configured, not using the daily rotate. After some amount of time, winston just simply stops writing to the log, both console and file.

I wrap winston in a simple setup class, so I replaced it with just plain calls to console.log and everything logs just fine, for as long as I let it go.

One thing that I notice. If I run the app with nodemon, everything seems to work ok. I'm having this issue when running under PM2 (or FOREVER, I've tried both).

The fact that it logs properly, under both PM2 and forever, at least for a short time, leads me to believe it's something about winston, but that this point I'm not entirely sure.

[crussell52]

Earlier today I had a case where logging just went silent -- turns out I had an edge-case in one of my custom formats which would throw a TypeError. After the error (which was silent and never made it to my global unhandledException listener caught by my logger wrapper) subsequent calls to the logger would do nothing!

A little while ago, I came across this report: (#1248) -- It
mentions that after the error no more logging occurs.

If unexpected errors are quietly killing the logging, that could explain the symptoms described by @drventure and @juanda99 as well and why it is so hard to reliably reproduce!

[drventure]

Many thanks for hunting that down! I'm still trying to verify but my suspicion is that that's exactly what's going on. I AM using a custom formatter, so I think I'll next look in that area. I'll keep you guys posted.

[crussell52]

@drventure Made a correction to my previous comment -- the initial TypeError in my case was not silent. My custom log wrapper was swallowing it. That explains why the initial error never made it to my uncaughtException listener... however, it does not change the fact that logging went silent after it happens. I've opened #1261 to specifically address format exceptions killing future logging.

[indexzero]

Confirmed this was fixed against master by #1291. Thank you @ChrisAlderson and thank you @crussell52 for reporting. We are going to include your code sample as part of our smoke test suite for winston.

We can add it for you or if you'd like to make a PR that creates test/smoke/file-watcher.js we'd love to have you as a contributor. Going to leave this open for now as a way to track that.

[indexzero]

This will be released in [email protected]