[Bug]: winston sometimes keeps file descriptors open after log rotation

[JohnXLivingston]

🔎 Search Terms

log rotation, file descriptor

The problem

Peertube (a web VOD software) sometimes keeps file descriptors on rotated log files. See here for the description of the issue: https://github.com/Chocobozzz/PeerTube/issues/6041

This report was done at a time Peertube was using Winston 3.8.2. It now uses Winston 3.11.0 and the bug is still present.

There were some discussion on issue #2100, as i thought it was the same issue. But the fix for #2100 does not fix my issue (as it is part of Winston 3.11.0, and I still have the bug). After discussing with @DABH , i'm opening this issue to continue here.

After restarting Peertube, we can quickly see that Peertube is loggin in multiple files:

In the above screenshot, there were some writing in the peertube1.log, despite the current logging file is peertube3.log.

Note: the peertube66.log (and above) were files written before restarting Peertube.

We can see, using lsof, that Peertube has peertube1.log opened several times:

After running Peertube a few days, we can see there are some deleted files still opened:

I don't know why the peertube1.log file is opened multiple times. Maybe this is related to the issue... @Chocobozzz , could it be related to multi-threading? Maybe the new threads keeps the logger has it was before spawning, and therefore continues to log in the first file?

I have an hypothesis: maybe we had 2 different bugs. The one in #2100 , and something related to multi threads. For now, with Winston 3.11.0 i only see peertube1.log that is still opened after rotation. (in the initial report, i had also a peertube17.log file)

Here is the Peertube code that instantiate the logger: https://github.com/Chocobozzz/PeerTube/blob/d1adcfadfd4201ab106286a5615dd3a6885c0c69/server/core/helpers/logger.ts#L61 A logger is created, and kept in a global constant: https://github.com/Chocobozzz/PeerTube/blob/d1adcfadfd4201ab106286a5615dd3a6885c0c69/server/core/helpers/logger.ts#L88

@DABH , unfortunately i have no easy way for you to test.

What version of Winston presents the issue?

3.11.0

What version of Node are you using?

v18.19.0

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

No response

Minimum Working Example

No response

Additional information

No response

[DABH]

Can you explain how the multi threading works in your app? My understanding is Node.js has a single event loop so we don’t have to worry about things like atomics, but if this were C++ code, I wouldn’t consider it thread safe, e.g. we’re checking this._rotate but I don’t think we’re considering the possibility of multiple threads changing that.

[DABH]

Or if there’s a way to launch and test Peertube with just one thread, to test?

[DABH]

And 😅 do you see issues like the log file being opened multiple times, if you don’t rotate files (e.g. set the max file size to be massive)? Perhaps there are two issues here, one with multiple copies of the file open, one with rotation, both in the case of multithreaded application?…

[JohnXLivingston]

Can you explain how the multi threading works in your app? My understanding is Node.js has a single event loop so we don’t have to worry about things like atomics, but if this were C++ code, I wouldn’t consider it thread safe, e.g. we’re checking this._rotate but I don’t think we’re considering the possibility of multiple threads changing that.

I don't exactly know how this part of Peertube works (i'm not part of the core maintainers). I mentioned @Chocobozzz, and also asked the question on the Peertube's issue. I suggest we wait for his opinion on this point.

And 😅 do you see issues like the log file being opened multiple times, if you don’t rotate files (e.g. set the max file size to be massive)? Perhaps there are two issues here, one with multiple copies of the file open, one with rotation, both in the case of multithreaded application?…

It seems that the first file is instantly opened multiple times. I have no idea why. Maybe @Chocobozzz will have some ideas.

[Chocobozzz]

Hi,

We just use classic worker threads in PeerTube. Logger instance may then be opened in multiple threads. I'm not sure how winston manage file rotation in such case :thinking:

[JohnXLivingston]

Hi,

We just use classic worker threads in PeerTube. Logger instance may then be opened in multiple threads. I'm not sure how winston manage file rotation in such case 🤔

Do you think it is possible that it only rotates on the main thread, and keeps the first file opened for all worker threads?

Maybe the bug is on the peertube side, and we should instantiate a new logger for each worker?

[Chocobozzz]

instantiate a new logger for each worker

We instantiate a new logger for each worker as we can't share a living JS object between threads.

[DABH]

Ah so that makes more sense then… if each thread has its own logger, then that already explains why a log file is opened multiple times (the logger objects don’t know about each other).

So then the issue here is how will the loggers living in multiple threads deal with rotation… this is something I don’t think that’s been accounted for in the rotation code… if anybody is a worker threads expert and has thought through this kind of question already feel free to opine. Right now I’m guessing that each logger instance is going to rotate on its own. I mean, that explains why you see a message logged to peertube1.log after a file is already rotated — it’s the final message coming from another worker, being logged to the old file. Rotation in Winston is happening on logged(), i.e. after the last message to a file gets logged. So if Thread 1 rotates, T2 won’t rotate till it’s logged one more message to the old file I think…

So, if you don’t hate the behavior, I’d say that neither of the first two things you mentioned are really a bug?

The last/third thing you mention about keeping open fd’s to deleted files definitely sounds buggy though. Can you enlighten me as to when Peertube deletes log files?

[JohnXLivingston]

As explained by @DABH , this could explain a lot.

@Chocobozzz , would it be possible to change the code to use another logger function in workers? So it uses a logger function that sends the text to log to the main process (using message channel). So that only the main process has a log file opened.

[DABH]

(If you do this... would be very happy to take some inspo from what you do and include it as a guide in the winston repo for anybody else who's doing logging in apps using worker threads :) ...)

[Chocobozzz]

would it be possible to change the code to use another logger function in workers?

Yes, I think it would be much more cleaner to do that anyway.