logging: capture each record once when propagate changes during a test (#15064)

[DawnofGenX]

Problem

Fixes #15064

Since #14375, pytest attaches its capture handlers to every logger which is non-propagating when capture starts (so their records don't get lost, #3697). If the test then sets logger.propagate = True, a single Logger.callHandlers walk invokes the same handler object twice - once on the logger and once on root - producing duplicate entries in caplog.messages, failure-report "Captured log" sections, --log-cli-level output, and --log-file output:

import logging

logger = logging.getLogger("example")
logger.propagate = False

def test_log_is_captured_once(caplog):
    logger.propagate = True
    logger.warning("only once")
    assert caplog.messages == ["only once"]  # got ['only once', 'only once']

Approach

Per the direction in the thread (@RonnyPfannschmidt: "we need a bound proxy handler for each logger that hinges on the current value of propagate"), catching_logs now attaches a small _BoundProxyHandler - instead of the real capture handler - to each logger which is non-propagating at capture setup, and to its ancestors up to (not including) root. The proxy:

• consults its logger's live propagate value in emit(), forwarding to the real handler (via handle(), so the real handler's own filters/level/lock/handleError apply) only while propagation is currently off;
• delegates level to the real handler so setLevel() on the capture handler keeps working unchanged;
• never closes the real handler.

When a record does propagate to root, every proxy on its path below root evaluates logger.propagate truthy and stays silent; the root-attached real handler does the work exactly once. When the barrier holds, the nearest proxy forwards it once. This fixes the reported False -> True case, the mixed child/parent transition, and also captures the previously-missed True -> False transition on the initially-affected loggers and their ancestors (the narrower owner set from the discussion; the cost/performance objections to proxies on every logger in #15064's comment thread do not apply here, since unrelated propagating routes get no proxies and pay nothing).

Cost: per-record work on affected routes is one Handler.handle() + one propagate attribute read on the proxy - the proxy only sits on loggers that were already getting a direct handler on main, so propagating routes through unaffected loggers are untouched. Direct Handler.handle() calls, custom filters on the capture handler, and logger.handlers contents during capture behave as before, except the extra handler in logger.handlers is now the proxy rather than the capture handler itself.

Known remaining limitation (unchanged, documented in a code comment): a logger which becomes non-propagating during the test outside those initial ancestor chains is still missed - same as main.

Evidence

• New regression tests (all fail on pristine main, reproducing the duplicate; pass with the fix):
  • testing/logging/test_fixture.py::test_capture_once_when_propagation_enabled_during_test - caplog.messages surface, incl. a child logger.
  • testing/logging/test_fixture.py::test_capture_once_when_propagation_barrier_moves_to_ancestor - mixed child/parent transition (barrier moves to an ancestor mid-test).
  • testing/logging/test_reporting.py::test_log_propagation_enabled_during_test_captured_once - failure-report Captured log call section surface.
• testing/logging/: 90 passed (87 on main + the 3 new tests).
• Local full testing/ suite: 4584 passed, 87 skipped, 12 xfailed, 7 xpassed. Full CI matrix green (36/36 checks, macOS/Ubuntu/Windows, py3.10-3.15 + Pypy).
• ruff check src testing clean, ruff format clean, mypy src/_pytest/logging.py clean.

AI assistance disclosure

This contribution was prepared with assistance from an AI agent (Hermes Agent by Nous Research, Qwen model) under human review and ownership; the human author has reviewed the change, understands the mechanism above, and will respond to review feedback.

[RonnyPfannschmidt]

Except for the nitpick where I need to read up on logging this looks good thanks

[RonnyPfannschmidt]

I believe this should be handle ?

[iamibi]

Thanks for working on this. I checked the current head (e502c27d) against its merge base (6a9ba0f0). The basic
False -> True case works, the logging suite passes, all current CI checks are green, and the new code remains below
McCabe complexity 10.

I found several cases that I think need to be addressed before merge.

Blocking correctness issues

1. The proxy can deadlock with the real handler across threads.

   Handler.handle() holds the proxy lock while _BoundProxyHandler.emit() calls real_handler.handle(). A thread can
   therefore acquire proxy lock -> target lock, while another thread that holds the target lock and logs through the
   owner acquires target lock -> proxy lock. A deterministic two-thread test deadlocks on this branch and completes on
   main.

   The proxy must not hold its own handler lock while invoking the target.

2. Some valid handler topologies still capture a record twice.

   I reproduced duplicates in all of these cases:

   • caplog.handler is also attached directly to the non-propagating logger;
   • two loggers share the same handlers list;
   • a non-root logger shares root.handlers.

   For the direct-target case, main records ['direct'], while this branch records ['direct', 'direct']. The proxy
   needs an identity check for a directly attached target, and shared/root-aliased handler lists need explicit handling.

3. Equality-based attachment and cleanup can remove a user handler.

   Logger.addHandler() and Logger.removeHandler() use list membership/removal semantics. With a custom handler that
   compares equal to _BoundProxyHandler, insertion of the proxy is suppressed, capture is lost, and exit removes the
   user's handler instead. Attachment ownership and cleanup need to be verified and performed by identity.

4. The per-context proxy lifecycle has a substantial cost.

   I benchmarked hash-verified base and PR source snapshots in alternating fresh CPython 3.13 processes, with plugin
   autoload disabled and source order alternated by round. The implementation exceeds the performance gates discussed
   on the issue:

   Scenario	Median PR/base ratio
   5,000 tests, one qualifying logger	1.065x
   5,000 tests, ten qualifying loggers	1.285x
   Stable-false emission, one target	1.74x
   Affected propagating sibling route	1.66x-2.11x
   Deep ancestor-barrier route	up to 14.05x
   1,000-owner context lifecycle	about 17x
   1,000-owner exit alone	about 29.6x

   The one-logger workload was slower in 14 of 15 paired runs. Ten loggers were slower in all 15 runs. Fully disjoint
   routes stayed near 1.00x, and the logging handler registry returned to baseline, so this is not a retained registry
   leak. The cost comes from constructing and destroying real Handler proxies for every owner, ancestor, target, and
   capture context. In particular, cleanup is repeated for pytest phases rather than being a one-time final cost.

Other behavioral issues

• proxy.setLevel() silently discards the write. Filters and formatters installed through logger.handlers also stop
  affecting capture once the logger propagates.
• On Python 3.12+, replacement-record filters have transition-dependent behavior because the logger checks the original
  record against the delegated target level before the proxy filter can replace it.
• Nested contexts using the same target create multiple proxies and duplicate records during their overlap.
• If a later local or ancestor handler raises after a propagating proxy skips delivery, root is never reached. main
  captures that record before the failure; this branch does not.
• Removing a proxy from the logger does not close or disable it. Code retaining the proxy can keep the target and logger
  alive and can still forward records after the capture context has ended.
• An unhashable custom Logger fails while building proxy_targets. Because root was already modified, the failed
  __enter__ leaves the capture handler attached. Entry needs transactional rollback.

Coverage and publication details

• The mixed child/parent barrier test already passes on pristine main; only the direct False -> True test is a new
  failing regression there.
• The changelog mentions caplog, failure reports, live CLI logging, and file output, but permanent tests currently cover
  only caplog and failure reports.
• The contributor is not yet listed in AUTHORS, which CONTRIBUTING.rst requests for non-trivial changes.

The minimum additional coverage should include direct target attachment, shared handler lists, identity-hostile
handlers, lock ordering, filters/levels/formatters, Python 3.12 replacement records, nested contexts, failed-entry
rollback, proxy collection, and live/file output.

The patch is much smaller than the earlier designs and fixes the primary happy path, but the locking, identity,
lifecycle, and scaling issues above make it unsafe to merge as written. Reusing proxies across the outer capture scope
and making registrations identity-based/refcounted would address several of these problems together.