[Bug]: File transport stops logging during rotate and leaks memory

[u8675309]

🔎 Search Terms

file leak memory

The problem

The Winston file transport occasionally will stop logging immediately after log rotation. This results in the new log file being size 0, the logger WritableState stuck in "writing" state with continuously increasing buffer. All transports for the logger are blocked. Eventually this leads to an out of memory and program crash.

This appears to be caused by:

1. EventEmitter kShapeMode/shapeMode is somehow set to true. This causes event keys to remain set as undefined. The eventNames still returns all keys set to undefined. events.js#L89
2. The Winston file transport checks for eventNames('rotate') to determine whether to emit the event or set _rotate false. file.ts#L442
3. The 'rotate' event is fired before the there is a listener so _rotate remains true.
4. A new log sees _rotate is true and waits indefinitely for the 'rotate' event.

To confirm this, I added a debug log inside the once('open':

      this.once('open', () => {
        debug('on open has rotate', this._stream.eventNames().includes('rotate'), ', count', this._stream.listenerCount('rotate'));
        if (this._stream.eventNames().includes('rotate')) {
          this._stream.emit('rotate');
        } else {
          this._rotate = false;
        }
      });

And eventually, after over an hour of logging, this log appeared:

on open has rotate true , count 0

Additionally I opened the inspector and observed the shapeMode symbol was set to true on the _stream PassThrough.

I am not sure why the shapeMode is set to true, but apparently eventNames() cannot be relied upon. For current event listeners. Possibly the file.js
if (this._stream.eventNames().includes('rotate')) {
should be replaced with
if (this._stream.listenerCount('rotate')) {
which will return 0 when there are no rotate listeners.

Additional versions:
[email protected]
[email protected]

What version of Winston presents the issue?

v3.13.0

What version of Node are you using?

20.11.1

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

No response

Minimum Working Example

No response

Additional information

No response

[DABH]

I'm open to a PR if you think something like your suggestion would be a reliable fix. You have looked more closely at this code than I have lately. Would it be better to try some kind of || with this._stream.eventNames().includes('rotate') and this._stream.listenerCount('rotate'), or would it make more sense to just replace with this._stream.listenerCount('rotate') as you suggest? If you have any way to stress test this as a potential fix (and verify that no other unintended behavior is introduced), definitely open to a PR like I mentioned. Thanks for your help in investigating.

[u8675309]

#2457

I plan to test this a bit before it should be reviewed/merged.

[DABH]

Amazing, thank you!! Keep us posted :)

[u8675309]

I tested it overnight and no issues.

Does it matter that the coverage reduced by 0.02%? The line count went down by 1 and it was a covered line.

[Markiz9999]

I encountered the same problem under high load. Please merge it.
Changing this._stream.eventNames().includes('rotate') to this._stream.listenerCount('rotate') helped in my case, but the suggested fix is ​​more reliable in my opinion.