From 8f7b2aa34f95c0d59a1d1d977b8cc3edcc1a626d Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Wed, 6 Mar 2024 11:44:40 +0200 Subject: [PATCH 1/2] gh-88352: Make TimedRotatingFileHandler tests more stable 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. --- Lib/test/test_logging.py | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index d71385bf2c78d7..861bac60f320d1 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6081,7 +6081,16 @@ def test_rollover(self): self.assertTrue(found, msg=msg) def test_rollover_at_midnight(self): - atTime = datetime.datetime.now().time() + 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') for i in range(3): fh = logging.handlers.TimedRotatingFileHandler( @@ -6095,7 +6104,7 @@ def test_rollover_at_midnight(self): 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) @@ -6103,7 +6112,7 @@ def test_rollover_at_midnight(self): 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=1) otherfn = f'{self.fn}.{rolloverDate:%Y-%m-%d}' self.assertLogFile(otherfn) with open(self.fn, encoding="utf-8") as f: @@ -6114,8 +6123,16 @@ def test_rollover_at_midnight(self): self.assertIn(f'testing1 {i}', line) def test_rollover_at_weekday(self): + 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') for i in range(3): fh = logging.handlers.TimedRotatingFileHandler( @@ -6129,7 +6146,7 @@ def test_rollover_at_weekday(self): 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=f'W{now.weekday()}', atTime=atTime) @@ -6137,7 +6154,7 @@ def test_rollover_at_weekday(self): r2 = logging.makeLogRecord({'msg': f'testing2 {i}'}) fh.emit(r2) fh.close() - rolloverDate = datetime.datetime.now() - datetime.timedelta(days=7) + rolloverDate = 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: From d9f6c990802146eef9a0ab779c5027005e1af372 Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Mon, 11 Mar 2024 10:42:00 +0200 Subject: [PATCH 2/2] Share code between test_rollover_at_midnight and test_rollover_at_weekday. --- Lib/test/test_logging.py | 50 +++++----------------------------------- 1 file changed, 6 insertions(+), 44 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 861bac60f320d1..1dfad6e1d2609b 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6080,7 +6080,7 @@ def test_rollover(self): print(tf.read()) self.assertTrue(found, msg=msg) - def test_rollover_at_midnight(self): + def test_rollover_at_midnight(self, weekly=False): os_helper.unlink(self.fn) now = datetime.datetime.now() atTime = now.time() @@ -6092,9 +6092,10 @@ def test_rollover_at_midnight(self): 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) @@ -6107,12 +6108,12 @@ def test_rollover_at_midnight(self): 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 = 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: @@ -6123,46 +6124,7 @@ def test_rollover_at_midnight(self): self.assertIn(f'testing1 {i}', line) def test_rollover_at_weekday(self): - 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') - 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, (now.timestamp() - 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 = 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