Repository navigation
TimedRotatingFileHandler stops rolling over permanently once doRollover() exits without updating rolloverAt #159690
Description
Bug report
Summary
TimedRotatingFileHandler.doRollover() updates rolloverAt only on its last line. If it exits earlier, rolloverAt stays in the past. It can exit earlier by raising after the base file has been renamed, or by taking the # Already rolled over. early return. The early return is taken without any error by a handler using local time at DST changes: with hourly rollover, and with the default daily rollover (when='midnight') when nothing is logged between midnight and the end of DST. From then on, every emit() calls doRollover() again and computes the same backup name. That name exists on disk, so the early return is taken again. The handler never rolls over again, the base file grows without bound, backupCount cleanup stops, and nothing is reported beyond the first error, if there was one.
Reproduction Code
A single FileNotFoundError from os.remove() during backup cleanup is enough. This happens when an old backup is removed by another process between os.listdir() and os.remove(). The failure is injected with unittest.mock, and the clock is mocked so that no sleeping is needed:
import logging, logging.handlers, os, tempfile, time
from unittest import mock
d = tempfile.mkdtemp()
fn = os.path.join(d, "app.log")
h = logging.handlers.TimedRotatingFileHandler(fn, when="S", backupCount=1)
now = [time.time()]
log = lambda msg: h.emit(logging.makeLogRecord({"msg": msg}))
real_remove = os.remove
def remove_once(path):
# Simulate an old backup removed by someone else between
# os.listdir() and os.remove().
os.remove = real_remove
real_remove(path)
raise FileNotFoundError(path)
with mock.patch("time.time", lambda: now[0]):
for i in range(3):
now[0] += 2; log(f"a{i}") # normal rollovers
os.remove = remove_once
now[0] += 2; log("b") # rollover whose cleanup fails once
os.remove = real_remove
for i in range(5):
now[0] += 2; log(f"c{i}") # five more rollover periods
print("rolloverAt in the past:", h.rolloverAt < now[0])
h.close()
print(sorted(os.listdir(d)))
with open(fn) as f:
print("app.log:", f.read().split())The script gives the results below on the main branch and on 3.12.3.
Actual Behavior
The failed rollover is reported once through handleError(), and after that nothing more is reported:
--- Logging error ---
Traceback (most recent call last):
FileNotFoundError: /tmp/tmpup6vttee/app.log.2026-10-18_21-18-38
Call stack:
Message: 'b'
Arguments: ()
rolloverAt in the past: True
['app.log', 'app.log.2026-10-18_21-18-40']
app.log: ['c0', 'c1', 'c2', 'c3', 'c4']
Five more rollover periods pass with no rollover. All of their records are written to app.log, and no new backup is created. The record that triggered the failed rollover (b) is not written to any file.
Expected Behavior
A failure during one rollover, or a backup that already exists, should affect only that rollover. The next period boundary should trigger a normal rollover: the base file should then hold only the current period's records, and old backups should be pruned according to backupCount. RotatingFileHandler behaves this way after the same kind of failure: its next emit() reopens the file and rotates normally.
Analysis
The relevant part of TimedRotatingFileHandler.doRollover() in Lib/logging/handlers.py:
dfn = self.rotation_filename(self.baseFilename + "." +
time.strftime(self.suffix, timeTuple))
if os.path.exists(dfn):
# Already rolled over.
return
if self.stream:
self.stream.close()
self.stream = None
self.rotate(self.baseFilename, dfn)
if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
if not self.delay:
self.stream = self._open()
self.rolloverAt = self.computeRollover(currentTime)dfn is derived from t = self.rolloverAt - self.interval. If os.remove(), _open() or a user-supplied rotator raises after self.rotate() has created dfn, the final assignment is skipped. BaseRotatingHandler.emit() catches the exception and calls handleError(). On every later emit(), shouldRollover() returns true because time.time() >= self.rolloverAt. doRollover() then computes the same dfn, finds it on disk, and returns early, which also leaves rolloverAt unchanged. FileHandler.emit() reopens baseFilename because self.stream is None, so records keep going to the base file without any rollover. Each record also pays for an extra os.path.exists() call.
A one-time _open() failure has the same effect. With mock.patch.object(h, "_open", side_effect=OSError("injected")) around a single rolling-over emit(), followed by three more periods, the result on main and on 3.12.3 is:
OSError: injected
rolloverAt in the past: True
app.log ['c0', 'c1', 'c2']
app.log.2026-10-18_21-18-35 ['a']
The early return was added in gh-88352 (GH-116191), which replaced the previous os.remove(dfn) with return so that existing backups are not overwritten. The same code is on the 3.13 and 3.14 branches. With 3.10, where os.remove(dfn) is still used, the script keeps rolling over (rolloverAt in the past: False, app.log: ['c4']).
The early return is also reached by a single handler with when='H' and local time (utc=False) at DST changes, with no exception involved. With a mocked clock in America/New_York, the handler stopped rolling over at both the March and the November change. For the November change (Unix only, uses time.tzset()):
import logging, logging.handlers, os, tempfile, time
from unittest import mock
os.environ["TZ"] = "America/New_York" # DST ends 2026-11-01 02:00
time.tzset()
d = tempfile.mkdtemp()
fn = os.path.join(d, "app.log")
start = time.mktime((2026, 10, 31, 23, 0, 0, 0, 0, -1))
now = [start]
with mock.patch("time.time", lambda: now[0]):
h = logging.handlers.TimedRotatingFileHandler(fn, when="H", delay=True)
for i in range(6):
now[0] = start + i * 3600
msg = time.strftime("%H:%M%Z", time.localtime(now[0]))
h.emit(logging.makeLogRecord({"msg": msg}))
h.close()
for name in sorted(os.listdir(d)):
with open(os.path.join(d, name)) as f:
print(name, f.read().split())On main and on 3.12.3, the rollover at 01:00 EST finds that its backup name already exists. No rollover happens after that, and the records of four hourly intervals stay in app.log:
app.log ['01:00EDT', '01:00EST', '02:00EST', '03:00EST']
app.log.2026-10-31_23 ['23:00EDT']
app.log.2026-11-01_00 ['00:00EDT']
Daily rollover at midnight is affected when the first record after midnight on the day DST ends is logged after the change. In America/New_York that is after 02:00 EDT, and in Europe/Berlin after 03:00 CEST. A handler that also gets a record between midnight and the change keeps rolling over. With records at 09:00 and 18:00 each day:
import logging, logging.handlers, os, tempfile, time
from unittest import mock
os.environ["TZ"] = "America/New_York" # DST ends 2026-11-01 02:00
time.tzset()
d = tempfile.mkdtemp()
fn = os.path.join(d, "app.log")
ts = lambda *args: time.mktime(args + (0, 0, -1))
now = [ts(2026, 10, 30, 8, 0, 0)]
with mock.patch("time.time", lambda: now[0]):
h = logging.handlers.TimedRotatingFileHandler(fn, when="midnight", delay=True)
# No records between midnight and 09:00.
for day in [(2026, 10, 30), (2026, 10, 31), (2026, 11, 1),
(2026, 11, 2), (2026, 11, 3)]:
for hour in (9, 18):
now[0] = ts(*day, hour, 0, 0)
msg = time.strftime("%m-%d_%H:%M%Z", time.localtime(now[0]))
h.emit(logging.makeLogRecord({"msg": msg}))
h.close()
for name in sorted(os.listdir(d)):
with open(os.path.join(d, name)) as f:
print(name, f.read().split())On main and on 3.12.3, the rollover on November 1 finds that its backup name already exists. No rollover happens after that, and the records of four days stay in app.log:
app.log ['10-31_09:00EDT', '10-31_18:00EDT', '11-01_09:00EST', '11-01_18:00EST', '11-02_09:00EST', '11-02_18:00EST', '11-03_09:00EST', '11-03_18:00EST']
app.log.2026-10-30 ['10-30_09:00EDT', '10-30_18:00EDT']
The same happened in Europe/Berlin at the October change. The start of DST in March did not stop the daily handler in either time zone.
CPython versions tested on:
CPython main branch, 3.12
Operating systems tested on:
Linux
Activity