ExceptionHandler silences printing of console errors?

[kramer65]

In my Winston logger I use an exceptionHandler so that the node exceptions/errors also reach my logs. I now have a problem though. When I run the script from the command line using node index.js (instead of pm2) the script ends silently when it has an error.

Have a look at my Winston implementation below. I added three console.log()s which try to log an undefined variable. When I run the script using node index.js it gives me a ReferenceError for the first wrong console.log(undefinedVariable) as expected. When I now remove that first and/or the second console.log, the script ends silently.

"use strict";

let winston = require('winston');
const path = require('path');

const PRODUCTION = false;

// LOGGING
const myFormat = winston.format.printf(info => {
    return `${info.timestamp} ${info.level}: ${info.message}`;
});

console.log(undefinedVariable);  // THIS GIVES A REFERENCE ERROR

const logger = winston.createLogger({
    level: 'debug',
    format: winston.format.combine(winston.format.timestamp(), myFormat),  // winston.format.json(),
    transports: [
        new winston.transports.File({filename: 'logs/error.log', level: 'error'}),
        new winston.transports.File({filename: 'logs/combined.log'}),
    ],
    exceptionHandlers: [
        new winston.transports.File({ filename: 'logs/exceptions.log' }),
        new winston.transports.File({ filename: 'logs/combined.log' })
    ]
});

console.log(undefinedVariable);  // THIS DOES NOT GIVE A REFERENCE ERROR, BUT ENDS THE SCRIPT SILENTLY

if (!PRODUCTION) {
    // If we're not in production then also log to the `console`
    logger.add(new winston.transports.Console(
        {format: winston.format.combine(winston.format.timestamp(), myFormat), level: 'debug'}
    ));
}

console.log(undefinedVariable);  // THIS ALSO DOES NOT GIVE A REFERENCE ERROR, BUT ENDS THE SCRIPT SILENTLY

function log(message, level='debug'){
    // Levels: error, warn, info, verbose, debug, silly
    const e = new Error();
    const regex = /\((.*):(\d+):(\d+)\)$/
    const match = regex.exec(e.stack.split("\n")[2]);
    let log_source = path.basename(match[1]) + ':' + match[2];  // eg: index.js:285

    if (typeof message === 'object'){
        message = JSON.stringify(message);
    }
    logger[level](log_source + ' - ' + message);
}

I'm running version 3.0.0-rc5on Ubuntu 18.04.

Does anybody know what I'm doing wrong here? All tips are welcome!

[DABH]

As one comment, in theory you can control whether the exception causes an exit or not by setting exitOnError on the logger (https://github.com/winstonjs/winston#to-exit-or-not-to-exit). When I set that to false in your example, I do see the first exception logged, but it does seem like the second one crashes it without logging. Also without that flag, I can reproduce your issue. Either way it does seem like there's some issue where exceptions are causing a premature exit. I see the code goes into _uncaughtException(...) which idk is correct or not. Might dig a bit more...

[DABH]

Looked a bit further and found this in exception-handler.js

  asyncForEach(handlers, function awaitLog(handler, next) {
    //
    // TODO: Change these to the correct WritableStream events
    // so that we wait until exit.
    //
    var done = once(next);
    var transport = handler.transport || handler;

    //
    // Debug wrapping so that we can inspect what's going on
    // under the covers.
    //
    function onDone(event) {
      return function () {
        debug(event);
        done();
      };
    }

    transport.once('logged', onDone('logged'));
    transport.once('error', onDone('error'));
  }, gracefulExit);

Seems like multiple issues here:

• that TODO... we aren't correctly waiting for the log event to finish writing, which is why you don't see your error written even though I do see 'logged' when I debug your example
• the fact we call gracefulExit there as the callback -- this breaks/ignores exitOnError right?? Shouldn't this be e.g. () => doExit && gracefulExit()?

So, issue confirmed, and there's some work to be done to get this all in order. Thanks for bringing it up! (PRs welcome of course if you're interested -- otherwise I'll try to find time to fix this up)

[DABH]

Even with ^^that little lambda as the callback and exitOnError: false I can only get the first error to log, then things crash totally silently as far as I can tell. Trying to track down where/when/why it's exiting or crashing... ideas welcome

[DABH]

So, did some more digging/learning and think I got some clarity on this.

First of all, https://nodejs.org/api/process.html#process_event_uncaughtexception . Uncaught exceptions are unsafe and it's not good / unsafe to attempt to resume normal execution after one of these.

Instead, the handling of uncaught exceptions should be thought of as doing some last-minute logging/cleanup before the process terminates. This isn't clearly documented, but it appears that Node will terminate the process after the process.on('uncaughtexception', ...) callback finishes.

Given that, exitOnError isn't a question of whether the process will terminate or not, it's just a question of whether you want winston to be the one killing the process, or if you want Node or some other callback to kill it (maybe you have some upstream application cleanup logic).

So I believe we are seeing the expected behavior here, i.e. we see one uncaught exception logged, and then the process terminates. Seems like this behavior is basically enforced by Node. Nonetheless, this warrants:

• doc update to make this behavior clearer
• fix for the callback as mentioned above
• properly await stream events as per above

[indexzero]

This is somewhat a duplicate of #1263, but there is more sublty. Look at this modification of your MWE (thanks for that btw):

let winston = require('winston');
const path = require('path');

const PRODUCTION = false;

// LOGGING
const myFormat = winston.format.printf(info => {
    return `${info.timestamp} ${info.level}: ${info.message}`;
});

//console.log(undefinedVariable);  // THIS GIVES A REFERENCE ERROR

const logger = winston.createLogger({
    level: 'debug',
    format: winston.format.combine(winston.format.timestamp(), myFormat),  // winston.format.json(),
    transports: [
        new winston.transports.File({filename: 'error.log', level: 'error'}),
        new winston.transports.File({filename: 'combined.log'}),
    ],
    exceptionHandlers: [
        new winston.transports.File({ filename: 'exceptions.log' }),
        new winston.transports.File({ filename: 'combined.log' })
    ]
});

// console.log(undefinedVariable);  // THIS DOES NOT GIVE A REFERENCE ERROR, BUT ENDS THE SCRIPT SILENTLY

if (!PRODUCTION) {
    // If we're not in production then also log to the `console`
    logger.add(new winston.transports.Console({
        format: winston.format.combine(winston.format.timestamp(), myFormat),
        level: 'debug',
        handleExceptions: true
    }));
}

setTimeout(() => {
    console.log(undefinedVariable);  // THIS ALSO DOES NOT GIVE A REFERENCE ERROR, BUT ENDS THE SCRIPT SILENTLY
}, 2000);

I've done two things:

1. Make the Console transport you add as handleExceptions: true
2. Wait briefly before causing a ReferenceError to allow for the files to open that you are logging to.

Now when I run this the log of the exception is written to all three locations (Console, combined.log and exceptions.log) as we expect. In other words:

1. The silent Console is silent by design because you have explicitly said do not log exceptions to the console by not passing handleExceptions: true when you create your new Console transport instance.
2. The silent File transports are silent because they do not hold open the process when it attempts exit after the ReferenceError. I believe @DABH is heading in the right direction with Attempt at fixing the issues with ExceptionHandler in #1289 #1355 but I'd like to discuss it this week and not rush out a fix.

Thanks for all your help! We're going to release 3.0.0 in a few hours, but the fix for this land in 3.0.1.

[shirakaba]

I believe @DABH is heading in the right direction with #1355 but I'd like to discuss it this week and not rush out a fix.

@indexzero I'd like to draw attention back to this issue from ~3 months ago. DABH's patch works (I've provided further tests in the PR to confirm this), but it sounds like DABH is looking for a confident verdict on it. This codebase is wholly unfamiliar to me (as are streams, etc.), so I appeal to core contributors such as yourself for the necessary expertise here.

[indexzero]

Fixed in #1355. Will be released in winston@3.2.0. Track the remainder of that release

[JarrodHollingworth]

I think this needs more work.

I came across this same issue with winston logging stopping when there is an unhandled exception. I was using an earlier version so I updated to 3.2.1 to get fix #1355 but it still not working as expected. I found the following two issues through extensive debugging.

1. The exception handling transport was stopping after logging the unhandled exception (exitOnError = false). This caused further logging to throw an exception which causes the process to exit:
   /winston/lib/winston/logger.js:309
   throw ex;
   ^
   Error: write after end
   at writeAfterEnd (/winston/node_modules/readable-stream/lib/_stream_writable.js:257:12)

This is caused by fix #1355 always setting transport._ending to true. As a work-around I changed it to assign doExit instead of true, but really the whole asyncForEach should probably not be run if doExit is false.

2. The default logger instance (created anytime you require('winston')) interferes if you also create your own (second) instance using winston.createLogger() with exitOnError = false, because the default instance defaults to exitOnError = true and also hooks process.on('uncaughtException'). My work-around was to use the default instance only and not create my own, by changing winston.createLogger() to winston.Configure() but you could probably just configure the default instance exitOnError = false and use your own instance.