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

[vsajip]

https://github.com/python/cpython/commit/e35430bec528dfb1a653cd457ea58b5a08543632
commit: e35430bec528dfb1a653cd457ea58b5a08543632
branch: 3.10
author: Miss Islington (bot) <31488909+miss-islington at users.noreply.github.com>
committer: vsajip <vinay_sajip at yahoo.co.uk>
date: 2022-01-07T22:15:25Z
summary:

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

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

files:
A Misc/NEWS.d/next/Library/2021-07-25-08-17-55.bpo-42378.WIhUZK.rst
M Doc/library/logging.handlers.rst
M Lib/logging/__init__.py
M Lib/test/test_logging.py

diff --git a/Doc/library/logging.handlers.rst b/Doc/library/logging.handlers.rst
index a664efdc62526..a5b181ee612d5 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 555f598de7a92..19bd2bc20b250 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -878,6 +878,7 @@ def __init__(self, level=NOTSET):
         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 @@ def close(self):
         #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 @@ def close(self):
             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 @@ def emit(self, record):
 
         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 40411b4488483..03d0319306a48 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -5168,6 +5168,9 @@ def assertLogFile(self, filename):
                         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 @@ def test_delay(self):
         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 0000000000000..90c3961dc87d8
--- /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.