gh-116267: Avoid formatting record twice in RotatingFileHandler.

Author: vsajip

Lib/logging/__init__.py

@@ -1148,9 +1148,8 @@ def emit(self, record):
         """
         try:
             msg = self.format(record)
-            stream = self.stream
             # issue 35046: merged two stream.writes into one.
-            stream.write(msg + self.terminator)
+            self.stream.write(msg + self.terminator)
             self.flush()
         except RecursionError:  # See issue 36272
             raise

Lib/logging/handlers.py

@@ -67,6 +67,7 @@ def __init__(self, filename, mode, encoding=None, delay=False, errors=None):
         self.mode = mode
         self.encoding = encoding
         self.errors = errors
+        self._msg = None  # cache to avoid reformatting - see gh-116267
 
     def emit(self, record):
         """
@@ -78,7 +79,13 @@ def emit(self, record):
         try:
             if self.shouldRollover(record):
                 self.doRollover()
-            logging.FileHandler.emit(self, record)
+            if self._msg:
+                msg = self._msg
+                self._msg = None
+            else:
+                msg = self.format(record)
+            self.stream.write(msg + self.terminator)
+            self.flush()
         except Exception:
             self.handleError(record)
 
@@ -195,10 +202,11 @@ def shouldRollover(self, record):
         """
         if self.stream is None:                 # delay was set...
             self.stream = self._open()
+        pos = self.stream.tell()
         if self.maxBytes > 0:                   # are we rolling over?
-            msg = "%s\n" % self.format(record)
+            self._msg = msg = self.format(record)
             self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
-            if self.stream.tell() + len(msg) >= self.maxBytes:
+            if self.stream.tell() + len(msg) + len(self.terminator) >= self.maxBytes:
                 # See bpo-45401: Never rollover anything other than regular files
                 if os.path.exists(self.baseFilename) and not os.path.isfile(self.baseFilename):
                     return False

Lib/test/test_logging.py

@@ -6258,6 +6258,24 @@ def rotator(self, source, dest):
         self.assertFalse(os.path.exists(rh.namer(self.fn + ".1")))
         rh.close()
 
+    def test_format_once(self):
+        class InstrumentedHandler(logging.handlers.RotatingFileHandler):
+            def __init__(self, *args, **kwargs):
+                super().__init__(*args, **kwargs)
+                self._format_count = 0
+
+            def format(self, record):
+                result = super().format(record)
+                self._format_count += 1
+                return result
+        rh = InstrumentedHandler(self.fn, encoding="utf-8",
+                                 backupCount=2, maxBytes=2)
+        rh.emit(self.next_rec())
+        self.assertLogFile(self.fn)
+        rh.emit(self.next_rec())
+        self.assertEqual(rh._format_count, 2)  # once per emit() call
+        rh.close()
+
     @support.requires_zlib()
     def test_rotator(self):
         def namer(name):