diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index cdb014bca04b6e..6ea86173a39011 100644 --- a/Lib/logging/handlers.py +++ b/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 @@ -269,7 +269,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) diff --git a/Lib/test/support/__init__.py b/Lib/test/support/__init__.py index 505d4bea83fe8d..d0f0058be9802c 100644 --- a/Lib/test/support/__init__.py +++ b/Lib/test/support/__init__.py @@ -37,6 +37,7 @@ "has_fork_support", "requires_fork", "has_subprocess_support", "requires_subprocess", "has_socket_support", "requires_working_socket", + "has_st_birthtime", "anticipate_failure", "load_package_tests", "detect_api_mismatch", "check__all__", "skip_if_buggy_ucrt_strfptime", "check_disallow_instantiation", "check_sanitizer", "skip_if_sanitizer", @@ -546,6 +547,9 @@ def requires_debug_ranges(reason='requires co_positions / debug_ranges'): 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()") diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index d71385bf2c78d7..e14b1aa4f68bbe 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6080,6 +6080,53 @@ 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): atTime = datetime.datetime.now().time() fmt = logging.Formatter('%(asctime)s %(message)s') diff --git a/Misc/ACKS b/Misc/ACKS index f01c7a70a65dc5..187f832c13f15e 100644 --- a/Misc/ACKS +++ b/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 diff --git a/Misc/NEWS.d/next/Library/2021-02-26-13-17-57.bpo-40469.yJHeQg.rst b/Misc/NEWS.d/next/Library/2021-02-26-13-17-57.bpo-40469.yJHeQg.rst new file mode 100644 index 00000000000000..eab474dfd2ea82 --- /dev/null +++ b/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.