diff --git a/changelog/7159.improvement.rst b/changelog/7159.improvement.rst new file mode 100644 index 000000000..c5f51a7b7 --- /dev/null +++ b/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. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 57aa14f27..52d75e66d 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -34,8 +34,8 @@ from _pytest.terminal import TerminalReporter 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 @@ class LogCaptureFixture: """ :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 @@ class LogCaptureFixture: .. 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 @@ class LoggingPlugin: 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,14 +667,19 @@ class LoggingPlugin: 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) @@ -680,7 +687,7 @@ class LoggingPlugin: 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 @@ class LoggingPlugin: 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: diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 3a3663464..da5303302 100644 --- a/testing/logging/test_fixture.py +++ b/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_caplog_captures_despite_exception(testdir): 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_caplog_captures_despite_exception(testdir): ) 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