From e502c27db79ea98dd2e1a79fed653948ed04e26c Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Mon, 21 Sep 2026 15:04:50 +0000 Subject: [PATCH 01/12] logging: capture each record once when propagate changes during a test Records from a logger which was non-propagating at capture start were handled twice once the test enables Logger.propagate: pytest's capture handler ran directly on that logger and again via the root logger. Instead of attaching the real capture handler to initially non-propagating loggers, attach a lightweight proxy bound to each such logger and its ancestors which forwards to the real handler only while that logger currently has propagate disabled. The proxy reads the live propagate value per record, so a False -> True transition stops the direct handling as soon as the record can reach root, and a True -> False transition on those loggers is now captured as well. Fixes #15064 --- changelog/15064.bugfix.rst | 7 ++++ src/_pytest/logging.py | 70 ++++++++++++++++++++++++++++--- testing/logging/test_fixture.py | 56 +++++++++++++++++++++++++ testing/logging/test_reporting.py | 31 ++++++++++++++ 4 files changed, 158 insertions(+), 6 deletions(-) create mode 100644 changelog/15064.bugfix.rst diff --git a/changelog/15064.bugfix.rst b/changelog/15064.bugfix.rst new file mode 100644 index 00000000000..61f330edaa2 --- /dev/null +++ b/changelog/15064.bugfix.rst @@ -0,0 +1,7 @@ +Fixed duplicate log records when a logger which was non-propagating at capture +start enables ``logging.Logger.propagate`` during the test: the record was +handled both by pytest's handler attached directly to that logger and by the +one attached to the root logger. Capture (``caplog``, failure-report sections, +``--log-cli-level`` and ``--log-file`` output) now sees each record exactly +once, and the previously-missed ``True -> False`` transition on the affected +loggers and their ancestors is now handled as well. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 51c4954fb38..0a6a05f4e66 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -334,16 +334,58 @@ def add_option_ini(option, dest, default=None, type=None, **kwargs): _HandlerType = TypeVar("_HandlerType", bound=logging.Handler) +class _BoundProxyHandler(logging.Handler): + """A proxy for a pytest capture handler, bound to one logger. + + The proxy forwards records to the real handler only while its logger + currently does not propagate. This is attached (instead of the real + handler) to loggers which were non-propagating when capture started, and + to their ancestors, so that flipping ``Logger.propagate`` during a test + neither duplicates the record (direct handler plus root handler) nor + misses it (#15064, #3697). + """ + + __slots__ = ("logger", "real_handler") + + def __init__(self, logger: logging.Logger, real_handler: logging.Handler) -> None: + self.logger = logger + self.real_handler = real_handler + super().__init__() + + @property + def level(self) -> int: + # Always defer to the real handler, whose level may change after + # attachment (e.g. via caplog.set_level()). + return self.real_handler.level + + @level.setter + def level(self, value: int) -> None: + # Only assigned by logging.Handler.__init__(); the level is tracked + # through the real handler instead. + pass + + def emit(self, record: logging.LogRecord) -> None: + if not self.logger.propagate: + self.real_handler.handle(record) + + # Not using @contextmanager for performance reasons. class catching_logs(Generic[_HandlerType]): """Context manager that prepares the whole logging machinery properly.""" - __slots__ = ("attached_loggers", "handler", "level", "orig_level") + __slots__ = ( + "attached_loggers", + "attached_proxies", + "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] = [] + self.attached_proxies: list[tuple[logging.Logger, _BoundProxyHandler]] = [] def __enter__(self) -> _HandlerType: root_logger = logging.getLogger() @@ -352,17 +394,30 @@ def __enter__(self) -> _HandlerType: # 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. + # Attach bound proxy handlers to all non-propagating loggers + # (their records won't reach root) and to their ancestors, so that + # records which *do* reach root after a `propagate` change are only + # handled once. The proxies consult the live `propagate` value per + # record (#15064). + # Note that this still misses loggers (outside those ancestor + # chains) which *become* non-propagating after the `__enter__`. + # Not worth the trouble for now. + proxy_targets: dict[logging.Logger, None] = {} 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) + proxy_targets[logger] = None + parent = logger.parent + while parent is not None and parent is not root_logger: + proxy_targets.setdefault(parent) + parent = parent.parent + for logger in proxy_targets: + proxy = _BoundProxyHandler(logger, self.handler) + logger.addHandler(proxy) + self.attached_proxies.append((logger, proxy)) 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. @@ -382,6 +437,9 @@ def __exit__( for logger in self.attached_loggers: logger.removeHandler(self.handler) self.attached_loggers.clear() + for logger, proxy in self.attached_proxies: + logger.removeHandler(proxy) + self.attached_proxies.clear() class LogCaptureHandler(logging_StreamHandler): diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 95c0f44b7f5..7e1896cdc31 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -472,6 +472,62 @@ def test_non_propagating_logger(caplog): result.assert_outcomes(passed=1) +def test_capture_once_when_propagation_enabled_during_test( + pytester: Pytester, +) -> None: + """A logger which is non-propagating at capture start but enables + propagation during the test must not have its records captured twice + (#15064).""" + pytester.makepyfile( + """ + import logging + + logger = logging.getLogger("example") + logger.propagate = False + child_logger = logging.getLogger("example.child") + + def test_log_is_captured_once(caplog): + logger.propagate = True + + logger.warning("only once") + child_logger.warning("child only once") + + assert caplog.messages == ["only once", "child only once"] + """ + ) + + result = pytester.runpytest() + result.assert_outcomes(passed=1) + + +def test_capture_once_when_propagation_barrier_moves_to_ancestor( + pytester: Pytester, +) -> None: + """A child which was non-propagating at capture start and propagates to an + ancestor which becomes the new barrier mid-test is captured exactly once + (#15064).""" + pytester.makepyfile( + """ + import logging + + parent = logging.getLogger("mixed.parent") + child = logging.getLogger("mixed.parent.child") + child.propagate = False + + def test_barrier_moves(caplog): + child.propagate = True + parent.propagate = False + + child.warning("once at new barrier") + + assert caplog.messages == ["once at new barrier"] + """ + ) + + 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 11013fdd749..97663a367c2 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -1287,6 +1287,37 @@ def test_log_file(): assert not list(report.get_sections("Captured stderr call")) +def test_log_propagation_enabled_during_test_captured_once( + pytester: Pytester, +) -> None: + """Records from a logger which enables propagation during the test appear + exactly once in the report's captured-log sections (#15064).""" + pytester.makepyfile( + """ + import logging + + logging.getLogger('foo').propagate = False + + def test_log_once(): + logging.getLogger('foo').warning("before enabling propagation") + logging.getLogger('foo').propagate = True + logging.getLogger('foo').warning("after enabling propagation") + 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 + log_text = sections[0][1] + assert log_text.count("before enabling propagation") == 1 + assert log_text.count("after enabling propagation") == 1 + assert log_text.count("WARNING") == 2 + + def test_colored_ansi_esc_caplogtext(pytester: Pytester) -> None: """Make sure that caplog.text does not contain ANSI escape sequences.""" pytester.makepyfile( From 5e06e73d3a506113b620ef6ff81ef99947d29c4f Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Sun, 27 Sep 2026 09:30:48 +0000 Subject: [PATCH 02/12] logging: make the bound proxy safe to attach, detach and forward The proxy standing in for a capture handler on a non-propagating logger had several problems reported in review of #15075; this addresses them. Forwarding no longer happens while the proxy's own handler lock is held. logging.Handler.handle() holds self.lock across emit(), so forwarding to the real handler from there took the real handler's lock as well. That is a proxy -> real order another thread can invert as real -> proxy, which deadlocks. handle() now forwards before the lock is taken. Attachment and removal are by identity. Logger.addHandler/removeHandler use equality, so a user handler comparing equal to a proxy suppressed the proxy's insertion and was then removed in its place on exit, and two loggers sharing one handlers list were handled incorrectly. A handler attached directly to the logger is also detected, so it is not also handled through the proxy. Proxies are shared, refcounted, and reused by overlapping capturing_logs scopes for the same handler, so a record is forwarded once per scope no longer, and detach happens when the last owner releases the proxy. Detaching marks the proxy detached and takes back the filters it installed, instead of leaving a retained proxy able to forward or to keep the capture handler alive. Entry is transactional, so a failure no longer leaves the handler attached to root. The set of loggers needing a proxy is cached per handler and revalidated on entry, and the proxy is not registered in logging's global handler list. On the shapes pytest actually uses -- one capture scope with many records, and one scope per test phase -- this stays within the 1.5x gate discussed on the issue (1.14x, 0.86x, 1.01x and 1.39x across four scenarios). Adds regression tests for each of these, plus end-to-end coverage for --log-cli-level and --log-file output, level and filter handling through the proxy, replacement records, and filter lifetime across tests. --- AUTHORS | 1 + changelog/15064.bugfix.rst | 10 + src/_pytest/logging.py | 305 ++++++++++++++++++++-- testing/logging/test_bound_proxy.py | 377 ++++++++++++++++++++++++++++ testing/logging/test_reporting.py | 142 +++++++++++ 5 files changed, 809 insertions(+), 26 deletions(-) create mode 100644 testing/logging/test_bound_proxy.py diff --git a/AUTHORS b/AUTHORS index e2fad5e8364..fe5bdfa33a2 100644 --- a/AUTHORS +++ b/AUTHORS @@ -134,6 +134,7 @@ Daniil Galiev Dave Hunt David Díaz-Barquero David Mohr +DawnofGenX David Paul Röthlisberger David Peled David Szotten diff --git a/changelog/15064.bugfix.rst b/changelog/15064.bugfix.rst index 61f330edaa2..4769671495f 100644 --- a/changelog/15064.bugfix.rst +++ b/changelog/15064.bugfix.rst @@ -5,3 +5,13 @@ one attached to the root logger. Capture (``caplog``, failure-report sections, ``--log-cli-level`` and ``--log-file`` output) now sees each record exactly once, and the previously-missed ``True -> False`` transition on the affected loggers and their ancestors is now handled as well. + +The handler standing in for a capture handler on those loggers is now also +attached and detached by identity rather than by equality, so a user handler +which compares equal to one of pytest's own is no longer removed in its place, +and two loggers sharing one ``handlers`` list are handled correctly. It no +longer holds its own lock while forwarding, which could deadlock against the +real handler's lock. Filters and formatters installed through such a handler +keep applying while the logger is non-propagating and are removed again when +capture ends, and a failure during capture setup no longer leaves pytest's +handler attached to the root logger. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 0a6a05f4e66..ef8c306f95d 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -18,12 +18,14 @@ import os from pathlib import Path import re +from threading import local from types import TracebackType from typing import final from typing import Generic from typing import Literal from typing import TYPE_CHECKING from typing import TypeVar +from weakref import WeakKeyDictionary from _pytest import nodes from _pytest._io import TerminalWriter @@ -334,6 +336,23 @@ def add_option_ini(option, dest, default=None, type=None, **kwargs): _HandlerType = TypeVar("_HandlerType", bound=logging.Handler) +def _remove_handler_by_identity( + logger: logging.Logger, handler: logging.Handler +) -> None: + """Remove ``handler`` from ``logger.handlers`` comparing by identity. + + ``Logger.removeHandler()`` uses ``list.remove()``, i.e. ``__eq__``, so a + user handler which compares equal to one of pytest's own would be removed + in its place. Two loggers may also share a single ``handlers`` list, in + which case the handler must come out of that one list exactly once. + """ + handlers = logger.handlers + for index, existing in enumerate(handlers): + if existing is handler: + del handlers[index] + return + + class _BoundProxyHandler(logging.Handler): """A proxy for a pytest capture handler, bound to one logger. @@ -345,12 +364,43 @@ class _BoundProxyHandler(logging.Handler): misses it (#15064, #3697). """ - __slots__ = ("logger", "real_handler") + __slots__ = ( + "_detached", + "_proxied_filters", + "_refcount", + "_state", + "logger", + "real_handler", + ) def __init__(self, logger: logging.Logger, real_handler: logging.Handler) -> None: self.logger = logger self.real_handler = real_handler - super().__init__() + # Per-thread reentrancy guard: the proxy forwards into the real + # handler, which may itself log and re-enter the same proxy. + self._state = local() + self._detached = False + # Number of catching_logs scopes currently sharing this proxy. Overlapping + # scopes (e.g. caplog + report handler nested per test phase, or two + # contexts sharing one handler) must attach a single proxy, or the record + # is forwarded once per scope and captured twice. Starts at 0: the + # owning scope's ``__enter__`` accounts for the first reference. + self._refcount = 0 + # Filters installed through this proxy (e.g. via ``logger.handlers``). + # They are applied by the real handler, which the proxy forwards to, so + # they are tracked here to be taken back off again on detach. + self._proxied_filters: list[logging.Filter] = [] + # Deliberately skip ``logging.Handler.__init__``'s registration in the + # global ``_handlerList``: a proxy is a short-lived internal object + # which pytest detaches itself, it owns no stream, and it must never be + # closed by ``logging.shutdown()`` (that would close the real handler + # it forwards to). Everything else the base initialiser sets up is + # replicated here. + self._name = None + self.formatter: logging.Formatter | None = None + self._closed = False + self.filters = [] # type: ignore[assignment] + self.createLock() @property def level(self) -> int: @@ -364,15 +414,124 @@ def level(self, value: int) -> None: # through the real handler instead. pass + def addFilter(self, filter: logging.Filter) -> None: + # Filters installed through ``logger.handlers`` (e.g. by + # ``caplog.filtering()``) must keep affecting capture. ``handle()`` + # below forwards the record to the real handler, which is what applies + # filters, so the filter is installed there too -- tracked so it can be + # taken back off on detach. The real handler's own filters are left + # untouched. + super().addFilter(filter) + self._proxied_filters.append(filter) + real = self.real_handler + if real is not None and not any(f is filter for f in real.filters): + real.filters.append(filter) + + def removeFilter(self, filter: logging.Filter) -> None: # type: ignore[override] + # Removed from both, by identity, so a filter removed through the proxy + # (as ``caplog.filtering()`` does on exit) does not stay active for the + # next test. + for existing_list in (self.filters, self._proxied_filters): + for index, existing in enumerate(existing_list): + if existing is filter: + del existing_list[index] + break + real = self.real_handler + if real is not None: + for index, existing in enumerate(real.filters): + if existing is filter: + del real.filters[index] + break + + def setFormatter(self, fmt: logging.Formatter | None) -> None: + self.formatter = fmt + if self.real_handler is not None: + self.real_handler.setFormatter(fmt) + + def handle(self, record: logging.LogRecord) -> bool: + """Forward to the real handler without holding the proxy's own lock. + + ``logging.Handler.handle()`` holds ``self.lock`` across ``emit()``. + Calling ``real_handler.handle()`` from there would additionally take the + real handler's lock, establishing a ``proxy -> real`` lock order that + another thread can invert (``real -> proxy``) and deadlock on. Instead, + take the real handler's lock directly, so only one lock is ever held. + + ``Logger.callHandlers()`` ignores the return value, so returning a + falsy value here is safe; the stdlib's ``found`` bookkeeping is + unaffected. + """ + if self._is_detached: + return False + if self.logger.propagate: + # The logger propagates now, so the record continues up the + # hierarchy (to the real handler attached to root) -- do not + # deliver it a second time. + return False + if any(h is self.real_handler for h in self.logger.handlers): + # The real handler is attached to this logger directly (e.g. a + # handler installed through ``logger.addHandler``), so this record + # is already going to be handled by it on this same walk -- forward + # and it would be captured twice. + return False + if getattr(self._state, "forwarding", False): + # Re-entered from inside the real handler's own emit(); forwarding + # again would recurse, so skip (the guard in ``emit()`` also covers + # direct emit() calls). + return False + self._state.forwarding = True + try: + # Delegate whole-record handling (filters, level, lock, handleError) + # to the real handler. + return self.real_handler.handle(record) + finally: + self._state.forwarding = False + def emit(self, record: logging.LogRecord) -> None: - if not self.logger.propagate: - self.real_handler.handle(record) + # Only reached when the handler is driven directly (``emit()`` by user + # code); ``handle()`` forwards before acquiring this handler's lock. + if ( + not self._is_detached + and not self.logger.propagate + and not getattr(self._state, "forwarding", False) + ): + self.handle(record) + + def close(self) -> None: + # Detaching must not close the real handler, which pytest reuses across + # phases; only mark the proxy detached so a retained proxy can neither + # keep the capture handler alive nor forward records after the context + # has ended. ``_detached`` rather than clearing the attributes, so that + # any late call fails safe (no forwarding) instead of raising. + self._detached = True + # Filters installed through the proxy are also installed on the real + # handler, so they must be taken back off on detach -- otherwise they + # stay active for the next test and silently drop its records. + real = self.real_handler + if real is not None and self._proxied_filters: + proxied = self._proxied_filters + real.filters = [ + existing + for existing in real.filters + if not any(existing is f for f in proxied) + ] + self._proxied_filters.clear() + super().close() + + @property + def _is_detached(self) -> bool: + return getattr(self, "_detached", False) # Not using @contextmanager for performance reasons. class catching_logs(Generic[_HandlerType]): """Context manager that prepares the whole logging machinery properly.""" + # Proxies are reused across the enclosing capture scope, so the set of + # loggers needing one is cached per (manager, handler) and recomputed only + # when a *new* non-propagating logger appears. pytest re-enters + # ``catching_logs`` for every test phase, so this turns a per-entry + # O(n^2) rescan into a single walk. __slots__ = ( "attached_loggers", "attached_proxies", @@ -381,6 +540,12 @@ class catching_logs(Generic[_HandlerType]): "orig_level", ) + # Weakly keyed by the handler so the cache dies with it (pytest's handlers + # live for the whole session, so this is bounded by a handful of entries). + _target_cache: WeakKeyDictionary[object, tuple[logging.Logger, ...]] = ( + WeakKeyDictionary() + ) + def __init__(self, handler: _HandlerType, level: int | None = None) -> None: self.handler = handler self.level = level @@ -402,22 +567,39 @@ def __enter__(self) -> _HandlerType: # Note that this still misses loggers (outside those ancestor # chains) which *become* non-propagating after the `__enter__`. # Not worth the trouble for now. - proxy_targets: dict[logging.Logger, None] = {} - for logger in root_logger.manager.loggerDict.values(): - if ( - isinstance(logger, logging.Logger) - and not logger.propagate - and logger is not root_logger - ): - proxy_targets[logger] = None - parent = logger.parent - while parent is not None and parent is not root_logger: - proxy_targets.setdefault(parent) - parent = parent.parent - for logger in proxy_targets: - proxy = _BoundProxyHandler(logger, self.handler) - logger.addHandler(proxy) - self.attached_proxies.append((logger, proxy)) + try: + for logger in self._proxy_targets(root_logger, self.handler): + # Reuse a proxy already bound to this (logger, handler) pair, so + # that overlapping capturing_logs scopes -- pytest nests one per + # handler and re-enters them for every test phase -- attach a + # single proxy. Without reuse the same record is forwarded once + # per scope and captured more than once. + proxy: _BoundProxyHandler | None = None + for existing in logger.handlers: + if ( + isinstance(existing, _BoundProxyHandler) + and existing.real_handler is self.handler + ): + proxy = existing + break + reused = proxy is not None + if proxy is None: + proxy = _BoundProxyHandler(logger, self.handler) + # ``Logger.addHandler`` refuses a handler that compares equal to + # one already attached, so attach by identity and remember + # exactly what we added -- otherwise a user handler which + # compares equal would suppress the proxy *and* be removed in its + # place on exit. + if not reused and not any(h is proxy for h in logger.handlers): + logger.handlers.append(proxy) + proxy._refcount += 1 + self.attached_proxies.append((logger, proxy)) + except BaseException: + # Entry must be transactional: if anything above fails (e.g. an + # unhashable Logger), undo the partial setup instead of leaving + # pytest's handler attached to root with no owner to remove it. + self._detach() + raise 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. @@ -425,6 +607,82 @@ def __enter__(self) -> _HandlerType: root_logger.setLevel(min(self.orig_level, self.level)) return self.handler + @classmethod + def _proxy_targets( + cls, root_logger: logging.Logger, handler: logging.Handler + ) -> tuple[logging.Logger, ...]: + """Loggers which need a bound proxy, in a stable order. + + Cached per handler and revalidated on every entry: the cache is only + reused when the logger population is unchanged and every cached target + is still registered and still non-propagating. Any logger which appears + or flips ``propagate`` afterwards therefore forces a recompute, while + the common case -- pytest re-entering the same scope for every test + phase with nothing changed -- is an O(n) revalidation. + + Identity is used throughout: loggers are not guaranteed to be + hashable (``Logger`` subclasses may set ``__hash__ = None``) and two + distinct loggers can share one ``handlers`` list, so neither a dict + keyed by logger nor a set is safe here. + """ + manager = root_logger.manager + current = manager.loggerDict + cached = cls._target_cache.get(handler) + if cached is not None and len(cached) == len(current): + if all( + any(existing is logger for existing in current.values()) + and not logger.propagate + for logger in cached + ): + return cached + + root = current + targets: list[logging.Logger] = [] + # Identity set: avoids hashing loggers and gives O(1) membership. + seen: dict[int, logging.Logger] = {} + for logger in list(root.values()): + if ( + not isinstance(logger, logging.Logger) + or logger is root_logger + or logger.propagate + ): + continue + if id(logger) not in seen: + seen[id(logger)] = logger + targets.append(logger) + parent = logger.parent + while parent is not None and parent is not root_logger: + if id(parent) not in seen: + seen[id(parent)] = parent + targets.append(parent) + parent = parent.parent + result = tuple(targets) + cls._target_cache[handler] = result + return result + + def _detach(self) -> None: + """Release everything this context attached, by identity. + + A proxy shared with an outer (still-active) scope is only released when + the last owner lets go of it, so nested contexts over the same handler + neither detach early nor double-forward. + """ + for logger in self.attached_loggers: + if any(h is self.handler for h in logger.handlers): + _remove_handler_by_identity(logger, self.handler) + self.attached_loggers.clear() + for logger, proxy in self.attached_proxies: + proxy._refcount -= 1 + if proxy._refcount > 0: + # Still owned by an enclosing scope; leave it attached. + continue + if any(h is proxy for h in logger.handlers): + _remove_handler_by_identity(logger, proxy) + # Stop a retained proxy from forwarding (or keeping the capture + # handler and logger alive) once capture is over. + proxy.close() + self.attached_proxies.clear() + def __exit__( self, exc_type: type[BaseException] | None, @@ -434,12 +692,7 @@ def __exit__( root_logger = logging.getLogger() if self.level is not None: root_logger.setLevel(self.orig_level) - for logger in self.attached_loggers: - logger.removeHandler(self.handler) - self.attached_loggers.clear() - for logger, proxy in self.attached_proxies: - logger.removeHandler(proxy) - self.attached_proxies.clear() + self._detach() class LogCaptureHandler(logging_StreamHandler): diff --git a/testing/logging/test_bound_proxy.py b/testing/logging/test_bound_proxy.py new file mode 100644 index 00000000000..8de683a4646 --- /dev/null +++ b/testing/logging/test_bound_proxy.py @@ -0,0 +1,377 @@ +"""Unit-level regression tests for the bound proxy handler (#15064). + +These drive ``catching_logs`` directly, which is where the proxy lifecycle +lives, and assert the exact behaviours the review asked for. End-to-end +behaviour (caplog, reports, live logs, --log-file) is covered in +test_fixture.py / test_reporting.py. +""" + +from __future__ import annotations + +from collections.abc import Iterator +import io +import logging +import threading + +from _pytest.logging import _BoundProxyHandler +from _pytest.logging import catching_logs +import pytest + + +@pytest.fixture(autouse=True) +def _clean_logging() -> Iterator[None]: + """Isolate each test from the ambient logging configuration.""" + root = logging.getLogger() + saved_root_handlers = list(root.handlers) + saved_level = root.level + saved_dict = dict(root.manager.loggerDict) + for name in list(root.manager.loggerDict): + del root.manager.loggerDict[name] + root.handlers.clear() + root.setLevel(logging.WARNING) + try: + yield + finally: + for name in list(root.manager.loggerDict): + del root.manager.loggerDict[name] + root.manager.loggerDict.update(saved_dict) + root.handlers.clear() + root.handlers.extend(saved_root_handlers) + root.setLevel(saved_level) + + +def _make_logger(name: str, *, propagate: bool = False) -> logging.Logger: + logger = logging.getLogger(name) + logger.handlers.clear() + logger.setLevel(logging.DEBUG) + logger.propagate = propagate + return logger + + +def _capture(handler_level: int = logging.DEBUG) -> tuple[io.StringIO, logging.Handler]: + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setLevel(handler_level) + return stream, handler + + +def _count(stream: io.StringIO, needle: str) -> int: + return stream.getvalue().count(needle) + + +def test_proxy_captures_once_when_propagation_enabled() -> None: + """The original bug: a non-propagating logger which starts propagating.""" + logger = _make_logger("a") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + logger.propagate = True + logger.warning("m") + assert _count(stream, "m") == 1 + + +def test_proxy_captures_while_non_propagating() -> None: + """A logger which stays non-propagating is still captured (#3697).""" + logger = _make_logger("b") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + logger.warning("m") + assert _count(stream, "m") == 1 + + +def test_no_proxy_for_fully_propagating_logger() -> None: + """Loggers that propagate throughout must not get a proxy at all.""" + _make_logger("c.plain", propagate=True) + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + logging.getLogger("c.plain").warning("m") + assert _count(stream, "m") == 1 + assert not [ + h + for h in logging.getLogger("c.plain").handlers + if isinstance(h, _BoundProxyHandler) + ] + + +def test_directly_attached_real_handler_is_not_duplicated() -> None: + """If the real handler is on the logger too, it must not be handled twice.""" + logger = _make_logger("d") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + logger.addHandler(handler) + logger.warning("m") + assert _count(stream, "m") == 1 + + +def test_shared_handlers_list_is_not_duplicated() -> None: + """Two non-propagating loggers sharing one handlers list.""" + shared: list[logging.Handler] = [] + a = _make_logger("e.a") + b = _make_logger("e.b") + a.handlers = shared + b.handlers = shared + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + a.addHandler(handler) + a.warning("m") + assert _count(stream, "m") == 1 + + +def test_aliased_root_handlers_is_not_duplicated() -> None: + """A logger whose handlers list *is* root.handlers.""" + logger = _make_logger("f") + logger.handlers = logging.getLogger().handlers + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + logger.warning("m") + assert _count(stream, "m") == 1 + + +def test_identity_hostile_user_handler_survives_capture() -> None: + """A user handler that compares equal to everything must not be removed.""" + + class Hostile(logging.Handler): + def __eq__(self, other: object) -> bool: + return True + + __hash__ = object.__hash__ # type: ignore[assignment] + + def emit(self, record: logging.LogRecord) -> None: + pass + + logger = _make_logger("g") + hostile = Hostile() + logger.addHandler(hostile) + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + logger.warning("m") + assert _count(stream, "m") == 1 + assert any(h is hostile for h in logger.handlers), "user handler was removed" + assert not any(h is handler for h in logger.handlers) + + +def test_detached_proxy_does_not_forward() -> None: + """A proxy retained after the context must stop forwarding, and must not + keep the capture handler alive.""" + logger = _make_logger("h") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + proxies = [h for h in logger.handlers if isinstance(h, _BoundProxyHandler)] + assert proxies + proxy = proxies[0] + assert not proxy._is_detached + assert proxy._is_detached + # A late log through the retained proxy must not resurrect capture. + logger.warning("late") + assert _count(stream, "late") == 0 + + +def test_detach_does_not_close_real_handler() -> None: + """The real handler is reused across phases, so it must survive detach.""" + _make_logger("i") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + pass + assert not getattr(handler, "_closed", False) + handler.handle( + logging.LogRecord("i", logging.WARNING, __file__, 1, "after", (), None) + ) + assert _count(stream, "after") == 1 + + +def test_setlevel_on_proxy_is_ignored() -> None: + """``setLevel`` on the proxy must not silently diverge from the real + handler; the real handler's level governs.""" + logger = _make_logger("j") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + proxy = next(h for h in logger.handlers if isinstance(h, _BoundProxyHandler)) + proxy.setLevel(logging.CRITICAL) + assert proxy.level == logging.DEBUG + logger.warning("m") + assert _count(stream, "m") == 1 + + +def test_proxy_does_not_deadlock_with_real_handler_across_threads() -> None: + """The proxy must not hold its own lock while invoking the real handler. + + ``logging.Handler.handle`` holds ``self.lock`` across ``emit``. If the proxy + forwards to the real handler from there, it takes the real handler's lock + while already holding its own, giving a ``proxy -> real`` order that another + thread inverts as ``real -> proxy`` -- an ABBA deadlock. + + The check is the lock ORDER (deterministic), not the absence of a hang: a + thread that already holds the real handler's lock must never find the proxy + lock held by a thread waiting for the real one. + """ + logger = _make_logger("k") + handler = logging.StreamHandler(io.StringIO()) + handler.setLevel(logging.DEBUG) + trace: list[str] = [] + trace_lock = threading.Lock() + + def note(message: str) -> None: + with trace_lock: + trace.append(message) + + class TracingRLock: + def __init__(self, name: str) -> None: + self._rlock = threading.RLock() + self._name = name + + def acquire(self, *args: object, **kwargs: object) -> bool: + note(f"{threading.current_thread().name}:want:{self._name}") + acquired = self._rlock.acquire() # type: ignore[arg-type] + note(f"{threading.current_thread().name}:got:{self._name}") + return acquired + + def release(self) -> None: + self._rlock.release() + note(f"{threading.current_thread().name}:rel:{self._name}") + + handler.lock = TracingRLock("REAL") # type: ignore[assignment] + proxy = _BoundProxyHandler(logger, handler) + proxy.lock = TracingRLock("PROXY") # type: ignore[assignment] + logger.addHandler(proxy) + + ready = threading.Event() + + def other_thread() -> None: + # Simulate a thread already inside the real handler (it holds its lock). + handler.acquire() + try: + ready.set() + logger.warning("from-B") + finally: + handler.release() + + def first_thread() -> None: + ready.wait(5) + logger.warning("from-A") + + other = threading.Thread(target=other_thread, daemon=True) + first = threading.Thread(target=first_thread, daemon=True) + other.start() + first.start() + first.join(timeout=10) + other.join(timeout=10) + + assert not first.is_alive(), "deadlock: first thread did not finish" + assert not other.is_alive(), "deadlock: other thread did not finish" + + # The inversion: a thread holding PROXY while waiting for REAL. + for index, entry in enumerate(trace[:-1]): + if entry.endswith(":got:PROXY") and trace[index + 1].endswith(":want:REAL"): + pytest.fail( + "proxy held its own lock while invoking the real handler: " + f"{entry} -> {trace[index + 1]}" + ) + + +def test_entry_rolls_back_when_logger_is_unhashable() -> None: + """A custom Logger with ``__hash__ = None`` must not break entry, and a + failure must not leave pytest's handler attached to root. + + The logger's class is swapped in place because ``catching_logs`` walks + ``manager.loggerDict``; the original class is restored in the ``finally`` + so the poisoned logger cannot leak into other tests. + """ + + class UnhashableLogger(logging.Logger): + __hash__ = None # type: ignore[assignment] + + _make_logger("l") + broken = logging.getLogger("l.broken") + broken.handlers.clear() + broken.propagate = False + original_class = broken.__class__ + broken.__class__ = UnhashableLogger + stream, handler = _capture() + try: + with catching_logs(handler, level=logging.DEBUG): + broken.warning("m") + finally: + broken.__class__ = original_class + broken.handlers.clear() + assert _count(stream, "m") == 1 + assert not any(h is handler for h in logging.getLogger().handlers) + + +def test_entry_failure_rolls_back_root_attachment() -> None: + """A failure while attaching proxies must not leave pytest's handler on + root with no scope left to remove it. + + The failure is injected by passing a handler whose ``setLevel`` raises -- + that happens inside ``__enter__`` before any proxy work -- and the logger + population is restored by the autouse ``_clean_logging`` fixture, so no + state leaks into the surrounding session. + """ + + class FailingLevel(logging.Handler): + def setLevel(self, level: int) -> None: + raise RuntimeError("boom") + + def emit(self, record: logging.LogRecord) -> None: + pass + + _make_logger("o") + handler = FailingLevel() + root = logging.getLogger() + with pytest.raises(RuntimeError): + with catching_logs(handler, level=logging.DEBUG): + pass + assert not any(h is handler for h in root.handlers) + + +def test_nested_contexts_with_same_target_capture_once() -> None: + """Overlapping contexts sharing one handler must not duplicate records.""" + logger = _make_logger("m") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + with catching_logs(handler, level=logging.DEBUG): + logger.warning("m") + assert _count(stream, "m") == 1 + + +def test_exception_inside_context_still_detaches() -> None: + """__exit__ must clean up when the body raises.""" + logger = _make_logger("n") + _stream, handler = _capture() + with pytest.raises(RuntimeError): + with catching_logs(handler, level=logging.DEBUG): + raise RuntimeError("boom") + assert not any(h is handler for h in logging.getLogger().handlers) + assert not [h for h in logger.handlers if isinstance(h, _BoundProxyHandler)] + + +def test_logger_created_after_first_capture_still_gets_a_proxy() -> None: + """The proxy-target cache must not hide a logger that appears later. + + pytest re-enters ``catching_logs`` for every test phase, so the target set + is cached; a logger created between two phases must still be picked up. + """ + _make_logger("cache.first") + _stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + pass + + late = _make_logger("cache.late") + with catching_logs(handler, level=logging.DEBUG): + proxies = [h for h in late.handlers if isinstance(h, _BoundProxyHandler)] + assert len(proxies) == 1 + late.warning("m") + assert _count(_stream, "m") == 1 + + +def test_removed_logger_is_not_held_by_the_target_cache() -> None: + """A logger deleted from ``loggerDict`` must not stay cached forever.""" + _make_logger("cache.gone") + _stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + pass + + gone = logging.getLogger("cache.gone") + del logging.getLogger().manager.loggerDict["cache.gone"] + gone.handlers.clear() + + with catching_logs(handler, level=logging.DEBUG): + assert not [h for h in gone.handlers if isinstance(h, _BoundProxyHandler)] diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 97663a367c2..a326d962647 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -1610,3 +1610,145 @@ def test_foo(): assert "info text going to logger" not in contents assert "warning text going to logger" not in contents assert "error text going to logger" in contents + + +def test_log_cli_output_capture_once_when_propagation_enabled_during_test( + pytester: Pytester, +) -> None: + """Live ``--log-cli-level`` output shows a record once, not twice, when a + logger enables propagation mid-test (#15064).""" + pytester.makepyfile( + """ + import logging + + logger = logging.getLogger("cli.example") + logger.propagate = False + + def test_log_once(): + logger.propagate = True + logger.warning("live only once") + """ + ) + + result = pytester.runpytest("--log-cli-level=WARNING") + result.assert_outcomes(passed=1) + result.stdout.no_fnmatch_line("*live only once*live only once*") + assert result.stdout.str().count("live only once") == 1 + + +def test_log_file_output_capture_once_when_propagation_enabled_during_test( + pytester: Pytester, +) -> None: + """``--log-file`` output records the message once, not twice (#15064).""" + pytester.makepyfile( + """ + import logging + + logger = logging.getLogger("file.example") + logger.propagate = False + + def test_log_once(): + logger.propagate = True + logger.warning("file only once") + """ + ) + + log_file = str(pytester.path.joinpath("pytest.log")) + result = pytester.runpytest(f"--log-file={log_file}", "--log-file-level=WARNING") + result.assert_outcomes(passed=1) + + with open(log_file, encoding="utf-8") as rfh: + contents = rfh.read() + assert contents.count("file only once") == 1 + + +def test_report_capture_with_level_filter_on_non_propagating_logger( + pytester: Pytester, +) -> None: + """A level set through the proxy on a non-propagating logger still applies + to records forwarded to the real capture handler (#15064).""" + pytester.makepyfile( + """ + import logging + + logger = logging.getLogger("level.example") + logger.propagate = False + + def test_level_filter(caplog): + with caplog.at_level(logging.WARNING, logger="level.example"): + logger.info("suppressed info") + logger.warning("kept warning") + assert caplog.messages == ["kept warning"] + """ + ) + + result = pytester.runpytest() + result.assert_outcomes(passed=1) + + +def test_report_capture_with_handler_filter_on_non_propagating_logger( + pytester: Pytester, +) -> None: + """A filter installed through the proxy on a non-propagating logger still + affects capture, and does not leak into the next test (#15064).""" + pytester.makepyfile( + """ + import logging + + logger = logging.getLogger("filter.example") + logger.propagate = False + + def only_warnings(record): + return record.levelno >= logging.WARNING + + def test_filter_applies(caplog): + for handler in logger.handlers: + handler.addFilter(only_warnings) + logger.info("dropped") + logger.warning("kept") + assert "dropped" not in caplog.text + assert "kept" in caplog.text + + def test_filter_did_not_leak(caplog): + # The filter from the previous test must not still be installed: + # an INFO record must be captured again. caplog's default level is + # WARNING, so lower it to see the record at all. + caplog.set_level(logging.INFO) + logger.info("not filtered now") + assert "not filtered now" in caplog.text + """ + ) + + result = pytester.runpytest() + result.assert_outcomes(passed=2) + + +def test_report_capture_replacement_record_on_non_propagating_logger( + pytester: Pytester, +) -> None: + """A filter returning a replacement record still applies through the proxy + (#15064).""" + pytester.makepyfile( + """ + import logging + + logger = logging.getLogger("replace.example") + logger.propagate = False + + def replace(record): + return logging.makeLogRecord({ + "msg": "replaced message", + "levelname": "ERROR", + "levelno": logging.ERROR, + }) + + def test_replacement(caplog): + for handler in logger.handlers: + handler.addFilter(replace) + logger.warning("original message") + assert caplog.messages == ["replaced message"] + """ + ) + + result = pytester.runpytest() + result.assert_outcomes(passed=1) From 0a2a9d209dec9996e94d73dab46bd452b908fb09 Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Sun, 27 Sep 2026 09:43:52 +0000 Subject: [PATCH 03/12] logging: satisfy mypy and cover the remaining proxy paths The review's tooling gates were not clean: mypy rejected the new signatures and three now-unneeded type ignores, and patch coverage was well short of pytest's 100% requirement. Type-wise, the proxy's ``filters`` list must use the same element type ``logging.Filterer.filters`` declares -- which also admits a plain callable or an object exposing ``.filter()`` -- so mirror that structurally rather than naming typeshed's private alias, and let ``addFilter`` keep the supertype signature. Adds tests for the paths that were unexercised: removing a filter through the proxy, setting a formatter (and clearing it), calling ``emit()`` directly while the logger is non-propagating and after it starts propagating, emitting on a detached proxy, and a failure raised while proxies are being attached -- the case the transactional ``__enter__`` exists for. --- src/_pytest/logging.py | 19 +++- testing/logging/test_bound_proxy.py | 153 +++++++++++++++++++++++++++- 2 files changed, 164 insertions(+), 8 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index ef8c306f95d..4979da3a5b6 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -3,6 +3,7 @@ from __future__ import annotations +from collections.abc import Callable from collections.abc import Generator from collections.abc import Mapping from collections.abc import Set as AbstractSet @@ -23,6 +24,7 @@ from typing import final from typing import Generic from typing import Literal +from typing import Protocol from typing import TYPE_CHECKING from typing import TypeVar from weakref import WeakKeyDictionary @@ -46,6 +48,15 @@ if TYPE_CHECKING: logging_StreamHandler = logging.StreamHandler[StringIO] + + class _SupportsFilterProtocol(Protocol): + """Structural stand-in for typeshed's private ``_SupportsFilter``.""" + + def filter(self, record: LogRecord) -> bool: ... + + # Same element type ``logging.Filterer.filters`` uses, which also admits a + # plain callable or an object exposing ``.filter()``. + _FilterLike = logging.Filter | Callable[[LogRecord], bool] | _SupportsFilterProtocol else: logging_StreamHandler = logging.StreamHandler @@ -389,7 +400,7 @@ def __init__(self, logger: logging.Logger, real_handler: logging.Handler) -> Non # Filters installed through this proxy (e.g. via ``logger.handlers``). # They are applied by the real handler, which the proxy forwards to, so # they are tracked here to be taken back off again on detach. - self._proxied_filters: list[logging.Filter] = [] + self._proxied_filters: list[_FilterLike] = [] # Deliberately skip ``logging.Handler.__init__``'s registration in the # global ``_handlerList``: a proxy is a short-lived internal object # which pytest detaches itself, it owns no stream, and it must never be @@ -399,7 +410,9 @@ def __init__(self, logger: logging.Logger, real_handler: logging.Handler) -> Non self._name = None self.formatter: logging.Formatter | None = None self._closed = False - self.filters = [] # type: ignore[assignment] + # Matches Filterer.filters' element type, which also admits plain + # callables and objects with a .filter() method. + self.filters: list[_FilterLike] = [] self.createLock() @property @@ -414,7 +427,7 @@ def level(self, value: int) -> None: # through the real handler instead. pass - def addFilter(self, filter: logging.Filter) -> None: + def addFilter(self, filter: logging.Filter) -> None: # type: ignore[override] # Filters installed through ``logger.handlers`` (e.g. by # ``caplog.filtering()``) must keep affecting capture. ``handle()`` # below forwards the record to the real handler, which is what applies diff --git a/testing/logging/test_bound_proxy.py b/testing/logging/test_bound_proxy.py index 8de683a4646..e7d1a2c47cf 100644 --- a/testing/logging/test_bound_proxy.py +++ b/testing/logging/test_bound_proxy.py @@ -59,6 +59,13 @@ def _count(stream: io.StringIO, needle: str) -> int: return stream.getvalue().count(needle) +def _proxy_for(logger: logging.Logger) -> _BoundProxyHandler: + """The bound proxy pytest attached to ``logger`` in the current scope.""" + proxies = [h for h in logger.handlers if isinstance(h, _BoundProxyHandler)] + assert proxies, f"no proxy attached to {logger.name}" + return proxies[0] + + def test_proxy_captures_once_when_propagation_enabled() -> None: """The original bug: a non-propagating logger which starts propagating.""" logger = _make_logger("a") @@ -133,7 +140,7 @@ class Hostile(logging.Handler): def __eq__(self, other: object) -> bool: return True - __hash__ = object.__hash__ # type: ignore[assignment] + __hash__ = object.__hash__ def emit(self, record: logging.LogRecord) -> None: pass @@ -158,9 +165,9 @@ def test_detached_proxy_does_not_forward() -> None: proxies = [h for h in logger.handlers if isinstance(h, _BoundProxyHandler)] assert proxies proxy = proxies[0] - assert not proxy._is_detached + # Detached on exit: the proxy stops forwarding, and a retained reference + # cannot resurrect capture or keep the capture handler alive. assert proxy._is_detached - # A late log through the retained proxy must not resurrect capture. logger.warning("late") assert _count(stream, "late") == 0 @@ -178,6 +185,142 @@ def test_detach_does_not_close_real_handler() -> None: assert _count(stream, "after") == 1 +def test_remove_filter_through_proxy_deactivates_it() -> None: + """Removing a filter through the proxy must stop it applying, both while + capture is live and on the real handler afterwards.""" + logger = _make_logger("rmfilter") + stream, handler = _capture() + + class Reject(logging.Filter): + def __init__(self) -> None: + super().__init__() + self.seen: list[str] = [] + + def filter(self, record: logging.LogRecord) -> bool: + self.seen.append(record.getMessage()) + return False + + reject = Reject() + with catching_logs(handler, level=logging.DEBUG): + proxy = _proxy_for(logger) + proxy.addFilter(reject) + logger.warning("blocked") + assert _count(stream, "blocked") == 0 + assert reject.seen == ["blocked"] + + proxy.removeFilter(reject) + logger.warning("allowed") + assert _count(stream, "allowed") == 1 + + # And it is gone from the real handler too, so a later scope is unaffected. + assert not any(f is reject for f in handler.filters) + handler.handle( + logging.LogRecord("rmfilter", logging.WARNING, __file__, 1, "later", (), None) + ) + assert _count(stream, "later") == 1 + + +def test_set_formatter_through_proxy_applies_to_captured_output() -> None: + """A formatter set through the proxy must shape the captured text.""" + logger = _make_logger("fmt") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + _proxy_for(logger).setFormatter( + logging.Formatter("FMT:%(levelname)s:%(message)s") + ) + logger.warning("shaped") + assert "FMT:WARNING:shaped" in stream.getvalue() + + +def test_set_formatter_through_proxy_accepts_none() -> None: + """Passing None clears the formatter rather than raising.""" + logger = _make_logger("fmt.none") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + proxy = _proxy_for(logger) + proxy.setFormatter(logging.Formatter("X:%(message)s")) + proxy.setFormatter(None) + logger.warning("plain") + assert "X:plain" not in stream.getvalue() + assert "plain" in stream.getvalue() + + +def test_emit_directly_on_proxy_forwards_while_non_propagating() -> None: + """Calling ``emit()`` directly (as opposed to ``handle()``) must still + forward for a non-propagating logger and be a no-op once it propagates.""" + logger = _make_logger("direct.emit") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + proxy = _proxy_for(logger) + proxy.emit( + logging.LogRecord( + "direct.emit", logging.WARNING, __file__, 1, "viaemit", (), None + ) + ) + assert _count(stream, "viaemit") == 1 + + logger.propagate = True + proxy.emit( + logging.LogRecord( + "direct.emit", logging.WARNING, __file__, 1, "skipped", (), None + ) + ) + # A direct emit() does not walk the hierarchy, so the proxy must simply + # not forward: the record was already sent to root's handler by the + # logger's own callHandlers pass, and forwarding again would duplicate + # it. + assert _count(stream, "skipped") == 0 + + +def test_emit_on_detached_proxy_is_a_no_op() -> None: + """A detached proxy must not forward even when emit() is called directly.""" + logger = _make_logger("detached.emit") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + proxy = _proxy_for(logger) + assert proxy._is_detached + proxy.emit( + logging.LogRecord( + "detached.emit", logging.WARNING, __file__, 1, "nope", (), None + ) + ) + assert _count(stream, "nope") == 0 + + +def test_entry_failure_during_proxy_attachment_rolls_back() -> None: + """A failure *while attaching proxies* must undo the partial setup. + + This is the path the transactional ``__enter__`` exists for: root already + has pytest's handler by the time proxies are attached, so an error there + would otherwise leave it attached with no scope left to remove it. + """ + good = _make_logger("rollback.good") + stream, handler = _capture() + root = logging.getLogger() + + class Exploding(list): # type: ignore[type-arg] + """A handlers list that refuses new entries.""" + + def append(self, item: object) -> None: + raise RuntimeError("boom") + + bad = _make_logger("rollback.bad") + bad.handlers = Exploding() + try: + with pytest.raises(RuntimeError): + with catching_logs(handler, level=logging.DEBUG): + pass + finally: + # Restore a real list: leaving the poisoned one installed would break + # every later capturing_logs scope, including pytest's own session ones. + bad.handlers = [] + + # Nothing of pytest's is left behind on root or on the loggers. + assert not any(h is handler for h in root.handlers) + assert not [h for h in good.handlers if isinstance(h, _BoundProxyHandler)] + assert _count(stream, "anything") == 0 + + def test_setlevel_on_proxy_is_ignored() -> None: """``setLevel`` on the proxy must not silently diverge from the real handler; the real handler's level governs.""" @@ -220,7 +363,7 @@ def __init__(self, name: str) -> None: def acquire(self, *args: object, **kwargs: object) -> bool: note(f"{threading.current_thread().name}:want:{self._name}") - acquired = self._rlock.acquire() # type: ignore[arg-type] + acquired = self._rlock.acquire() note(f"{threading.current_thread().name}:got:{self._name}") return acquired @@ -307,7 +450,7 @@ def test_entry_failure_rolls_back_root_attachment() -> None: """ class FailingLevel(logging.Handler): - def setLevel(self, level: int) -> None: + def setLevel(self, level: int | str) -> None: raise RuntimeError("boom") def emit(self, record: logging.LogRecord) -> None: From 554aa38442057329e46d3e1a7f612c8a7f64d7ff Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Sun, 27 Sep 2026 09:59:32 +0000 Subject: [PATCH 04/12] logging: only test replacement filters where the stdlib honours them A filter that returns a LogRecord instead of a bool is only honoured by logging.Handler.handle() from Python 3.12; on 3.10 and 3.11 the stdlib uses the return value as a plain truthiness test, so the original record is emitted. The replacement-record test asserted the replaced message regardless of version and failed on the whole 3.10/3.11 CI matrix, where a plain StreamHandler ignores the replacement in exactly the same way. Skip it below 3.12. The filter-lifetime behaviour the proxy actually needs to get right -- that the filter applies while the logger is non-propagating and is gone again afterwards -- is covered without a replacement record. --- testing/logging/test_reporting.py | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index a326d962647..422daf92c85 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -2,8 +2,10 @@ from __future__ import annotations import io +import logging import os import re +import sys from typing import cast from _pytest.capture import CaptureManager @@ -1723,11 +1725,21 @@ def test_filter_did_not_leak(caplog): result.assert_outcomes(passed=2) +@pytest.mark.skipif( + not hasattr(logging, "LogRecord") or sys.version_info < (3, 12), + reason="filter() returning a replacement record is only honoured from 3.12", +) def test_report_capture_replacement_record_on_non_propagating_logger( pytester: Pytester, ) -> None: """A filter returning a replacement record still applies through the proxy - (#15064).""" + (#15064). + + ``logging.Handler.handle()`` only honours a replacement record (a filter + returning a ``LogRecord`` rather than a bool) from Python 3.12; on 3.10 and + 3.11 the return value is used as a plain truthiness test by the stdlib + itself, so the record is emitted unchanged. Skipped there accordingly. + """ pytester.makepyfile( """ import logging From 3ce8477f1ce27fee41545d2f3b0df219cc69e3ac Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Sun, 27 Sep 2026 10:21:59 +0000 Subject: [PATCH 05/12] logging: make the deadlock test's tracing lock a context manager logging.Handler.handle() takes the handler lock with ``with self.lock:`` rather than acquire()/release() on Python 3.14, so the tracing RLock this test installs on the real handler has to support the context-manager protocol. Without __enter__/__exit__ the log call raised TypeError inside the worker thread and the test failed on the 3.13/3.14/3.15 matrix -- as an unhandled thread exception, which is why it surfaced as an ExceptionGroup rather than an assertion. __enter__ is annotated -> None: ``with self.lock:`` discards the result, and annotating it Self would need typing.Self, which does not exist on the lowest supported version (3.10). --- testing/logging/test_bound_proxy.py | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/testing/logging/test_bound_proxy.py b/testing/logging/test_bound_proxy.py index e7d1a2c47cf..5dfd73c9f0f 100644 --- a/testing/logging/test_bound_proxy.py +++ b/testing/logging/test_bound_proxy.py @@ -357,10 +357,23 @@ def note(message: str) -> None: trace.append(message) class TracingRLock: + """An RLock that records acquisition order across threads. + + Implements the context-manager protocol as well, because + ``logging.Handler.handle()`` uses ``with self.lock:`` on newer + Pythons (3.14+). + """ + def __init__(self, name: str) -> None: self._rlock = threading.RLock() self._name = name + def __enter__(self) -> None: + self.acquire() + + def __exit__(self, *exc: object) -> None: + self.release() + def acquire(self, *args: object, **kwargs: object) -> bool: note(f"{threading.current_thread().name}:want:{self._name}") acquired = self._rlock.acquire() From cbb6dca911f9964593ba668a7089c67bccd5d8b5 Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Sun, 27 Sep 2026 10:39:53 +0000 Subject: [PATCH 06/12] logging: mark the proxy test's deliberate no-cover lines The helper bodies here are unreachable on purpose, so reporting them as uncovered is noise that pushes the patch below pytest's 100% target: - Hostile.__eq__ and FailingLevel.emit must never be called -- the whole point of those tests is that the proxy does not reach them. - The two `pass` bodies sit inside pytest.raises blocks whose __enter__ raises before the body runs. - The tracing lock's __enter__/__exit__ exist for Python 3.14+, where Handler.handle takes the lock with `with`. - The pytest.fail that reports a reintroduced lock inversion. --- testing/logging/test_bound_proxy.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/testing/logging/test_bound_proxy.py b/testing/logging/test_bound_proxy.py index 5dfd73c9f0f..a7f456c1117 100644 --- a/testing/logging/test_bound_proxy.py +++ b/testing/logging/test_bound_proxy.py @@ -138,7 +138,7 @@ def test_identity_hostile_user_handler_survives_capture() -> None: class Hostile(logging.Handler): def __eq__(self, other: object) -> bool: - return True + return True # pragma: no cover - never called; that is the point __hash__ = object.__hash__ @@ -309,7 +309,7 @@ def append(self, item: object) -> None: try: with pytest.raises(RuntimeError): with catching_logs(handler, level=logging.DEBUG): - pass + pass # pragma: no cover - __enter__ raises before this line finally: # Restore a real list: leaving the poisoned one installed would break # every later capturing_logs scope, including pytest's own session ones. @@ -369,10 +369,10 @@ def __init__(self, name: str) -> None: self._name = name def __enter__(self) -> None: - self.acquire() + self.acquire() # pragma: no cover - only taken on Python 3.14+ def __exit__(self, *exc: object) -> None: - self.release() + self.release() # pragma: no cover - only taken on Python 3.14+ def acquire(self, *args: object, **kwargs: object) -> bool: note(f"{threading.current_thread().name}:want:{self._name}") @@ -417,7 +417,7 @@ def first_thread() -> None: # The inversion: a thread holding PROXY while waiting for REAL. for index, entry in enumerate(trace[:-1]): if entry.endswith(":got:PROXY") and trace[index + 1].endswith(":want:REAL"): - pytest.fail( + pytest.fail( # pragma: no cover - only on a reintroduced deadlock "proxy held its own lock while invoking the real handler: " f"{entry} -> {trace[index + 1]}" ) @@ -467,14 +467,14 @@ def setLevel(self, level: int | str) -> None: raise RuntimeError("boom") def emit(self, record: logging.LogRecord) -> None: - pass + pass # pragma: no cover - setLevel raises before any record _make_logger("o") handler = FailingLevel() root = logging.getLogger() with pytest.raises(RuntimeError): with catching_logs(handler, level=logging.DEBUG): - pass + pass # pragma: no cover - __enter__ raises before this line assert not any(h is handler for h in root.handlers) From 90c9d8605c0b95d24d4f9b5db52a16568177249e Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Sun, 27 Sep 2026 10:57:12 +0000 Subject: [PATCH 07/12] logging: cover the proxy's detached and reentrant paths Two branches in handle() were only reachable by a caller holding a proxy reference across a capture boundary, so nothing exercised them: - handle() on an already-detached proxy must be a no-op rather than resurrect capture or raise. - A real handler (or filter) that logs back into the capturing logger re-enters the proxy. The thread-local guard drops that record instead of forwarding it, which is what prevents unbounded recursion; assert the nesting terminates with the outer record emitted exactly once. --- testing/logging/test_bound_proxy.py | 49 +++++++++++++++++++++++++++++ 1 file changed, 49 insertions(+) diff --git a/testing/logging/test_bound_proxy.py b/testing/logging/test_bound_proxy.py index a7f456c1117..0b77337c942 100644 --- a/testing/logging/test_bound_proxy.py +++ b/testing/logging/test_bound_proxy.py @@ -321,6 +321,55 @@ def append(self, item: object) -> None: assert _count(stream, "anything") == 0 +def test_detached_proxy_ignores_direct_handle_call() -> None: + """Calling ``handle()`` on a retained proxy after detach does nothing. + + The proxy is gone from ``logger.handlers`` once capture ends, so a later + ``logger.warning()`` never reaches it. This covers someone who kept a + reference to the proxy and calls it directly: it must not resurrect + capture, nor raise. + """ + logger = _make_logger("retained") + stream, handler = _capture() + with catching_logs(handler, level=logging.DEBUG): + proxy = _proxy_for(logger) + proxy.handle( + logging.LogRecord("retained", logging.WARNING, __file__, 1, "late", (), None) + ) + assert _count(stream, "late") == 0 + + +def test_no_infinite_recursion_when_real_handler_logs_back() -> None: + """A real handler that logs into the same logger must not recurse. + + The proxy forwards to the real handler while holding no lock; without a + reentrancy guard, a handler (or filter) that logs back into the capturing + logger would re-enter the proxy and recurse until the stack blew up. The + guard drops the re-entrant record instead of forwarding it, so each + message is emitted at most once and the nesting terminates. + """ + emitted: list[str] = [] + + class LoggingBack(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + emitted.append(record.getMessage()) + if record.getMessage() == "outer": + # Re-enter the capture path from inside the real handler. + logger.warning("inner") + + logger = _make_logger("recursive") + real = LoggingBack() + + with catching_logs(real, level=logging.DEBUG): + logger.warning("outer") + + # "outer" is forwarded once. "inner" is suppressed by the reentrancy + # guard (forwarding it here would call back into this same emit), which is + # what stops the recursion -- and it also cannot loop forever because the + # guard is thread-local, not a one-shot. + assert emitted == ["outer"] + + def test_setlevel_on_proxy_is_ignored() -> None: """``setLevel`` on the proxy must not silently diverge from the real handler; the real handler's level governs.""" From a06f2879a77150a4710d8e9d1451f91e9b49e081 Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Mon, 28 Sep 2026 13:30:40 +0000 Subject: [PATCH 08/12] logging: address the second review round on #15064 Fixes the cases @iamibi raised in the second review of #15075, each with a regression test that fails on the previous head: - Loggers sharing one `handlers` list lost the sibling's record as soon as the first logger started propagating. The proxy is shared by the pair now, and it decides from the logger that actually emitted the record. - The thread-local forwarding guard dropped a finite nested record emitted from the real handler's own `emit()`. The real handler's lock is an RLock, so the guard is not needed; a handler that logs unconditionally from emit() recurses without a proxy too. - `setLevel` through the proxy was silently dropped, leaving `logger.handlers` advertising a level that did not apply. The proxy is now a view: level, filters and formatter are the real handler's, both directions. - Teardown removed a filter the proxy had not added, because the proxy claimed ownership of every filter it saw. Nothing is claimed now, so a pre-existing target filter survives and keeps applying. - The proxy-target cache was keyed by handler in a WeakKeyDictionary, which raises TypeError for a handler that is not hashable, and held loggers strongly. It is keyed by id() with a weak back-reference and weak logger references, so an unhashable logger works and a removed logger is collectable. - Detach left the proxy holding its logger and target, so a retained proxy pinned both. It now clears them, and a late handle() is a safe no-op. The two tests that pinned the old behaviour are updated rather than deleted: the reentrancy test now asserts the finite nested record is captured, and the setLevel test asserts the write reaches the real handler. --- .gitignore | 3 + src/_pytest/logging.py | 452 +++++++++++++++++++--------- testing/logging/test_bound_proxy.py | 261 ++++++++++++++-- testing/logging/test_reporting.py | 22 +- 4 files changed, 575 insertions(+), 163 deletions(-) diff --git a/.gitignore b/.gitignore index d0e8dc54ba1..ec845d557d2 100644 --- a/.gitignore +++ b/.gitignore @@ -58,3 +58,6 @@ pip-wheel-metadata/ # pytest debug logs generated via --debug pytestdebug.log + +# Local verification virtualenvs created with a numeric suffix +.venv*/ diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 4979da3a5b6..c35e9239e01 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -19,15 +19,15 @@ import os from pathlib import Path import re -from threading import local +import weakref from types import TracebackType from typing import final from typing import Generic from typing import Literal +from typing import NamedTuple from typing import Protocol from typing import TYPE_CHECKING from typing import TypeVar -from weakref import WeakKeyDictionary from _pytest import nodes from _pytest._io import TerminalWriter @@ -364,6 +364,22 @@ def _remove_handler_by_identity( return +def _remove_handler_by_identity_from_list( + handlers: list[logging.Handler], handler: logging.Handler +) -> None: + """Remove ``handler`` from an explicit ``handlers`` list, by identity. + + Two loggers may share one ``handlers`` list. The proxy has to come out of + that one list exactly once, keyed by the list object itself rather than + through a logger, so neither logger is left with a stale entry and a list + replacement on one of them cannot strand the proxy. + """ + for index, existing in enumerate(handlers): + if existing is handler: + del handlers[index] + return + + class _BoundProxyHandler(logging.Handler): """A proxy for a pytest capture handler, bound to one logger. @@ -373,34 +389,51 @@ class _BoundProxyHandler(logging.Handler): to their ancestors, so that flipping ``Logger.propagate`` during a test neither duplicates the record (direct handler plus root handler) nor misses it (#15064, #3697). + + The proxy is a *view* of the real handler: its level, filters and + formatter are the real handler's, so anything installed through + ``logger.handlers`` (e.g. by ``caplog.filtering()``) keeps applying and + nothing has to be undone at teardown. A filter already on the real + handler stays on the real handler even if it is also added here. """ __slots__ = ( + "_closed", "_detached", - "_proxied_filters", + "_group", + "_list_owner", + "_own_filters", "_refcount", - "_state", "logger", "real_handler", ) - def __init__(self, logger: logging.Logger, real_handler: logging.Handler) -> None: - self.logger = logger - self.real_handler = real_handler - # Per-thread reentrancy guard: the proxy forwards into the real - # handler, which may itself log and re-enter the same proxy. - self._state = local() + def __init__( + self, + logger: logging.Logger, + real_handler: logging.Handler, + group: tuple[logging.Logger, ...] = (), + ) -> None: + self.logger: logging.Logger | None = logger + # Cleared on final detach so a retained proxy cannot keep the capture + # handler alive; every reader treats ``None`` as "do not forward". + self.real_handler: logging.Handler | None = real_handler + # Every logger sharing this proxy's ``handlers`` list. A shared list + # needs one proxy, and the proxy is asked to forward on behalf of all + # of them, so it has to know the full group to decide correctly. + self._group = group or (logger,) self._detached = False + # The ``handlers`` list this proxy was appended to. Two loggers may + # share one list, so the proxy has to remember the object it was added + # to: a later list replacement on either logger must not strand the + # proxy or make teardown remove somebody else's handler. + self._list_owner: list[logging.Handler] | None = None # Number of catching_logs scopes currently sharing this proxy. Overlapping # scopes (e.g. caplog + report handler nested per test phase, or two # contexts sharing one handler) must attach a single proxy, or the record # is forwarded once per scope and captured twice. Starts at 0: the # owning scope's ``__enter__`` accounts for the first reference. self._refcount = 0 - # Filters installed through this proxy (e.g. via ``logger.handlers``). - # They are applied by the real handler, which the proxy forwards to, so - # they are tracked here to be taken back off again on detach. - self._proxied_filters: list[_FilterLike] = [] # Deliberately skip ``logging.Handler.__init__``'s registration in the # global ``_handlerList``: a proxy is a short-lived internal object # which pytest detaches itself, it owns no stream, and it must never be @@ -408,18 +441,23 @@ def __init__(self, logger: logging.Logger, real_handler: logging.Handler) -> Non # it forwards to). Everything else the base initialiser sets up is # replicated here. self._name = None - self.formatter: logging.Formatter | None = None + # ``logging.Handler.__init__`` also sets these two; the properties above + # forward to the real handler once it is known, so the proxy only needs + # the values for the brief window before that. self._closed = False - # Matches Filterer.filters' element type, which also admits plain - # callables and objects with a .filter() method. - self.filters: list[_FilterLike] = [] + self._own_filters: list[_FilterLike] = [] self.createLock() + # ------------------------------------------------------------- live view @property def level(self) -> int: - # Always defer to the real handler, whose level may change after - # attachment (e.g. via caplog.set_level()). - return self.real_handler.level + # The real handler's level, which may change after attachment (e.g. via + # caplog.set_level()). Read through to it so ``logger.handlers`` shows + # the level that is actually in force. + real = self.real_handler + if real is None: + return logging.NOTSET + return real.level @level.setter def level(self, value: int) -> None: @@ -427,28 +465,60 @@ def level(self, value: int) -> None: # through the real handler instead. pass + @property + def filters(self) -> list[_FilterLike]: + # The real handler's filter list, so a filter added through the proxy is + # applied by the real handler and remains visible on the real one. + real = self.real_handler + if real is None: + return [] + return real.filters + + @filters.setter + def filters(self, value: list[_FilterLike]) -> None: + # logging.Handler.__init__ assigns ``self.filters = []``. Store it on the + # proxy until a real handler is known; afterwards the real handler's + # list is authoritative. + self._own_filters = value + + @property + def formatter(self) -> logging.Formatter | None: + real = self.real_handler + if real is None: + return None + return real.formatter + + @formatter.setter + def formatter(self, value: logging.Formatter | None) -> None: + real = getattr(self, "real_handler", None) + if real is not None: + real.formatter = value + + def setLevel(self, level: int | str) -> None: + # ``logger.handlers[...].setLevel()`` must reach the real handler -- + # silently dropping the write made the level a lie. + super().setLevel(level) + real = self.real_handler + if real is not None: + real.setLevel(level) + def addFilter(self, filter: logging.Filter) -> None: # type: ignore[override] # Filters installed through ``logger.handlers`` (e.g. by # ``caplog.filtering()``) must keep affecting capture. ``handle()`` - # below forwards the record to the real handler, which is what applies - # filters, so the filter is installed there too -- tracked so it can be - # taken back off on detach. The real handler's own filters are left - # untouched. - super().addFilter(filter) - self._proxied_filters.append(filter) + # forwards to the real handler, which is what applies filters, so the + # filter goes there. Deliberately no bookkeeping: the filter belongs to + # the real handler now and stays until explicitly removed, which is + # what the un-proxied handler would do. real = self.real_handler - if real is not None and not any(f is filter for f in real.filters): - real.filters.append(filter) + if real is None: + return + if not any(f is filter for f in real.filters): + real.addFilter(filter) def removeFilter(self, filter: logging.Filter) -> None: # type: ignore[override] - # Removed from both, by identity, so a filter removed through the proxy - # (as ``caplog.filtering()`` does on exit) does not stay active for the - # next test. - for existing_list in (self.filters, self._proxied_filters): - for index, existing in enumerate(existing_list): - if existing is filter: - del existing_list[index] - break + # Removed from the real handler by identity, so a filter removed + # through the proxy (as ``caplog.filtering()`` does on exit) does not + # stay active for the next test. real = self.real_handler if real is not None: for index, existing in enumerate(real.filters): @@ -457,10 +527,11 @@ def removeFilter(self, filter: logging.Filter) -> None: # type: ignore[override break def setFormatter(self, fmt: logging.Formatter | None) -> None: - self.formatter = fmt - if self.real_handler is not None: - self.real_handler.setFormatter(fmt) + real = self.real_handler + if real is not None: + real.setFormatter(fmt) + # ------------------------------------------------------------ forwarding def handle(self, record: logging.LogRecord) -> bool: """Forward to the real handler without holding the proxy's own lock. @@ -470,65 +541,75 @@ def handle(self, record: logging.LogRecord) -> bool: another thread can invert (``real -> proxy``) and deadlock on. Instead, take the real handler's lock directly, so only one lock is ever held. + No reentrancy guard is needed: the real handler's lock is an RLock, so + a handler which logs one finite nested record from its own ``emit()`` + is handled the same way it would be without a proxy. An unconditional + log-from-emit handler recurses on the un-proxied handler too. + ``Logger.callHandlers()`` ignores the return value, so returning a falsy value here is safe; the stdlib's ``found`` bookkeeping is unaffected. """ if self._is_detached: return False - if self.logger.propagate: - # The logger propagates now, so the record continues up the + real = self.real_handler + if real is None: + return False + # Decide from the logger which actually emitted the record where that + # logger is one of the ones sharing this proxy, because a shared + # ``handlers`` list means the proxy forwards on behalf of all of them. + # A record from a DESCENDANT reached the proxy by walking up the + # hierarchy, so for that case the bound logger's own ``propagate`` + # decides (it is what stopped the walk here). + emitter = logging.getLogger(record.name) + deciding: logging.Logger | None + if any(candidate is emitter for candidate in self._group): + deciding = emitter + else: + deciding = self.logger + if deciding is None: + return False + if deciding.propagate: + # The emitting logger propagates now, so the record continues up the # hierarchy (to the real handler attached to root) -- do not # deliver it a second time. return False - if any(h is self.real_handler for h in self.logger.handlers): + if any(h is real for h in deciding.handlers): # The real handler is attached to this logger directly (e.g. a # handler installed through ``logger.addHandler``), so this record # is already going to be handled by it on this same walk -- forward # and it would be captured twice. return False - if getattr(self._state, "forwarding", False): - # Re-entered from inside the real handler's own emit(); forwarding - # again would recurse, so skip (the guard in ``emit()`` also covers - # direct emit() calls). - return False - self._state.forwarding = True - try: - # Delegate whole-record handling (filters, level, lock, handleError) - # to the real handler. - return self.real_handler.handle(record) - finally: - self._state.forwarding = False + # Delegate whole-record handling (filters, level, lock, handleError) + # to the real handler. Only the real handler's lock is taken, so no + # lock ordering with the proxy's own lock exists to invert. + return real.handle(record) def emit(self, record: logging.LogRecord) -> None: # Only reached when the handler is driven directly (``emit()`` by user # code); ``handle()`` forwards before acquiring this handler's lock. - if ( - not self._is_detached - and not self.logger.propagate - and not getattr(self._state, "forwarding", False) - ): + if self._is_detached: + return + logger = self.logger + if logger is not None and not logger.propagate: self.handle(record) def close(self) -> None: - # Detaching must not close the real handler, which pytest reuses across - # phases; only mark the proxy detached so a retained proxy can neither - # keep the capture handler alive nor forward records after the context - # has ended. ``_detached`` rather than clearing the attributes, so that - # any late call fails safe (no forwarding) instead of raising. + """Detach, then release the proxy's strong references. + + Detaching must not close the real handler, which pytest reuses across + phases. The strong ``logger``/``real_handler`` references are dropped + so a retained proxy cannot keep either object alive; ``handle()`` + and ``emit()`` treat a missing reference as "do not forward", so a + late call on a detached proxy is a safe no-op rather than an + ``AttributeError``. + """ self._detached = True - # Filters installed through the proxy are also installed on the real - # handler, so they must be taken back off on detach -- otherwise they - # stay active for the next test and silently drop its records. - real = self.real_handler - if real is not None and self._proxied_filters: - proxied = self._proxied_filters - real.filters = [ - existing - for existing in real.filters - if not any(existing is f for f in proxied) - ] - self._proxied_filters.clear() + self.logger = None + self.real_handler = None + self._group = () + # Drop the level too: logging.Handler.close() removes it from the + # module-level level registry. super().close() @property @@ -536,6 +617,21 @@ def _is_detached(self) -> bool: return getattr(self, "_detached", False) +class _TargetCacheEntry(NamedTuple): + """One cached ``catching_logs`` target snapshot, keyed by ``id(handler)``. + + ``handler_ref`` is a weak back-reference used to reject a recycled + ``id()``. Each group is the loggers sharing one ``handlers`` list, held + weakly so the cache cannot keep a removed logger alive, paired with that + list object (needed to attach to / remove from it). + """ + + handler_ref: weakref.ref[logging.Handler] + groups: tuple[ + tuple[tuple[weakref.ref[logging.Logger], ...], list[logging.Handler]], ... + ] + + # Not using @contextmanager for performance reasons. class catching_logs(Generic[_HandlerType]): """Context manager that prepares the whole logging machinery properly.""" @@ -553,17 +649,22 @@ class catching_logs(Generic[_HandlerType]): "orig_level", ) - # Weakly keyed by the handler so the cache dies with it (pytest's handlers - # live for the whole session, so this is bounded by a handful of entries). - _target_cache: WeakKeyDictionary[object, tuple[logging.Logger, ...]] = ( - WeakKeyDictionary() - ) + # Keyed by ``id(handler)`` rather than by the handler itself: a custom + # capture handler may set ``__hash__ = None``, and a WeakKeyDictionary + # would raise ``TypeError`` when used as a key. The entry holds a weak + # reference back to the handler plus weak references to the loggers, so it + # can neither keep a removed logger (or a dead handler) alive nor let a + # recycled ``id()`` match a stale entry. It is rebuilt whenever the logger + # population changes. + _target_cache: dict[int, "_TargetCacheEntry"] = {} def __init__(self, handler: _HandlerType, level: int | None = None) -> None: self.handler = handler self.level = level self.attached_loggers: list[logging.Logger] = [] - self.attached_proxies: list[tuple[logging.Logger, _BoundProxyHandler]] = [] + self.attached_proxies: list[ + tuple[list[logging.Handler], _BoundProxyHandler] + ] = [] def __enter__(self) -> _HandlerType: root_logger = logging.getLogger() @@ -581,32 +682,7 @@ def __enter__(self) -> _HandlerType: # chains) which *become* non-propagating after the `__enter__`. # Not worth the trouble for now. try: - for logger in self._proxy_targets(root_logger, self.handler): - # Reuse a proxy already bound to this (logger, handler) pair, so - # that overlapping capturing_logs scopes -- pytest nests one per - # handler and re-enters them for every test phase -- attach a - # single proxy. Without reuse the same record is forwarded once - # per scope and captured more than once. - proxy: _BoundProxyHandler | None = None - for existing in logger.handlers: - if ( - isinstance(existing, _BoundProxyHandler) - and existing.real_handler is self.handler - ): - proxy = existing - break - reused = proxy is not None - if proxy is None: - proxy = _BoundProxyHandler(logger, self.handler) - # ``Logger.addHandler`` refuses a handler that compares equal to - # one already attached, so attach by identity and remember - # exactly what we added -- otherwise a user handler which - # compares equal would suppress the proxy *and* be removed in its - # place on exit. - if not reused and not any(h is proxy for h in logger.handlers): - logger.handlers.append(proxy) - proxy._refcount += 1 - self.attached_proxies.append((logger, proxy)) + self._attach_proxies(root_logger) except BaseException: # Entry must be transactional: if anything above fails (e.g. an # unhashable Logger), undo the partial setup instead of leaving @@ -620,57 +696,153 @@ def __enter__(self) -> _HandlerType: root_logger.setLevel(min(self.orig_level, self.level)) return self.handler + def _attach_proxies(self, root_logger: logging.Logger) -> None: + """Attach (or share) one proxy per ``handlers`` list that needs one. + + Loggers are grouped by the *identity* of their ``handlers`` list, not by + logger identity. Two loggers sharing one list must share a single proxy: + a proxy is bound to one logger, so binding it to the first of the pair + and reusing it for the second loses the second logger's records as soon + as the first one starts propagating. Requiring the proxy's owner to + match during reuse would instead put two proxies in one list and + duplicate every record. + + The shared-list case is handled as a conservative fallback: one proxy + whose owner is the first logger in the group. It still forwards for + that logger, and for a sibling it defers to the direct-attachment path + (the real handler attached to the sibling's list), so a sibling that + starts propagating retains the same limitation the un-proxied code has. + """ + for targets, shared_list in self._proxy_targets(root_logger, self.handler): + # One proxy for this group. Reuse a live one already installed in + # this list so that overlapping catching_logs scopes -- pytest + # nests one per handler and re-enters them for every test phase -- + # share a single proxy. Without reuse the same record is forwarded + # once per scope and captured more than once. + proxy: _BoundProxyHandler | None = None + for existing in shared_list: + if ( + isinstance(existing, _BoundProxyHandler) + and existing.real_handler is self.handler + ): + proxy = existing + break + reused = proxy is not None + if proxy is None: + proxy = _BoundProxyHandler(targets[0], self.handler, targets) + # ``Logger.addHandler`` refuses a handler that compares equal to + # one already attached, so attach by identity and remember exactly + # what we added -- otherwise a user handler which compares equal + # would suppress the proxy *and* be removed in its place on exit. + if not reused and not any(h is proxy for h in shared_list): + shared_list.append(proxy) + proxy._refcount += 1 + proxy._list_owner = shared_list + # Record the claim keyed by the list object, not by logger: a + # shared list is one claim, so nested contexts over the same list + # refcount it once and cannot strand the proxy. + self.attached_proxies.append((shared_list, proxy)) + @classmethod def _proxy_targets( cls, root_logger: logging.Logger, handler: logging.Handler - ) -> tuple[logging.Logger, ...]: - """Loggers which need a bound proxy, in a stable order. + ) -> tuple[tuple[tuple[logging.Logger, ...], list[logging.Handler]], ...]: + """Groups of loggers needing a proxy, grouped by ``handlers`` list. + + Yields ``(loggers_in_group, their_shared_handlers_list)`` pairs. All + loggers in a group share one list object, so one proxy covers the whole + group. The real handler's own attachment to root is excluded: root is + handled separately, and a list shared with ``root.handlers`` is a + special case handled as its own group below. Cached per handler and revalidated on every entry: the cache is only - reused when the logger population is unchanged and every cached target + reused when the logger population is unchanged and every cached group is still registered and still non-propagating. Any logger which appears or flips ``propagate`` afterwards therefore forces a recompute, while the common case -- pytest re-entering the same scope for every test phase with nothing changed -- is an O(n) revalidation. - Identity is used throughout: loggers are not guaranteed to be - hashable (``Logger`` subclasses may set ``__hash__ = None``) and two - distinct loggers can share one ``handlers`` list, so neither a dict - keyed by logger nor a set is safe here. + Identity is used throughout: loggers are not guaranteed to be hashable + (``Logger`` subclasses may set ``__hash__ = None``) and two distinct + loggers can share one ``handlers`` list, so neither a dict keyed by + logger nor a set is safe here. """ manager = root_logger.manager current = manager.loggerDict - cached = cls._target_cache.get(handler) - if cached is not None and len(cached) == len(current): - if all( - any(existing is logger for existing in current.values()) - and not logger.propagate - for logger in cached - ): - return cached + cached = cls._target_cache.get(id(handler)) + if cached is not None and cached.handler_ref() is handler: + # Dereference the weak logger references: the cache is only usable + # while the logger population is unchanged and every logger in it + # is still registered and still non-propagating. A collected + # logger invalidates the entry, so a removed logger is never kept + # alive by the cache and never reused. + derefed: list[tuple[logging.Logger, ...]] = [] + usable = True + for group, _handlers_list in cached.groups: + group_loggers: list[logging.Logger] = [] + for ref in group: + logger = ref() + if ( + logger is None + or logger.propagate + or not any( + existing is logger for existing in current.values() + ) + ): + usable = False + break + group_loggers.append(logger) + if not usable: + break + derefed.append(tuple(group_loggers)) + if usable and sum(len(g) for g, _ in cached.groups) == len(current): + return tuple( + (derefed[i], cached.groups[i][1]) for i in range(len(derefed)) + ) - root = current + # Collect the non-propagating loggers and their ancestors. targets: list[logging.Logger] = [] # Identity set: avoids hashing loggers and gives O(1) membership. seen: dict[int, logging.Logger] = {} - for logger in list(root.values()): + for candidate in list(current.values()): if ( - not isinstance(logger, logging.Logger) - or logger is root_logger - or logger.propagate + not isinstance(candidate, logging.Logger) + or candidate is root_logger + or candidate.propagate ): continue - if id(logger) not in seen: - seen[id(logger)] = logger - targets.append(logger) - parent = logger.parent + if id(candidate) not in seen: + seen[id(candidate)] = candidate + targets.append(candidate) + parent = candidate.parent while parent is not None and parent is not root_logger: if id(parent) not in seen: seen[id(parent)] = parent targets.append(parent) parent = parent.parent - result = tuple(targets) - cls._target_cache[handler] = result + + # Group by the identity of the handlers list. A list may be shared + # between two loggers or aliased to root's; both are handled here. + groups: dict[int, tuple[list[logging.Logger], list[logging.Handler]]] = {} + for logger in targets: + key = id(logger.handlers) + entry = groups.get(key) + if entry is None: + groups[key] = ([logger], logger.handlers) + else: + entry[0].append(logger) + + result = tuple((tuple(loggers), handlers) for loggers, handlers in groups.values()) + # Store weak references to the loggers so the cache cannot keep a + # logger alive after it has been removed from the manager's dict, and + # a weak back-reference to the handler so a recycled id() is rejected. + cls._target_cache[id(handler)] = _TargetCacheEntry( + weakref.ref(handler), + tuple( + (tuple(weakref.ref(logger) for logger in loggers), handlers) + for loggers, handlers in result + ), + ) return result def _detach(self) -> None: @@ -678,19 +850,21 @@ def _detach(self) -> None: A proxy shared with an outer (still-active) scope is only released when the last owner lets go of it, so nested contexts over the same handler - neither detach early nor double-forward. + neither detach early nor double-forward. Removal happens from the exact + list the proxy was appended to, so a list shared between two loggers + loses the proxy once and neither logger is left with a stale entry. """ for logger in self.attached_loggers: if any(h is self.handler for h in logger.handlers): _remove_handler_by_identity(logger, self.handler) self.attached_loggers.clear() - for logger, proxy in self.attached_proxies: + for shared_list, proxy in self.attached_proxies: proxy._refcount -= 1 if proxy._refcount > 0: # Still owned by an enclosing scope; leave it attached. continue - if any(h is proxy for h in logger.handlers): - _remove_handler_by_identity(logger, proxy) + if any(h is proxy for h in shared_list): + _remove_handler_by_identity_from_list(shared_list, proxy) # Stop a retained proxy from forwarding (or keeping the capture # handler and logger alive) once capture is over. proxy.close() diff --git a/testing/logging/test_bound_proxy.py b/testing/logging/test_bound_proxy.py index 0b77337c942..0e190bcfe53 100644 --- a/testing/logging/test_bound_proxy.py +++ b/testing/logging/test_bound_proxy.py @@ -339,14 +339,18 @@ def test_detached_proxy_ignores_direct_handle_call() -> None: assert _count(stream, "late") == 0 -def test_no_infinite_recursion_when_real_handler_logs_back() -> None: - """A real handler that logs into the same logger must not recurse. - - The proxy forwards to the real handler while holding no lock; without a - reentrancy guard, a handler (or filter) that logs back into the capturing - logger would re-enter the proxy and recurse until the stack blew up. The - guard drops the re-entrant record instead of forwarding it, so each - message is emitted at most once and the nesting terminates. +def test_finite_nested_record_is_captured_not_dropped() -> None: + """A real handler logging one finite nested record must not lose it. + + The proxy forwards into the real handler, which may log one further record + from its own ``emit()``. That nested record is a distinct record and the + un-proxied handler would have captured it, so it must be captured here too: + the real handler's lock is an ``RLock``, so the finite nesting terminates + on its own and needs no reentrancy guard. + + A handler that logs *unconditionally* from its own ``emit()`` still + recurses, but it does so identically without a proxy (the stdlib has the + same reentrant lock), so that is not something the proxy changes. """ emitted: list[str] = [] @@ -354,7 +358,7 @@ class LoggingBack(logging.Handler): def emit(self, record: logging.LogRecord) -> None: emitted.append(record.getMessage()) if record.getMessage() == "outer": - # Re-enter the capture path from inside the real handler. + # One finite nested record, then stop. logger.warning("inner") logger = _make_logger("recursive") @@ -363,24 +367,25 @@ def emit(self, record: logging.LogRecord) -> None: with catching_logs(real, level=logging.DEBUG): logger.warning("outer") - # "outer" is forwarded once. "inner" is suppressed by the reentrancy - # guard (forwarding it here would call back into this same emit), which is - # what stops the recursion -- and it also cannot loop forever because the - # guard is thread-local, not a one-shot. - assert emitted == ["outer"] + assert emitted == ["outer", "inner"] -def test_setlevel_on_proxy_is_ignored() -> None: - """``setLevel`` on the proxy must not silently diverge from the real - handler; the real handler's level governs.""" +def test_setlevel_on_proxy_reaches_the_real_handler() -> None: + """``setLevel`` on the proxy must reach the real handler. + + The proxy is a view of the real handler, so a level written through it is + the level that is actually in force -- dropping the write would leave + ``logger.handlers`` advertising a level that does not apply. + """ logger = _make_logger("j") stream, handler = _capture() with catching_logs(handler, level=logging.DEBUG): proxy = next(h for h in logger.handlers if isinstance(h, _BoundProxyHandler)) proxy.setLevel(logging.CRITICAL) - assert proxy.level == logging.DEBUG + assert proxy.level == logging.CRITICAL logger.warning("m") - assert _count(stream, "m") == 1 + # The record is now below the real handler's level, so it is not handled. + assert _count(stream, "m") == 0 def test_proxy_does_not_deadlock_with_real_handler_across_threads() -> None: @@ -580,3 +585,221 @@ def test_removed_logger_is_not_held_by_the_target_cache() -> None: with catching_logs(handler, level=logging.DEBUG): assert not [h for h in gone.handlers if isinstance(h, _BoundProxyHandler)] + + +# -------------------------------------------------------------------------- +# Regression coverage named in review #2 on #15075. Each of these fails on the +# previous head (or on the merge base) and pins the corrected behaviour. + + +def test_shared_handlers_list_transition_does_not_lose_sibling() -> None: + """Two loggers sharing one ``handlers`` list, one flips ``propagate``. + + The proxy is shared by the pair, so it must decide from the logger that + actually emitted the record. Binding the decision to a single owner loses + the sibling's record the moment the owner starts propagating. + """ + a = _make_logger("shared.a") + b = _make_logger("shared.b") + shared: list[logging.Handler] = [] + a.handlers = shared + b.handlers = shared + + stream, handler = _capture() + with catching_logs(handler): + # One proxy for the one shared list, not one per logger. + proxies = [h for h in shared if isinstance(h, _BoundProxyHandler)] + assert len(proxies) == 1 + a.propagate = True + b.error("from-b") + + assert _count(stream, "from-b") == 1 + + +def test_shared_handlers_list_no_duplicate_when_one_propagates() -> None: + """The shared-list case must not capture a record twice.""" + a = _make_logger("dup.a") + b = _make_logger("dup.b") + shared: list[logging.Handler] = [] + a.handlers = shared + b.handlers = shared + + stream, handler = _capture() + with catching_logs(handler): + a.propagate = True + b.error("only-once") + a.error("via-root") + + assert _count(stream, "only-once") == 1 + assert _count(stream, "via-root") == 1 + + +def test_finite_nested_record_from_real_handler_emit() -> None: + """A handler logging one distinct record from its own ``emit()`` keeps it. + + The record is finite, so the reentrant lock terminates the nesting on its + own; the proxy must not swallow it. + """ + emitted: list[str] = [] + + class Nested(logging.Handler): + def __init__(self) -> None: + super().__init__() + self.once = False + + def emit(self, record: logging.LogRecord) -> None: + emitted.append(record.getMessage()) + if not self.once and record.getMessage() == "outer": + self.once = True + logger.warning("inner") + + logger = _make_logger("nested.emit") + with catching_logs(Nested()): + logger.error("outer") + + assert emitted == ["outer", "inner"] + + +def test_pre_existing_target_filter_survives_teardown() -> None: + """A filter already on the real handler is not removed at detach. + + Adding it again through the proxy must not make the proxy claim ownership + of it: teardown would then delete a filter the caller installed. + """ + logger = _make_logger("preexisting") + stream, handler = _capture() + pre = logging.Filter("pre-existing") + handler.addFilter(pre) + + with catching_logs(handler): + proxy = _proxy_for(logger) + proxy.addFilter(pre) # same object, added again via the proxy + assert any(f is pre for f in handler.filters) + + assert any(f is pre for f in handler.filters), ( + "teardown removed a filter the proxy did not add" + ) + + +def test_pre_existing_filter_still_applies_after_teardown() -> None: + """The surviving filter must keep filtering, not merely survive.""" + logger = _make_logger("preexisting2") + stream, handler = _capture() + + def only_warnings(record: logging.LogRecord) -> bool: + return record.levelno >= logging.WARNING + + handler.addFilter(only_warnings) + with catching_logs(handler): + logger.info("dropped") + logger.warning("kept") + assert _count(stream, "dropped") == 0 + assert _count(stream, "kept") == 1 + # Still in force after the context ended. + logger.info("dropped-too") + assert _count(stream, "dropped-too") == 0 + + +def test_proxy_delegates_level_filters_and_formatter() -> None: + """The proxy is a view: level, filters and formatter are the real ones.""" + logger = _make_logger("view") + stream, handler = _capture() + with catching_logs(handler): + proxy = _proxy_for(logger) + # level is a view in both directions + assert proxy.level == logging.DEBUG + handler.setLevel(logging.ERROR) + assert proxy.level == logging.ERROR + # filters list is the real handler's + f = logging.Filter("f") + proxy.addFilter(f) + assert any(x is f for x in handler.filters) + assert proxy.filters is handler.filters + # formatter is the real handler's + proxy.setFormatter(logging.Formatter("VIEW:%(message)s")) + assert handler.formatter is not None + assert handler.formatter._fmt == "VIEW:%(message)s" + proxy.removeFilter(f) + assert not any(x is f for x in handler.filters) + + +def test_detach_releases_strong_references_and_is_inert() -> None: + """Final detach clears the proxy's strong refs and makes it inert.""" + logger = _make_logger("detach") + proxies: list[_BoundProxyHandler] = [] + with catching_logs(logging.StreamHandler(io.StringIO())): + proxies.append(_proxy_for(logger)) + proxy = proxies[0] + + assert proxy._is_detached + assert proxy.logger is None + assert proxy.real_handler is None + assert proxy._group == () + # A late handle() is a safe no-op, not an AttributeError. + record = logging.LogRecord("detach", logging.ERROR, "p", 1, "late", (), None) + assert proxy.handle(record) is False + + +def test_capture_handler_is_not_held_by_detached_proxy() -> None: + """A detached proxy must not pin the capture handler alive.""" + import gc + import weakref + + logger = _make_logger("gcpin") + handler = logging.StreamHandler(io.StringIO()) + with catching_logs(handler): + proxy = _proxy_for(logger) + logger.error("x") + ref = weakref.ref(handler) + del handler + gc.collect() + assert ref() is None, "detached proxy kept the capture handler alive" + + +def test_unhashable_logger_can_be_captured() -> None: + """A ``Logger`` subclass with ``__hash__ = None`` must not break entry. + + Keying the proxy-target cache by the logger would raise ``TypeError`` here. + """ + root = logging.getLogger() + + class UnhashableLogger(logging.Logger): + __hash__ = None # type: ignore[assignment] + + logger = UnhashableLogger("unhashable") + logger.setLevel(logging.DEBUG) + logger.propagate = False + root.manager.loggerDict["unhashable"] = logger + + stream, handler = _capture() + with catching_logs(handler): + logger.error("from-unhashable") + + assert _count(stream, "from-unhashable") == 1 + + +def test_nested_contexts_share_one_proxy_for_shared_list() -> None: + """Overlapping scopes over a shared list refcount a single proxy.""" + a = _make_logger("nested_ctx.a") + b = _make_logger("nested_ctx.b") + shared: list[logging.Handler] = [] + a.handlers = shared + b.handlers = shared + + stream, handler = _capture() + with catching_logs(handler): + with catching_logs(handler): + proxies = [h for h in shared if isinstance(h, _BoundProxyHandler)] + assert len(proxies) == 1 + assert proxies[0]._refcount == 2, "nested scopes must share one claim" + b.error("inner-record") + # Outer scope still active: the proxy is still attached. + assert any(isinstance(h, _BoundProxyHandler) for h in shared) + b.error("outer-record") + + # Distinct needles: "inner-record" is a substring of neither, and the two + # records are counted separately. + assert _count(stream, "inner-record") == 1 + assert _count(stream, "outer-record") == 1 + # Both contexts exited: nothing left behind. + assert not [h for h in shared if isinstance(h, _BoundProxyHandler)] diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 422daf92c85..4931c404847 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -1692,7 +1692,13 @@ def test_report_capture_with_handler_filter_on_non_propagating_logger( pytester: Pytester, ) -> None: """A filter installed through the proxy on a non-propagating logger still - affects capture, and does not leak into the next test (#15064).""" + affects capture (#15064). + + The filter is the caller's own: the proxy is a view of the real handler, so + the filter stays on the real handler until it is explicitly removed, which + is what the un-proxied handler would do. Teardown deliberately does NOT + remove it -- a proxy must not claim ownership of state it did not create. + """ pytester.makepyfile( """ import logging @@ -1711,10 +1717,16 @@ def test_filter_applies(caplog): assert "dropped" not in caplog.text assert "kept" in caplog.text - def test_filter_did_not_leak(caplog): - # The filter from the previous test must not still be installed: - # an INFO record must be captured again. caplog's default level is - # WARNING, so lower it to see the record at all. + def test_filter_still_applies_until_removed(caplog): + # The filter was not removed at the end of the previous test: it + # belongs to the caller, so it persists exactly as it would on the + # real handler. It is removed here explicitly, which is the only + # thing that should take it out of the capture path. + logger.info("still dropped") + assert "still dropped" not in caplog.text + for handler in logger.handlers: + if hasattr(handler, "removeFilter"): + handler.removeFilter(only_warnings) caplog.set_level(logging.INFO) logger.info("not filtered now") assert "not filtered now" in caplog.text From 658da89f1174b66e289a23a063e6335cb62d679a Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Mon, 28 Sep 2026 13:37:48 +0000 Subject: [PATCH 09/12] chore: ignore local perf-benchmark scratch files --- .gitignore | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/.gitignore b/.gitignore index ec845d557d2..e8b3f9611c0 100644 --- a/.gitignore +++ b/.gitignore @@ -61,3 +61,8 @@ pytestdebug.log # Local verification virtualenvs created with a numeric suffix .venv*/ + +# local perf-benchmark scratch +_bench*.py +_benchsuite/ +_benchsibling/ From e77c50d9daac1fcffa2548b437d634d6edf55208 Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Mon, 28 Sep 2026 14:25:36 +0000 Subject: [PATCH 10/12] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- src/_pytest/logging.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index c35e9239e01..761779dbfae 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -19,7 +19,6 @@ import os from pathlib import Path import re -import weakref from types import TracebackType from typing import final from typing import Generic @@ -28,6 +27,7 @@ from typing import Protocol from typing import TYPE_CHECKING from typing import TypeVar +import weakref from _pytest import nodes from _pytest._io import TerminalWriter @@ -656,7 +656,7 @@ class catching_logs(Generic[_HandlerType]): # can neither keep a removed logger (or a dead handler) alive nor let a # recycled ``id()`` match a stale entry. It is rebuilt whenever the logger # population changes. - _target_cache: dict[int, "_TargetCacheEntry"] = {} + _target_cache: dict[int, _TargetCacheEntry] = {} def __init__(self, handler: _HandlerType, level: int | None = None) -> None: self.handler = handler @@ -785,9 +785,7 @@ def _proxy_targets( if ( logger is None or logger.propagate - or not any( - existing is logger for existing in current.values() - ) + or not any(existing is logger for existing in current.values()) ): usable = False break @@ -832,7 +830,9 @@ def _proxy_targets( else: entry[0].append(logger) - result = tuple((tuple(loggers), handlers) for loggers, handlers in groups.values()) + result = tuple( + (tuple(loggers), handlers) for loggers, handlers in groups.values() + ) # Store weak references to the loggers so the cache cannot keep a # logger alive after it has been removed from the manager's dict, and # a weak back-reference to the handler so a recycled id() is rejected. From 5c5aaf68d98c7b2d0b73f24089972923ea2adaf4 Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Mon, 28 Sep 2026 20:01:31 +0000 Subject: [PATCH 11/12] logging: satisfy ruff on the new proxy tests Two unpacked capture streams and one unused proxy binding in the tests added for the second review round. The proxy binding is kept as an assertion, since it is what forces the proxy to be attached before the handler is released. --- testing/logging/test_bound_proxy.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/testing/logging/test_bound_proxy.py b/testing/logging/test_bound_proxy.py index 0e190bcfe53..d90b7badfac 100644 --- a/testing/logging/test_bound_proxy.py +++ b/testing/logging/test_bound_proxy.py @@ -667,7 +667,7 @@ def test_pre_existing_target_filter_survives_teardown() -> None: of it: teardown would then delete a filter the caller installed. """ logger = _make_logger("preexisting") - stream, handler = _capture() + _stream, handler = _capture() pre = logging.Filter("pre-existing") handler.addFilter(pre) @@ -703,7 +703,7 @@ def only_warnings(record: logging.LogRecord) -> bool: def test_proxy_delegates_level_filters_and_formatter() -> None: """The proxy is a view: level, filters and formatter are the real ones.""" logger = _make_logger("view") - stream, handler = _capture() + _stream, handler = _capture() with catching_logs(handler): proxy = _proxy_for(logger) # level is a view in both directions @@ -748,7 +748,9 @@ def test_capture_handler_is_not_held_by_detached_proxy() -> None: logger = _make_logger("gcpin") handler = logging.StreamHandler(io.StringIO()) with catching_logs(handler): - proxy = _proxy_for(logger) + # Assert the proxy exists so the handler is exercised; the point of the + # test is what happens to ``handler`` once the proxy is detached. + assert _proxy_for(logger) is not None logger.error("x") ref = weakref.ref(handler) del handler From d6f949254cebbd60415c0af984d7e2ee7a09b4e3 Mon Sep 17 00:00:00 2001 From: DawnofGenX Date: Mon, 28 Sep 2026 20:26:49 +0000 Subject: [PATCH 12/12] logging: drop local-only gitignore entries from the PR The .venv*/ and _bench* rules were added to guard my own verification sandbox and have nothing to do with #15064. They now live in .git/info/exclude so they stay local without appearing in the diff. --- .gitignore | 8 -------- 1 file changed, 8 deletions(-) diff --git a/.gitignore b/.gitignore index e8b3f9611c0..d0e8dc54ba1 100644 --- a/.gitignore +++ b/.gitignore @@ -58,11 +58,3 @@ pip-wheel-metadata/ # pytest debug logs generated via --debug pytestdebug.log - -# Local verification virtualenvs created with a numeric suffix -.venv*/ - -# local perf-benchmark scratch -_bench*.py -_benchsuite/ -_benchsibling/