gh-84649: Make TimedRotatingFileHandler use CTIME instead of MTIME (GH-24660)

The TimedRotatingFileHandler previously only used st_mtime attribute of the
log file to detect whether it has to be rotate yet or not. In cases when the
file is changed within the rotatation period the st_mtime is also updated
to the current time and the rotation never happens.

It's more appropriate to check the file creation time (st_ctime) instead.
Whenever available, the more appropriate st_birthtime will be in use. (This
feature is available on FreeBSD, MacOS and Windows at the moment.) If
the st_mtime would be newer than st_ctime (e.g.: because the inode
related to the file has been changed without any file content
modification), then the earliest attribute will be used.

Author: martonivan

Lib/logging/handlers.py

@@ -282,7 +282,16 @@ def __init__(self, filename, when='h', interval=1, backupCount=0,
         # path object (see Issue #27493), but self.baseFilename will be a string
         filename = self.baseFilename
         if os.path.exists(filename):
-            t = int(os.stat(filename).st_mtime)
+            # Use the minimum of file creation and modification time as
+            # the base of the rollover calculation
+            stat_result = os.stat(filename)
+            # Use st_birthtime whenever it is available or use st_ctime
+            # instead otherwise
+            try:
+                creation_time = stat_result.st_birthtime
+            except AttributeError:
+                creation_time = stat_result.st_ctime
+            t = int(min(creation_time, stat_result.st_mtime))
         else:
             t = int(time.time())
         self.rolloverAt = self.computeRollover(t)

Lib/test/support/__init__.py

@@ -40,6 +40,7 @@
     "has_fork_support", "requires_fork",
     "has_subprocess_support", "requires_subprocess",
     "has_socket_support", "requires_working_socket",
+    "has_st_birthtime",
     "has_remote_subprocess_debugging", "requires_remote_subprocess_debugging",
     "anticipate_failure", "load_package_tests", "detect_api_mismatch",
     "check__all__", "skip_if_buggy_ucrt_strfptime",
@@ -620,6 +621,10 @@ def skip_wasi_stack_overflow():
     or is_android
 )
 
+# At the moment, st_birthtime attribute is only supported on Windows,
+# MacOS and FreeBSD.
+has_st_birthtime = sys.platform.startswith(("win", "freebsd", "darwin"))
+
 def requires_fork():
     return unittest.skipUnless(has_fork_support, "requires working os.fork()")
 

Lib/test/test_logging.py

@@ -6615,6 +6615,56 @@ def test_rollover(self):
                     print(tf.read())
         self.assertTrue(found, msg=msg)
 
+    @unittest.skipUnless(support.has_st_birthtime,
+        "st_birthtime not available or supported by Python on this OS")
+    def test_rollover_based_on_st_birthtime_only(self):
+        def add_record(message: str) -> None:
+            fh = logging.handlers.TimedRotatingFileHandler(
+                    self.fn, when='S', interval=4, encoding="utf-8", backupCount=1)
+            fmt = logging.Formatter('%(asctime)s %(message)s')
+            fh.setFormatter(fmt)
+            record = logging.makeLogRecord({'msg': message})
+            fh.emit(record)
+            fh.close()
+
+        add_record('testing - initial')
+        self.assertLogFile(self.fn)
+        # Sleep a little over the half of rollover time - and this value
+        # must be over 2 seconds, since this is the mtime resolution on
+        # FAT32 filesystems.
+        time.sleep(2.1)
+        add_record('testing - update before rollover to renew the st_mtime')
+        time.sleep(2.1)    # a little over the half of rollover time
+        add_record('testing - new record supposedly in the new file after rollover')
+
+        # At this point, the log file should be rotated if the rotation
+        # is based on creation time but should be not if it's based on
+        # creation time.
+        found = False
+        now = datetime.datetime.now()
+        GO_BACK = 5 # seconds
+        for secs in range(GO_BACK):
+            prev = now - datetime.timedelta(seconds=secs)
+            fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
+            found = os.path.exists(fn)
+            if found:
+                self.rmfiles.append(fn)
+                break
+        msg = 'No rotated files found, went back %d seconds' % GO_BACK
+        if not found:
+            # print additional diagnostics
+            dn, fn = os.path.split(self.fn)
+            files = [f for f in os.listdir(dn) if f.startswith(fn)]
+            print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
+            print('The only matching files are: %s' % files, file=sys.stderr)
+            for f in files:
+                print('Contents of %s:' % f)
+                path = os.path.join(dn, f)
+                print(os.stat(path))
+                with open(path, 'r') as tf:
+                    print(tf.read())
+        self.assertTrue(found, msg=msg)
+
     def test_rollover_at_midnight(self, weekly=False):
         os_helper.unlink(self.fn)
         now = datetime.datetime.now()

Misc/ACKS

@@ -1226,6 +1226,7 @@ Owen Martin
 Sidney San Martín
 Westley Martínez
 Sébastien Martini
+Iván Márton
 Roger Masse
 Nick Mathewson
 Simon Mathieu

Misc/NEWS.d/next/Library/2021-02-26-13-17-57.bpo-40469.yJHeQg.rst

@@ -0,0 +1,6 @@
+A bug has been fixed that made the ``TimedRotatingFileHandler`` use the
+MTIME attribute of the configured log file to to detect whether it has to be
+rotated yet or not. In cases when the file was changed within the rotation
+period the value of the MTIME was also updated to the current time and as a
+result the rotation never happened. The file creation time (CTIME) is used
+instead that makes the rotation file modification independent.