[3.0.0-rc] Exception during formatting kills logging

[crussell52]

If a formatter throws an exception, logging stops working -- even if the exception is handled.

Related: #1248,
Possibly Related: #1144

Recreation:

const winston = require('winston');

const logger = winston.createLogger( {
    transports: [ new winston.transports.Console()],
    format: winston.format.printf((info) => {
        // Set a trap.
        if (info.message === 'ENDOR') {
            throw new Error('ITS A TRAP!');
        } else {
            return info.message;
        }
    })
});

// STart out logging fine.
console.log('Console: I am the raw console.');
logger.info('Logger: I am the logger.');
logger.info("Logger: I hear Endor is nice this time of year.");

// Trigger the trap.  Swallow the error so processing continues.
try {
    logger.info('ENDOR');
} catch (err) { console.log('Swallowed Error: ', err); }

// Confirm that the program is still running.
console.log("Console: Logger? Are you there?");

// All subsequent logger messages silently fail.
logger.info("I can hear you!");
logger.info("Can you hear me?");
logger.info("HELLO?");

[indexzero]

The thrown error has caused an error event to be raised in the stream pipe chain which causes all transports to be unpiped from the logger. Not sure the best approach on how to handle this – my gut says that it's up to the format to handle the error

... alternatively it could be up to you the caller who swallowed the error to reconnect everything.

[crussell52]

... alternatively it could be up to you the caller who swallowed the error to reconnect everything.

The only reason that would be viable for me is because I am using a custom wrapper to winston. For most users, that would mean wrapping every call to logger.log() in a try/catch.

my gut says that it's up to the format to handle the error

I agree that any format should handle potential errors. However, we all know that not all errors are foreseen and many occur in rare cases. For example, #1248 identifies a case where some objects will cause an Error in a seemingly very trivial format function.

Of course, if that error goes unhandled AND the app is following best practices, the application will terminate. HOWEVER, most logging is done alongside other code which will often be wrapped inside try/catch blocks that will are designed to handle the functional failures rather than the logging failures. Interpreting logging failures as functional failures can cause a host of new side effects; it is impractical to train each such catch block to uniquely handle logging errors.

We're left with the standard practice being one big try/catch inside every non-trivial format where "non-trivial" is subject to interpretation.

Not sure the best approach on how to handle this

Yeah... I totally understand that. Without the knowledge of what the formatter was trying to do, how can you meaningfully handle exceptions that come out of it?

Maybe, the best that can be done is to catch an error coming out of the call to format.transform() and log the info object with console.error() -- At least the information went somewhere and future logging is unaffected. Hopefully applications are doing something with the console error output (instead of &2>/dev/null) since it is always possible for important information to show up there. There is precedence for using console.log() as a last-ditch output mechanism elsewhere in winston@3

[crussell52]

@indexzero Any additional thoughts on this?

[indexzero]

@crussell52 it's a blocker on our Roadmap so it's definitely going to get handled before the 3.0.0 release on May 29. Still not sure the right approach yet however.

[indexzero]

@crussell52 dug in and discovered that the silencing was due to the callback in _transform not being invoked. #1347 solves this by re-throwing the error, but then ensuring that the callback is invoked to allow stream processing to continue if the user decides to catch the error.

[indexzero]

Fixed in #1347. Will be released later today in winston@3.0.0. 🎉