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.

1 files changed, 17 insertions, 38 deletions

diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index d71385b..1dfad6e 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -6080,46 +6080,22 @@ 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):
+    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=f'W{now.weekday()}', atTime=atTime)
+                self.fn, encoding="utf-8", when=when, atTime=atTime)
             fh.setFormatter(fmt)
             r2 = logging.makeLogRecord({'msg': f'testing1 {i}'})
             fh.emit(r2)
@@ -6129,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=f'W{now.weekday()}', 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=7)
+        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:
@@ -6147,6 +6123,9 @@ class TimedRotatingFileHandlerTest(BaseFileTest):
             for i, line in enumerate(f):
                 self.assertIn(f'testing1 {i}', line)
 
+    def test_rollover_at_weekday(self):
+        self.test_rollover_at_midnight(weekly=True)
+
     def test_invalid(self):
         assertRaises = self.assertRaises
         assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,