gh-116267: Avoid formatting record twice in RotatingFileHandler.

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,15 @@ 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 RecursionError:  # See issue bpo-36272
+            raise
         except Exception:
             self.handleError(record)
 
@@ -196,9 +205,9 @@ def shouldRollover(self, record):
         if self.stream is None:                 # delay was set...
             self.stream = self._open()
         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
@@ -687,6 +696,8 @@ def emit(self, record):
         try:
             s = self.makePickle(record)
             self.send(s)
+        except RecursionError:  # See issue bpo-36272
+            raise
         except Exception:
             self.handleError(record)
 
@@ -1016,6 +1027,8 @@ def emit(self, record):
                 self.socket.sendto(msg, self.address)
             else:
                 self.socket.sendall(msg)
+        except RecursionError:  # See issue bpo-36272
+            raise
         except Exception:
             self.handleError(record)
 
@@ -1096,6 +1109,8 @@ def emit(self, record):
                 smtp.login(self.username, self.password)
             smtp.send_message(msg)
             smtp.quit()
+        except RecursionError:  # See issue bpo-36272
+            raise
         except Exception:
             self.handleError(record)
 
@@ -1190,6 +1205,8 @@ def emit(self, record):
                 type = self.getEventType(record)
                 msg = self.format(record)
                 self._welu.ReportEvent(self.appname, id, cat, type, [msg])
+            except RecursionError:  # See issue bpo-36272
+                raise
             except Exception:
                 self.handleError(record)
 
@@ -1293,6 +1310,8 @@ def emit(self, record):
             if self.method == "POST":
                 h.send(data.encode('utf-8'))
             h.getresponse()    #can't do anything with the result
+        except RecursionError:  # See issue bpo-36272
+            raise
         except Exception:
             self.handleError(record)
 
@@ -1488,6 +1507,8 @@ def emit(self, record):
         """
         try:
             self.enqueue(self.prepare(record))
+        except RecursionError:  # See issue bpo-36272
+            raise
         except Exception:
             self.handleError(record)
 

Lib/test/test_logging.py

@@ -6258,6 +6258,26 @@ 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.assertLogFile(self.fn + ".1")
+        self.assertLogFile(self.fn + ".2")
+        self.assertEqual(rh._format_count, 2)  # once per emit() call
+        rh.close()
+
     @support.requires_zlib()
     def test_rotator(self):
         def namer(name):