Fails to log to file transport in Linux when used in http async responses

[kabexnuf]

Hi,

Interestingly, winston does not log to the file transport on Linux when I try to log something in the http responses. I am using async and request packages in my implementation.

Please note that it works on Windows 8. I am using the same implementation in an Amazon EC2 Linux 64-bit instance and seeing the problem.

For instance:

var winston = require("winston");
var async = require("async");
var request = require("request");
winston.add(winston.transports.File, { filename: './abc.log', timestamp:true });
winston.info('Araba');
winston.warn('Selam');

async.waterfall([
        function(callback){
                url = "http://ec2-22-114-212-13.compute-1.amazonaw:s.com:3001/fooService";
                winston.info('ps1 lifetime');
                request(url, function(error, response, body){
                        winston.info("Inside of request callback");
                        if(error || response.statusCode != 200){
                                callback(error);
                        }
                        else{
                                callback(null);
                        }
                });
        }
]);

yields this

$ node abc.js
info: Araba
warn: Selam
info: ps1 lifetime
info: Inside of request callback
$ cat abc.log
{"level":"info","message":"Araba","timestamp":"2013-02-25T21:09:04.233Z"}
{"level":"warn","message":"Selam","timestamp":"2013-02-25T21:09:04.235Z"}
{"level":"info","message":"ps1 lifetime","timestamp":"2013-02-25T21:09:04.236Z"}
[ec2-user@ip-10-235-85-141 simulation]$

The fourth line, "Inside of request callback" is missing in the log file.

Regards,

[wansong]

Yes, i have met the same issue on my Ubuntu, it seems that it happens in high frequency when try to write logs to a file transport in a callback function on Linux.

[zivester]

+1 seeing this on Ubuntu x64 12.04 w/ Node v0.10.0 (and v0.9.8)
Logging to File works for a random amount of entries, then does not work anymore.
Console logging works just fine running alongside File.

[javiern]

i have the smae problem, for example in this code:

var winston = require('winston');

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

//logger.log('info', 'Hello distributed log files!');
//logger.info('Hello again distributed logs');

setTimeout(function(){
    logger.info("from timeout");
    logger.info("from timeout 2");
},100);

logger.log('info', 'Hello distributed log files!');

the calls in time out wil not bu flushed to the file....
i make a quick patch by doing this:

i added this 2 calls in lib/winston/transports/file.js:447

  self.emit('flush');
  self.emit('logged');

after this:

  //
  // When the stream has drained we have flushed
  // our buffer.
  //
  self._stream.once('drain', function () {
    self.emit('flush');
    self.emit('logged');
  });

that make the thing work... but im sure is not really ok... the problem is the drain event in the buffer is never emmited so, the opening flag is never set to false again... so... it thinks the file is still opening and doesnt try to fluash again...

[vikasgorur]

+1 I can confirm this bug as well. I'm currently using @javiern 's fix above, and it seems to work. As he says, the cause seems to be that the file is stuck in the 'opening' state because the drain event is never emitted.

[dalssoft]

It's weird. It could the reason my log works on local dev env but doesn't work when running on AWS EC2. I'm gonna try the fix above.

[FerCa]

+1 same problem here. And also solved using @javiern fix!

[indexzero]

Looks like this is fixed in #159. @chjj any thoughts?

[chjj]

@indexzero, it very well could be. For a while now, the file transport seems to have held up despite my doubts (the original issue that caused my concern about that issue turned out to be unrelated), but I'll look at this. To be on the safe side we can always merge that reverted branch.

[srlowe]

Also getting very inconsistent / random logging with the winston file transport. With async code often log outputting is missing from the log file.

[indexzero]

Fixed in #446. Published in [email protected]

[ralyodio]

doesn't log to file for me for some reason.

[indexzero]

@chovy could you please double check you are on [email protected] and post the exact code sample you are using so we can reproduce?

[fernandoghisi]

I was having a similar problem with the version 1.1.0, but the solution was simple and not related to winston: I just had to use "__dirname + '/logs/log_file.log'" instead of "./logs/log_file.log", and it started to create the files on the linux environment too (inside the "logs" folder in my project folder).

var logger = require('winston');
logger.add(logger.transports.DailyRotateFile, { filename: __dirname + '/logs/log_file.log' });

[dhrubajs]

@fernandoghisi : A small change to your answer that works for me :
// Add this
var path = require('path');

// Updated code
logger.add(logger.transports.DailyRotateFile, { filename: path.join(__dirname, './logs/log_file.log') });

Hope it helps.