TimedRotatingFileHandler rotating on use not time

@vsajip

BPO	40469
Nosy	@vsajip, @stevendaprano, @martonivan
PRs	gh-84649: Make TimedRotatingFileHandler use CTIME instead of MTIME #24660
Files	logging_config.ymal app.py: Eg code to use the ymal file config.json: JSON version of test config log_40469.py: Modified test script log_40469_new_instance.py log_40469_single.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2020-05-01.15:02:02.675>
labels = ['3.8']
title = 'TimedRotatingFileHandler rotating on use not time'
updated_at = <Date 2022-03-31.20:48:10.169>
user = 'https://bugs.python.org/markhallett'

bugs.python.org fields:

activity = <Date 2022-03-31.20:48:10.169>
actor = 'steven.daprano'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = []
creation = <Date 2020-05-01.15:02:02.675>
creator = 'markhallett'
dependencies = []
files = ['49111', '49112', '50196', '50197', '50208', '50209']
hgrepos = []
issue_num = 40469
keywords = []
message_count = 11.0
messages = ['367849', '367922', '398684', '399306', '399481', '399496', '399499', '399500', '399506', '399531', '416458']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'steven.daprano', 'markhallett', 'martonivan']
pr_nums = ['24660']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue40469'
versions = ['Python 3.8']

Linked PRs

I found this issue as I use logging with short-running scripts that are scheduled to run regularly. I had a script that was rotating weekly and working fine. I was surprised when I tried another script where I expected it to rotate daily and it did not.

While I can see that things may be working as designed and documented, consider the apparent inconsistency created by the following two examples.

The first works as expected, rotating the log file weekly. The second (where creating the handler on line 11 is the only significant change) I expected to rotate daily, but never does.

#!/usr/bin/python3
# This script is to be scheduled to execute and write to the log daily.
# It should rotate the log files weekly.

import logging
import logging.handlers

logger = logging.getLogger('daily_logger')
logger.setLevel(logging.DEBUG)
handler = logging.handlers.TimedRotatingFileHandler(
        'daily.log', when='w5', backupCount=4)
logger.addHandler(handler)
formatter = logging.Formatter(
        fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s',
        datefmt='%Y-%m-%d %H:%M:%S')
handler.setFormatter(formatter)
logger.info('Hello, world!')

#!/usr/bin/python3
# This script is to be scheduled to execute and write to the log hourly.
# It should rotate the log files daily.

import logging
import logging.handlers

logger = logging.getLogger('hourly_logger')
logger.setLevel(logging.DEBUG)
handler = logging.handlers.TimedRotatingFileHandler(
        'hourly.log', when='d', backupCount=4)
logger.addHandler(handler)
formatter = logging.Formatter(
        fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s',
        datefmt='%Y-%m-%d %H:%M:%S')
handler.setFormatter(formatter)
logger.info('Hello, world!')

I was just about to create the same issue. It is not so uncommon use case -- run a script by schedule instead of as a daemon and want to have a timed logs rotation. Even if you have a daemon, if it crashes more often than the rotation interval, this will prevent the logs rotation.

I do not think that the new use_ctime option is needed.

pythongh-84649: Make TimedRotatingFileHandler use CTIME instead of MTIME

Let me say a couple of words too) I faced rotation bug about 10 years ago. The correction based on ctime not seems good to me.
Lets see my real case. I have a program (on windows) running every 5 minutes by scheduler. And I want log rotation once per month (30 days). Due to the fact that base log creation time will not changing(windows feature :) every time program run the rotation will occur. Not what I want.
Ten years ago I made a workaround(inherited class) that analyze ROTATED logs list in order to determine when rotation happened. For first rotation to work I used creation time.
Something like that:
In the end of MyTimedRotatingFileHandler.init:
self.rolloverAt = self.computeRollover(self.getlastrollover())
where:

    def getlastrollover(self):
        """
        Get last rollover moment based on rolled logs
        :return: timestamp of last rollover or CREATE time of current log or current time
        """
        dirName, baseName = os.path.split(self.baseFilename)
        fileNames = os.listdir(dirName)
        result = []
        prefix = baseName + "."
        plen = len(prefix)
        for fileName in fileNames:
            if fileName[:plen] == prefix:
                suffix = fileName[plen:]
                if self.extMatch.match(suffix):
                    f2add = os.path.join(dirName, fileName)
                    mdft = os.stat(f2add).st_mtime
                    result.append((f2add, mdft))
        if len(result):
            sortedresult = sorted(result, key=lambda x: x[1])
            t = sortedresult[len(sortedresult)-1][1]
            del sortedresult
        else:
            if os.path.exists(self.baseFilename):
                t = os.stat(self.baseFilename)[ST_CTIME]  # before first rolling check creation date
            else:
                t = int(time.time())
         return t

May be this can be useful for somebody.
Best regards.

gh-84649: Make TimedRotatingFileHandler use CTIME instead of MTIME (G…

Tests are passed on Windows. But they are fluky. For example, https://github.com/python/cpython/actions/runs/26977440552/job/79607964742?pr=150933

test_rollover_based_on_st_birthtime_only (test.test_logging.TimedRotatingFileHandlerTest.test_rollover_based_on_st_birthtime_only) ... Test time: 2026-06-04 20-36-35
The only matching files are: ['test_logging-2-rmvdjl71.log', 'test_logging-2-rmvdjl71.log.2026-06-04_20-36-30']
Contents of test_logging-2-rmvdjl71.log:
os.stat_result(st_mode=33206, st_ino=37436171902554484, st_dev=12836552922071869373, st_nlink=1, st_uid=0, st_gid=0, st_size=88, st_atime=1780605395, st_mtime=1780605395, st_ctime=1780605390)
2026-06-04 20:36:35,151 testing - new record supposedly in the new file after rollover

Contents of test_logging-2-rmvdjl71.log.2026-06-04_20-36-30:
os.stat_result(st_mode=33206, st_ino=70368744177664258, st_dev=12836552922071869373, st_nlink=1, st_uid=0, st_gid=0, st_size=123, st_atime=1780605393, st_mtime=1780605393, st_ctime=1780605390)
2026-06-04 20:36:30,949 testing - initial
2026-06-04 20:36:33,050 testing - update before rollover to renew the st_mtime

FAIL

======================================================================
FAIL: test_rollover_based_on_st_birthtime_only (test.test_logging.TimedRotatingFileHandlerTest.test_rollover_based_on_st_birthtime_only)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\cpython\cpython\Lib\test\test_logging.py", line 6666, in test_rollover_based_on_st_birthtime_only
    self.assertTrue(found, msg=msg)
    ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^
AssertionError: False is not true : No rotated files found, went back 5 seconds

----------------------------------------------------------------------

I'll work on this.

I created issue gh-150960 to track "test_logging: rotation tests fails on Windows, macOS and FreeBSD".

gh-84649: Fix unstable test_rollover_based_on_st_birthtime_only (GH-1…

We now have os.statx() which provides the birth time on Linux. So we can add support of this on Linux: #150968.

pythongh-84649: Use statx() in TimedRotatingFileHandler if available

gh-84649: Use statx() in TimedRotatingFileHandler if available (ПР-15…

The PR gh-150954 fixed test_rollover_based_on_st_birthtime_only(), but test_rollover_at_midnight() still fails randomly on Windows.

Example on "Windows / Build and test (x64, tail-call)" CI: https://github.com/python/cpython/actions/runs/27354264616/job/80824220476?pr=151346

FAIL: test_rollover_at_midnight (test.test_logging.TimedRotatingFileHandlerTest.test_rollover_at_midnight)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\cpython\cpython\Lib\test\test_logging.py", line 6744, in test_rollover_at_midnight
    self.assertIn(f'testing2 {i}', line)
    ~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'testing2 0' not found in '2026-06-11 14:42:16,101 testing1 0\n'

The test failed twice.

I closed issue gh-151463 as a duplicate of this issue. Copy of @ByteFlowing1337's message.

Bug report

Bug description:

test_logging CI randomly fails with a test_rollover_at_midnight AssertionError.

I can reproduce the failure locally on Windows—and less frequently on WSL2 Ubuntu 22.04—using:
./python -m test test_logging -m "test_rollover_at_weekday" -F

The output:

test test_logging failed -- Traceback (most recent call last):
  File "C:\coding\cpython\Lib\test\test_logging.py", line 6750, in test_rollover_at_weekday
    self.test_rollover_at_midnight(weekly=True)
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^
  File "C:\coding\cpython\Lib\test\test_logging.py", line 6744, in test_rollover_at_midnight
    self.assertIn(f'testing2 {i}', line)
    ~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'testing2 0' not found in '2026-06-14 13:45:50,101 testing1 0\n'

See https://github.com/python/cpython/actions/runs/27469272829/job/81197168217 and https://github.com/python/cpython/actions/runs/27463542896/job/81181712774

CPython versions tested on:

CPython main branch

Operating systems tested on:

Linux, Windows

pythongh-84649: Make TimedRotatingFileHandler use CTIME instead of MT…

pythongh-84649: Fix unstable test_rollover_based_on_st_birthtime_only (…

pythongh-84649: Use statx() in TimedRotatingFileHandler if available …

gh-84649: Fix unstable test_rollover_at_midnight (GH-151813)

The test is still flaky in the CI, for example this run from today (on main after I merged a PR):

======================================================================
FAIL: test_rollover_at_midnight (test.test_logging.TimedRotatingFileHandlerTest.test_rollover_at_midnight)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\a\cpython\cpython\Lib\test\test_logging.py", line 6749, in test_rollover_at_midnight
    self.assertIn(f'testing2 {i}', line)
    ~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'testing2 0' not found in '2026-06-29 09:32:51,103 testing1 0\n'

----------------------------------------------------------------------

Another in #152760 / https://github.com/python/cpython/actions/runs/28508559349/job/84502982384?pr=152760:

======================================================================
FAIL: test_rollover_at_midnight (test.test_logging.TimedRotatingFileHandlerTest.test_rollover_at_midnight)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\cpython\cpython\Lib\test\test_logging.py", line 6749, in test_rollover_at_midnight
    self.assertIn(f'testing2 {i}', line)
    ~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'testing2 0' not found in '2026-07-01 10:00:19,101 testing1 0\n'

pythongh-84649: Fix unstable test_rollover_at_midnight (pythonGH-151813)

@serhiy-storchaka

Windows / Build and test (Win32, switch-case) on the main branch: https://github.com/python/cpython/actions/runs/29167896618/job/86584142360?pr=153591

test_logging fails with:

FAIL: test_rollover_at_midnight (test.test_logging.TimedRotatingFileHandlerTest.test_rollover_at_midnight)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\cpython\cpython\Lib\test\test_logging.py", line 6749, in test_rollover_at_midnight
    self.assertIn(f'testing2 {i}', line)
    ~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: 'testing2 0' not found in '2026-07-11 21:19:17,102 testing1 0\n'

cc @serhiy-storchaka

I know. It is annoying.

My previous fix was not enough. Claude initially proposed a fix that deferred the purpose of the test, so I need to be very cautious here. I'll fix it when my current blackout ends and I could test it locally on Windows.

gh-84649: Fix unstable test_rollover_at_midnight (GH-154463)

The root cause was that on Windows/NTFS, if delete and recreate a file, it keeps the birth time of the old file. 🧟

Navigation Menu

Repository navigation

TimedRotatingFileHandler rotating on use not time #84649

Linked PRs

Bug report

Bug description:

CPython versions tested on:

Operating systems tested on:

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

TimedRotatingFileHandler rotating on use not time #84649

Description

Linked PRs

Activity

JChristensen commented on Feb 11, 2024

serhiy-storchaka commented on Mar 1, 2024

DmitriSaburov commented on Mar 27, 2024

serhiy-storchaka commented on Jun 5, 2026

vstinner commented on Jun 5, 2026

serhiy-storchaka commented on Jun 5, 2026

vstinner commented on Jun 11, 2026

vstinner commented on Jun 15, 2026

Bug report

Bug description:

CPython versions tested on:

Operating systems tested on:

StanFromIreland commented on Jun 29, 2026

hugovk commented on Jul 1, 2026

vstinner commented on Jul 11, 2026

serhiy-storchaka commented on Jul 12, 2026

serhiy-storchaka commented on Jul 22, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions