From e35430bec528dfb1a653cd457ea58b5a08543632 Mon Sep 17 00:00:00 2001 From: "Miss Islington (bot)" <31488909+miss-islington@users.noreply.github.com> Date: Fri, 7 Jan 2022 14:15:25 -0800 Subject: [3.10] bpo-42378: fixed log truncation on logging shutdown (GH-27310) (GH-30468) Co-authored-by: andrei kulakov --- Doc/library/logging.handlers.rst | 3 +++ Lib/logging/__init__.py | 13 +++++++++++-- Lib/test/test_logging.py | 18 ++++++++++++++---- .../Library/2021-07-25-08-17-55.bpo-42378.WIhUZK.rst | 4 ++++ 4 files changed, 32 insertions(+), 6 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2021-07-25-08-17-55.bpo-42378.WIhUZK.rst diff --git a/Doc/library/logging.handlers.rst b/Doc/library/logging.handlers.rst index a664efd..a5b181e 100644 --- a/Doc/library/logging.handlers.rst +++ b/Doc/library/logging.handlers.rst @@ -117,6 +117,9 @@ sends logging output to a disk file. It inherits the output functionality from Outputs the record to the file. + Note that if the file was closed due to logging shutdown at exit and the file + mode is 'w', the record will not be emitted (see :issue:`42378`). + .. _null-handler: diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 555f598..19bd2bc 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -878,6 +878,7 @@ class Handler(Filterer): self._name = None self.level = _checkLevel(level) self.formatter = None + self._closed = False # Add the handler to the global _handlerList (for cleanup on shutdown) _addHandlerRef(self) self.createLock() @@ -996,6 +997,7 @@ class Handler(Filterer): #get the module data lock, as we're updating a shared structure. _acquireLock() try: #unlikely to raise an exception, but you never know... + self._closed = True if self._name and self._name in _handlers: del _handlers[self._name] finally: @@ -1184,6 +1186,8 @@ class FileHandler(StreamHandler): finally: # Issue #19523: call unconditionally to # prevent a handler leak when delay is set + # Also see Issue #42378: we also rely on + # self._closed being set to True there StreamHandler.close(self) finally: self.release() @@ -1203,10 +1207,15 @@ class FileHandler(StreamHandler): If the stream was not opened because 'delay' was specified in the constructor, open it before calling the superclass's emit. + + If stream is not open, current mode is 'w' and `_closed=True`, record + will not be emitted (see Issue #42378). """ if self.stream is None: - self.stream = self._open() - StreamHandler.emit(self, record) + if self.mode != 'w' or not self._closed: + self.stream = self._open() + if self.stream: + StreamHandler.emit(self, record) def __repr__(self): level = getLevelName(self.level) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 40411b4..03d0319 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -5168,6 +5168,9 @@ class BaseFileTest(BaseTest): msg="Log file %r does not exist" % filename) self.rmfiles.append(filename) + def next_rec(self): + return logging.LogRecord('n', logging.DEBUG, 'p', 1, + self.next_message(), None, None, None) class FileHandlerTest(BaseFileTest): def test_delay(self): @@ -5180,11 +5183,18 @@ class FileHandlerTest(BaseFileTest): self.assertTrue(os.path.exists(self.fn)) fh.close() -class RotatingFileHandlerTest(BaseFileTest): - def next_rec(self): - return logging.LogRecord('n', logging.DEBUG, 'p', 1, - self.next_message(), None, None, None) + def test_emit_after_closing_in_write_mode(self): + # Issue #42378 + os.unlink(self.fn) + fh = logging.FileHandler(self.fn, encoding='utf-8', mode='w') + fh.setFormatter(logging.Formatter('%(message)s')) + fh.emit(self.next_rec()) # '1' + fh.close() + fh.emit(self.next_rec()) # '2' + with open(self.fn) as fp: + self.assertEqual(fp.read().strip(), '1') +class RotatingFileHandlerTest(BaseFileTest): def test_should_not_rollover(self): # If maxbytes is zero rollover never occurs rh = logging.handlers.RotatingFileHandler( diff --git a/Misc/NEWS.d/next/Library/2021-07-25-08-17-55.bpo-42378.WIhUZK.rst b/Misc/NEWS.d/next/Library/2021-07-25-08-17-55.bpo-42378.WIhUZK.rst new file mode 100644 index 0000000..90c3961 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2021-07-25-08-17-55.bpo-42378.WIhUZK.rst @@ -0,0 +1,4 @@ +Fixes the issue with log file being overwritten when +:class:`logging.FileHandler` is used in :mod:`atexit` with *filemode* set to +``'w'``. Note this will cause the message in *atexit* not being logged if +the log stream is already closed due to shutdown of logging. -- cgit v0.12