From 10cb8b993b3b10ecd6d858ab4ab87f31cb059b88 Mon Sep 17 00:00:00 2001 From: Tobias Deiminger Date: Fri, 16 Sep 2022 17:41:09 +0200 Subject: [PATCH 1/2] testing/logging/test_reporting: add xfail test for report capturing of non-propagating loggers Demonstrate the bug/missing functionality of reporting logs emitted by non-propagating loggers (i.e. loggers which don't reach the root logger, where we currently attach our handler). Refs #3697 [ran: extracted from #10303 and changed to use HookRecorder] --- testing/logging/test_reporting.py | 34 +++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 4974532e888..95a44d7cdf0 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -1255,6 +1255,40 @@ def test_foo(): ) +@pytest.mark.xfail(reason="#3697 - not capturing propagate=False loggers yet") +def test_log_propagation_false(pytester: Pytester) -> None: + pytester.makepyfile( + """ + import pytest + import logging + + logging.getLogger('foo').propagate = False + + def test_log_file(request): + logging.getLogger().warning("log goes to root logger") + logging.getLogger('foo').warning("log goes to initially non-propagating logger") + logging.getLogger('foo.bar').propagate = False + logging.getLogger('foo.bar').warning("log goes to propagation-disabled-in-test logger") + assert False, "intentionally fail to trigger report logging output" + """ + ) + + reprec = pytester.inline_run() + reports = reprec.getfailures() + assert len(reports) == 1 + report = reports[0] + sections = list(report.get_sections("Captured log call")) + assert len(sections) == 1 + assert sections[0][1] == "\n".join( + [ + "WARNING root:test_log_propagation_false.py:7 log goes to root logger", + "WARNING foo:test_log_propagation_false.py:8 log goes to initially non-propagating logger", + "WARNING foo.bar:test_log_propagation_false.py:10 log goes to propagation-disabled-in-test logger", + ] + ) + assert not list(report.get_sections("Captured stderr call")) + + def test_colored_ansi_esc_caplogtext(pytester: Pytester) -> None: """Make sure that caplog.text does not contain ANSI escape sequences.""" pytester.makepyfile( From 975a6e28a958e480da95648c1e1c939afb746d9e Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Fri, 10 Apr 2026 11:42:36 +0300 Subject: [PATCH 2/2] logging: also capture logs from non-propagating loggers Previously, we only attached our capturing handler to the root logger. This means that logs emitted by non-propagating loggers (including all children which propagate to *them*) were not captured. As far as I can see, for the pytest use case, we do always want to capture these logs, for both test reporting (i.e. the "Captured log calls" section) and `caplog` testing. Fix by attaching to all non-propagating loggers in addition to the root logger. This approach doesn't handle loggers which become non-propagating during the test, which seems OK to me. A downside is that the (somewhat performance-sensitive) per-test logging setup becomes a bit slower (depending on the logging setup). Fix #3697 --- changelog/3697.bugfix.rst | 3 +++ src/_pytest/logging.py | 22 ++++++++++++++++++++-- testing/logging/test_fixture.py | 27 +++++++++++++++++++++++++++ testing/logging/test_reporting.py | 6 ++---- 4 files changed, 52 insertions(+), 6 deletions(-) create mode 100644 changelog/3697.bugfix.rst diff --git a/changelog/3697.bugfix.rst b/changelog/3697.bugfix.rst new file mode 100644 index 00000000000..59f1872786d --- /dev/null +++ b/changelog/3697.bugfix.rst @@ -0,0 +1,3 @@ +Logging capture now works for non-propagating loggers. +Previously only logs which reached the root logger were captured. +This includes :fixture:`caplog` and the "Captured log calls" test reporting. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 6f34c1b93fd..2a22c9eb4aa 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -342,18 +342,34 @@ def add_option_ini(option, dest, default=None, type=None, **kwargs): class catching_logs(Generic[_HandlerType]): """Context manager that prepares the whole logging machinery properly.""" - __slots__ = ("handler", "level", "orig_level") + __slots__ = ("attached_loggers", "handler", "level", "orig_level") def __init__(self, handler: _HandlerType, level: int | None = None) -> None: self.handler = handler self.level = level + self.attached_loggers: list[logging.Logger] = [] def __enter__(self) -> _HandlerType: root_logger = logging.getLogger() if self.level is not None: self.handler.setLevel(self.level) + # Attach to root logger. root_logger.addHandler(self.handler) + self.attached_loggers.append(root_logger) + # Attach to all non-propagating loggers (won't reach root). + # Note that will miss loggers that *become* non-propagating + # after the `__enter__`. Not worth the trouble for now. + for logger in root_logger.manager.loggerDict.values(): + if ( + isinstance(logger, logging.Logger) + and not logger.propagate + and logger is not root_logger + ): + logger.addHandler(self.handler) + self.attached_loggers.append(logger) if self.level is not None: + # Non-propagating loggers still inherit the level (unless a logger + # explicitly set level), so only do this on the root logger. self.orig_level = root_logger.level root_logger.setLevel(min(self.orig_level, self.level)) return self.handler @@ -367,7 +383,9 @@ def __exit__( root_logger = logging.getLogger() if self.level is not None: root_logger.setLevel(self.orig_level) - root_logger.removeHandler(self.handler) + for logger in self.attached_loggers: + logger.removeHandler(self.handler) + self.attached_loggers.clear() class LogCaptureHandler(logging_StreamHandler): diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 5f94cb8508a..c98b7d84258 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -411,6 +411,33 @@ def test_log_level_override(request, caplog): assert result.ret == 0 +def test_can_capture_non_propagating_logger(pytester: Pytester) -> None: + """Logs emitted by non-propagating loggers are still captured (#3697).""" + pytester.makepyfile( + """ + import logging + + logger = logging.getLogger("catchlog") + logger.propagate = False + child_logger = logging.getLogger("catchlog.child") + + def test_non_propagating_logger(caplog): + caplog.set_level(logging.INFO) + + logger.info("parent logger message") + child_logger.info("child logger message") + + assert caplog.record_tuples == [ + ("catchlog", logging.INFO, "parent logger message"), + ("catchlog.child", logging.INFO, "child logger message"), + ] + """ + ) + + result = pytester.runpytest() + result.assert_outcomes(passed=1) + + def test_captures_despite_exception(pytester: Pytester) -> None: pytester.makepyfile( """ diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 95a44d7cdf0..e8919d1f36a 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -1255,7 +1255,6 @@ def test_foo(): ) -@pytest.mark.xfail(reason="#3697 - not capturing propagate=False loggers yet") def test_log_propagation_false(pytester: Pytester) -> None: pytester.makepyfile( """ @@ -1267,8 +1266,7 @@ def test_log_propagation_false(pytester: Pytester) -> None: def test_log_file(request): logging.getLogger().warning("log goes to root logger") logging.getLogger('foo').warning("log goes to initially non-propagating logger") - logging.getLogger('foo.bar').propagate = False - logging.getLogger('foo.bar').warning("log goes to propagation-disabled-in-test logger") + logging.getLogger('foo.bar').warning("log goes to initially non-propagating nested logger") assert False, "intentionally fail to trigger report logging output" """ ) @@ -1283,7 +1281,7 @@ def test_log_file(request): [ "WARNING root:test_log_propagation_false.py:7 log goes to root logger", "WARNING foo:test_log_propagation_false.py:8 log goes to initially non-propagating logger", - "WARNING foo.bar:test_log_propagation_false.py:10 log goes to propagation-disabled-in-test logger", + "WARNING foo.bar:test_log_propagation_false.py:9 log goes to initially non-propagating nested logger", ] ) assert not list(report.get_sections("Captured stderr call"))