From b13fcb23d79b3f38e497824c438c926a0a015561 Mon Sep 17 00:00:00 2001
From: Ran Benita <ran@unusedvar.com>
Date: Tue, 19 May 2020 10:41:33 +0300
Subject: [PATCH] logging: propagate errors during log message emits

Currently, a bad logging call, e.g.

    logger.info('oops', 'first', 2)

triggers the default logging handling, which is printing an error to
stderr but otherwise continuing.

For regular programs this behavior makes sense, a bad log message
shouldn't take down the program. But during tests, it is better not to
skip over such mistakes, but propagate them to the user.
---
 changelog/6433.feature.rst        | 10 +++++++
 src/_pytest/logging.py            | 30 ++++++++++++++++++--
 testing/logging/test_reporting.py | 46 +++++++++++++++++++++++++++++++
 3 files changed, 83 insertions(+), 3 deletions(-)
 create mode 100644 changelog/6433.feature.rst

diff --git a/changelog/6433.feature.rst b/changelog/6433.feature.rst
new file mode 100644
index 000000000..c331b0f58
--- /dev/null
+++ b/changelog/6433.feature.rst
@@ -0,0 +1,10 @@
+If an error is encountered while formatting the message in a logging call, for
+example ``logging.warning("oh no!: %s: %s", "first")`` (a second argument is
+missing), pytest now propagates the error, likely causing the test to fail.
+
+Previously, such a mistake would cause an error to be printed to stderr, which
+is not displayed by default for passing tests. This change makes the mistake
+visible during testing.
+
+You may supress this behavior temporarily or permanently by setting
+``logging.raiseExceptions = False``.
diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py
index e2f691a31..f6a206327 100644
--- a/src/_pytest/logging.py
+++ b/src/_pytest/logging.py
@@ -312,6 +312,14 @@ class LogCaptureHandler(logging.StreamHandler):
         self.records = []
         self.stream = StringIO()
 
+    def handleError(self, record: logging.LogRecord) -> None:
+        if logging.raiseExceptions:
+            # Fail the test if the log message is bad (emit failed).
+            # The default behavior of logging is to print "Logging error"
+            # to stderr with the call stack and some extra details.
+            # pytest wants to make such mistakes visible during testing.
+            raise
+
 
 class LogCaptureFixture:
     """Provides access and control of log capturing."""
@@ -499,9 +507,7 @@ class LoggingPlugin:
         # File logging.
         self.log_file_level = get_log_level_for_setting(config, "log_file_level")
         log_file = get_option_ini(config, "log_file") or os.devnull
-        self.log_file_handler = logging.FileHandler(
-            log_file, mode="w", encoding="UTF-8"
-        )
+        self.log_file_handler = _FileHandler(log_file, mode="w", encoding="UTF-8")
         log_file_format = get_option_ini(config, "log_file_format", "log_format")
         log_file_date_format = get_option_ini(
             config, "log_file_date_format", "log_date_format"
@@ -687,6 +693,16 @@ class LoggingPlugin:
         self.log_file_handler.close()
 
 
+class _FileHandler(logging.FileHandler):
+    """
+    Custom FileHandler with pytest tweaks.
+    """
+
+    def handleError(self, record: logging.LogRecord) -> None:
+        # Handled by LogCaptureHandler.
+        pass
+
+
 class _LiveLoggingStreamHandler(logging.StreamHandler):
     """
     Custom StreamHandler used by the live logging feature: it will write a newline before the first log message
@@ -737,6 +753,10 @@ class _LiveLoggingStreamHandler(logging.StreamHandler):
                 self._section_name_shown = True
             super().emit(record)
 
+    def handleError(self, record: logging.LogRecord) -> None:
+        # Handled by LogCaptureHandler.
+        pass
+
 
 class _LiveLoggingNullHandler(logging.NullHandler):
     """A handler used when live logging is disabled."""
@@ -746,3 +766,7 @@ class _LiveLoggingNullHandler(logging.NullHandler):
 
     def set_when(self, when):
         pass
+
+    def handleError(self, record: logging.LogRecord) -> None:
+        # Handled by LogCaptureHandler.
+        pass
diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py
index c1335b180..709df2b57 100644
--- a/testing/logging/test_reporting.py
+++ b/testing/logging/test_reporting.py
@@ -3,6 +3,7 @@ import os
 import re
 
 import pytest
+from _pytest.pytester import Testdir
 
 
 def test_nothing_logged(testdir):
@@ -1101,3 +1102,48 @@ def test_colored_ansi_esc_caplogtext(testdir):
     )
     result = testdir.runpytest("--log-level=INFO", "--color=yes")
     assert result.ret == 0
+
+
+def test_logging_emit_error(testdir: Testdir) -> None:
+    """
+    An exception raised during emit() should fail the test.
+
+    The default behavior of logging is to print "Logging error"
+    to stderr with the call stack and some extra details.
+
+    pytest overrides this behavior to propagate the exception.
+    """
+    testdir.makepyfile(
+        """
+        import logging
+
+        def test_bad_log():
+            logging.warning('oops', 'first', 2)
+        """
+    )
+    result = testdir.runpytest()
+    result.assert_outcomes(failed=1)
+    result.stdout.fnmatch_lines(
+        [
+            "====* FAILURES *====",
+            "*not all arguments converted during string formatting*",
+        ]
+    )
+
+
+def test_logging_emit_error_supressed(testdir: Testdir) -> None:
+    """
+    If logging is configured to silently ignore errors, pytest
+    doesn't propagate errors either.
+    """
+    testdir.makepyfile(
+        """
+        import logging
+
+        def test_bad_log(monkeypatch):
+            monkeypatch.setattr(logging, 'raiseExceptions', False)
+            logging.warning('oops', 'first', 2)
+        """
+    )
+    result = testdir.runpytest()
+    result.assert_outcomes(passed=1)