[Bug]: Filetransport for exceptionHandlers closes after first exception

[RoelVB]

🔎 Search Terms

uncaughtException

The problem

After Winston logged an uncaughtException it seems to close the logfile, which makes the process crash at the next uncaughtException.

The issue might be related to #2219

What version of Winston presents the issue?

v3.9.0

What version of Node are you using?

v18.16.0

If this worked in a previous version of Winston, which was it?

No response

Minimum Working Example

const winston = require('winston');

winston.createLogger({
    format: winston.format.combine(
        winston.format.printf(info=>`[${info.level}]: ${info.message}`),
    ),
    exceptionHandlers: [
        new winston.transports.Console(),
        new winston.transports.File({filename: 'exceptions.log'}),
    ],
    exitOnError: false,
});

const sleep = (ms)=>new Promise(r=>setTimeout(r, ms));

setTimeout(()=>{
    throw 'First exception';
}, 100);

setTimeout(()=>{
    throw 'Second exception';
}, 200);

(async ()=>{
    await sleep(1000);

    console.log('Process end');
})();

Additional information

Without the second exception present in the code, the output looks (as expected) like this:

[error]: uncaughtException: First exception
  No stack trace
Process end

But when we include the second exception the process crashes and the output looks like:

[error]: uncaughtException: First exception
  No stack trace
[error]: uncaughtException: Second exception
  No stack trace
events.js:377
      throw er; // Unhandled 'error' event
      ^

NodeError: write after end
    at writeAfterEnd (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\readable-stream\lib\_stream_writable.js:264:12)
    at PassThrough.Writable.write (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\readable-stream\lib\_stream_writable.js:300:21)
    at File.log (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\winston\lib\winston\transports\file.js:190:34)    
    at DerivedLogger.ondata (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\readable-stream\lib\_stream_readable.js:629:20)
    at DerivedLogger.emit (events.js:412:35)
    at addChunk (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\readable-stream\lib\_stream_readable.js:279:12)
Emitted 'error' event on PassThrough instance at:
    at errorOrDestroy (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\readable-stream\lib\internal\streams\destroy.js:90:101)
    at writeAfterEnd (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\readable-stream\lib\_stream_writable.js:266:3)
    at PassThrough.Writable.write (C:\Users\Me\Development\Temp\winston-exception-handler-test\node_modules\readable-stream\lib\_stream_writable.js:300:21)
    [... lines matching original stack trace ...]
    at DerivedLogger.emit (events.js:412:35)

With DEBUG=winston:file we see the file gets closed after the first exception:

winston:file: stat done: exceptions.log { size: 62 }
winston:file: create stream start exceptions.log { flags: 'a' }
winston:file: create stream ok exceptions.log
winston:file: file open ok exceptions.log
[error]: uncaughtException: First exception
  No stack trace
winston:file: written true false
winston:file: logged 124 [error]: uncaughtException: First exception
  No stack trace

winston:file: close exceptions.log 62
[error]: uncaughtException: Second exception
  No stack trace
events.js:377
      throw er; // Unhandled 'error' event
      ^

[wbt]

Is this possibly a duplicate of #228 or #1613 (or do they provide useful insights)?

[RoelVB]

Thank you for your reply. Those issues don't seem the same to me.

[RoelVB]

Quick work-around I'm currently using (custom uncaughtException handler and exception loglevel):

const winston = require('winston');

const logger = winston.createLogger({
    levels: {exception: 0, error: 1, warn: 2, info: 3, verbose: 4},
    format: winston.format.combine(
        winston.format.printf(info=>`[${info.level}]: ${info.message}`),
    ),
    transports: [
        new winston.transports.File({filename: 'exceptions.log', level: 'exception'}),
        new winston.transports.Console(),
    ],
});

process.on('uncaughtException', (error)=>{
    const message = typeof error === 'string' ? error : error.message;
    logger.log('exception', `${message}\n${error && error.stack || '  No stack trace'}`);
});

const sleep = (ms)=>new Promise(r=>setTimeout(r, ms));

setTimeout(()=>{
    throw 'First exception';
}, 100);

setTimeout(()=>{
    throw 'Second exception';
}, 200);

(async ()=>{
    await sleep(1000);

    console.log('Process end');
})();

Which results in the expected output:

[exception]: First exception
  No stack trace
[exception]: Second exception
  No stack trace
Process end

[DABH]

If you're able to dive in and see why your exception handler is working but the winston built-in one is not, we'd be more than happy to review a PR...

[zinevych]

I would like to try to investigate this. Looks like will have some time to work on this

[DABH]

Thank you so much! Like I said, above, happy to review any PR‘s! Bonus points if those come with any kind of new test cases so we can ensure that this functionality remains working in the future :)