Loguru: rotation could not keep with write

[yoonghm]

Hi,

I am testing loguru.disable() and loguru.enable() with rotation. Here are my codes:

mylibrary.py

from loguru import logger
import sys

class MyLibrary:
    def __init__(self):
        config = {
            'handlers': [
                {'sink': 'logfile.log',
                 'rotation': '1 kB',
                 'format': '{time:YYYY-MM-DD hh:mm:ss} - {name}:{file}:{line} - {message}'
                },
                {'sink': sys.stdout,
                 'format': '{time:YYYY-MM-DD hh:mm:ss} - {name}:{file}:{line} - {message}'
                },
            ],
            'extra': {'user': 'someone'}
        }
        logger.configure(**config)
        logger.disable('mylibrary')
        logger.info('This message is not displayed')

    def do_something(self, msg):
        logger.error(f'Processing message {msg} ...')

and this is the script that uses the library

uselibrary

from mylibrary import MyLibrary
from loguru import logger
#import time

myl = MyLibrary()

logger.info('This message is from uselibrary.py')
myl.do_something('start')
logger.enable('mylibrary')

for i in range(100):
    myl.do_something(str(i))
    #time.sleep(0.0001)

myl.do_something('end')

It will produce the following errors:

--- Logging error in Loguru Handler #1 ---
Record was: {'elapsed': datetime.timedelta(microseconds=15621), 'exception': None, 'extra': {'user': 'someone'}, 'file': 'uselibrary.py', 'function': '<module>', 'level': 'INFO', 'line': 7, 'message': 'This message is from uselibrary.py', 'module': 'uselibrary', 'name': '__main__', 'process': '4596', 'thread': '13404', 'time': datetime(2019, 11, 24, 9, 24, 33, 778833, tzinfo=datetime.timezone(datetime.timedelta(seconds=28800), 'Malay Peninsula Standard Time'))}
Traceback (most recent call last):
  File "C:\home\Anaconda3\lib\site-packages\loguru\_handler.py", line 144, in emit
    self._writer(str_record)
  File "C:\home\Anaconda3\lib\site-packages\loguru\_file_sink.py", line 67, in write
    self._initialize_file(rename_existing=True)
  File "C:\home\Anaconda3\lib\site-packages\loguru\_file_sink.py", line 85, in _initialize_file
    os.rename(new_path, renamed_path)
FileExistsError: [WinError 183] Cannot create a file when that file already exists: 'C:\\MyLesson\\python\\logfile.log' -> 'C:\\MyLesson\\python\\logfile.2019-11-24_09-23-45_671958.log'
--- End of logging error ---
2019-11-24 09:24:33 - __main__:uselibrary.py:7 - This message is from uselibrary.py
2019-11-24 09:24:33 - mylibrary:mylibrary.py:26 - Processing message 0 ...
--- Logging error in Loguru Handler #1 ---
Record was: {'elapsed': datetime.timedelta(seconds=1, microseconds=16096), 'exception': None, 'extra': {'user': 'someone'}, 'file': 'mylibrary.py', 'function': 'do_something', 'level': 'ERROR', 'line': 26, 'message': 'Processing message 1 ...', 'module': 'mylibrary', 'name': 'mylibrary', 'process': '4596', 'thread': '13404', 'time': datetime(2019, 11, 24, 9, 24, 34, 779308, tzinfo=datetime.timezone(datetime.timedelta(seconds=28800), 'Malay Peninsula Standard Time'))}
Traceback (most recent call last):
  File "C:\home\Anaconda3\lib\site-packages\loguru\_handler.py", line 144, in emit
    self._writer(str_record)
  File "C:\home\Anaconda3\lib\site-packages\loguru\_file_sink.py", line 67, in write
    self._initialize_file(rename_existing=True)
  File "C:\home\Anaconda3\lib\site-packages\loguru\_file_sink.py", line 85, in _initialize_file
    os.rename(new_path, renamed_path)
FileExistsError: [WinError 183] Cannot create a file when that file already exists: 'C:\\MyLesson\\python\\logfile.log' -> 'C:\\MyLesson\\python\\logfile.2019-11-24_09-23-45_671958.log'

...
--- End of logging error ---

If I enable the delay via time.sleep(0.0001) the problem disappear. Thanks.

[Delgan]

Ugh, sorry for this bug... I did not expect the rotation to happen twice at the same microsecond. I just realized that the internal clock resolution is quite large on Windows (like 15 ms), so it makes this error much more likely to happen.

I will add a check before calling os.rename(), and probably add another suffix to the desination filename if it already exists. Thanks for the report. :wink:

[Delgan]

Howerver, it happens from your first message, and the time in the file name doesn't match the time in the error record. So maybe there's something else to investigate. :confused:

Edit: This is related to win32-setctime, as the date used to format the file come from _get_creation_time(). I guess resolution of .st_ctime is too big.

[Delgan]

Fixed. :+1:

If destination of the renamed file exists despite the time added to the file name, another counter will be added and incremented until no such file exists: "logfile.2019-11-24_09-23-45_671958.2.log".