bpo-40469: Make TimedRotatingFileHandler use CTIME instead of MTIME

The TimedRotatingFileHandler previously used 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 MTIME is also updated
to the current time and the rotation never happens. It's more
appropriate to check the file creation time (CTIME) instead.

Author: martonivan

Lib/logging/handlers.py

@@ -24,7 +24,7 @@
 """
 
 import io, logging, socket, os, pickle, struct, time, re
-from stat import ST_DEV, ST_INO, ST_MTIME
+from stat import ST_DEV, ST_INO
 import queue
 import threading
 import copy
@@ -263,7 +263,15 @@ 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 = 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/test_logging.py

@@ -6080,6 +6080,56 @@ def test_rollover(self):
                     print(tf.read())
         self.assertTrue(found, msg=msg)
 
+    def test_rollover_based_on_creation_time_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()
+            print(f"Filename: {self.fn}")
+            import subprocess
+            subprocess.run(["stat", self.fn])
+            print(os.stat(self.fn))
+
+        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):
         atTime = datetime.datetime.now().time()
         fmt = logging.Formatter('%(asctime)s %(message)s')

Misc/ACKS

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