From 823c5ffbb8baa344b1758f015911ff2dbff2c8e1 Mon Sep 17 00:00:00 2001 From: Harry Lees Date: Sun, 6 Jun 2021 00:07:43 +0100 Subject: [PATCH 1/7] bpo-44186: prevent TimedRotatingFileHandler overwriting log files TimedRotatingFileHandler deletes any file with the destination name when it rotates, this change adds a number to the end of the filename to prevent conflict. --- Lib/logging/handlers.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index b0d5885989ea42..3f0e854b331adf 100644 --- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -255,6 +255,7 @@ def __init__(self, filename, when='h', interval=1, backupCount=0, raise ValueError("Invalid rollover interval specified: %s" % self.when) self.extMatch = re.compile(self.extMatch, re.ASCII) + self.file_number = re.compile(r'(\()([0-9])(\))$') self.interval = self.interval * interval # multiply by units requested # The following line added because the filename passed in could be a # path object (see Issue #27493), but self.baseFilename will be a string @@ -401,8 +402,12 @@ def doRollover(self): timeTuple = time.localtime(t + addend) dfn = self.rotation_filename(self.baseFilename + "." + time.strftime(self.suffix, timeTuple)) - if os.path.exists(dfn): - os.remove(dfn) + while os.path.exists(dfn): + if match := re.search(self.file_number, dfn): + name = re.sub(self.file_number, f'({int(match.groups()[1]) + 1})', dfn) + dfn = self.rotation_filename(name) + else: + dfn = self.rotation_filename(self.baseFilename + '.' + time.strftime(self.suffix, timeTuple) + ' (2)') self.rotate(self.baseFilename, dfn) if self.backupCount > 0: for s in self.getFilesToDelete(): From f2f269a7a510539168ce00e841233a710b0f9913 Mon Sep 17 00:00:00 2001 From: Harry-Lees Date: Sun, 20 Jun 2021 17:26:27 +0100 Subject: [PATCH 2/7] removed redundant regex groups and added support for one or more numbers --- Lib/logging/handlers.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index 3f0e854b331adf..26e839965468d2 100644 --- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -255,7 +255,7 @@ def __init__(self, filename, when='h', interval=1, backupCount=0, raise ValueError("Invalid rollover interval specified: %s" % self.when) self.extMatch = re.compile(self.extMatch, re.ASCII) - self.file_number = re.compile(r'(\()([0-9])(\))$') + self.file_number = re.compile(r'\(([0-9]+)\)$') self.interval = self.interval * interval # multiply by units requested # The following line added because the filename passed in could be a # path object (see Issue #27493), but self.baseFilename will be a string @@ -404,7 +404,7 @@ def doRollover(self): time.strftime(self.suffix, timeTuple)) while os.path.exists(dfn): if match := re.search(self.file_number, dfn): - name = re.sub(self.file_number, f'({int(match.groups()[1]) + 1})', dfn) + name = re.sub(self.file_number, f'({int(match.groups()[0]) + 1})', dfn) dfn = self.rotation_filename(name) else: dfn = self.rotation_filename(self.baseFilename + '.' + time.strftime(self.suffix, timeTuple) + ' (2)') From b6d220f5785cf0a2b5448722fb96f3e6f4190206 Mon Sep 17 00:00:00 2001 From: Harry-Lees Date: Sun, 20 Jun 2021 17:41:40 +0100 Subject: [PATCH 3/7] updated docs to reflect change --- Doc/library/logging.handlers.rst | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/Doc/library/logging.handlers.rst b/Doc/library/logging.handlers.rst index 059ab3d3a34448..1182f43eb96ff0 100644 --- a/Doc/library/logging.handlers.rst +++ b/Doc/library/logging.handlers.rst @@ -382,7 +382,8 @@ timed intervals. The system will save old log files by appending extensions to the filename. The extensions are date-and-time based, using the strftime format ``%Y-%m-%d_%H-%M-%S`` or a leading portion thereof, depending on the - rollover interval. + rollover interval. In the case that an existing file has the same name, + a numbered suffix will be added to the new file to prevent overwriting logs. When computing the next rollover time for the first time (when the handler is created), the last modification time of an existing log file, or else From 8b21aa54cf0099af29d36248ebee10da3919be9f Mon Sep 17 00:00:00 2001 From: Harry-Lees Date: Sun, 20 Jun 2021 17:41:55 +0100 Subject: [PATCH 4/7] updated ACKS --- Misc/ACKS | 1 + 1 file changed, 1 insertion(+) diff --git a/Misc/ACKS b/Misc/ACKS index 0cb738b3a12ee4..b349430af8cd24 100644 --- a/Misc/ACKS +++ b/Misc/ACKS @@ -1017,6 +1017,7 @@ John J. Lee Thomas Lee Robert Leenders Cooper Ry Lees +Harry Lees Yaron de Leeuw Tennessee Leeuwenburg Luc Lefebvre From 15ce117723a9ec6a5a1648c48e97abf2893461c2 Mon Sep 17 00:00:00 2001 From: Harry-Lees Date: Sun, 20 Jun 2021 18:43:06 +0100 Subject: [PATCH 5/7] added tests --- Lib/test/test_logging.py | 52 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 52 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 6d111908e7c395..c4fa32fdd36037 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -5331,6 +5331,58 @@ def test_rollover(self): print(tf.read()) self.assertTrue(found, msg=msg) + def test_overwrite_rollover(self): + # bpo-44186 test that pre-existing files aren't overwritten by rollover + now = datetime.datetime.now() + handlers = [ + logging.handlers.TimedRotatingFileHandler( + self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), + logging.handlers.TimedRotatingFileHandler( + self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), + logging.handlers.TimedRotatingFileHandler( + self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), + ] + + # compute the filename + t = handlers[0].rolloverAt - handlers[0].interval + timeTuple = time.gmtime(t) + fn = handlers[0].rotation_filename( + handlers[0].baseFilename + '.' + time.strftime(handlers[0].suffix, timeTuple)) + + r = logging.makeLogRecord({'msg': 'test msg'}) + + for handler in handlers: + handler.emit(r) + handler.close() + + self.assertLogFile(fn) + self.assertLogFile(fn + ' (2)') + self.assertLogFile(fn + ' (3)') + + def test_lowest_filename_generated(self): + # test that when the filename is generated, the lowest possible suffix is used + # e.g. if the files "log.2021-06-19", "log.2021-06-19 (2)", and "log.2021-06-19 (4)" exist + # the filename generated should be "log.2021-06-19 (3)" + now = datetime.datetime.now() + fh = logging.handlers.TimedRotatingFileHandler( + self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1) + + # compute the filename + t = fh.rolloverAt - fh.interval + timeTuple = time.gmtime(t) + fn = fh.rotation_filename( + fh.baseFilename + '.' + time.strftime(fh.suffix, timeTuple)) + + for filename in [fn, fn + ' (2)', fn + ' (4)']: + pathlib.Path(filename).touch() + self.rmfiles.append(filename) + + r = logging.makeLogRecord({'msg': 'test msg'}) + fh.emit(r) + fh.close() + + self.assertLogFile(fn + ' (3)') + def test_invalid(self): assertRaises = self.assertRaises assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler, From d1203123b41b595c36c9b9e46ad68e6d720b5142 Mon Sep 17 00:00:00 2001 From: Harry-Lees Date: Sun, 20 Jun 2021 18:55:46 +0100 Subject: [PATCH 6/7] trimmed trailing whitespace --- Lib/test/test_logging.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index c4fa32fdd36037..2616cccbe0f24e 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -5335,11 +5335,11 @@ def test_overwrite_rollover(self): # bpo-44186 test that pre-existing files aren't overwritten by rollover now = datetime.datetime.now() handlers = [ - logging.handlers.TimedRotatingFileHandler( + logging.handlers.TimedRotatingFileHandler( self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), - logging.handlers.TimedRotatingFileHandler( + logging.handlers.TimedRotatingFileHandler( self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), - logging.handlers.TimedRotatingFileHandler( + logging.handlers.TimedRotatingFileHandler( self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), ] From 1f94389918f5f1fe25cbf3aa9860b166dd76d967 Mon Sep 17 00:00:00 2001 From: Harry-Lees Date: Mon, 21 Jun 2021 23:28:18 +0100 Subject: [PATCH 7/7] changed testing methodology to fix Windows build --- Lib/test/test_logging.py | 27 +++++++++++---------------- 1 file changed, 11 insertions(+), 16 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 2616cccbe0f24e..dc578f31b3e865 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -5334,30 +5334,25 @@ def test_rollover(self): def test_overwrite_rollover(self): # bpo-44186 test that pre-existing files aren't overwritten by rollover now = datetime.datetime.now() - handlers = [ - logging.handlers.TimedRotatingFileHandler( - self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), - logging.handlers.TimedRotatingFileHandler( - self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), - logging.handlers.TimedRotatingFileHandler( - self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1), - ] + handler = logging.handlers.TimedRotatingFileHandler( + self.fn, 'midnight', atTime=now, encoding='utf-8', backupCount=1) # compute the filename - t = handlers[0].rolloverAt - handlers[0].interval + t = handler.rolloverAt - handler.interval timeTuple = time.gmtime(t) - fn = handlers[0].rotation_filename( - handlers[0].baseFilename + '.' + time.strftime(handlers[0].suffix, timeTuple)) + fn = handler.rotation_filename( + handler.baseFilename + '.' + time.strftime(handler.suffix, timeTuple)) + + # touch a file with the intended filename + pathlib.Path(fn).touch() + self.rmfiles.append(fn) r = logging.makeLogRecord({'msg': 'test msg'}) - for handler in handlers: - handler.emit(r) - handler.close() + handler.emit(r) + handler.close() - self.assertLogFile(fn) self.assertLogFile(fn + ' (2)') - self.assertLogFile(fn + ' (3)') def test_lowest_filename_generated(self): # test that when the filename is generated, the lowest possible suffix is used