From d8712fa0c75ad5ea56543903fa45674ab47cc647 Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Mon, 11 Mar 2024 11:57:07 +0200 Subject: [PATCH] gh-88352: Make TimedRotatingFileHandler tests more stable (GH-116409) The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday. --- Lib/test/test_logging.py | 55 +++++++++++++--------------------------- 1 file changed, 17 insertions(+), 38 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index d71385bf2c7..1dfad6e1d26 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6080,12 +6080,22 @@ class TimedRotatingFileHandlerTest(BaseFileTest): print(tf.read()) self.assertTrue(found, msg=msg) - def test_rollover_at_midnight(self): - atTime = datetime.datetime.now().time() + def test_rollover_at_midnight(self, weekly=False): + os_helper.unlink(self.fn) + now = datetime.datetime.now() + atTime = now.time() + if not 0.1 < atTime.microsecond/1e6 < 0.9: + # The test requires all records to be emitted within + # the range of the same whole second. + time.sleep((0.1 - atTime.microsecond/1e6) % 1.0) + now = datetime.datetime.now() + atTime = now.time() + atTime = atTime.replace(microsecond=0) fmt = logging.Formatter('%(asctime)s %(message)s') + when = f'W{now.weekday()}' if weekly else 'MIDNIGHT' for i in range(3): fh = logging.handlers.TimedRotatingFileHandler( - self.fn, encoding="utf-8", when='MIDNIGHT', atTime=atTime) + self.fn, encoding="utf-8", when=when, atTime=atTime) fh.setFormatter(fmt) r2 = logging.makeLogRecord({'msg': f'testing1 {i}'}) fh.emit(r2) @@ -6095,15 +6105,15 @@ class TimedRotatingFileHandlerTest(BaseFileTest): for i, line in enumerate(f): self.assertIn(f'testing1 {i}', line) - os.utime(self.fn, (time.time() - 1,)*2) + os.utime(self.fn, (now.timestamp() - 1,)*2) for i in range(2): fh = logging.handlers.TimedRotatingFileHandler( - self.fn, encoding="utf-8", when='MIDNIGHT', atTime=atTime) + self.fn, encoding="utf-8", when=when, 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) + rolloverDate = now - datetime.timedelta(days=7 if weekly else 1) otherfn = f'{self.fn}.{rolloverDate:%Y-%m-%d}' self.assertLogFile(otherfn) with open(self.fn, encoding="utf-8") as f: @@ -6114,38 +6124,7 @@ class TimedRotatingFileHandlerTest(BaseFileTest): 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) + self.test_rollover_at_midnight(weekly=True) def test_invalid(self): assertRaises = self.assertRaises