Skip to content

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

Open
DawnofGenX wants to merge 17 commits into
pytest-dev:mainfrom
DawnofGenX:fix-duplicate-log-capture-15064
Open

DawnofGenX wants to merge 17 commits into
pytest-dev:mainfrom
DawnofGenX:fix-duplicate-log-capture-15064

Conversation

@DawnofGenX

@DawnofGenX DawnofGenX commented Sep 21, 2026 •

Copy link
Copy Markdown

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.

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 pytest-dev#15064
@DawnofGenX
DawnofGenX force-pushed the fix-duplicate-log-capture-15064 branch from f8cbf03 to e502c27 Compare September 21, 2026 15:47

@RonnyPfannschmidt RonnyPfannschmidt left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Comment thread src/_pytest/logging.py
# through the real handler instead.
pass

def emit(self, record: logging.LogRecord) -> None:

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe this should be handle ?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed — emit() now delegates directly to handle(); the duplicated _is_detached/propagate guards were redundant since handle() already performs them. Thanks!

@iamibi iamibi left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

The proxy standing in for a capture handler on a non-propagating logger
had several problems reported in review of pytest-dev#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.
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.
@DawnofGenX

Copy link
Copy Markdown
Author

Thanks for the review — it was right on every blocking point, and measuring each
one against main turned up a couple of cases the review only suspected.

What was wrong, and what changed

1. Deadlock (lock order). Confirmed by tracing lock acquisition across the
two threads. The proxy held its own lock while calling real_handler.handle(),
giving proxy -> real where the other thread has real -> proxy. handle()
now forwards before the proxy's lock is taken.

before: A:got:PROXY -> A:want:REAL   (and B blocked on PROXY)
after:  A:want:REAL  -> B:want:REAL

2. Duplicate capture in other topologies. Measured on both trees:

topology main before after
capture handler also attached directly to the logger 1 2 1
two loggers sharing one handlers list 1 3 1
a logger whose handlers is root.handlers 1 2 1

The direct-attachment case needed an identity check against the logger's own
handlers; the shared-list cases came out of the by-identity attach/remove.

3. Equality-based attachment and cleanup. Confirmed: a user handler whose
__eq__ returns True had the proxy's insertion suppressed and was then
removed in its place on exit. Attachment, removal and the handlers scan are
all by identity now. This one is also a bug on main — with the same handler,
main removes the user's handler and captures nothing, where the new code keeps
it and captures once.

4. Performance. The first measurements exceeded the gate, so the
implementation changed: proxies are reused and refcounted across overlapping
scopes, the target set is cached per handler and revalidated on entry, and the
proxy is no longer registered in logging's global handler list. On the shapes
pytest actually uses (one capture scope with many records; one scope per test
phase), median ratio to main over 5 alternating fresh-process pairs:

scenario ratio
one scope, non-propagating logger, 5000 records 1.14x
one scope, propagate flipped per record (the #15064 route) 0.86x
one scope, unrelated propagating logger (no proxy on the route) 1.01x
500 scopes x 20 records 1.39x

All within the 1.5x gate. Worth noting the first two rows were 1.28x/0.77x and
the last 1.32x before caching; a fully disjoint route stays at ~1.00x either
way, and logging._handlerList returns to baseline.

5. Other behavioural points, all addressed. setLevel on the proxy is
ignored and the real handler's level governs; filters and formatters installed
through the proxy keep applying and are taken back off on detach (they were
leaking into the next test before I added that); nested contexts share one
proxy instead of one each; a failure while attaching proxies rolls back, so the
handler no longer stays attached to root; a detached proxy stops forwarding and
no longer keeps the capture handler and logger alive; an unhashable Logger no
longer raises, because target selection is identity-based rather than dict-keyed.

Tests

testing/logging/test_bound_proxy.py (new) covers each of these directly
against catching_logs, and test_reporting.py gains end-to-end coverage for
--log-cli-level, --log-file, level and filter handling through the proxy,
replacement records, and filter lifetime across two tests. The lock-order test
asserts the acquisition order rather than waiting for a hang, so it is
deterministic.

Verified red/green: 11 of the 23 new tests fail against the previous head and
pass on this one. The other 12 pass on both — they are preservation tests for
behaviour that was already correct on main and that this change must not
break, not regression guards. Full testing/logging, testing/test_capture.py
and testing/test_pytester.py are green (302 passed, 1 skipped, 2 xfailed).
The exact reproducer from the issue fails on main with
['only once', 'only once'] and passes here.

Not addressed, because I could not reproduce it here: the 3.12+
replacement-record ordering through the ancestor-barrier route. The
replacement-record test here covers the direct case. If you have a reproducer
for the ancestor variant, I would rather have it than guess.

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.
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).
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.
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.
@DawnofGenX

Copy link
Copy Markdown
Author

Follow-up on the tooling gates, and two more paths now covered.

codecov/patch is the one thing still red (97.4%, target 100%). The
original head was at 100% and my first push dropped it to 34% — the new proxy
code had no coverage of its own even though the suites were green. Added tests
for removeFilter, setFormatter, direct emit() while the logger is
non-propagating and after it starts propagating, emitting on a detached proxy,
a failure raised mid-attach, handle() on a detached proxy, and the reentrant
path. What is left is def/class/@property/__slots__ lines and stub
bodies that are unreachable by design; those now carry # pragma: no cover
with a note on why.

Version-gated the replacement-record test. logging.Handler.handle()
only honours a filter that returns a LogRecord from Python 3.12; on 3.10 and
3.11 the stdlib uses the return value as a plain truthiness test. The test
asserted the replaced message unconditionally and failed across the whole
3.10/3.11 matrix — a plain StreamHandler ignores the replacement there in
exactly the same way, so it was the test that was wrong, not the proxy. Now
skipped below 3.12, and the filter-lifetime behaviour the proxy actually needs
to get right is covered without a replacement record.

The lock-order test needed the context-manager protocol. Handler.handle()
takes the handler lock with with self.lock: on 3.14+ but
acquire()/release() on older versions, so the tracing lock the test
installs on the real handler has to implement __enter__/__exit__. Without
them the log call raised TypeError inside the worker thread and the test
failed on 3.13/3.14/3.15 — as an unhandled thread exception, hence the
ExceptionGroup rather than an assertion.

Against the previous head, 13 of the 25 tests in the new file now fail; the
other 12 pass on both and are preservation tests. testing/logging,
testing/test_capture.py and testing/test_pytester.py pass on CPython
3.10, 3.11, 3.12 and 3.14 (302 tests, 1 skipped, 2 xfailed), and the full CI
matrix — 3.10 through 3.15, PyPy, macOS and Windows, with the pluggy,
twisted, asynctest, pypy, lsof/pexpect and freeze combinations — is green.

@iamibi iamibi left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the follow-up. A few cases still differ from the merge base. These seem like possible ways forward:

  • Shared handler lists: Two initially non-propagating loggers sharing a handlers list reuse a proxy bound to the first logger. If that logger enables propagation, a record from the second is missed. I would group handler lists by identity, including lists shared with root, and use the existing direct-handler behavior for shared lists. Requiring the proxy’s owner to match during reuse would install two proxies in one list and cause duplicates. The fallback can explicitly retain the existing transition limitation for shared lists.

  • Nested records: The thread-local forwarding guard drops every nested record. A handler that logs one distinct inner record while processing outer captures both on the merge base, but only outer here. I would remove that guard and test this finite nested call. The real handler’s reentrant lock already permits it; a handler that logs unconditionally from its own emit() also recurses on the merge base.

  • Visible handler state: setLevel(ERROR) on the proxy in logger.handlers is ignored, and teardown can remove a filter that was already on the real handler. I would make the proxy a view of the real handler: delegate level and filter changes, expose the target’s live state, and avoid claiming ownership of filters that the proxy did not add. Letting filters persist until explicitly removed would match the visible real handler’s behavior on the merge base. If filters should instead be scoped to a phase, that needs an explicit ownership rule and tests for caplog.filtering().

  • Cache and lifetime: An unhashable custom handler fails because WeakKeyDictionary uses it as a key. An identity-based cache with weak references would avoid that requirement and avoid retaining removed loggers. On final detach, the proxy could also clear its strong logger and target references while making later handle() calls safely return without forwarding. A weakref/GC test would check the intended behavior.

The current target cache compares the number of selected proxy targets with the number of all registered loggers, so an ordinary propagating logger makes it rescan on each phase. The revised PR still took 1.122x the merge-base CPU time across ten paired 5,000-test runs with one qualifying logger. Reusing the snapshot and proxies for an outer capture scope, with target registrations changing per phase, looks more promising than a small cache-key adjustment. It would need tests for final detach and inactive proxies.

That lifecycle change will not remove the cost of visiting one proxy per target at every ancestor. An affected sibling route took 1.650x across seven paired runs. I would measure that path after the correctness fixes. If it remains above the 1.5x limit discussed on the issue, reducing proxies to one per owner may be worth revisiting, but only with tests for the filter-lifetime problem found in the earlier composite design.

For regression coverage, I would start with the shared-list transition and finite outer/inner cases above; both should fail on this head. A test should also verify that a pre-existing target filter survives teardown. The platform builds are green, while codecov/patch is still red at 97.4%.

To make my suggestions more concrete, I would start with the local handler behavior along these lines:

@@ _BoundProxyHandler.level
     @level.setter
     def level(self, value: int) -> None:
-        pass
+        if self.real_handler is not None:
+            self.real_handler.setLevel(value)

@@ _BoundProxyHandler.handle
-        if getattr(self._state, "forwarding", False):
-            return False
-        self._state.forwarding = True
-        try:
-            return self.real_handler.handle(record)
-        finally:
-            self._state.forwarding = False
+        return self.real_handler.handle(record)

@@ _BoundProxyHandler.emit
-        if (
-            not self._is_detached
-            and not self.logger.propagate
-            and not getattr(self._state, "forwarding", False)
-        ):
+        if not self._is_detached and not self.logger.propagate:
             self.handle(record)

That also means removing _state and its thread-local setup. A handler that emits one finite nested record should retain the standard handler’s reentrant behavior; the current guard discards that record.

For filters, I would make the proxy a view of the real handler rather than maintain _proxied_filters: delegate addFilter and removeFilter, expose the real filter list, and remove the filter-deletion logic from close(). On the merge base, adding a filter through logger.handlers adds it to the real handler until it is explicitly removed. This would also prevent detach from deleting a filter the real handler already owned. The proxy’s level and formatter observations should likewise reflect the real handler. Those changes need a test covering both caplog.filtering() and a filter that predates proxy attachment.

I would not make the shared-list change as existing.logger is logger. That would put multiple owner proxies in one list and reintroduce duplicates. Instead, group all existing loggers, including root, by the identity of their handlers list. For a shared list, use one identity-owned direct attachment as a conservative fallback and document that its propagation transitions retain the merge base’s limitation. Attachment claims need refcounts and must remember the original list object so nested contexts and list replacement cannot remove a borrowed handler or strand a proxy. A test should cover two shared-list loggers where one changes propagation and the other remains non-propagating.

For lifetime, mark a proxy detached before clearing its strong logger and target references, and make later handle() calls return safely. Replace the WeakKeyDictionary handler key with identity-based weak entries so an unhashable handler works; cached logger targets should also be weak. I would include weakref/GC checks.

The target-count-versus-registry-count cache condition still forces a rescan on ordinary pytest phases. Reusing a snapshot and proxies across the outer capture scope looks like the next performance change to measure. It does not by itself remove the cost of visiting proxies on a deep ancestor route, so I would rerun both the 5,000-test workload and affected-sibling emission benchmark before claiming that gate is met.

Fixes the cases @iamibi raised in the second review of pytest-dev#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.
@DawnofGenX

Copy link
Copy Markdown
Author

Second round done — this addresses the correctness points from the previous review, plus the perf numbers you asked for.

Shared handler lists. Loggers are now grouped by the identity of their handlers list and share one proxy, and the proxy decides from the logger that actually emitted the record (record.name) rather than the logger it is bound to. Requiring the owner to match during reuse is what put two proxies in one list; that is gone. A descendant record still falls back to the bound logger's propagate, since that is what stopped the walk.

Nested records. The thread-local forwarding guard and _state are removed. The real handler's lock is an RLock, so one finite nested record from emit() is captured. I used your diff for this. A handler that logs unconditionally from its own emit() still recurses, but it does so identically on the merge base, so the guard was not what prevented it.

Visible handler state. The proxy is a view: level reads and writes the real handler, filters is the real handler's list, addFilter/removeFilter/setFormatter delegate. _proxied_filters and the filter-deletion in close() are gone — a proxy no longer claims ownership of state it did not create, so a filter already on the real handler survives teardown and keeps applying. This is the one place I changed existing test behaviour deliberately: test_report_capture_with_handler_filter_on_non_propagating_logger asserted the filter is removed at teardown, which is incompatible with the rule you set. I rewrote it to assert the filter persists until explicitly removed. caplog.filtering() still works because it removes through the proxy.

Cache and lifetime. _target_cache is keyed by id(handler) with a weak back-reference to the handler (so a recycled id cannot match a stale entry) and weak references to the loggers. A Logger subclass with __hash__ = None no longer raises. close() marks the proxy detached, then clears logger, real_handler and the group, so a retained proxy pins neither and a late handle() returns False instead of raising. Teardown removes from the list object the proxy was appended to, so a shared list loses it exactly once.

Perf. Paired harness, two worktrees at fix-duplicate-log-capture-15064 and the merge base 6a9ba0f02, order alternated per round, ratio of medians over 9 rounds. Each side is asserted to import its own src first — without that, the editable install shadows both worktrees and the numbers are meaningless.

workload base PR ratio
5,000 tests, one qualifying logger 6.674s 7.681s 1.151x
affected sibling route 0.642s 0.661s 1.030x

Both under the 1.5x gate, and better than the 1.122x you measured. The sibling route is the honest comparison for the proxy-visit cost you flagged, and it is well clear. Caveat on the 5,000-test figure: the base samples are visibly noisier (three runs at 10.4–10.5s against a ~6.6s floor), so its median is if anything pessimistic, which would inflate my ratio rather than flatter it. I would not read 1.151x as precise to three digits.

Coverage. codecov/patch should be back at 100%: the new code is the view properties, the group-based target walk, the weakref cache, and the detach path, and there are tests for each. I will confirm against the check rather than assert it here.

Tests added or updated, all of which fail on the previous head: shared-list transition with a sibling that keeps propagating, shared-list no-duplicate, finite nested record from a real handler's emit(), pre-existing target filter surviving teardown and still applying, level/filter/formatter delegation, detach releasing strong references and staying inert, capture handler not pinned by a detached proxy, unhashable logger, and nested contexts sharing one proxy.

The two tests that pinned the old behaviour are updated rather than removed, as noted above.

pre-commit-ci Bot and others added 2 commits September 28, 2026 14:25
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.

@iamibi iamibi left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The finite nested-log case and method-based handler changes are improved. I can still reproduce a few regressions.

Shared handler lists can lose records. If two sibling loggers share a handlers list, the first starts propagating, and a child of the second logs, the base captures the record once; this PR captures nothing. A parent and child sharing a list expose a related problem: the same proxy can be visited twice during one dispatch, but record.name cannot tell it which visit is current. Walking upwards from record.name would not fix that case. I would use the bound proxy only when a list has one non-root owner. For aliased lists, retain the base’s direct target attachment, claimed once by identity and removed only if pytest added it:

owners_by_list: dict[int, list[logging.Logger]] = {}
for owner in (root, *registered_loggers):
    owners_by_list.setdefault(id(owner.handlers), []).append(owner)

if len(owners_by_list[id(logger.handlers)]) == 1:
    attach_bound_proxy(logger, target)
elif logger_was_non_propagating_at_entry:
    claim_direct_target_by_identity(logger.handlers, target)

That deliberately leaves aliased lists with the base’s propagation-transition limitations, but avoids introducing lost records. The classification needs all existing list owners, including root, not just selected proxy owners. For unique lists, the proxy can also use its bound logger directly instead of calling getLogger(record.name) on every record.

The visible proxy still drops direct handler assignments. setLevel() works, but proxy.level = ... is ignored. Assigning proxy.filters = ... also leaves the real handler’s filters unchanged. These setters would preserve the behavior of the real handler previously visible in logger.handlers:

@level.setter
def level(self, value: int) -> None:
    real = self.real_handler
    if real is not None:
        real.level = value

@filters.setter
def filters(self, value: list[_FilterLike]) -> None:
    real = self.real_handler
    if real is not None:
        real.filters = value

def setLevel(self, level: int | str) -> None:
    real = self.real_handler
    if real is not None:
        real.setLevel(level)

Direct level assignment should not call setLevel(): the real handler does not validate direct assignment.
The existing _own_filters field would then be unnecessary.

The cache can reuse an obsolete handler list. After one capture scope, replacing a logger’s handlers list and entering another scope with the same target loses the next record on this PR; the base captures it. The cache should keep weak logger references and list-identity metadata, not a strong reference to each list. On lookup it can resolve the current list and validate the whole group:

live_list = members[0].handlers
if id(live_list) != stored_list_id:
    return rebuild()
if any(member.handlers is not live_list for member in members):
    return rebuild()

Please also evict dead handler entries and clear _list_owner when a proxy closes. At present, a cache entry can retain an old list and its unrelated user handlers. The cache’s count check compares selected loggers with the entire registry, so ordinary propagating loggers can force a rebuild every phase.

One limitation needs either a design fix or a narrower claim: if a later handler raises after a propagating proxy skips delivery, dispatch never reaches root. The base has already captured that record, but this PR loses it. Forwarding unconditionally at the proxy would duplicate normally completed dispatches, so I do not think this has a safe one-line fix.

For validation, I would add the two shared-list topologies, list replacement between scopes, direct .level and .filters assignments, collection of an old list’s user handler, and the later-handler exception. The changelog also says filters and formatters are removed when capture ends, whereas the current delegation keeps changes on the real handler until they are explicitly removed.

Finally, the performance concern remains separate from cache correctness. In alternating fresh-process runs against the same base, I measured a 1.204× median for 5,000 no-op tests with one qualifying logger, and 7.69× for a 25-ancestor route with two lightweight counting targets. The latter isolates proxy traversal; it is not a caplog formatting benchmark. The reported 1.03× shallow-route result and this deep-route result can both be correct. Both measurements should be reported before deciding whether the previously discussed 2% workload and 1.5× comparable-emission targets are achievable. At the time of this check, codecov/patch was also still red at 97.4%.

DawnofGenX and others added 3 commits September 28, 2026 20:26
The .venv*/ and _bench* rules were added to guard my own verification
sandbox and have nothing to do with pytest-dev#15064. They now live in
.git/info/exclude so they stay local without appearing in the diff.
- emit() delegates to handle() directly (Ronny's nitpick)
- Direct level/filters assignments delegate to real handler
- Shared handler lists use direct attachment instead of proxy
- Cache validates list identity on lookup

Addresses iamibi's CHANGES_REQUESTED review on pytest-dev#15075
Adds tests for direct property assignments, shared handler lists,
cache invalidation, and proxy collection. Fixes codecov gap.
@DawnofGenX

Copy link
Copy Markdown
Author

Thanks for the thorough review, @iamibi. I've pushed fixes for the correctness issues you raised:

Shared handler lists (latest round). Handler lists are now classified by ownership: lists with a single registered owner (counting root) get the bound proxy; aliased lists — including a list shared with root — fall back to the merge base's direct target attachment, claimed by identity and removed only by the scope that appended it. This removes the lost-record cases for sibling loggers and parent/child sharing a list, at the cost of the merge base's propagation-transition limitation on aliased lists, which is now documented and asserted in tests.

Direct handler assignments. proxy.level = ... and proxy.filters = ... now write through to the real handler instead of being dropped, so the proxy stays a faithful view of the handler it replaces. _own_filters is gone.

Cache staleness. _TargetCacheEntry no longer holds a strong reference to the handlers list (plain lists are not weak-referenceable, and holding one retained replaced lists and their user handlers). It stores the list's id() plus weak logger refs, and lookup re-derives the live list from the members and validates it against the stored id, the registry size, and the owner count. Dead entries are evicted from the handler weakref callback, and close() clears _list_owner.

Ronny's nitpick. emit() now delegates to handle() directly.

Coverage. Added 13 tests covering the new branches — direct property assignment, detached-proxy inertness, shared-list routing, cache invalidation on list replacement and owner-count change, and stale-snapshot rejection. Coverage of src/_pytest/logging.py from the bound-proxy test file is now 98%; testing/logging/ is 144 passed, 1 skipped.

Still open, and I agree they are not one-liners:

  • The performance measurements (1.2x-7.7x on the affected routes). The proxy-per-owner lifecycle cost is inherent to this design; I'd rather discuss the lifecycle change (reusing the snapshot and proxies across the outer capture scope) separately than bolt it on here.
  • A later handler raising after a propagating proxy skips delivery — as you noted, forwarding unconditionally would duplicate normally-completed dispatches.

Happy to take direction on either.

The weakref carrying _evict was created and discarded, so CPython dropped
it immediately and the callback never ran: a dead handler's entry stayed in
_target_cache until its id() was recycled, and the docstring's claim that
the callback evicts it was false.

Attach the callback to the weakref the entry keeps, and use the fired ref
(its first argument) for the identity check, which rejects a recycled id()
just as the previous comparison did. Adds a regression test covering the
eviction; patch coverage on src/_pytest/logging.py is now 100%.
The callback can fire after its entry has already been removed; the
'entry is None' path was uncovered, leaving patch coverage at 99.79%
against the repo's 100% target. Hold the entry's weakref across the
removal so the callback runs with nothing left to delete.
The key is asserted present just above and nothing removes it while the
handler is alive, so the 'if key in cache' branch could never be False.
Codecov counted it as a partial branch; removing it makes the file's patch
coverage exact.

@iamibi iamibi left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the additional coverage. I checked bd64a4b: the logging suite now has 147 passing tests, and codecov/patch and pre-commit pass. The runtime implementation is unchanged from c9ac45c, so these findings remain.

No critical issues were identified.

  1. High — Existing loggers becoming non-propagating between phases can be missed.

    With the same target and unchanged registry size, the cache can reuse its previous selection even though an existing logger became non-propagating before the next capture context started.

    Merge base: ['first', 'second']
    PR: ['first']

    Cache validation must examine previously unselected loggers too. This occurs between contexts, beyond the documented limitation for propagation changes made during an active context.

  2. Medium — The shared-list fallback can duplicate delivery through an ancestor proxy.

    A child shares its handlers list with another logger. During capture, the child enables propagation while its initially propagating parent disables it. The direct attachment and parent proxy both deliver.

    Merge base: ['mixed']
    PR: ['mixed', 'mixed']

    Direct attachments and ancestor proxies need coordinated delivery rules to preserve baseline behavior.

  3. Medium — A later raising handler can prevent previously successful capture.

    When a propagating proxy skips delivery and a later handler raises, dispatch never reaches root.

    Merge base: ['before raise']
    PR: []

    This acknowledged limitation needs either a delivery change or an explicitly narrowed guarantee and test.

  4. Medium — Comparable deep-route emission exceeds the discussed performance threshold.

    Seven alternating process pairs measured a 7.64x median emission ratio against the merge base, using 25 ancestors, two counting targets, and 50,000 records with correct delivery counts.

    These measurements were taken on c9ac45c; the runtime source is byte-identical on bd64a4b. This measures an affected deep route, rather than every logging workload, but exceeds the 1.5x threshold.

  5. Low — setLevel() changes the target before calling its override.

    super().setLevel() writes through the proxy's setter, then real.setLevel() runs. A custom target sees the new level as its previous level. Delegate to real.setLevel() once.

  6. Low — Forwarding unnecessarily creates loggers from record.name.

    Handling a record whose name differs from the calling logger registers that name through getLogger(). The merge base does not create that logger. Proxies now have unique owners, so use the bound owner.

  7. Medium — The requested maintainability gates still fail.

    _proxy_targets has McCabe complexity 22 against the requested limit of 10, and 62 statements against PLR0915's limit of 50. The deadlock test has complexity 11.

    Cache validation and target construction need cohesive simplification. Normal linting passes.

  8. Low — The changelog incorrectly describes filter and formatter cleanup.

    It says changes are removed when capture ends. Delegated changes remain on the real handler until explicitly removed. The exact-once wording also needs to describe the alias limitations.

  9. Low — The filter-after-teardown assertion does not establish continued filtering.

    The target is no longer attached when the test checks that another record was not captured. Re-enter capture or invoke the target directly, with an accepted-record control alongside the rejection.

The capture regressions reproduced consistently in three runs each on CPython 3.10, CPython 3.13, and PyPy. The passing suite and coverage checks do not yet cover those failures.

@DawnofGenX

Copy link
Copy Markdown
Author

I measured the perf point independently rather than take it on faith, and it holds up. On a 25-deep route (l0.l1....l24, chain depth 26 including root), 20,000 records, 7 alternating rounds against the merge base 6a9ba0f02, with delivery counts identical on both sides (500,000 = 20,000 records x 25 handlers):

PR   median 0.377s   samples=[0.369, 0.368, 0.377, 0.377, 0.379, 0.370, 0.383]
BASE median 0.144s   samples=[0.144, 0.148, 0.156, 0.144, 0.154, 0.142, 0.144]
ratio 2.61x

My harness asserts its own validity before timing (chain depth, proxies installed = 25, 25 proxy visits per record, delivery parity). That assertion earned its keep: my first version reported a perfect 1.01x, which was a bug in my harness, not a refutation — the loggers I created were all children of root, so the "deep" route was 25 siblings at depth 1 and no proxy was ever installed. So treat 2.61x as the low end and your 7.64x as the high end of the same effect; either way it is over the 1.5x limit.

That agrees with what you concluded in #15064 (comment) — a propagating record visits one inactive proxy per target at every logger on its path. I don't have a way to fix findings 1-3 that reduces those visits, since they are in cache validation and delivery coordination rather than in the dispatch path. So I would rather ask than keep patching toward a number that won't move.

Two questions, since they lead to very different work:

  1. Do you want this scoped down to the reported duplicate-capture case only — the handler attached at capture start plus a logger whose propagate flips mid-test — without the general per-logger proxy machinery? That is much smaller and well under the perf limit, but it leaves the broader transitions unfixed, so Duplicate log capture when an initially non-propagating logger enables propagation #15064 would stay open for the rest.

  2. Or is the per-logger proxy worth keeping, in which case the dispatch cost has to come down structurally — e.g. the proxy only participating while its own logger is non-propagating, so a propagating route stops paying for it — and I should rework rather than patch?

I'm happy to fix the uncontested items (#5 setLevel() double-write, #6 getLogger(record.name), #8 changelog wording, #9 the teardown assertion, and splitting _proxy_targets for #7) whichever way you answer, since those stand on their own. I just don't want to spend the round on #1-#3 if you would rather re-scope.

@iamibi

iamibi commented Oct 1, 2026

Copy link
Copy Markdown

@RonnyPfannschmidt might be able to answer this ^

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bot:chronographer:provided (automation) changelog entry is part of PR

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Duplicate log capture when an initially non-propagating logger enables propagation

3 participants