Bug with with logging.handlers.TimedRotatingFileHandler?

Question

The following code produces some unexpected behaviour with 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")

I leave it running for a few minutes and everything appears ok at the end of first run. I'm aware there is some sort of off-by-one behaviour where files don't rollover at exactly the instant one might expect, but I'm ok with this:

-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

However, if I wait some minutes before starting the script again in the same directory without deleting the existing service.log* files, now logger1 starts writing to service.log.2019-09-24_09-11 and logger2 writes to service.log as expected. Note the last modified time of 16:17 next to 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

This seems like a bug to me as logger1 continues writing to the file from several minutes ago across distinct calls to logger.error- it's not just the first entry when script is restarted.

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
...

I'm using Python 3.7.4.

Edit: Alarming behaviour can be reproduced without stopping and starting the script, simply if no logs are written for a few minutes.

Observe the state of the log files (purged down to 36 bytes in size each!) during the sleep(180) time if we replace

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

...with...

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")

score 0 · Accepted Answer · answered Sep 24 '19 at 12:31

Basically the root of the error stems from the fact that there are multiple instances of TimedRotatingFileHandlers. I guess the rolling-over doesn't deal well with this unusual case. It seems like this can be avoided in almost all situations, because we can set the same formatter object on both handlers, and add the same handler instance to multiple logger objects.

Bug with with logging.handlers.TimedRotatingFileHandler?

1 Answers1