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

[iamibi]

I ran into a case where one logging call is captured twice if a logger is non-propagating when pytest starts capture and
enables propagation during the test.

Here is a minimal reproducer:

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"]

On current main, caplog.messages is:

['only once', 'only once']

I reconfirmed this on pytest-dev/pytest main at 6a0de9be56365e75ff30d75cee9654739ca95f97.

I can also reproduce the duplicate in captured failure-report sections, --log-cli-level output, and --log-file
output.

Environment

• macOS 26.7 (Apple silicon)
• Python 3.13.13
• pytest 9.2.0.dev0

Installed packages

PyYAML==6.0.3
Pygments==2.21.0
argcomplete==3.7.2
attrs==26.1.0
certifi==2026.7.22
charset-normalizer==3.5.1
coverage==7.16.1
elementpath==5.1.4
execnet==2.1.2
hypothesis==6.168.0
idna==3.20
iniconfig==2.3.0
mock==5.2.0
numpy==2.5.3
packaging==26.3
pexpect==4.9.0
pluggy==1.6.0
ptyprocess==0.7.0
pytest-xdist==3.8.0
pytest==9.2.0.dev0
requests==2.34.2
setuptools==84.0.0
sortedcontainers==2.4.0
urllib3==2.8.0
xmlschema==4.3.2

Why it happens

#14375 fixed #3697 by attaching pytest's active logging handlers to root and to every logger which is non-propagating
when capture begins. That is necessary for a record which cannot reach root.

In the example above, the same handler is therefore attached to both example and root. After example.propagate
becomes true, one Logger.callHandlers walk invokes that handler at example and then invokes the same object again at
root.

The inverse limitation is unchanged: a logger which becomes non-propagating after capture starts may still be missed
because it was not part of the entry snapshot.

Possible scoped fix

I have a local prototype which leaves the real pytest handlers exactly where they are today. A private mixin on pytest's
capture, file, and live-output handlers suppresses later occurrences of that same handler during one standard
Logger.callHandlers invocation.

The important part is the scope: this does not deduplicate records globally or by message/record identity. It identifies
the exact active callHandlers frame, processes the first occurrence normally, and suppresses only later occurrences
from that same frame. Reusing one LogRecord in a later dispatch, reentrant logging, and overlapping threads remain
separate dispatches.

Direct Handler.handle() calls and custom Logger.callHandlers methods keep their native behavior. If the
implementation cannot prove that the caller is the standard dispatcher, it fails open and handles the record normally.

This keeps handler identity, filters, levels, formatters, locking, replacement records, and logger.handlers behavior
in the stdlib path. I tried forwarding handlers first (including one shared proxy per logger), but those designs had
subtle filter/identity semantics and much higher setup and cleanup complexity.

Design question

The tradeoff is that the prototype uses sys._getframe(1), compares its code object with
logging.Logger.callHandlers.__code__, and reads self, c, and record from that frame. It works on the supported
CPython versions and PyPy in local testing, and audit-hook denial falls back to native handling, but it is still an
implementation-sensitive dependency.

PR #10303 approached this family of problems by intercepting Logger.propagate and was closed because the mechanism was
considered too complex/invasive. I have a draft PR ready so the implementation can be reviewed concretely, but I would
like maintainer feedback on two points: is the narrower frame-based approach acceptable here, and is the False -> True
transition behavior something pytest wants to support?

There are two other limits I would document in a PR:

• pruning assumes one active Python f_back chain per OS thread, so native greenlet-style stack switching can fail open
  to a duplicate; and
• after an abnormal nested dispatch on a worker, exact frame identity can keep one returned frame per abandoned
  reentrant level alive until that worker next uses the handler or exits. Sequential failures do not accumulate, but a
  retained record payload can be large.

Clearing another worker's pending frame during context teardown caused a real race and duplicate in an earlier
prototype, so the local implementation keeps route ownership thread-local and treats this bounded retention as an
explicit tradeoff rather than hiding it.

Local evidence

The local patch has focused regressions for all four parent/child propagation states, the mixed child/parent transition,
levels, normal and replacement filters, caplog/report/CLI/file output, record reuse, reentrancy, threads, a true
mid-dispatch fork, custom dispatchers, denied frame access, abandoned routes, concurrent activation-refcount updates,
and cleanup.

These checks were completed against base 7d90c44cca8f2e37dc0ab3d9643a4672a8a3f7f9. The one newer upstream commit does
not touch logging code or tests; I will refresh the final PR evidence after rebasing the draft implementation onto
current main.

• CPython 3.10–3.15 and PyPy logging matrix: all passed (123 tests on 3.12–3.15; 122 plus one expected skip on 3.10,
  3.11, and PyPy)
• free-threaded CPython 3.13.13 logging: 123 passed with the GIL confirmed disabled before and after the run
• Python 3.13 coverage/lsof: 123 passed; logging.py 96%; lsof clean
• full Python 3.13 suite: 4,640 passed, 51 skipped, 15 xfailed, 5 xpassed
• focused stability: 20 fresh processes, 580/580 aggregate tests passed
• Ruff, formatting, mypy, C901 <= 10, PLR0915, and diff check: clean
• temporary mutation harness: 26/26 selected non-equivalent mutants killed, including removal of the activation and
  deactivation counter locks
• lifecycle/thread stress: 1,000 collectible lifecycle cycles; 10,000 sequential abandoned routes bounded and pruned;
  16,000 unique threaded records captured exactly once
• 21-pair HEAD/candidate benchmarks: maximum workload regression 1.868%; maximum emission ratio 1.29631x; 1,000-logger
  context setup 0.238 ms

For this validation pass, the host had the project environments but no tox executable. The matrix, coverage, and lsof
commands therefore ran directly through the provisioned .tox interpreters with PYTHONPATH=src; the tox
packaging/setup phase was not exercised. The separate free-threaded run used an installed CPython 3.13.13t build and
confirmed sys._is_gil_enabled() == False.

I would include the raw benchmark method and results in the PR rather than only reporting the favorable paths.

Related work

• Handling of loggers with propagate=False #3697
• logging: also capture logs from non-propagating loggers #14375
• Automatically attach to non-propagating loggers #10303
• pytest 9.1.0 add handlers to non-propagated loggers #14603
• downstream example: mcp(test[middleware]): Fix caplog double-capture on pytest 9.1.0 tmux-python/libtmux-mcp#83

I repeated open/closed issue and PR searches on 2026-09-19 using both behavior and implementation terms. I also checked
every pytest logging item created or updated since 2026-09-18. The only new logging item was #15062, an unrelated
set_log_path() documentation PR; I did not find a duplicate of this report.

[RonnyPfannschmidt]

we need a bound proxy handler for each logger that hinges on the current value of propagate

[iamibi]

Thanks. I want to make sure I understand the scope before reworking it. Do you mean one bound proxy on every logger that
exists when capture starts, forwarding only while its logger currently has propagate=False? Or one proxy only on each
logger that is non-propagating at setup?

The first also handles an existing parent that changes True -> False while a child changes False -> True. The second
keeps the current True -> False limitation.

[iamibi]

I tested the first interpretation: install a bound proxy on every existing non-root logger and consult that logger's
live propagate value for each record.

I built two pure-Python variants from the same upstream revision:

1. One composite proxy per logger, multiplexing all active pytest output handlers.
2. One proxy per logger and pytest output handler, retained for reuse across test phases.

Both variants handled False -> True, True -> False, and the mixed child/parent transition in focused tests. I did
not continue with either implementation because each crossed a gate chosen before the comparison.

The composite variant failed a public filter-lifetime regression. Inside caplog.filtering(drop), code which adds the
same filter through logger.handlers leaves that filter on the long-lived proxy after caplog.filtering() removes it
from the real caplog handler. Capture from that non-propagating logger is then silently missing in the next test. The
same three-test reproducer passes on current main. Fixing this faithfully would require target-specific filter
ownership and replay, which is the complexity I was trying to avoid with the composite shape.

The per-target variant could isolate that lifetime with narrow identity-linked cleanup, but failed the preselected
1.5x comparable-emission limit. In 21 alternating fresh-process pairs with a 25-level propagating route and two
active targets:

Route	Median candidate/main	Range
Root reachable	1.741x	1.535x to 1.896x
Propagation barrier moved to an ancestor	1.579x	1.530x to 1.679x
Stable non-propagating owner	1.171x	1.075x to 1.398x

The first two comparable paths exceeded the limit in every pair. This is structural: a normal propagating record must
visit one inactive proxy per target at every logger on its path before reaching the real handlers on root.

An independent review also found unfinished lifecycle work in the spike, including tokenized root-level claims,
transactional rollback, root-shared handler-list fallback, replacement-record ordering, target-order reconciliation,
and fork lock reinitialization. Those issues are fixable, but fixing them would not remove the dispatch cost above.

Based on those results, I have stopped the "proxy on every existing logger" approach and will not open a PR for it.

A narrower interpretation still looks worth evaluating: install bound proxies only on loggers which are
non-propagating at capture setup and on their existing ancestors. That should fix the reported False -> True case and
the mixed case where the barrier moves to one of those ancestors, while leaving unrelated logger routes untouched. It
would intentionally retain the missed True -> False limitation for loggers outside those initially affected paths.

Does that narrower owner set match what you had in mind?