mirrors/cpython
1
0
Fork 0
mirror of https://github.com/python/cpython.git synced 2025-08-10 03:49:18 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 10

[3.12] gh-88352: Fix logging.TimedRotatingFileHandler (GH-116191) (GH-116208)

Browse source 
* Do not overwrite already rolled over files. It happened at midnight or
  during the DST change and caused the loss of data.
* computeRollover() now always return the timestamp larger than the
  specified time.
* Fix computation of the rollover time during the DST change.
(cherry picked from commit fee86fd9a4)

Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
This commit is contained in:
Miss Islington (bot) 2024-03-01 17:41:30 +01:00 • committed by GitHub
parent 694874b7dc
commit 8dae3faab6
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
3 changed files with 373 additions and 32 deletions
Download patch file Download diff file Expand all files Collapse all files

348
Lib/test/test_logging.py
View file

@ -6025,6 +6025,73 @@ class TimedRotatingFileHandlerTest(BaseFileTest):
print(tf.read())
self.assertTrue(found, msg=msg)
def test_rollover_at_midnight(self):
atTime = datetime.datetime.now().time()
fmt = logging.Formatter('%(asctime)s %(message)s')
for i in range(3):
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', atTime=atTime)
fh.setFormatter(fmt)
r2 = logging.makeLogRecord({'msg': f'testing1 {i}'})
fh.emit(r2)
fh.close()
self.assertLogFile(self.fn)
with open(self.fn, encoding="utf-8") as f:
for i, line in enumerate(f):
self.assertIn(f'testing1 {i}', line)
os.utime(self.fn, (time.time() - 1,)*2)
for i in range(2):
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', atTime=atTime)
fh.setFormatter(fmt)
r2 = logging.makeLogRecord({'msg': f'testing2 {i}'})
fh.emit(r2)
fh.close()
rolloverDate = datetime.datetime.now() - datetime.timedelta(days=1)
otherfn = f'{self.fn}.{rolloverDate:%Y-%m-%d}'
self.assertLogFile(otherfn)
with open(self.fn, encoding="utf-8") as f:
for i, line in enumerate(f):
self.assertIn(f'testing2 {i}', line)
with open(otherfn, encoding="utf-8") as f:
for i, line in enumerate(f):
self.assertIn(f'testing1 {i}', line)
def test_rollover_at_weekday(self):
now = datetime.datetime.now()
atTime = now.time()
fmt = logging.Formatter('%(asctime)s %(message)s')
for i in range(3):
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when=f'W{now.weekday()}', atTime=atTime)
fh.setFormatter(fmt)
r2 = logging.makeLogRecord({'msg': f'testing1 {i}'})
fh.emit(r2)
fh.close()
self.assertLogFile(self.fn)
with open(self.fn, encoding="utf-8") as f:
for i, line in enumerate(f):
self.assertIn(f'testing1 {i}', line)
os.utime(self.fn, (time.time() - 1,)*2)
for i in range(2):
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when=f'W{now.weekday()}', atTime=atTime)
fh.setFormatter(fmt)
r2 = logging.makeLogRecord({'msg': f'testing2 {i}'})
fh.emit(r2)
fh.close()
rolloverDate = datetime.datetime.now() - datetime.timedelta(days=7)
otherfn = f'{self.fn}.{rolloverDate:%Y-%m-%d}'
self.assertLogFile(otherfn)
with open(self.fn, encoding="utf-8") as f:
for i, line in enumerate(f):
self.assertIn(f'testing2 {i}', line)
with open(otherfn, encoding="utf-8") as f:
for i, line in enumerate(f):
self.assertIn(f'testing1 {i}', line)
def test_invalid(self):
assertRaises = self.assertRaises
assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
@ -6034,22 +6101,47 @@ class TimedRotatingFileHandlerTest(BaseFileTest):
assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
self.fn, 'W7', encoding="utf-8", delay=True)
# TODO: Test for utc=False.
def test_compute_rollover_daily_attime(self):
currentTime = 0
rh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT',
utc=True, atTime=None)
try:
actual = rh.computeRollover(currentTime)
self.assertEqual(actual, currentTime + 24 * 60 * 60)
actual = rh.computeRollover(currentTime + 24 * 60 * 60 - 1)
self.assertEqual(actual, currentTime + 24 * 60 * 60)
actual = rh.computeRollover(currentTime + 24 * 60 * 60)
self.assertEqual(actual, currentTime + 48 * 60 * 60)
actual = rh.computeRollover(currentTime + 25 * 60 * 60)
self.assertEqual(actual, currentTime + 48 * 60 * 60)
finally:
rh.close()
atTime = datetime.time(12, 0, 0)
rh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', interval=1, backupCount=0,
self.fn, encoding="utf-8", when='MIDNIGHT',
utc=True, atTime=atTime)
try:
actual = rh.computeRollover(currentTime)
self.assertEqual(actual, currentTime + 12 * 60 * 60)
actual = rh.computeRollover(currentTime + 12 * 60 * 60 - 1)
self.assertEqual(actual, currentTime + 12 * 60 * 60)
actual = rh.computeRollover(currentTime + 12 * 60 * 60)
self.assertEqual(actual, currentTime + 36 * 60 * 60)
actual = rh.computeRollover(currentTime + 13 * 60 * 60)
self.assertEqual(actual, currentTime + 36 * 60 * 60)
finally:
rh.close()
#@unittest.skipIf(True, 'Temporarily skipped while failures investigated.')
# TODO: Test for utc=False.
def test_compute_rollover_weekly_attime(self):
currentTime = int(time.time())
today = currentTime - currentTime % 86400
@ -6074,14 +6166,28 @@ class TimedRotatingFileHandlerTest(BaseFileTest):
expected += 12 * 60 * 60
# Add in adjustment for today
expected += today
actual = rh.computeRollover(today)
if actual != expected:
print('failed in timezone: %d' % time.timezone)
print('local vars: %s' % locals())
self.assertEqual(actual, expected)
actual = rh.computeRollover(today + 12 * 60 * 60 - 1)
if actual != expected:
print('failed in timezone: %d' % time.timezone)
print('local vars: %s' % locals())
self.assertEqual(actual, expected)
if day == wday:
# goes into following week
expected += 7 * 24 * 60 * 60
actual = rh.computeRollover(today + 12 * 60 * 60)
if actual != expected:
print('failed in timezone: %d' % time.timezone)
print('local vars: %s' % locals())
self.assertEqual(actual, expected)
actual = rh.computeRollover(today + 13 * 60 * 60)
if actual != expected:
print('failed in timezone: %d' % time.timezone)
@ -6176,6 +6282,244 @@ class TimedRotatingFileHandlerTest(BaseFileTest):
suffix = fn[(len(prefix)+1):]
self.assertRegex(suffix, matcher)
# Run with US-style DST rules: DST begins 2 a.m. on second Sunday in
# March (M3.2.0) and ends 2 a.m. on first Sunday in November (M11.1.0).
@support.run_with_tz('EST+05EDT,M3.2.0,M11.1.0')
def test_compute_rollover_MIDNIGHT_local(self):
# DST begins at 2012-3-11T02:00:00 and ends at 2012-11-4T02:00:00.
DT = datetime.datetime
def test(current, expected):
actual = fh.computeRollover(current.timestamp())
diff = actual - expected.timestamp()
if diff:
self.assertEqual(diff, 0, datetime.timedelta(seconds=diff))
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', utc=False)
test(DT(2012, 3, 10, 23, 59, 59), DT(2012, 3, 11, 0, 0))
test(DT(2012, 3, 11, 0, 0), DT(2012, 3, 12, 0, 0))
test(DT(2012, 3, 11, 1, 0), DT(2012, 3, 12, 0, 0))
test(DT(2012, 11, 3, 23, 59, 59), DT(2012, 11, 4, 0, 0))
test(DT(2012, 11, 4, 0, 0), DT(2012, 11, 5, 0, 0))
test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 5, 0, 0))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', utc=False,
atTime=datetime.time(12, 0, 0))
test(DT(2012, 3, 10, 11, 59, 59), DT(2012, 3, 10, 12, 0))
test(DT(2012, 3, 10, 12, 0), DT(2012, 3, 11, 12, 0))
test(DT(2012, 3, 10, 13, 0), DT(2012, 3, 11, 12, 0))
test(DT(2012, 11, 3, 11, 59, 59), DT(2012, 11, 3, 12, 0))
test(DT(2012, 11, 3, 12, 0), DT(2012, 11, 4, 12, 0))
test(DT(2012, 11, 3, 13, 0), DT(2012, 11, 4, 12, 0))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', utc=False,
atTime=datetime.time(2, 0, 0))
test(DT(2012, 3, 10, 1, 59, 59), DT(2012, 3, 10, 2, 0))
# 2:00:00 is the same as 3:00:00 at 2012-3-11.
test(DT(2012, 3, 10, 2, 0), DT(2012, 3, 11, 3, 0))
test(DT(2012, 3, 10, 3, 0), DT(2012, 3, 11, 3, 0))
test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 0))
# No time between 2:00:00 and 3:00:00 at 2012-3-11.
test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 12, 2, 0))
test(DT(2012, 3, 11, 4, 0), DT(2012, 3, 12, 2, 0))
test(DT(2012, 11, 3, 1, 59, 59), DT(2012, 11, 3, 2, 0))
test(DT(2012, 11, 3, 2, 0), DT(2012, 11, 4, 2, 0))
test(DT(2012, 11, 3, 3, 0), DT(2012, 11, 4, 2, 0))
# 1:00:00-2:00:00 is repeated twice at 2012-11-4.
test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 4, 2, 0))
test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 4, 2, 0))
test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 5, 2, 0))
test(DT(2012, 11, 4, 3, 0), DT(2012, 11, 5, 2, 0))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', utc=False,
atTime=datetime.time(2, 30, 0))
test(DT(2012, 3, 10, 2, 29, 59), DT(2012, 3, 10, 2, 30))
# No time 2:30:00 at 2012-3-11.
test(DT(2012, 3, 10, 2, 30), DT(2012, 3, 11, 3, 30))
test(DT(2012, 3, 10, 3, 0), DT(2012, 3, 11, 3, 30))
test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 30))
# No time between 2:00:00 and 3:00:00 at 2012-3-11.
test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 12, 2, 30))
test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 12, 2, 30))
test(DT(2012, 11, 3, 2, 29, 59), DT(2012, 11, 3, 2, 30))
test(DT(2012, 11, 3, 2, 30), DT(2012, 11, 4, 2, 30))
test(DT(2012, 11, 3, 3, 0), DT(2012, 11, 4, 2, 30))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='MIDNIGHT', utc=False,
atTime=datetime.time(1, 30, 0))
test(DT(2012, 3, 11, 1, 29, 59), DT(2012, 3, 11, 1, 30))
test(DT(2012, 3, 11, 1, 30), DT(2012, 3, 12, 1, 30))
test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 12, 1, 30))
# No time between 2:00:00 and 3:00:00 at 2012-3-11.
test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 12, 1, 30))
test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 12, 1, 30))
# 1:00:00-2:00:00 is repeated twice at 2012-11-4.
test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 4, 1, 30))
test(DT(2012, 11, 4, 1, 29, 59), DT(2012, 11, 4, 1, 30))
test(DT(2012, 11, 4, 1, 30), DT(2012, 11, 5, 1, 30))
test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 5, 1, 30))
# It is weird, but the rollover date jumps back from 2012-11-5
# to 2012-11-4.
test(DT(2012, 11, 4, 1, 0, fold=1), DT(2012, 11, 4, 1, 30, fold=1))
test(DT(2012, 11, 4, 1, 29, 59, fold=1), DT(2012, 11, 4, 1, 30, fold=1))
test(DT(2012, 11, 4, 1, 30, fold=1), DT(2012, 11, 5, 1, 30))
test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 5, 1, 30))
test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 5, 1, 30))
test(DT(2012, 11, 4, 2, 30), DT(2012, 11, 5, 1, 30))
fh.close()
# Run with US-style DST rules: DST begins 2 a.m. on second Sunday in
# March (M3.2.0) and ends 2 a.m. on first Sunday in November (M11.1.0).
@support.run_with_tz('EST+05EDT,M3.2.0,M11.1.0')
def test_compute_rollover_W6_local(self):
# DST begins at 2012-3-11T02:00:00 and ends at 2012-11-4T02:00:00.
DT = datetime.datetime
def test(current, expected):
actual = fh.computeRollover(current.timestamp())
diff = actual - expected.timestamp()
if diff:
self.assertEqual(diff, 0, datetime.timedelta(seconds=diff))
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='W6', utc=False)
test(DT(2012, 3, 4, 23, 59, 59), DT(2012, 3, 5, 0, 0))
test(DT(2012, 3, 5, 0, 0), DT(2012, 3, 12, 0, 0))
test(DT(2012, 3, 5, 1, 0), DT(2012, 3, 12, 0, 0))
test(DT(2012, 10, 28, 23, 59, 59), DT(2012, 10, 29, 0, 0))
test(DT(2012, 10, 29, 0, 0), DT(2012, 11, 5, 0, 0))
test(DT(2012, 10, 29, 1, 0), DT(2012, 11, 5, 0, 0))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='W6', utc=False,
atTime=datetime.time(0, 0, 0))
test(DT(2012, 3, 10, 23, 59, 59), DT(2012, 3, 11, 0, 0))
test(DT(2012, 3, 11, 0, 0), DT(2012, 3, 18, 0, 0))
test(DT(2012, 3, 11, 1, 0), DT(2012, 3, 18, 0, 0))
test(DT(2012, 11, 3, 23, 59, 59), DT(2012, 11, 4, 0, 0))
test(DT(2012, 11, 4, 0, 0), DT(2012, 11, 11, 0, 0))
test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 11, 0, 0))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='W6', utc=False,
atTime=datetime.time(12, 0, 0))
test(DT(2012, 3, 4, 11, 59, 59), DT(2012, 3, 4, 12, 0))
test(DT(2012, 3, 4, 12, 0), DT(2012, 3, 11, 12, 0))
test(DT(2012, 3, 4, 13, 0), DT(2012, 3, 11, 12, 0))
test(DT(2012, 10, 28, 11, 59, 59), DT(2012, 10, 28, 12, 0))
test(DT(2012, 10, 28, 12, 0), DT(2012, 11, 4, 12, 0))
test(DT(2012, 10, 28, 13, 0), DT(2012, 11, 4, 12, 0))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='W6', utc=False,
atTime=datetime.time(2, 0, 0))
test(DT(2012, 3, 4, 1, 59, 59), DT(2012, 3, 4, 2, 0))
# 2:00:00 is the same as 3:00:00 at 2012-3-11.
test(DT(2012, 3, 4, 2, 0), DT(2012, 3, 11, 3, 0))
test(DT(2012, 3, 4, 3, 0), DT(2012, 3, 11, 3, 0))
test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 0))
# No time between 2:00:00 and 3:00:00 at 2012-3-11.
test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 18, 2, 0))
test(DT(2012, 3, 11, 4, 0), DT(2012, 3, 18, 2, 0))
test(DT(2012, 10, 28, 1, 59, 59), DT(2012, 10, 28, 2, 0))
test(DT(2012, 10, 28, 2, 0), DT(2012, 11, 4, 2, 0))
test(DT(2012, 10, 28, 3, 0), DT(2012, 11, 4, 2, 0))
# 1:00:00-2:00:00 is repeated twice at 2012-11-4.
test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 4, 2, 0))
test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 4, 2, 0))
test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 11, 2, 0))
test(DT(2012, 11, 4, 3, 0), DT(2012, 11, 11, 2, 0))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='W6', utc=False,
atTime=datetime.time(2, 30, 0))
test(DT(2012, 3, 4, 2, 29, 59), DT(2012, 3, 4, 2, 30))
# No time 2:30:00 at 2012-3-11.
test(DT(2012, 3, 4, 2, 30), DT(2012, 3, 11, 3, 30))
test(DT(2012, 3, 4, 3, 0), DT(2012, 3, 11, 3, 30))
test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 11, 3, 30))
# No time between 2:00:00 and 3:00:00 at 2012-3-11.
test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 18, 2, 30))
test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 18, 2, 30))
test(DT(2012, 10, 28, 2, 29, 59), DT(2012, 10, 28, 2, 30))
test(DT(2012, 10, 28, 2, 30), DT(2012, 11, 4, 2, 30))
test(DT(2012, 10, 28, 3, 0), DT(2012, 11, 4, 2, 30))
fh.close()
fh = logging.handlers.TimedRotatingFileHandler(
self.fn, encoding="utf-8", when='W6', utc=False,
atTime=datetime.time(1, 30, 0))
test(DT(2012, 3, 11, 1, 29, 59), DT(2012, 3, 11, 1, 30))
test(DT(2012, 3, 11, 1, 30), DT(2012, 3, 18, 1, 30))
test(DT(2012, 3, 11, 1, 59, 59), DT(2012, 3, 18, 1, 30))
# No time between 2:00:00 and 3:00:00 at 2012-3-11.
test(DT(2012, 3, 11, 3, 0), DT(2012, 3, 18, 1, 30))
test(DT(2012, 3, 11, 3, 30), DT(2012, 3, 18, 1, 30))
# 1:00:00-2:00:00 is repeated twice at 2012-11-4.
test(DT(2012, 11, 4, 1, 0), DT(2012, 11, 4, 1, 30))
test(DT(2012, 11, 4, 1, 29, 59), DT(2012, 11, 4, 1, 30))
test(DT(2012, 11, 4, 1, 30), DT(2012, 11, 11, 1, 30))
test(DT(2012, 11, 4, 1, 59, 59), DT(2012, 11, 11, 1, 30))
# It is weird, but the rollover date jumps back from 2012-11-11
# to 2012-11-4.
test(DT(2012, 11, 4, 1, 0, fold=1), DT(2012, 11, 4, 1, 30, fold=1))
test(DT(2012, 11, 4, 1, 29, 59, fold=1), DT(2012, 11, 4, 1, 30, fold=1))
test(DT(2012, 11, 4, 1, 30, fold=1), DT(2012, 11, 11, 1, 30))
test(DT(2012, 11, 4, 1, 59, 59, fold=1), DT(2012, 11, 11, 1, 30))
test(DT(2012, 11, 4, 2, 0), DT(2012, 11, 11, 1, 30))
test(DT(2012, 11, 4, 2, 30), DT(2012, 11, 11, 1, 30))
fh.close()
def secs(**kw):
return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)