CODEWITHSUNDEEP
pythonlogging
karlosss
karlosss

Reputation: 3155

separate logfiles for every minute not always generated

I am trying to set up logging where all logs from every minute will end up in a separate file. This is the setup I have:

import logging
from logging.handlers import TimedRotatingFileHandler
import time

logging.basicConfig(
    format="[%(asctime)s] %(levelname)s in %(name)s: %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
    handlers=[TimedRotatingFileHandler("test.log", when="m", interval=1, backupCount=10, utc=True)],
)
logging.Formatter.converter = time.gmtime

logger = logging.getLogger(__name__)

logger.error("asdf")

When I ran the script multiple times, this is what I found in test.log.2020-01-01_22-16:

[2022-01-01 22:15:46] ERROR in __main__: asdf
[2022-01-01 22:15:55] ERROR in __main__: asdf
[2022-01-01 22:16:06] ERROR in __main__: asdf
[2022-01-01 22:16:14] ERROR in __main__: asdf
[2022-01-01 22:16:15] ERROR in __main__: asdf
[2022-01-01 22:16:45] ERROR in __main__: asdf
[2022-01-01 22:16:56] ERROR in __main__: asdf

Can anyone please explain how come that test.log.2020-01-01_22-15 does not even exist and the records that I would assume to be in there are found in the 22:16 log instead?

EDIT: I found out that a new file is only generated if there is a whole minute when nothing was logged. Can I somehow achieve what I want?

Upvotes: 0

Views: 39

Answers (1)

Lenormju
Lenormju

Reputation: 4378

Indeed, the TimedRotatingFileHandler documentation says so :

When computing the next rollover time for the first time (when the handler is created), the last modification time of an existing log file, or else the current time, is used to compute when the next rotation will occur.

Which is a correct translation for the corresponding code from TimedRotatingFileHandler.__init__ :

        if os.path.exists(filename):
            t = os.stat(filename)[ST_MTIME]
        else:
            t = int(time.time())

It is intended for long-running applications. If what you want is to have the same behavior for your short-running application, you will have to write some custom code. Re-using as much as possible from TimedRotatingFileHandler, we could cheat with modification times.

import logging
from logging.handlers import TimedRotatingFileHandler
import time
import datetime
import os
import re
import stat


def cheat_logfile_mtime():
    filename = "test.log"
    with open(filename, "rt") as logfile:
        first_line = logfile.readline().rstrip()
    pattern = re.compile(r"\[(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})]")  # [2022-01-03 16:06:07]
    match = pattern.match(first_line)
    assert match is not None
    logline_datetime_str = match.group(1)
    local_timezone = datetime.datetime.now().astimezone().tzinfo
    logline_datetime = datetime.datetime.fromisoformat(logline_datetime_str).replace(tzinfo=datetime.timezone.utc).astimezone()
    file_mtime_datetime = datetime.datetime.fromtimestamp(os.stat(filename)[stat.ST_MTIME], tz=local_timezone)
    now = datetime.datetime.now(tz=local_timezone)
    one_minute_delta = datetime.timedelta(minutes=1)
    if now - file_mtime_datetime < one_minute_delta < now - logline_datetime:
        # the logfile was last modified less than one minute ago, but was first written more than one minute ago
        os.utime("test.log", (logline_datetime.timestamp(), logline_datetime.timestamp()))
        print("cheating the file mtime")


cheat_logfile_mtime()


logging.basicConfig(
    format="[%(asctime)s] %(levelname)s in %(name)s: %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
    handlers=[TimedRotatingFileHandler("test.log", when="m", interval=1, backupCount=10, utc=True)],
)
logging.Formatter.converter = time.gmtime

logger = logging.getLogger(__name__)

logger.error("asdf")

This works as you wanted : a logfile will not contain more than 1 real minute of logs, whatever the number of times you start the application. I tested it with 1 run by second, getting ~59 lines in the file before the rotation.
It seems to respect the user timezone (I am currently in CET). But it requires being able to reliably read and write modification times, which may not be able on network drives or other conditions.

Upvotes: 1

Related Questions