Merge pull request #7434 from bluetech/distinct_log_handlers-rebased

logging: use unique handlers for caplog and reports

Author: bluetech

changelog/7159.improvement.rst

@@ -0,0 +1,3 @@
+When the ``caplog`` fixture is used to change the log level for capturing,
+using ``caplog.set_level()`` or ``caplog.at_level()``, it no longer affects
+the level of logs that are shown in the "Captured log report" report section.

src/_pytest/logging.py

@@ -34,8 +34,8 @@
 DEFAULT_LOG_FORMAT = "%(levelname)-8s %(name)s:%(filename)s:%(lineno)d %(message)s"
 DEFAULT_LOG_DATE_FORMAT = "%H:%M:%S"
 _ANSI_ESCAPE_SEQ = re.compile(r"\x1b\[[\d;]+m")
-catch_log_handler_key = StoreKey["LogCaptureHandler"]()
-catch_log_records_key = StoreKey[Dict[str, List[logging.LogRecord]]]()
+caplog_handler_key = StoreKey["LogCaptureHandler"]()
+caplog_records_key = StoreKey[Dict[str, List[logging.LogRecord]]]()
 
 
 def _remove_ansi_escape_sequences(text: str) -> str:
@@ -362,7 +362,7 @@ def handler(self) -> LogCaptureHandler:
         """
         :rtype: LogCaptureHandler
         """
-        return self._item._store[catch_log_handler_key]
+        return self._item._store[caplog_handler_key]
 
     def get_records(self, when: str) -> List[logging.LogRecord]:
         """
@@ -376,7 +376,7 @@ def get_records(self, when: str) -> List[logging.LogRecord]:
 
         .. versionadded:: 3.4
         """
-        return self._item._store[catch_log_records_key].get(when, [])
+        return self._item._store[caplog_records_key].get(when, [])
 
     @property
     def text(self) -> str:
@@ -523,8 +523,10 @@ def __init__(self, config: Config) -> None:
             get_option_ini(config, "log_auto_indent"),
         )
         self.log_level = get_log_level_for_setting(config, "log_level")
-        self.log_handler = LogCaptureHandler()
-        self.log_handler.setFormatter(self.formatter)
+        self.caplog_handler = LogCaptureHandler()
+        self.caplog_handler.setFormatter(self.formatter)
+        self.report_handler = LogCaptureHandler()
+        self.report_handler.setFormatter(self.formatter)
 
         # File logging.
         self.log_file_level = get_log_level_for_setting(config, "log_file_level")
@@ -665,22 +667,27 @@ def pytest_runtest_logreport(self) -> None:
 
     def _runtest_for(self, item: nodes.Item, when: str) -> Generator[None, None, None]:
         """Implements the internals of pytest_runtest_xxx() hook."""
-        with catching_logs(self.log_handler, level=self.log_level) as log_handler:
-            log_handler.reset()
-            item._store[catch_log_records_key][when] = log_handler.records
-            item._store[catch_log_handler_key] = log_handler
+        with catching_logs(
+            self.caplog_handler, level=self.log_level,
+        ) as caplog_handler, catching_logs(
+            self.report_handler, level=self.log_level,
+        ) as report_handler:
+            caplog_handler.reset()
+            report_handler.reset()
+            item._store[caplog_records_key][when] = caplog_handler.records
+            item._store[caplog_handler_key] = caplog_handler
 
             yield
 
-            log = log_handler.stream.getvalue().strip()
+            log = report_handler.stream.getvalue().strip()
             item.add_report_section(when, "log", log)
 
     @pytest.hookimpl(hookwrapper=True)
     def pytest_runtest_setup(self, item: nodes.Item) -> Generator[None, None, None]:
         self.log_cli_handler.set_when("setup")
 
         empty = {}  # type: Dict[str, List[logging.LogRecord]]
-        item._store[catch_log_records_key] = empty
+        item._store[caplog_records_key] = empty
         yield from self._runtest_for(item, "setup")
 
     @pytest.hookimpl(hookwrapper=True)
@@ -694,8 +701,8 @@ def pytest_runtest_teardown(self, item: nodes.Item) -> Generator[None, None, Non
         self.log_cli_handler.set_when("teardown")
 
         yield from self._runtest_for(item, "teardown")
-        del item._store[catch_log_records_key]
-        del item._store[catch_log_handler_key]
+        del item._store[caplog_records_key]
+        del item._store[caplog_handler_key]
 
     @pytest.hookimpl
     def pytest_runtest_logfinish(self) -> None:

testing/logging/test_fixture.py

@@ -1,7 +1,7 @@
 import logging
 
 import pytest
-from _pytest.logging import catch_log_records_key
+from _pytest.logging import caplog_records_key
 
 logger = logging.getLogger(__name__)
 sublogger = logging.getLogger(__name__ + ".baz")
@@ -137,7 +137,7 @@ def test_caplog_captures_for_all_stages(caplog, logging_during_setup_and_teardow
     assert [x.message for x in caplog.get_records("setup")] == ["a_setup_log"]
 
     # This reaches into private API, don't use this type of thing in real tests!
-    assert set(caplog._item._store[catch_log_records_key]) == {"setup", "call"}
+    assert set(caplog._item._store[caplog_records_key]) == {"setup", "call"}
 
 
 def test_ini_controls_global_log_level(testdir):
@@ -216,12 +216,10 @@ def test_log_level_override(request, caplog):
             plugin = request.config.pluginmanager.getplugin('logging-plugin')
             assert plugin.log_level == logging.WARNING
 
-            logger.info("INFO message won't be shown")
-
-            caplog.set_level(logging.INFO, logger.name)
+            logger.error("ERROR message " + "will be shown")
 
             with caplog.at_level(logging.DEBUG, logger.name):
-                logger.debug("DEBUG message will be shown")
+                logger.debug("DEBUG message " + "won't be shown")
                 raise Exception()
     """
     )
@@ -233,5 +231,46 @@ def test_log_level_override(request, caplog):
     )
 
     result = testdir.runpytest()
-    result.stdout.fnmatch_lines(["*DEBUG message will be shown*"])
+    result.stdout.fnmatch_lines(["*ERROR message will be shown*"])
+    result.stdout.no_fnmatch_line("*DEBUG message won't be shown*")
+    assert result.ret == 1
+
+
+def test_log_report_captures_according_to_config_option_upon_failure(testdir):
+    """ Test that upon failure:
+    (1) `caplog` succeeded to capture the DEBUG message and assert on it => No `Exception` is raised
+    (2) The `DEBUG` message does NOT appear in the `Captured log call` report
+    (3) The stdout, `INFO`, and `WARNING` messages DO appear in the test reports due to `--log-level=INFO`
+    """
+    testdir.makepyfile(
+        """
+        import pytest
+        import logging
+
+        def function_that_logs():
+            logging.debug('DEBUG log ' + 'message')
+            logging.info('INFO log ' + 'message')
+            logging.warning('WARNING log ' + 'message')
+            print('Print ' + 'message')
+
+        def test_that_fails(request, caplog):
+            plugin = request.config.pluginmanager.getplugin('logging-plugin')
+            assert plugin.log_level == logging.INFO
+
+            with caplog.at_level(logging.DEBUG):
+                function_that_logs()
+
+            if 'DEBUG log ' + 'message' not in caplog.text:
+                raise Exception('caplog failed to ' + 'capture DEBUG')
+
+            assert False
+    """
+    )
+
+    result = testdir.runpytest("--log-level=INFO")
+    result.stdout.no_fnmatch_line("*Exception: caplog failed to capture DEBUG*")
+    result.stdout.no_fnmatch_line("*DEBUG log message*")
+    result.stdout.fnmatch_lines(
+        ["*Print message*", "*INFO log message*", "*WARNING log message*"]
+    )
     assert result.ret == 1