Is it possible to make logging calls during files rotation?

[mberdyshev]

Hello! Thank you for this simple and awesome library!
In my project I was trying to log some useful information right after the log files rotation, so I added logging call into rotation function. I know that the documentation advises not to do that, but still I tested it. I provided enqueue parameter, so it could work, those were my thoughts.

Either way, if you use a custom function designed according to your preferences, you must be very careful not to use the logger within your function. Otherwise, there is a risk that your program hang because of a deadlock.

With modified rotator from the recipe I created this code:

import datetime
import os
import os.path
import time

from loguru import logger
from loguru._string_parsers import parse_frequency, parse_size


class Rotator:
    def __init__(self, str_size, str_freq):
        self._size_limit = parse_size(str_size)
        self._freq = parse_frequency(str_freq)
        self._time_limit = None

    def should_rotate(self, message, file):
        if self._time_limit is None:
            modified_datetime = datetime.datetime.fromtimestamp(os.path.getmtime(file.name))
            self._time_limit = self._freq(modified_datetime)

        file.seek(0, 2)
        if file.tell() + len(message) > self._size_limit:
            self._log_useful_info()
            return True
        if message.record["time"].timestamp() >= self._time_limit.timestamp():
            self._time_limit = self._freq(message.record["time"])
            self._log_useful_info()
            return True
        return False

    def _log_useful_info(self):
        logger.info("<...>" * 100)


logger.add("main.log", enqueue=True, rotation=Rotator('50MB', 'DAILY').should_rotate)
# Small hack to change the log mtime for testing purposes
mtime = os.path.getmtime("main.log") - 60*60*24
os.utime("main.log", times=(mtime, mtime))

logger.debug("New debug info")
time.sleep(0.1)  # For the loguru queue thread

Awesome, it works properly for my use case. But the problem comes when I try to log a long message (an app config in my case) inside _log_useful_info. For example if I change the multiplier to 1000 ("<...>" * 1000), the program halts. Especially if I use serialize option which increases the log message length. Through trial and error I identified that the problematic length of a log message is around 3770 on my machine.

I've already investigated a little bit - it's some OS-specific problem, because it works properly on WSL Ubuntu. It seems like the described case has the direct connection to this Python bug.
I tried to change the queue definition inside the loguru handler to self._queue = multiprocessing.Queue() as it was proposed in the issue. Regarding the given example it helped to successfully write logs to the file, but some other errors arose from multiprocessing. Strangely it seems that the fix helped in my main project.

I know that probably the best solution is not to log during files rotation or limit the string length, but I think it might be an interesting case to analyze. So my main question from the title does remain.

Technical details:
Windows 10 22H2, Python 3.11.2, Loguru 0.7.2

[Delgan]

Hi @mberdyshev.

Using enqueue=True is indeed a possible workaround in order to be able to use the logger within the rotation function. I'm aware of the SimpleQueue problem, and I have a fix for that, but it's not yet merged on master (I have yet to fix a bug with PyPy).

It's also possible to call logger.disable() for the specific file where is implemented the rotation function. However, although such solution would avoid any deadlock, it won't log anything, so this is likely not what you want.

So, basically, the enqueue=True solution is the is the right way to go. But I need to fix the SimpleQueue issue. :)