Winston: High concurrency writes leads to data loss

[linbo]

testing script

$ cat winston.js 
var winston = require('winston');

var logger = new (winston.Logger)({
        transports: [
          new (winston.transports.Console)(),
          new (winston.transports.File)({ filename: 'win.log' })
        ]
      });

var http=require('http');

var server = http.createServer(function(request, response){
    response.writeHead(200, {'Content-Type': 'text/plain'});
    var rd = Math.random() * 50;
    logger.info("hello " + rd);
    response.write('hello ');
    if (Math.floor(rd) == 30){
        process.exit(1);
    }
    response.end();
}).listen(4444);

ab testing command

ab -c 10 -n 100 localhost:4444/ 

console log result all request

$ node winston.js 
info: hello 40.635715366806835
info: hello 47.55378740373999
info: hello 3.97098318208009
info: hello 21.402712271083146
info: hello 13.45938507001847
info: hello 34.73868641303852
info: hello 35.19469986204058
info: hello 17.50683527207002
info: hello 46.6102683218196
info: hello 16.208414710126817
info: hello 18.39921014616266
info: hello 23.423498892225325
info: hello 44.21681684907526
info: hello 35.54235898191109
info: hello 9.904313215520233
info: hello 27.047289244364947
info: hello 32.58601982379332
info: hello 36.48257440654561
info: hello 42.66765915090218
info: hello 9.47293157223612
info: hello 38.31890656147152
info: hello 40.63100240891799
info: hello 26.544194167945534
info: hello 17.846915975678712
info: hello 43.33941290387884
info: hello 26.012209930922836
info: hello 30.679881805554032

But file log only has 3 result:

$ cat win.log 
{"level":"info","message":"hello 40.635715366806835","timestamp":"2013-07-30T03:03:43.441Z"}
{"level":"info","message":"hello 47.55378740373999","timestamp":"2013-07-30T03:03:43.446Z"}
{"level":"info","message":"hello 3.97098318208009","timestamp":"2013-07-30T03:03:43.446Z"}

[matanster]

Running probably into the same issue though not from a stress test like above. If this is to be expected also for code like above, which I need for testing my application, then this is even worse. Major issue for a logging library!

[matanster]

This reproduces in my stress test, and it is quite horrible. Ubuntu 13.04 if it matters (express.js).
Under humble stress, a huge proportion of logging fades away rather than getting into the log files. I think @linbo's reproduction code is much more concise than my huge application, and solving it would probably solve the general case, hopefully. I wonder how this issue survived so long :(

[indexzero]

Related to #228

[DubHunt]

This seems like a pretty significant issue and one that is still present in 1.0.0.

[watsoncj]

The best we could hope for is configuration to enable flushing the streams on uncaught exception or exit since the library probably shouldn't do this out of the box.

Here's how to setup hooks to flush the streams manually on exit uncaught exception:

http://stackoverflow.com/questions/18771707/how-to-flush-winston-logs
https://github.com/flatiron/winston/blob/master/lib/winston/logger.js#L594-L637

[SyRenity]

Are there plans to have Winston flush the logs by itself on uncaught exceptions?

[SyRenity]

Was there any resolution to this issue?

[indexzero]

The resolution to this issue is going to be [email protected]. This work is actively underway using native streams and will be much more performant. see https://github.com/winstonjs/winston/compare/v2.x.x

[chorsley]

Prospective Winston user, and came across this issue early in my research which gave me pause. Is this issue now resolved in the latest master branch, given it's 2.2.0?

[matanster]

You are lucky to learn about this before having jumped in I guess..

On Wed, Mar 30, 2016 at 7:17 AM, Chris Horsley [email protected]
wrote:

Prospective Winston user, and came across this issue early in my research
which gave me pause. Is this issue now resolved in the latest master
branch, given it's 2.2.0?

—
You are receiving this because you commented.
Reply to this email directly or view it on GitHub
https://github.com/winstonjs/winston/issues/288#issuecomment-203238768

[destructivecreator]

"winston": "^3.0.0-rc1" facing the same issue. Logs go away under high concurrency writes. Any comments??

[indexzero]

This was finally resolved in 3.0.0

[matanster]

@indexzero how sure are you about that?
is there any better or at-par node.js logging library by now? this issue is like four years old I think.

[indexzero]

Very. We have appropriate test coverage ensuring this. See: https://github.com/winstonjs/winston/blob/master/test/transports/00-file-stress.test.js.

Locking issue due to age.