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

[yzapuchlak]

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/

[3rd-Eden]

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 (#228).

[yzapuchlak]

Hmm. In that case, if one must kill a node process but needs to log information right before they kill it, is putting the process.exit() inside of a setTimeout() with a sufficiently large time duration the only thing one can do to ensure that winston actually writes messages to the log file?

[danmilon]

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

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

[dtex]

@yzapuchlak setTimeout will probably work without problems, but I think it would be wise to use the optional callback param instead.

[yzapuchlak]

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?');

[dtex]

@yzaouchiak Curious, is that version 0.6.2?

[yzapuchlak]

└─┬ [email protected]
├── [email protected]
├── [email protected]
├── [email protected]
├── [email protected]
├── [email protected]
├── [email protected]
└── [email protected]

[gansbrest]

Having same issue now, need to terminate process and make a note in the log file. Would be nice to have callback option, which we could use to exit process only after message was written. Or maybe it's already exist?

[pierrickchabi]

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

[nomiddlename]

This is the same issue as #288 and also the log4js-node issue (log4js-node/log4js-node#148). I think the problem is that the event loop does not run once the process.exit callback has finished - so any pending async calls (like file writes) don't get a chance to run. I'd be very happy if someone can prove me wrong, and come up with a fix.

[jengler]

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?

[indexzero]

Related to log4js-node/log4js-node#148

[indexzero]

Related to #288.

[jtmalinowski]

Any updates here? Still failing for me with ~ 0.9.0

[gtorodelvalle]

Yeah, I am still using the setTimeout() hack mentioned by @yzapuchlak previously :(

[3rd-Eden]

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.

[stephanoparaskeva]

@cjbarth This does not work:

  process.on(type as any, (err: ErrorExtended) => {
    const processLogger: Logger = loggers.get('processLogger');

    processLogger.error(errorFormatter(err, type));

    processLogger.on('finish', function () {
      processLogger.end();
      console.log('never reaches here');
      process.exit(1);
    });
  });

processExit('uncaughtException');
// log and exit for unhandledRejection events.
processExit('unhandledRejection');

[cjbarth]

@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.

[stephanoparaskeva]

@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.

Gotcha, so something like this?

process.on(type as any, (err: ErrorExtended) => {
  const processLogger: Logger = loggers.get('processLogger');

  processLogger.error(errorFormatter(err, type));
  processLogger.end()

  processLogger.on('finish', function () {
    process.disconnect();
  });
});

// log and exit for uncaughtException events.
processExit('uncaughtException');
// log and exit for unhandledRejection events.
processExit('unhandledRejection');

[cjbarth]

@stephanoparaskeva That looks better.

I would typically bind the event handler before calling processLogger.end(), but it shouldn't matter because the finish event should fire only after the event loop turns, by which time the handler will be bound. I just think writing the code where the event handler is bound first makes it clearer.

[stephanoparaskeva]

@cjbarth
Oh, how do you bind the event handler to something?
Would that be:

processLogger.on('finish', () => {
    this.process.disconnect();
  });

[cjbarth]

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

{
  this.process.disconnect();
}

To the finish event emitted by the object processLogger.

[DmitriyFriz]

It works for me: https://stackoverflow.com/a/59260151

[deedf]

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.

[maxxrdrgz]

See this: https://stackoverflow.com/a/37592669 to get a better understanding as to what @deedf is referring to. Following this advice, alleviated this problem for me as well.

[oonqt]

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.

[efratha94]

I don't get how this hasn't been solved yet by winston. I have a problem that only the very first logger in my code gets logged to Logstash (using also winston-elasticsearch). If I use logger.end() then everything gets logged, but the program exits too early. tried using all of the above solutions, and none really worked.
I'm really helpless

[ortexx]

I don't get how this hasn't been solved yet by winston. I have a problem that only the very first logger in my code gets logged to Logstash (using also winston-elasticsearch). If I use logger.end() then everything gets logged, but the program exits too early. tried using all of the above solutions, and none really worked.
I'm really helpless

Did you try this ?

[deedf]

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.

[oonqt]

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.

So our solution to this problem is to not call process.exit()?

[deedf]

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.

So our solution to this problem is to not call process.exit()?

Yes, it's always a bad idea in nodejs, see https://stackoverflow.com/a/37592669

[oonqt]

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.

So our solution to this problem is to not call process.exit()?

Yes, it's always a bad idea in nodejs, see https://stackoverflow.com/a/37592669

Well the reason that I personally am using process.exit is because I am listening to uncaughtException and unhandledRejection to log to all my transports, then quit the application. Is there a better way to accomplish this issue?

[efratha94]

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()?

[deedf]

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.

[efratha94]

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.

You must be so busy if you come to an issue that's been open for 8 years and offer no proper help at all.

[deedf]

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.

So our solution to this problem is to not call process.exit()?

Yes, it's always a bad idea in nodejs, see https://stackoverflow.com/a/37592669

Well the reason that I personally am using process.exit is because I am listening to uncaughtException and unhandledRejection to log to all my transports, then quit the application. Is there a better way to accomplish this issue?

I haven't used winston in a while, but won't it log thos anyway ? if not, won't rethrowing the error after logging it work ?

[deedf]

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.

You must be so busy if you come to an issue that's been open for 8 years and offer no proper help at all.

At least I can solve my own issues without whining like an entitled brat.

[yogeshbiz]

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.

[sorenlouv]

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

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

[stianlp]

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

[wendellouyang]

export function _sleep(ms: number) {
    return new Promise((resolve) => {
        setTimeout(resolve, ms);
    });
}

export async function _exit(exitCode: number, ms: number = 1000) {
    await _sleep(ms);
    process.exit(exitCode);
}

(async () => {
    logger.warn(`will exit after writing this log`);
    await _exit(1);
    console.log('this message will never be display');
})();

It wakes for me:)

[Reedbeta]

Here again in 2024, encountering this same problem. IMHO the issue really deserves a mention in the docs, e.g. in the "Awaiting logs to be written" section.

The way I got here was trying to implement graceful shutdown on SIGINT/SIGTERM; usually, if you install a signal handler for those then you have to exit the process yourself (as the signal handler replaces the normal exiting behavior). I learned here that it is better to get the event loop to exit "naturally" by closing connections and so forth. That indeed seems to solve my file flushing problem. But it took so many hours of frustration to get here. 😩

(BTW, deferring the process.exit call to the logger finish event did not work for me.)

[DABH]

If you have some documentation or recommendations, could totally be open to reviewing a PR!