TimeRotatingFileHandler doesn't work as expected

[Ixiodor]

Bug report

Bug description:

Referencing #111054, I found the same issue.
Original post:

Here we go!
I ran into the same issue: the rotation is set to daily, but the logger keeps writing multiple days into the same log file.
args = args = ('logs/logs.log', "D", 1, 7, 'utf-8')

Started:

29-09-2025 16:29:16 | INFO | configuration(root) | Loaded config file: config/config.ini

Still going:

01-10-2025 12:21:23 | INFO | REDACTED

I have some files with GIGA of logs from multiple days.

EDIT:
Seems like each time the application restart for some reason, the "internal day" restars, that means:
Started 29/09 01:00 -> crash at 29/09 13:00, the new rotation is 30/09 13:00 -> crash at 30/09 17:00, the new rotation is 01/09 17:00. On same file, keep going till a full day.

CPython versions tested on:

3.13

Operating systems tested on:

Linux

[StanFromIreland]

cc @vsajip

Note that one of the main issues with the original issue was that no (working) reproducer was provided.

[Ixiodor]

I'll try to make an application that simulate all alone. The problem is that need a crash and restart. I'll check what I can do with FreezeGun and subprocess

[Ixiodor]

I don't know if that can be considered valid, in case we can investigate:

Execute that:

import os
import shutil
import subprocess
import sys
import time

# --- CONFIG:
START_TIMES = [
    "2025-10-01T01:00:00",
    "2025-10-01T12:00:00",
    "2025-10-02T01:00:00",
    "2025-10-03T02:00:00",
    "2025-10-04T03:00:00",
    "2025-10-05T02:00:00",
    "2025-11-06T03:00:00",
    "2025-11-07T02:00:00",
    "2025-12-08T12:00:00",
]
# -------------------------------------------------------------------

PYTHON = sys.executable
WORKER_SCRIPT = "worker.py"


def run_session(i, start_time):
    cmd = [PYTHON, WORKER_SCRIPT,
           "--start-time", start_time,
           "--session-id", str(i + 1),
           "--duration", "2.0"]
    env = os.environ.copy()
    print(f"[driver] Launching session {i + 1} with start_time={start_time} using {PYTHON}")
    proc = subprocess.Popen(cmd, env=env)
    proc.wait()
    print(f"[driver] Session {i + 1} finished with exit code {proc.returncode}.")


def main():
    shutil.rmtree("logs", ignore_errors=True)
    os.makedirs("logs", exist_ok=True)
    if len(START_TIMES) == 0:
        print("Nessun start time definito. Esco.")
        return

    for i, ts in enumerate(START_TIMES):
        run_session(i, ts)
        time.sleep(0.2)

    print("[driver] Tutte le sessioni completate.")


if __name__ == "__main__":
    main()

call this 'worker.py':

import argparse
import datetime
import logging
import os
import sys
import time
from logging.handlers import TimedRotatingFileHandler

from freezegun import freeze_time

LOG_FILE = os.path.join("logs", "log.log")


def setup_logging():
    os.makedirs("logs", exist_ok=True)

    logger = logging.getLogger()
    logger.setLevel(logging.INFO)

    # formatter ISO-like
    fmt = "%(asctime)s %(levelname)s [session:%(session_id)s] %(message)s"
    datefmt = "%Y-%m-%dT%H:%M:%S"

    class SessionFilter(logging.Filter):
        def filter(self, record):
            if not hasattr(record, "session_id"):
                record.session_id = "-"
            return True

    formatter = logging.Formatter(fmt=fmt, datefmt=datefmt)

    # File handler:
    fh = TimedRotatingFileHandler(
        LOG_FILE, when="D", interval=1, backupCount=7, encoding="utf-8")
    fh.setFormatter(formatter)
    fh.addFilter(SessionFilter())

    # Console handler
    ch = logging.StreamHandler(sys.stdout)
    ch.setFormatter(formatter)
    ch.addFilter(SessionFilter())

    for h in list(logger.handlers):
        logger.removeHandler(h)

    logger.addHandler(fh)
    logger.addHandler(ch)

    return logger


def do_work(session_id, duration_sec=2):
    logger = logging.getLogger()
    adapter = logging.LoggerAdapter(logger, {"session_id": session_id})
    adapter.info(f"Session {session_id} started work loop for {duration_sec}s")
    time.sleep(2)


if __name__ == "__main__":
    p = argparse.ArgumentParser()
    p.add_argument("--start-time", required=True, help="ISO datetime string e.g. '2025-09-01T10:00:00'")
    p.add_argument("--session-id", required=True, help="ID della sessione")
    p.add_argument("--duration", type=float, default=2.0, help="Durata del lavoro in secondi")
    args = p.parse_args()

    setup_logging()

    try:
        # freeze_time:
        with freeze_time(args.start_time):
            logger = logging.getLogger()
            adapter = logging.LoggerAdapter(logger, {"session_id": args.session_id})
            adapter.info(f"*** Session {args.session_id} START (frozen: {args.start_time}) ***")
            do_work(args.session_id, duration_sec=args.duration)
            adapter.info(f"Session {args.session_id} about to crash at {datetime.datetime.now().isoformat()}")
            # crash
            os._exit(1)
    except Exception:
        logging.exception("Unhandled exception in worker")
        sys.exit(2)

[vsajip]

As stated in the gh-111054 thread (this comment),

Also note that writing to the same file from multiple processes isn't supported. See the cookbook for recipes that can be used in multiple-process scenarios, in case you are logging directly to file from your Django views.

Unless I've misunderstood something, @Ixiodor , your script above seems to be creating multiple processes writing to the same file - something that isn't supported, though as mentioned the cookbook has a couple of suggested approaches for this scenario.

[Ixiodor]

No, it's the same process that is launched sequentially and not in parallel

[vsajip]

Oh, I see, I missed the proc.wait().

[picnixz]

Here's the summary of what I understood, so correct me if I'm wrong:

• You have a daily rotating handler. IOW, you want one file per day.
• Let's say your start your app on Day 1, at 10:00 with some file app.day1.log (let's simplify the format here). On Day 2, at 10:00, we would create app.day2.log and then push everything else there right?
• If the app crashes on Day 1, at 18:00 for instance, and you restart it, we'll still have app.day1.log because we're still on the same day. However, app.day2.log won't be created at 10:00 next day as we originally expected but at 18:00. And this is where you think this is buggy right?

AFAICT, the issue is hard to fix because internally we do:

if os.path.exists(filename):
    t = int(os.stat(filename).st_mtime)
else:
    t = int(time.time())

to compute the last modified time, which we assume to be the initial time of our counting. Then computeRollover simply returns (in the case of a daily rotation) t + interval where here the interval is a day.

What you actually want is for the rolloverAt to be shifted by 8 hours (we started at 10 but crashed at 18, so it's 8 hours) so that the remaining time before rolling over is not 24 hours since the last modified time but 16 hours. Unfortunately there is a subtle issue:

• We only take into account the last time since the file was modified. In particular, the rotating handler would work assuming there is no log between 10:00 and 18:00. But if there is some, and this is likely the case, then you'll be shifted.
• In order to handle your issue, we would need to actually determine the last time the file was closed in order. One possibility for that is to close the file and re-open it just before we crash so that we can rely on ST_ATIME instead. However, this entirely depends on whether the filesystem reports this accurately.

I can however suggest another interface but this would require some manipulation on the client side to handle "crashes" that is, add a parameter to offset the first remaining time until roll over. We could maybe provide a helper function for that, but you'll need to manually supply it to the handler constructor.

Alternatively, we could add some finalization callback to forcibly change the modified time. For that we could remove and rewrite the last line though to force a new mtime. touch should be able to do it but I don't think Python has an interface for programatically changing mtime without actually changing the content itself.

[picnixz]

For now, I'll consider this to be a feature-bug: a feature because we would be changing our implementation, and between crashes, I don't think we cannot expect that cached results are actually retained, and a bug because we could also do something on our side to retain backward compatibility.

Vinay, feel free to remove either bug or feature (or both and close this as not planned) if you think the "last-resort-refresh" approach is not worth the cost). We could also be able to emulate a touch changes with the existing API by rewriting the last line.

[Ixiodor]

Why not rely on the creation date instead of the last modified date? You can then check whether the file is too old for your newer session. You can have absolute offsets.