winston: Logging to file fails when calling process.exit(0)

I don’t really see this as a bug of winston anyways. When you process.exit in your code you have made the decision to completely kill everything that is still running on processing. If there are still HTTP requests running you don’t assume that these will also be replied to, so why would assume that log messages do end up in your log? This is just how node works things are async for a reason. If if you used the callback or setTimeout approach there is nothing preventing your application to log another line right before your setTimeout is done or callback is called.

The only ways around this is to have synchronous logging but then you defeat the whole purpose of having an async system as a simple log statement when you’re handling requests…

So what i’m suggesting is closing this issue with a wont fix. If you don’t want to mis any log messages make sure you correctly clean up and shut down your application before calling process.exit.

edit Also all your setTimeout hacks are flawed and do not fix the issue as you have no idea how long it will take to have all data be written to the operating system and how fast your disks or ssds’s are processing it. The only decent solution here is to listen to the stream’s drain event and exit the process. But if you application is continuously logging this might not even be called for a long period ;p making this just another hack because you didn’t properly shutdown your application before exiting.

So many people have problem over this aspect of Winston. If it is not bug, then the specific behavior when exit() called must be made clear in documents. Such caveats must be stated in the documents. Any idea, how many hours got consumed in finding solution to this problem in last 8 years, globally by node developers? There is no clear clue about what is going on, to most developers. Please have a caveats section in documentation.

For me it took 6-7 hours to realize why logs not written reliably. For some it may be 5 mins. But think of time waste.

Many faced this problem, obviously there is https://www.npmjs.com/package/winston-log-and-exit which indicates a lot about the problem that Winston won’t fix. It is not bug, but it is a problem. If you will not fix the problem someone else will. And now you need Winston and the patch while using.

@danielweck Nope, it is broken: #1629 #1504!

6 years, that is right, 6 years for a bug that is marked important. It is borderline impressive.

I use a waitForWinston() Promise:

const winston = require('winston');

const fileTransport = new winston.transports.File({ name: 'file', filename: FILE_PATH });
const consoleTransport = new winston.transports.Console({ name: 'console', stderrLevels: ['error'] });
const transports = [
    fileTransport,
    consoleTransport
];
winston.configure({
    level: 'verbose',
    transports,
    format: winston.format.cli()
});
winston.log('info', 'TEST MSG');
try {
    await waitForWinston();
} catch (err) {
    console.log(err);
}
process.exit(0);

const waitForWinston = async () => {
    return new Promise(async (resolve, _reject) => {
        for (const transport of transports) {
            try {
                await closeWinstonTransportAndWaitForFinish(transport);
            } catch (err) {
                console.log(err);
            }
        }
        resolve();
    });
};

const closeWinstonTransportAndWaitForFinish = async (transport) => {
    if (!transport.close) {
        // e.g. transport.name === 'console'
        return Promise.resolve();
    }
    // e.g. transport.name === 'file'

    return new Promise(async (resolve, _reject) => {
        transport._doneFinish = false;
        function done() {
            if (transport._doneFinish) {
                return; // avoid resolving twice, for example timeout after successful 'finish' event
            }
            transport._doneFinish = true;
            resolve();
        }
        setTimeout(() => { // TODO: use a cancellable setInterval instead
            done();
        }, 5000); // just in case the 'finish' event never occurs
        const finished = () => {
            done();
        };

/* Update: `stream.end()` does not flush pending writes, so this solution is inadequate.  For some reason, in recent tests `transport.close();` + `transport.once('finish', ...);` works just fine ... not sure why this works now though! (it used to fail!) */

/*
        if (transport._stream) {
            transport._stream.once('finish', finished);
            transport._stream.end();
        }
*/
            transport.once('finish', finished);
            transport.close();
    });  
};

Try this one. It works pretty well in my case. Instead of calling process.exit directly we let the logger call process.exit after the log was flushed.

logger.js :

var winston = require('winston');

winston.loggers.add('my-logger', {
    console: {
        level: 'debug',
        colorize: true,
        timestamp: true,
        handleExceptions: true
    },
    file: {
        level: 'info',
        colorize: false,
        timestamp: true,
        filename: 'file.log',
        handleExceptions: true
    }
});

var logger = winston.loggers.get('my-logger');


/* ******* *
 * EXPORTS
 * ******* */

exports.exitAfterFlush = function(code) {
    logger.transports.file.on('flush', function() {
        process.exit(code);
    });
};

exports.info = function() {
    logger.info.apply(this, arguments);
};

exports.warn = function() {
    logger.info.apply(this, arguments);
};

exports.error = function() {
    logger.info.apply(this, arguments);
};

in your code:

var logger = require('./logger.js');
logger.exitAfterFlush(0);
logger.info('Done!');

Tested on NodeJS v4.1.2 and winston 1.1.0

For what it’s worth, you can get around the use of setTimeout but you need to grab the underlying _stream:

// log then exit(1)
logger.error("The thing to log", function(err) {
  var numFlushes = 0;
  var numFlushed = 0;
  Object.keys(logger.transports).forEach(function(k) {
    if (logger.transports[k]._stream) {
      numFlushes += 1;
      logger.transports[k]._stream.once("finish", function() {
        numFlushed += 1;
        if (numFlushes === numFlushed) {
          process.exit(1);
        }
      });
      logger.transports[k]._stream.end();
    }
  });
  if (numFlushes === 0) {
    process.exit(1);
  }
});

As mentioned above, use of the callback function alone is not sufficient to get it to have flushed correctly to file. This feels like a bug to me.

Note that I’m actually listening for the finish event: https://nodejs.org/api/stream.html#stream_event_finish rather than using winston’s flush or closed event because that too is insufficient to get it to log correctly 😕

I don’t see how performance has any impact here. The process is about to be killed, winston only needs to do bookkeeping on the final log lines during which time it can happily block IMO.

Given how old this issue is, and the fact that there is a workaround for it, I’m not exactly holding out for anyone addressing this in winston anytime soon.

tldr: replace process.exit(1) with process.exitCode = 1;

After wasting a couple of hours I hope this will help someone else.

The fact that the finish event still doesn’t emit after years is just embarrassing at this point. This is going to be a pain to have to switch loggers and rewrite all my custom transports for them.

@redhat-raptor. That will work most of the time, but it’s not guaranteed to work all of the time. It just happens that your buffers were cleared by the time nextTick() was called, but depending on the connections that your loggers rely on, this could easily result in lost messages…

Can this ticket at least change the docs so it doesn’t look like it’s currently supported I just spent 30 minutes debugging this issue which purports to be supported by when you search for seriously in the repo it’s only supported in the README. This to be just seems like either an unsupported feature or a bug and the workarounds aren’t really too palatable.

If you don’t call process.exit but do a proper shutdown instead, by closing all connections and waiting for the event loop to drain, then there is no problem at all.

For any logging system, the calculus is:

• If you absolutely must have your logs and are willing to pay the cost of slower response times, use a synchronous logger
• If you are calling process.exit() yourself, wait until the buffered messages are cleared. For winston, the winston-log-and-exit package does this for you.
• If some other code is calling process.exit() and your platform has an on-exit hook, use that hook and wait until the buffered messages are cleared. winston-log-and-exit can help with that too.
• If you’re using a platform like AWS Lambda which doesn’t have an on-exit hook, then you’re trading the benefits of the platform for the risk of loosing data.

Incidentally, @begin-again this the log_and_exit() method is essentially the same as log-4js’s shutdown() method with the additional guarantee that the log message provided will be logged.

log4js-node has implemented a shutdown method with flushes all transports and takes a callback such as process.exit(). Could something like this be added to winston?

@mscharley would the above await solution work for your use case? Perhaps instead of log.exit() a better api would await log.finish() which would wait until all transports have finished writing and then let you do whatever (call process.exit, call the lamda done callback, etc)

I understand that this is not an issue but there should definitely be a function to finish all writes to files and close any open stuff so that the process can exit on its own without calling it explicitly. So hard to use such things in production systems.

log4js-node it is then

Not to be a broken record, but winston-log-and-exit also solves this issue

Frankly, I think adding shutdown(callback) seems appropriate but with the caveat that transports need to actively support it. Individual transports are the “Information Experts” about their underlying output mechanism; they have the most information on how it should cleanly shutdown.

Anything the winston core does – and most definitely anything we do in user land – requires implementation details of the transports to leak.

So winston shouldn’t need to do the work… but it really needs to provide a way for the work to get done. Then we can all go work with the Transport authors to do the heavy lifting.

Some psuedo-code to illustrate the point below.

shutdown(callback) {
    var transportCount = transports.length
    var finished = 0;
    // for each transport
    if (transport.shutdown) {
       transport.shutdown(function() {
           // increase finished count. 
           // if all finished, call original callback.            
       });
    } else {
       // Transport does not (yet) support it.
       // increment finished counter
    }
}

Yes, having a fileSync transport would be useful in some situations, even if it would be a net performance decrease.

@jdthorpe I think your idea about having a library that handles closing things cleanly before shutting down is a good one but it still doesn’t shift the responsibility away from winston to provide a method of waiting for it to flush everything to disk (ie, provide a mechanism to close itself) which could then be combined with such a library to aggregate up the close methods for various libraries.

I’m having the same issue, with Winston 0.7.2. I tested setTimeout and callback workaround without any success.

setTimeout of 2000 or 5000 works in my simple test script, but not when I try to use it in my real code. So, I don’t know how reliable that potential fix will be. I’ll dig into that problem later if I have no luck on the optional callback front.

@dtex I just tried use the optional callback (as seen in the following example code), but it’s still not resulting in the logs getting written to the file. The file actually gets created in this case but no logs get written to it.

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

logger.info('winston - info logged');
logger.error('winston - error logged');

logger.info('winston - exiting now', { seriously: true }, function(err, level, msg, meta) {
  console.log('console - CALLING PROCESS EXIT');
  process.exit(0);
});

logger.warn('winston - I probably should only appear in console, not the log file?');

Like @yogeshbiz, I just spent a few hours on this… Tried to figure out why I didn’t get the last log on the line right before process.exit(0) 🤯

This works fine though: https://github.com/winstonjs/winston#awaiting-logs-to-be-written-in-winston

I don’t get how people don’t get that this “problem” hasn’t been “solved” cause there isn’t any. Just write proper code by not calling exit() and you’ll be fine.

Where did you see I said I used exit()?

Sorry for assuming your reading and understanding ability is sufficient to understand what this bug is about. Check the title again.

Easier way:

logger.error(`No value specified for ${missing_vars.join(',')} variable! Node will exit now...`, () => {
            process.exit(1);
        });

That is basically exactly what we’ve been pushing for in this issue, except inside Winston. Why would this be a plugin? Seems like something that should come up more often. I don’t feel like what we’re doing is anything special yet we’ve hit this wall on every project - which is why we moved away from Winston eventually. Loosing logs, especially at end of process - where errors are most likely to occur - seems hazardous at the least.

Only for very, very specific use cases. I couldn’t use winston-log-and-exit in say AWS Lambda where the process doesn’t exit, but it does freeze between executions so logs still get lost. It also assumes I know which messages are my final ones which may not always be the case in a successful execution path.

Would love to see this fixed in v3.x.

Echoing that this really does need a solution on winston’s side. Whether that’s providing a synchronous file transport or providing a shutdown hook to close down Winston ‘safely’ I don’t really care, either would be a satisfactory solution to me. But having nothing just makes it impossible to write logs and then quit and be assured that they will actually be written.

npm install winston-log-and-exit

@stephanoparaskeva Yes. That is the correct syntax for binding the function

{
  this.process.disconnect();
}

To the finish event emitted by the object processLogger.

@stephanoparaskeva If I’m not mistaken, the finish event will never be fired on processLogger because you never call processLogger.end(). If you call that, then, when Winston is done logging, the finish event should fire.

I would also use process.disconnect() instead of process.exit(), which allows the queue to drain. It will exit automatically when the queue is drained.

The following works for me:

logger.info('winston - info logged');
logger.error('winston - error logged');
process.nextTick(() => {
    process.exit(0)
})

I would say maybe wrote a generic shutdown() function for everyone as a new feature, and this feature is pretty critical.

This is about what winston.log_and_exit() does. Note that log4js.shutdown() depends on writable.end(complete) in the case of appends based on writable streams, (appenders.filter(a => a.shutdown).forEach(a => a.shutdown(complete));) which is still an asynchronous shutdown.

I think with regard to @mscharley’s comment, the advantage is that there is an fileSync appender, which does not require the use of shutdown() to have the complete logs written to file when the Node process quits…

It sounds like you and I are talking (writing) across purposes. It sounds like you are interested in synchronously writing final messages to file, whereas my concern was ensuring that the logs which were written asynchronously just before the error get written to file.

Writing the messages to file that occurred just before the error synchronously would require that all messages are written synchronously, and that is the performance issue.

Others have been concerned about stopping other JS code from running after an error but before the last logs have been written to file.

An option that might satisfy everyone’s needs is to write a custom transport which writes asynchronously, and keeps a buffer of messages not yet confirmed as written (flushed) to file, which could be written to file synchronously on error (at the risk of duplicating messages, in the case that NodeJS already finished writing to file, but the flushed event hasn’t been processed yet…).

Just for clarity, console.log and friends are synchronous.

@yzapuchlak I haven’t actually tested, but that’s what I do too.

In node the console.* methods are writing async, the File transport is async. You are closing the process before node has even written data.

On Monday 25 March 2013 at 19:45, Yuri Zapuchlak wrote:

When you have winston configured to log to a file and you call process.exit(0) in your code, winston never ends up creating the log file and appending the log messages to the file. In a perfect world, winston would happily handle this edge case and write to the file, but I’d also be fine with being able to call flush on a logger instance in order to manually force a flush to file. There may be some way to manually ‘flush’ at the moment, but it’s not documented nor have I had any luck with manually to closing/ending/destroying a logger instance or its inner streams so far in a way that actually results in the loges being written out to a file… var winston = require(‘winston’); var logger = new (winston.Logger)({ transports: [ new (winston.transports.Console)(), new (winston.transports.File)({ filename: ‘winston.log’ }) ] }); logger.info(‘info logged’); logger.error(‘error logged’); process.exit(0); // the two logs get written out to console, but not to the winston.log file/

— Reply to this email directly or view it on GitHub (https://github.com/flatiron/winston/issues/228).