Losing log messages due to file flushing race condition

[muirmanders]

Using a File transport, some of my startup log messages are not making it to the log (but later messages show up fine). I also have a console Transport, and everything shows up fine there, so I know the messages are getting written. I am running winston v0.6.1, node v0.8.0, Mac OS X 10.7.3.

I do not have a test case to reproduce it, but I have identified the race condition with some debug output (from transports/file.js):

DEBUG: self._buffer.push (buffering because file not open yet): "LOG MESSAGE 1"

DEBUG: starting loop over _buffer in flush()

DEBUG: self._buffer.length = 0 (truncating _buffer)

DEBUG: self._buffer.push (buffering because file not open yet): "LOG MESSAGE 2"

DEBUG: flushing via self._write (inside _buffer loop in flush()): "LOG MESSAGE 1"

DEBUG: self.opening = false (will no longer buffer writes)

As you can see, once we start looping over _buffer in fush() there is no protection against writing more messages that may never get flushed. In this case "LOG MESSAGE 2" is the one that never shows up in my log (but "LOG MESSAGE 1" and later messages show up properly).

[johnvh]

It looks like I'm running into this as well on master e31885f. I seem to be
getting a log message in after File.flush() is called, but before stream's
drain event is received. The message makes it into the buffer, but then it
never gets emptied.

I would love to create a test/repro for this, but I would think the right way to do
that is to mock out a writable stream.

In the meantime, manually flushing on open event seems to work.

log.transports.file.once('open', function(e){
    log.transports.file.flush();
});

[shaharke]

+1

[rajbala]

I think I'm running into this same problem as well. Where should I put this code?

log.transports.file.once('open', function(e){
log.transports.file.flush();
});

And is log actually just the winston import like this?

var log = require('winston');

[srlowe]

+1

[lerman]

👍 Also experiencing this..temp fix works for now

[Oleg12]

Also got that issue, temp fix seems to work... but can somebody fix it?
Spent several hours debugging...

[lerman]

I wonder if this was ever fixed? I still have the hack in place and I'm surprised this is not a problem for many more people...

[mirkokiefer]

I still have the same problem in version 0.7.3.

[svenjacobs]

Also loosing log messages for File transport :( Console works fine but log file is missing most of the entries. I wonder why such critical issue isn't fixed after two years?

winston: 0.7.3
nodejs: 0.10.28

[matanox]

+1

[kmdm]

I've just worked around this by passing the file transport a stream instead of a filename:-

{ stream: fs.createWriteStream('/path/to/logfile', { flags: 'a' }), ... }

Seems to be working, but early days!

[matanox]

I've implemented my own logger instead, and ended up with something more flexible in many regards.

[crocket]

Is it fixed?

[indexzero]

Yes. This should be fixed in the latest winston

[crocket]

I don't know how to reproduce this issue in the first place because there is not enough information.

I'll test it if somebody tells me how to reproduce the issue.

[muirmanders]

It seems to be fixed in winston >= 0.8.0 (fixed in 0c28041). Below is a script you can use to reproduce the issue on previous versions of winston. After running the script, examine /tmp/foo.log to observe the missing log messages. Note that things are particularly bad on newer versions of node (e.g. 0.10.33) and older versions of winston (0.6.x).

var winston = require('winston');

var file_transport = new (winston.transports.File)({filename: '/tmp/foo.log'});

var logger = new (winston.Logger)({
  transports: [
    new (winston.transports.Console)(),
    file_transport
  ]
});

var n = 5;
var logged = 0;
var finished = 0;
var async_log = function(cb) {
  logger.info("message " + logged);

  if (++logged < n) {
    setTimeout(async_log.bind(null, cb), 0);
  } else {
    cb();
  }
};

async_log(function() {
  setTimeout(function() {
    logger.info("last message!");
  }, 100);
});

[jcrugzz]

@muirmanders thanks for the confirmation :). And yea the internal buffering started changing things due to the file stream implementation. Steps are being made to clean it up even more.

[logysis]

This is still not fixed in daily-rotate-file.js.

[yubeiluo]

The DailyRotateTransport is also having the issue for my app.
I have configured two transports: Console VS DailyRotateTransport with the same level of INFO.
During the bootstrap process, the app is logging some meaningful stuff. All the messages are shown correctly in the Console whereas some are missing in the DailyRotateTransport.

I am using winston@1.0.0 and v0.10.35.