Attempt at fixing the issues with ExceptionHandler in #1289

[DABH]

#1289 observed that the ExceptionHandler was broken, at least with the File transport, because the File transport emits the logged event before content is flushed to disk (and the handler exits upon seeing logged events from the handling transports).

This is one potential way to get the desired behavior. We add an _ending flag to the File transport, which is set to true on an unhandled exception in ExceptionHandler. The File transport's log() checks if _ending is true when logging, and if so, ends the stream and passes up the stream's finish event (when stuff is flushed) to the exception handler. There is also a check to wait for the file to open first, if it's opening (otherwise you end before the file opens and so nothing is logged still).

This does appear to fix the test case provided by the OP in #1289 but this is also near the limit of my stream skills so feel free to just use it as inspiration if there is a better approach.

[DABH]

This isn't really related, I had just noticed that it was possible to make this throw if _dest or callback weren't set, so I added some bumpers...

[shirakaba]

Thank you so much for making this patch. I've done some tests of my own with it, this time using winston-daily-rotate-file (my use case). I draw your attention to the six test cases.

Tests 1,2 and 4 failed before application of your patch, i.e. with the following two packages:

• winston v3.1.0, (sub-dependency: winston-transport v4.2.0)
• winston-daily-file-rotate v3.3.3 (sub-dependency: file-stream-rotator v0.3.1)

All tests pass with your patch.

"use strict";

let winston = require('winston');
require('winston-daily-rotate-file');

/*
0: Don't throw any errors.

1: Throw an error immediately after queuing a regular log message.
    This is called before Daily Rotate File's 'new' file event, i.e.
    before the file has been opened.
   (Pre-patch: would have failed to log to the file)

2: Throw an error 1 ms after the Daily Rotate File's 'new' file event.
   (Pre-patch: would have failed to log to the file)

3: Throw an error 3 ms after the Daily Rotate File's 'new' file event.
   (Pre-patch: would have succeeded in logging to the file)

4: Throw an error 1 ms after the Daily Rotate File's 'rotate' file event.
   (Pre-patch: would have failed to log to the file)

5: Throw an error 4 ms after the Daily Rotate File's 'new' file event.
   (Pre-patch: would have succeeded in logging to the file)

*/
const TEST_NUMBER = 0;

const humanReadableFormat = printf((info) => {
    const { timestamp, message, level, ...rest } = info;
    return `[${timestamp}] ${level}: ${message}` + 
    (Object.keys(rest).length > 0 ? ` – ${JSON.stringify(rest, null, 3)}` : "");
});

const stringifiedJsonFormatter = winston.format.printf((info, opts) => {
    return JSON.stringify(info);
});

const consoleTransport = new transports.Console({
    level: "silly",
    format: winston.format.combine(
        winston.format.colorize(),
        winston.format.timestamp(),
        winston.format.align(),
        humanReadableFormat,
    )
})

const dailyRotateTransport = new winston.transports.DailyRotateFile({
    filename: '%DATE%-debug.json',
    dirname: "logs",
    datePattern: 'YYYY-MM-DD',
    zippedArchive: true,
    maxSize: '20m',
    maxFiles: '3d',
    level: 'debug',
    handleExceptions: true
});

dailyRotateTransport.logStream.on('new', (file) => {
    // To pass the event from the logStream up to dailyRotateTransport.
    dailyRotateTransport.emit('new', file);
});

const LOG_FILE_CERTAINLY_NOT_YET_OPENED_TIMEPOINT = 1;
const NEW_LOG_FILE_LIKELY_OPENED_TIMEPOINT = 3;
const ROTATED_LOG_FILE_LIKELY_OPENED_TIMEPOINT = 4;

dailyRotateTransport
.on('new', (filename) => {
    /* It's possible to enqueue several log messages in the seconds
     * before the 'new' event has fired. */
    console.log(`Will log initially to ${filename}.`);
    if(TEST_NUMBER < 2) return;

    setTimeout(
        () => { throw new Error("BOOM"); },
        TEST_NUMBER === 2 ?
            LOG_FILE_CERTAINLY_NOT_YET_OPENED_TIMEPOINT :
            NEW_LOG_FILE_LIKELY_OPENED_TIMEPOINT
    );
})
.on('rotate', (oldFilename, newFilename) => {
    console.log(`Rotating log from ${oldFilename} to ${newFilename}`);
    if(TEST_NUMBER < 4) return;

    setTimeout(
        () => { throw new Error("BOOM"); },
        TEST_NUMBER === 4 ?
            LOG_FILE_CERTAINLY_NOT_YET_OPENED_TIMEPOINT :
            ROTATED_LOG_FILE_LIKELY_OPENED_TIMEPOINT
    );
});

const logger = winston.createLogger({
    format: winston.format.combine(
        winston.format.timestamp(),
        stringifiedJsonFormatter,
    ),
    transports: [
        consoleTransport,
        dailyRotateTransport,
    ],

    /* NOTE: If you declare them again here, they'll simply log twice.
     *       Don't know whether that's intentional... */
    // exceptionHandlers: [
    //     consoleTransport,
    //     dailyRotateTransport,
    // ]
});

logger.log({
    level: "debug",
    message: "If you start me up, I'll never stop ♬"
});

if(TEST_NUMBER === 1) throw new Error("BOOM");

I haven't looked through the code of your patch to determine how perfect it is, but certainly it fixes my use cases!

Something interesting: In the three seconds that you permit before allowing the app to shut down, further exceptions can be caught and logged during that time (easy to observe by throwing errors on an interval). I don't mind about this (any error-logging is better than nothing), but it seems like a point to improve upon – the app should really stop execution upon the first error.

I'll be using your patch nonetheless.

[DABH]

Thanks @shirakaba for the thorough analysis! Curious that this helps winston-daily-rotate-file; my fixes were only intended for the base File transport, but maybe some of that code gets used by winston-daily-rotate-file. Regardless, the test cases are quite helpful! Could be pretty valuable to try to add those as official test cases to e.g. winston-daily-rotate-file when/if this patch gets merged.

I think it's debatable whether you'd only want to log the first error that occurs (what if a bug is a result of two exceptions from different parts of an app), but certainly that's something we could think about.

I believe @indexzero and I are scheduled to chat next Friday, so I'll try to make it a point to go over this PR unless he has time to review it sooner.

[VarvaraZadnepriak]

Guys, when do you plan to merge this very important PR ?
It is strange that with exitOnError: true the logger logs just nothing =(

[indexzero]

Likely related to #1541