[3.10] bpo-42378: fixed log truncation on logging shutdown (GH-27310) (GH-30468)

Co-authored-by: andrei kulakov <andrei.avk@gmail.com>

diff --git a/Doc/library/logging.handlers.rst b/Doc/library/logging.handlers.rst
index a664efdc625261f4e5559909d48af992dea6547b..a5b181ee612d5fd9489a3b53ff6ad3a2dd3d919d 100644 (file)
--- 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 555f598de7a9253a80192cae23a326e7e6ea069b..19bd2bc20b250248321b15b21a90761db1fa9d0c 100644 (file)
--- 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 40411b448848357f8cc5e687438cdd0dae808cc6..03d0319306a480d241d680eb9b59bb5544ae8411 100644 (file)
--- 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 (file)
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.