Ошибка с logging.handlers.TimedRotatingFileHandler? - PullRequest
Новая
       40

Ошибка с logging.handlers.TimedRotatingFileHandler?

0 голосов
/ 24 сентября 2019

Следующий код вызывает неожиданное поведение при logging.handlers.TimedRotatingFileHandler: 

logger1 = logging.getLogger("One")
logger2 = logging.getLogger("Two")

handler1 = TimedRotatingFileHandler(
    "service.log",
    when="M",
    backupCount=2,
    utc=True
)
handler2 = TimedRotatingFileHandler(
    "service.log",
    when="M",
    backupCount=2,
    utc=True
)

formatter = logging.Formatter("%(asctime)s - %(name)s - %(message)s")

handler1.setFormatter(formatter)
handler2.setFormatter(formatter)

logger1.addHandler(handler1)
logger2.addHandler(handler2)

while True:
    sleep(0.5)
    logger1.error("ONE")
    logger2.error("TWO")

Я оставляю его включенным на несколько минут, и все выглядит нормально в конце первого запуска.Я знаю, что есть какое-то поведение, когда файлы не переносятся в тот момент, когда это можно было ожидать, но я согласен с этим: 

-rw-rw-r-- 1 dave dave 3.8K Sep 24 16:11 service.log
-rw-rw-r-- 1 dave dave 3.8K Sep 24 16:11 service.log.2019-09-24_09-09
-rw-rw-r-- 1 dave dave 4.3K Sep 24 16:10 service.log.2019-09-24_09-08

Однако, если яподождите несколько минут, прежде чем снова запустить скрипт в том же каталоге , не удаляя существующие файлы service.log *, файлы , теперь logger1 начинает запись в service.log.2019-09-24_09-11, а logger2 пишет в service.log, как и ожидалось.Обратите внимание, что время последнего изменения 16:17 рядом с service.log.2019-09-24_09-11. 

-rw-rw-r-- 1 dave dave  540 Sep 24 16:17 service.log
-rw-rw-r-- 1 dave dave  540 Sep 24 16:17 service.log.2019-09-24_09-11
-rw-rw-r-- 1 dave dave 3.8K Sep 24 16:11 service.log.2019-09-24_09-09

Мне кажется, что это ошибка, поскольку logger1 продолжает записывать в файл несколько минут назад при различных вызовах logger.error - это не просто первая запись при перезапуске скрипта. 

dave:~$ cat service.log.2019-09-24_09-11

2019-09-24 16:16:55,390 - One - ONE
2019-09-24 16:16:55,892 - One - ONE
2019-09-24 16:16:56,393 - One - ONE
2019-09-24 16:16:56,894 - One - ONE
2019-09-24 16:16:57,395 - One - ONE
2019-09-24 16:16:57,896 - One - ONE
2019-09-24 16:16:58,397 - One - ONE
2019-09-24 16:16:58,898 - One - ONE
...

Я использую Python 3.7.4.

Редактировать: Тревожное поведение можно воспроизвести без остановки изапуск сценария, просто если журналы не записываются в течение нескольких минут.

Наблюдайте за состоянием файлов журналов (очищенных до 36 байт каждый!) в течение sleep(180) времени, если мы заменим 

while True:
    sleep(0.5)
    logger1.error("ONE")
    logger2.error("TWO")

... с ... 

for _ in range(60):
    sleep(1)
    logger1.error("ONE")
    logger2.error("TWO")

sleep(180)  # blocking, no logs written but log files are in eroded state

for _ in range(60):
    sleep(1)
    logger1.error("ONE")
    logger2.error("TWO")

1 Ответ

0 голосов
/ 24 сентября 2019

По сути, причина ошибки заключается в том, что существует несколько экземпляров TimedRotatingFileHandlers.Я думаю, что переворачивание не справляется с этим необычным случаемКажется, что этого можно избежать почти во всех ситуациях, потому что мы можем установить один и тот же объект форматирования для обоих обработчиков и добавить один и тот же экземпляр обработчика для нескольких объектов регистратора.

...