process.exit(1) didn't flush log to File appender #148

Closed
linbo opened this Issue Jul 30, 2013 · 9 comments

Projects

None yet

6 participants

@linbo
linbo commented Jul 30, 2013

I write a test script for log4js, to log information for http server

$ cat app.js 
var log4js = require('log4js');
log4js.configure({
      appenders: [
        { type: 'file', filename: 'cheese.log', category: 'cheese' },
        { type: 'console'}
  ]
});

var logger = log4js.getLogger('cheese');
logger.setLevel('INFO');

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/

the console result all logs

2013-07-30 10:54:06.310] [INFO] cheese - hello 21.4723559794947
5
[2013-07-30 10:54:06.321] [INFO] cheese - hello 6.07837556162849
1
[2013-07-30 10:54:06.323] [INFO] cheese - hello 8.04304217454046
[2013-07-30 10:54:06.323] [INFO] cheese - hello 41.8673762585967
8
[2013-07-30 10:54:06.323] [INFO] cheese - hello 9.80634874431416
4
[2013-07-30 10:54:06.324] [INFO] cheese - hello 19.9419380631297
83
[2013-07-30 10:54:06.324] [INFO] cheese - hello 39.8182258824817
84
[2013-07-30 10:54:06.325] [INFO] cheese - hello 5.41856697527691
7
[2013-07-30 10:54:06.326] [INFO] cheese - hello 43.5724457260221
24
[2013-07-30 10:54:06.326] [INFO] cheese - hello 14.1538650146685
54
[2013-07-30 10:54:06.328] [INFO] cheese - hello 19.2279046750627
46
[2013-07-30 10:54:06.328] [INFO] cheese - hello 30.4130541975609
96

the file log result only part of logs

$ cat cheese.log 
[2013-07-30 10:54:06.310] [INFO] cheese - hello 21.47235597949475
[2013-07-30 10:54:06.321] [INFO] cheese - hello 6.078375561628491
[2013-07-30 10:54:06.323] [INFO] cheese - hello 8.04304217454046
@nomiddlename
Owner

I'm not sure that there's anything I can do about this - process.exit short-circuits the event loop. I'm happy to be proved wrong, and I'll keep an eye on the equivalent winston issue (winstonjs/winston#288) in case they manage to fix it.

@nomiddlename
Owner

This is also the same issue as #122 and pull request #65

@jengler
jengler commented Apr 3, 2014

I am willing to dedicate time to fixing this if we can come up with a solution. The key issue seems to be that WritableStreams do not guarantee flushing on process.exit() or unhandled exception. Have any alternative solutions been investigated? It seems like we could cache the logs in memory until the WritableStream drains. Then if a process.exit or uncaught exception occurs, we can synchronously write any logs that have not been drained. This might produce duplicate logs, but would at least prevent logloss. Any thoughts?

@nomiddlename
Owner

Looks like @jengler has fixed this issue. Call log4js.shutdown with a callback to be notified when all the logs have finished being written (for file appender anyway). In your example above replace process.exit(1); with

log4js.shutdown(function() { process.exit(1); });

to make sure all logs are written.

@lulurun
lulurun commented Apr 21, 2014

I am very happy to see the "shutdown" method, but I think there is a bug, please have a look at pull request #199.

And, looks like "shutdown" is only available in file appender, could we also add the same in dateFile appender ?
As I tried, the "shutdown" also work good with dateFile appender.

@nomiddlename
Owner

Added the shutdown function to dateFile appender, pushed to npm in v0.6.14

@danie11am danie11am referenced this issue Jun 16, 2014
Merged

Flush on exit #195

@vishwanath-gowda

@jengler Hi, using log4js.shutdown(function() { process.exit(1); }); throws "log4js.fileAppender - Writing to file /usr/local/app/log/my.log, error happened [Error: write after end]".

@jengler
jengler commented Dec 14, 2015

@vishwanath-gowda Will take a look. Will you please include some more context and the test case you are using to reproduce this? Thanks

@guy-mograbi-at-gigaspaces

+1 I got the same error.. currently writing manually to a file to see what i need.

log4js.fileAppender - Writing to file /usr/local/app/log/my.log, error happened [Error: write after end]

==> 2 minutes after

just noticed that there's a fileSync appender.. guessing it does what I need it for my temporary purpose.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment