Skip to content

Commit b124977

Browse files
authored
gh-159690: Fix timed log rotation after a failed or duplicate rollover (GH-159692)
1 parent 4b33a9d commit b124977

3 files changed

Lines changed: 73 additions & 1 deletion

File tree

‎Lib/logging/handlers.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -469,6 +469,7 @@ def doRollover(self):
469469
timeTuple = time.localtime(t + addend)
470470
dfn = self.rotation_filename(self.baseFilename + "." +
471471
time.strftime(self.suffix, timeTuple))
472+
self.rolloverAt = self.computeRollover(currentTime)
472473
if os.path.exists(dfn):
473474
# Already rolled over.
474475
return
@@ -482,7 +483,6 @@ def doRollover(self):
482483
os.remove(s)
483484
if not self.delay:
484485
self.stream = self._open()
485-
self.rolloverAt = self.computeRollover(currentTime)
486486

487487
class WatchedFileHandler(logging.FileHandler):
488488
"""

‎Lib/test/test_logging.py‎

Lines changed: 69 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6902,6 +6902,75 @@ def test_rollover_at_midnight(self, weekly=False):
69026902
def test_rollover_at_weekday(self):
69036903
self.test_rollover_at_midnight(weekly=True)
69046904

6905+
def _make_fake_time_handler(self, now, when='S', **kwargs):
6906+
dirname = tempfile.mkdtemp()
6907+
self.addCleanup(os_helper.rmtree, dirname)
6908+
fn = os.path.join(dirname, 'test.log')
6909+
with patch('time.time', lambda: now[0]):
6910+
fh = logging.handlers.TimedRotatingFileHandler(
6911+
fn, when=when, encoding='utf-8', delay=True, **kwargs)
6912+
self.addCleanup(fh.close)
6913+
return fh
6914+
6915+
def test_rollover_after_failed_rollover(self):
6916+
for target in 'os.remove', '_open':
6917+
with self.subTest(target=target):
6918+
now = [1_000_000_000]
6919+
fh = self._make_fake_time_handler(now, backupCount=1)
6920+
fn = fh.baseFilename
6921+
emit = lambda msg: fh.emit(logging.makeLogRecord({'msg': msg}))
6922+
with patch('time.time', lambda: now[0]):
6923+
for msg in 'a', 'b':
6924+
now[0] += 2
6925+
emit(msg)
6926+
now[0] += 2
6927+
if target == '_open':
6928+
failure = patch.object(fh, '_open', side_effect=OSError)
6929+
fh.delay = False
6930+
else:
6931+
failure = patch('os.remove', side_effect=OSError)
6932+
with failure as failed, support.captured_stderr():
6933+
emit('c')
6934+
failed.assert_called_once()
6935+
self.assertGreater(fh.rolloverAt, now[0])
6936+
fh.delay = True
6937+
for msg in 'd', 'e':
6938+
now[0] += 2
6939+
emit(msg)
6940+
fh.close()
6941+
with open(fn, encoding='utf-8') as f:
6942+
self.assertEqual(f.read(), 'e\n')
6943+
backups = [f for f in os.listdir(os.path.dirname(fn))
6944+
if f != 'test.log']
6945+
self.assertEqual(len(backups), 1)
6946+
6947+
def test_rollover_existing_backup(self):
6948+
now = [1_000_000_000]
6949+
fh = self._make_fake_time_handler(now)
6950+
fn = fh.baseFilename
6951+
with patch('time.time', lambda: now[0]):
6952+
fh.emit(logging.makeLogRecord({'msg': 'a'}))
6953+
t = fh.rolloverAt - fh.interval
6954+
dfn = fh.rotation_filename(
6955+
fn + '.' + time.strftime(fh.suffix, time.localtime(t)))
6956+
with open(dfn, 'w', encoding='utf-8') as f:
6957+
f.write('existing\n')
6958+
now[0] += 2
6959+
fh.emit(logging.makeLogRecord({'msg': 'b'}))
6960+
self.assertGreater(fh.rolloverAt, now[0])
6961+
t = fh.rolloverAt - fh.interval
6962+
next_dfn = fh.rotation_filename(
6963+
fn + '.' + time.strftime(fh.suffix, time.localtime(t)))
6964+
now[0] += 2
6965+
fh.emit(logging.makeLogRecord({'msg': 'c'}))
6966+
fh.close()
6967+
with open(dfn, encoding='utf-8') as f:
6968+
self.assertEqual(f.read(), 'existing\n')
6969+
with open(next_dfn, encoding='utf-8') as f:
6970+
self.assertEqual(f.read(), 'a\nb\n')
6971+
with open(fn, encoding='utf-8') as f:
6972+
self.assertEqual(f.read(), 'c\n')
6973+
69056974
def test_invalid(self):
69066975
assertRaises = self.assertRaises
69076976
assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,3 @@
1+
Fix :class:`logging.handlers.TimedRotatingFileHandler` permanently stopping
2+
rollover after a rollover failed or its backup file already existed, for
3+
example at a DST change.

0 commit comments

Comments
 (0)