Python logger `RotatingFileHandler` не работает под Windows

Question

Я пытаюсь использовать обработчик RotatingFileHandler для управления потенциально длинными файлами журналов для проекта Python, работающего под Windows.Я обнаружил, что ротация файла журнала работает нормально при запуске с использованием интерпретатора IDLE (на ПК с Windows), но происходит сбой с исключением WindowsError при запуске из командной строки Windows.

Вот пример кода, который показываетпроблема -

import logging, logging.handlers
import datetime
import time

mainlogfile = 'fred.log'
logging_level = logging.DEBUG
logging_rotate_time = datetime.timedelta(minutes=1)

logger = logging.getLogger('Main_Logger')
logger.setLevel(logging.DEBUG)

handler = logging.handlers.RotatingFileHandler(mainlogfile, backupCount=7)
handler.setLevel(logging_level)
formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
handler.setFormatter(formatter)      
logger.addHandler(handler)

next_rotate = datetime.datetime.now() + logging_rotate_time

while True:
    time.sleep(5)
    logger.info('Tick ')
    n = datetime.datetime.now()
    if n>next_rotate:
        logger.info('Rotating logfile')
        handler.doRollover()
        logger.info('Succesfully rotated logfile')
        next_rotate = next_rotate + logging_rotate_time
        logger.info('Next logfile rotate at '+ str(next_rotate))

Когда я запускаю это в интерпретаторе IDLE, он работает нормально, и файл журнала fred.log вращается каждую минуту, производя fred.log.1, fred.log.2 и т. д. с содержимым, таким как -

2018-12-10 12:24:40,269 INFO Succesfully rotated logfile
2018-12-10 12:24:40,269 INFO Next logfile rotate at 2018-12-10 12:25:40.182000
2018-12-10 12:24:45,269 INFO Tick 
2018-12-10 12:24:50,269 INFO Tick 
2018-12-10 12:24:55,269 INFO Tick 
2018-12-10 12:25:00,267 INFO Tick 
2018-12-10 12:25:05,267 INFO Tick 
2018-12-10 12:25:10,266 INFO Tick 
2018-12-10 12:25:15,266 INFO Tick 
2018-12-10 12:25:20,266 INFO Tick 
2018-12-10 12:25:25,266 INFO Tick 
2018-12-10 12:25:30,265 INFO Tick 
2018-12-10 12:25:35,265 INFO Tick 
2018-12-10 12:25:40,263 INFO Tick 
2018-12-10 12:25:40,263 INFO Rotating logfile

Тем не менее, при запуске в командной строке происходит сбой при первой попытке поворота -

C:\> python try10.py
Traceback (most recent call last):
  File "try10.py", line 29, in <module>
    handler.doRollover()
  File "C:\Python27\lib\logging\handlers.py", line 142, in doRollover
    os.rename(self.baseFilename, dfn)
WindowsError: [Error 32] The process cannot access the file because it is being used by another process

Я искал и обнаружил, что есть проблемы под Windows при попытке закрытьили переименуйте файлы журналов, которые используются другим процессом Python, но я не могу понять, как это относится к моему простому примеру.Я пытался позвонить handler.flush() и handler.close() до handler.doRollover(), но это не изменило поведение.

Мои вопросы -

• Почему возникает исключение при запуске из командной строки, но не в режиме IDLE?
• Могу ли я внести какие-либо изменения вкод для запуска в командной строке Windows

Answer 1

Глядя на код метода doRollover() в модуле logging.handlers, можно увидеть, что приведенное выше исключение возникает, когда doRollover пытается переименовать файл журнала fred.log в fred.log.1, используяos.rename().Попытка переименовать открытый файл таким образом вызовет исключение под Windows, хотя ранее в методе doRollover() открытый файл журнала должен был быть закрыт.Так как моя программа как стоящая всегда терпит неудачу в консоли Windows, похоже, что файл журнала не закрывается должным образом.В интерпретаторе IDLE кажется, что файловый ввод / вывод выполняется не так, как консоль (через сокеты, как описано в документации ), поэтому, возможно, именно это позволяет коду запускаться там.

Учитывая, что для того, чтобы doRollover() мог переименовать файл журнала, сначала его нужно закрыть, и я обнаружил, что это можно принудительно вызвать, временно удалив обработчик из регистратора во время ролловера - вот так -

while True:
    time.sleep(5)
    logger.info('Tick ')
    n = datetime.datetime.now()
    if n>next_rotate:
        logger.info('Rotating logfile')

        logger.removeHandler(handler)      
        handler.doRollover()        
        logger.addHandler(handler)

        logger.info('Succesfully rotated logfile')
        next_rotate = next_rotate + logging_rotate_time
        logger.info('Next logfile rotate at '+ str(next_rotate))

С этими модами код работает нормально, а файл журнала fred.log вращается каждую минуту, создавая fred.log.1, fred.log.2 и т. Д., Как и ожидалось