Merge pull request #7231 from bluetech/logging-error

logging: propagate errors during log message emits

Author: bluetech

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``.

src/_pytest/logging.py

@@ -312,6 +312,14 @@ def reset(self) -> None:
         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 @@ def __init__(self, config: Config) -> None:
         # 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 @@ def pytest_unconfigure(self):
         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 @@ def emit(self, record):
                 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 @@ def reset(self):
 
     def set_when(self, when):
         pass
+
+    def handleError(self, record: logging.LogRecord) -> None:
+        # Handled by LogCaptureHandler.
+        pass

testing/logging/test_reporting.py

@@ -3,6 +3,7 @@
 import re
 
 import pytest
+from _pytest.pytester import Testdir
 
 
 def test_nothing_logged(testdir):
@@ -1101,3 +1102,48 @@ def test_foo(caplog):
     )
     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)