From c17983df9b37896147c66ba1eb73304b300eca70 Mon Sep 17 00:00:00 2001 From: lipengyu Date: Mon, 19 Oct 2026 10:40:10 +0800 Subject: [PATCH 1/4] Fix timed log rotation after a failed or duplicate rollover --- Lib/logging/handlers.py | 12 ++- Lib/test/test_logging.py | 90 +++++++++++++++++++ ...-09-25-00-12-05.gh-issue-159690.vZgLP6.rst | 4 + 3 files changed, 99 insertions(+), 7 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index e225a21da408fa..d2274ae67c02d6 100644 --- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -469,20 +469,18 @@ def doRollover(self): timeTuple = time.localtime(t + addend) 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: + rolledOver = os.path.exists(dfn) + if not rolledOver: + self.rotate(self.baseFilename, dfn) + self.rolloverAt = self.computeRollover(currentTime) + if not rolledOver and self.backupCount > 0: for s in self.getFilesToDelete(): os.remove(s) if not self.delay: self.stream = self._open() - self.rolloverAt = self.computeRollover(currentTime) class WatchedFileHandler(logging.FileHandler): """ diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index b1852ee43b594f..7d0b9f981199a4 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6902,6 +6902,96 @@ def test_rollover_at_midnight(self, weekly=False): def test_rollover_at_weekday(self): self.test_rollover_at_midnight(weekly=True) + def _make_fake_time_handler(self, now, when='S', **kwargs): + dirname = tempfile.mkdtemp() + self.addCleanup(os_helper.rmtree, dirname) + fn = os.path.join(dirname, 'test.log') + with patch('time.time', lambda: now[0]): + fh = logging.handlers.TimedRotatingFileHandler( + fn, when=when, encoding='utf-8', delay=True, **kwargs) + self.addCleanup(fh.close) + return fh + + def test_rollover_after_failed_rollover(self): + for target in 'os.remove', '_open': + with self.subTest(target=target): + now = [1_000_000_000] + fh = self._make_fake_time_handler(now, backupCount=1) + fn = fh.baseFilename + emit = lambda msg: fh.emit(logging.makeLogRecord({'msg': msg})) + with patch('time.time', lambda: now[0]): + for msg in 'a', 'b': + now[0] += 2 + emit(msg) + now[0] += 2 + if target == '_open': + failure = patch.object(fh, '_open', side_effect=OSError) + fh.delay = False + else: + failure = patch('os.remove', side_effect=OSError) + with failure, support.captured_stderr(): + emit('c') + fh.delay = True + for msg in 'd', 'e': + now[0] += 2 + emit(msg) + self.assertGreater(fh.rolloverAt, now[0]) + fh.close() + with open(fn, encoding='utf-8') as f: + self.assertEqual(f.read(), 'e\n') + backups = [f for f in os.listdir(os.path.dirname(fn)) + if f != 'test.log'] + self.assertEqual(len(backups), 1) + + def test_rollover_already_rolled_over(self): + now = [1_000_000_000] + fh1 = self._make_fake_time_handler(now) + fn = fh1.baseFilename + with patch('time.time', lambda: now[0]): + fh2 = logging.handlers.TimedRotatingFileHandler( + fn, when='S', encoding='utf-8', delay=True) + self.addCleanup(fh2.close) + for i in range(4): + if os.name == 'nt' and fh2.stream: + fh2.stream.close() + fh2.stream = None + fh1.emit(logging.makeLogRecord({'msg': f'a{i}'})) + fh2.emit(logging.makeLogRecord({'msg': f'b{i}'})) + now[0] += 2 + self.assertGreater(fh2.rolloverAt, now[0] - 2) + fh1.close() + fh2.close() + with open(fn, encoding='utf-8') as f: + self.assertEqual(f.read(), 'a3\nb3\n') + backups = sorted(f for f in os.listdir(os.path.dirname(fn)) + if f != 'test.log') + self.assertEqual(len(backups), 3) + for backup, i in zip(backups, range(3)): + with open(os.path.join(os.path.dirname(fn), backup), + encoding='utf-8') as f: + self.assertEqual(f.read(), f'a{i}\nb{i}\n') + + def test_rollover_existing_destination_reopens_stream(self): + now = [1_000_000_000] + fh = self._make_fake_time_handler(now) + fn = fh.baseFilename + with patch('time.time', lambda: now[0]): + fh.emit(logging.makeLogRecord({'msg': 'a'})) + old_stream = fh.stream + t = fh.rolloverAt - fh.interval + dfn = fh.rotation_filename( + fn + '.' + time.strftime(fh.suffix, time.localtime(t))) + with open(dfn, 'w', encoding='utf-8'): + pass + now[0] += 2 + fh.emit(logging.makeLogRecord({'msg': 'b'})) + self.assertTrue(old_stream.closed) + self.assertIsNot(fh.stream, old_stream) + self.assertGreater(fh.rolloverAt, now[0]) + fh.close() + with open(fn, encoding='utf-8') as f: + self.assertEqual(f.read(), 'a\nb\n') + def test_invalid(self): assertRaises = self.assertRaises assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler, diff --git a/Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst b/Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst new file mode 100644 index 00000000000000..630b0fcf228863 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst @@ -0,0 +1,4 @@ +Fix :class:`logging.handlers.TimedRotatingFileHandler` permanently stopping +rotation after an error in :meth:`!doRollover` that occurred after the log +file had been renamed, or when the backup file for the current period +already existed. From b72b235cfd7da69a3d00c3100d99863ca6913bb4 Mon Sep 17 00:00:00 2001 From: lipengyu Date: Tue, 20 Oct 2026 10:48:57 +0800 Subject: [PATCH 2/4] update --- Lib/logging/handlers.py | 14 +++-- Lib/test/test_logging.py | 60 +++++++------------ ...-09-25-00-12-05.gh-issue-159690.vZgLP6.rst | 4 -- ...-10-20-00-12-05.gh-issue-159690.vZgLP6.rst | 3 + 4 files changed, 34 insertions(+), 47 deletions(-) delete mode 100644 Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst create mode 100644 Misc/NEWS.d/next/Library/2026-10-20-00-12-05.gh-issue-159690.vZgLP6.rst diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index d2274ae67c02d6..4c96deb59255c1 100644 --- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -469,14 +469,18 @@ def doRollover(self): timeTuple = time.localtime(t + addend) dfn = self.rotation_filename(self.baseFilename + "." + time.strftime(self.suffix, timeTuple)) + # Compute the next rollover time first, so that an early return or + # a failure below affects only this rollover. + self.rolloverAt = self.computeRollover(currentTime) + if os.path.exists(dfn): + # Already rolled over. + return + if self.stream: self.stream.close() self.stream = None - rolledOver = os.path.exists(dfn) - if not rolledOver: - self.rotate(self.baseFilename, dfn) - self.rolloverAt = self.computeRollover(currentTime) - if not rolledOver and self.backupCount > 0: + self.rotate(self.baseFilename, dfn) + if self.backupCount > 0: for s in self.getFilesToDelete(): os.remove(s) if not self.delay: diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 7d0b9f981199a4..2a44aeec126658 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6913,7 +6913,7 @@ def _make_fake_time_handler(self, now, when='S', **kwargs): return fh def test_rollover_after_failed_rollover(self): - for target in 'os.remove', '_open': + for target in 'os.remove', '_open', 'os.rename': with self.subTest(target=target): now = [1_000_000_000] fh = self._make_fake_time_handler(now, backupCount=1) @@ -6927,10 +6927,14 @@ def test_rollover_after_failed_rollover(self): if target == '_open': failure = patch.object(fh, '_open', side_effect=OSError) fh.delay = False - else: + elif target == 'os.remove': failure = patch('os.remove', side_effect=OSError) - with failure, support.captured_stderr(): + else: + failure = patch('os.rename', side_effect=OSError) + with failure as failed, support.captured_stderr(): emit('c') + failed.assert_called_once() + self.assertGreater(fh.rolloverAt, now[0]) fh.delay = True for msg in 'd', 'e': now[0] += 2 @@ -6943,54 +6947,34 @@ def test_rollover_after_failed_rollover(self): if f != 'test.log'] self.assertEqual(len(backups), 1) - def test_rollover_already_rolled_over(self): - now = [1_000_000_000] - fh1 = self._make_fake_time_handler(now) - fn = fh1.baseFilename - with patch('time.time', lambda: now[0]): - fh2 = logging.handlers.TimedRotatingFileHandler( - fn, when='S', encoding='utf-8', delay=True) - self.addCleanup(fh2.close) - for i in range(4): - if os.name == 'nt' and fh2.stream: - fh2.stream.close() - fh2.stream = None - fh1.emit(logging.makeLogRecord({'msg': f'a{i}'})) - fh2.emit(logging.makeLogRecord({'msg': f'b{i}'})) - now[0] += 2 - self.assertGreater(fh2.rolloverAt, now[0] - 2) - fh1.close() - fh2.close() - with open(fn, encoding='utf-8') as f: - self.assertEqual(f.read(), 'a3\nb3\n') - backups = sorted(f for f in os.listdir(os.path.dirname(fn)) - if f != 'test.log') - self.assertEqual(len(backups), 3) - for backup, i in zip(backups, range(3)): - with open(os.path.join(os.path.dirname(fn), backup), - encoding='utf-8') as f: - self.assertEqual(f.read(), f'a{i}\nb{i}\n') - - def test_rollover_existing_destination_reopens_stream(self): + def test_rollover_existing_backup(self): now = [1_000_000_000] fh = self._make_fake_time_handler(now) fn = fh.baseFilename with patch('time.time', lambda: now[0]): fh.emit(logging.makeLogRecord({'msg': 'a'})) - old_stream = fh.stream t = fh.rolloverAt - fh.interval dfn = fh.rotation_filename( fn + '.' + time.strftime(fh.suffix, time.localtime(t))) - with open(dfn, 'w', encoding='utf-8'): - pass + with open(dfn, 'w', encoding='utf-8') as f: + f.write('existing\n') now[0] += 2 fh.emit(logging.makeLogRecord({'msg': 'b'})) - self.assertTrue(old_stream.closed) - self.assertIsNot(fh.stream, old_stream) self.assertGreater(fh.rolloverAt, now[0]) + with open(dfn, encoding='utf-8') as f: + self.assertEqual(f.read(), 'existing\n') + t = fh.rolloverAt - fh.interval + next_dfn = fh.rotation_filename( + fn + '.' + time.strftime(fh.suffix, time.localtime(t))) + now[0] += 2 + fh.emit(logging.makeLogRecord({'msg': 'c'})) fh.close() - with open(fn, encoding='utf-8') as f: + with open(dfn, encoding='utf-8') as f: + self.assertEqual(f.read(), 'existing\n') + with open(next_dfn, encoding='utf-8') as f: self.assertEqual(f.read(), 'a\nb\n') + with open(fn, encoding='utf-8') as f: + self.assertEqual(f.read(), 'c\n') def test_invalid(self): assertRaises = self.assertRaises diff --git a/Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst b/Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst deleted file mode 100644 index 630b0fcf228863..00000000000000 --- a/Misc/NEWS.d/next/Library/2026-09-25-00-12-05.gh-issue-159690.vZgLP6.rst +++ /dev/null @@ -1,4 +0,0 @@ -Fix :class:`logging.handlers.TimedRotatingFileHandler` permanently stopping -rotation after an error in :meth:`!doRollover` that occurred after the log -file had been renamed, or when the backup file for the current period -already existed. diff --git a/Misc/NEWS.d/next/Library/2026-10-20-00-12-05.gh-issue-159690.vZgLP6.rst b/Misc/NEWS.d/next/Library/2026-10-20-00-12-05.gh-issue-159690.vZgLP6.rst new file mode 100644 index 00000000000000..b94d79501b9abe --- /dev/null +++ b/Misc/NEWS.d/next/Library/2026-10-20-00-12-05.gh-issue-159690.vZgLP6.rst @@ -0,0 +1,3 @@ +Fix :class:`logging.handlers.TimedRotatingFileHandler` permanently stopping +rollover after a rollover failed or its backup file already existed, for +example at a DST change. From 44ede53f708422aa43140bb68e7bda4e6115d9f5 Mon Sep 17 00:00:00 2001 From: lipengyu Date: Tue, 20 Oct 2026 10:55:47 +0800 Subject: [PATCH 3/4] Remove comments --- Lib/logging/handlers.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index 4c96deb59255c1..9d31cd4bc3a101 100644 --- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -469,8 +469,6 @@ def doRollover(self): timeTuple = time.localtime(t + addend) dfn = self.rotation_filename(self.baseFilename + "." + time.strftime(self.suffix, timeTuple)) - # Compute the next rollover time first, so that an early return or - # a failure below affects only this rollover. self.rolloverAt = self.computeRollover(currentTime) if os.path.exists(dfn): # Already rolled over. From 9cf02b43e8de09859c6a0865a0fef9bde013d442 Mon Sep 17 00:00:00 2001 From: lipengyu Date: Tue, 20 Oct 2026 11:03:23 +0800 Subject: [PATCH 4/4] update test --- Lib/test/test_logging.py | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 2a44aeec126658..0ab1f7ef31afb1 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6913,7 +6913,7 @@ def _make_fake_time_handler(self, now, when='S', **kwargs): return fh def test_rollover_after_failed_rollover(self): - for target in 'os.remove', '_open', 'os.rename': + for target in 'os.remove', '_open': with self.subTest(target=target): now = [1_000_000_000] fh = self._make_fake_time_handler(now, backupCount=1) @@ -6927,10 +6927,8 @@ def test_rollover_after_failed_rollover(self): if target == '_open': failure = patch.object(fh, '_open', side_effect=OSError) fh.delay = False - elif target == 'os.remove': - failure = patch('os.remove', side_effect=OSError) else: - failure = patch('os.rename', side_effect=OSError) + failure = patch('os.remove', side_effect=OSError) with failure as failed, support.captured_stderr(): emit('c') failed.assert_called_once() @@ -6939,7 +6937,6 @@ def test_rollover_after_failed_rollover(self): for msg in 'd', 'e': now[0] += 2 emit(msg) - self.assertGreater(fh.rolloverAt, now[0]) fh.close() with open(fn, encoding='utf-8') as f: self.assertEqual(f.read(), 'e\n') @@ -6961,8 +6958,6 @@ def test_rollover_existing_backup(self): now[0] += 2 fh.emit(logging.makeLogRecord({'msg': 'b'})) self.assertGreater(fh.rolloverAt, now[0]) - with open(dfn, encoding='utf-8') as f: - self.assertEqual(f.read(), 'existing\n') t = fh.rolloverAt - fh.interval next_dfn = fh.rotation_filename( fn + '.' + time.strftime(fh.suffix, time.localtime(t)))