logging: capture a record once when a non-propagating logger starts propagating (#15064)

[RonnyPfannschmidt]

Requested by Ronny · project thread

🤖 Written by Claude Opus 5.5 via Claude Code for the pytest maintainers; I prompted it, it did the work, I read it.

Fixes #15064.

Since #14375, catching_logs attaches the capture handler to root and also directly to every logger that is non-propagating at enter. Once such a logger propagates again, a record reaches the handler on the logger and again on root.

Change

• Each logger that is non-propagating at enter, and each of its ancestors, gets a small stand-in handler instead of the capture handler itself.
• At emit time the stand-in walks up from its logger while propagate is true. It forwards to the capture handler only if that walk ends below root at a logger that nothing else delivers on. Otherwise root, or a stand-in further up, delivers the record. Because ancestors have stand-ins, a record that stops at an ancestor which became non-propagating mid-test (for example from a sibling logger) is still captured.
• Loggers that share one handlers list cannot tell their records apart, so such a list gets the capture handler itself, as on main. A stand-in per logger there would capture every record twice.
• The capture handler's own level and filters apply exactly once; the stand-in has none of its own.
• The stand-in overrides handle(), not emit(), and takes no lock (lock = None, as logging.NullHandler does). It therefore cannot deadlock against the target handler's lock. It also skips Handler.__init__, so it is not registered in logging's global handler list.
• There is no cache and no global or class-level state, and nothing is created per record.
• On exit only what was added is removed. Main used to also remove the capture handler from loggers where the user had added it.

Tests

12 new tests on public behaviour (caplog, report sections, live log), across testing/logging/test_fixture.py and test_reporting.py:

• 5 fail on main: the duplicates (the issue case, a nested logger, subtests, live log) and a sibling's record stopping at an ancestor that became non-propagating.
• The raising-handler test also fails on main, which delivers the record anyway; this PR follows stdlib semantics there (see below).
• 6 pass on main and guard against regressions: a logger made non-propagating by a session fixture or by a previous test, no loggers created for foreign record names, a handler also added directly to the logger, the propagation barrier moving to an ancestor, and loggers sharing one handlers list.

Cost

CPython 3.13, medians of 3 runs (emit in ns per record, enter+exit in µs), end to end median of 5:

scenario	main	this PR
emit, unrelated propagating logger	6234	5986
emit, non-propagating leaf, depth 3	5761	5996
emit, propagating sibling, depth 3	6251	6568
emit, propagating sibling, depth 25	7674	12521
emit, logger flipped to propagating	7353	6391
enter+exit, 300 loggers / 3 non-propagating	18	51
enter+exit, 3000 loggers / 30 non-propagating	148	198
2000 tests, 300 loggers / 3 non-propagating	2.09 s	2.18 s

At realistic depths the difference is within noise. The visible cost is one stand-in visit, about 190 ns, per ancestor a propagating record passes on its way to root, so it grows with the depth of the logger tree below a non-propagating logger. An experiment that kept stand-ins on every logger, to also cover the remaining gap below, cost 1.4–1.5x on every emitted record, so this PR does not do that.

Behaviour notes and open questions

• Remaining gap, shared with main. A logger that becomes non-propagating mid-test is missed unless it was non-propagating at enter or is an ancestor of such a logger. A logger below one that was non-propagating at enter is still missed. Session-scoped live log and the log file likewise miss loggers made non-propagating after the session started.
• Shared handlers lists keep main's behaviour, including its duplicate when one of those loggers starts propagating.
• A handler that raises between the flipped logger and root. The record is lost, as stdlib logging loses it for any propagating logger. Main delivered it only because the capture handler sat directly on the logger. The new test pins the stdlib behaviour. Keep it, or drop the test?
• logger.handlers now shows the stand-in, not the capture handler. So caplog.handler in logger.handlers changes from True to False for non-propagating loggers. Filters or a formatter added to the stand-in are ignored. Should it honour filters too?
• Reuse across phases. Is the enter cost acceptable, or should stand-ins be reused across phases? That needs state on LoggingPlugin.

The first commit was verified on CPython 3.14 and 3.11, the follow-ups on 3.13. At the head commit the full suite passes on 3.14, and so does pre-commit run -a.

[nicoddemus]

While this works, it seems to me like a complex solution to solve a somewhat minor problem, my gut feeling was to dedup the messages instead.

I asked Claude if it could come up with a simpler solution, see that below. Feel free to consider it before merging.

---

I think the stand-in approach adds more machinery than #15064 needs. It brings a new handler class, ancestor stand-ins, a fallback for shared handlers lists, and a way to skip Handler.__init__. It also has a few edge cases of its own:

• Records captured twice: when propagating ancestors share a handlers list, the shared-list fallback attaches the real handler to a logger that still propagates. For example, with b.handlers = a.handlers and a.c/b.c non-propagating, a.warning("x") ends up captured twice. On main it is captured once.
• Extra handlers on ancestors: every ancestor of a non-propagating logger now has a stand-in in logger.handlers. That breaks the common if not logger.handlers: configure() guard, and tests that assert on handlers.
• Records lost: if something like dictConfig clears an ancestor's handlers mid-test, its stand-in is removed. A child's stand-in still defers to that ancestor, so the child's records are dropped.

Proposal: keep the current behaviour (the handler attached to root and to every non-propagating logger) and make the handler ignore a record it has already seen while catching_logs is active:

class _HandleOnceFilter(logging.Filter):
    """Lets each record through only once.

    The handler is attached to root and to the loggers which do not propagate
    when capture starts; if one of those starts propagating, its records reach
    the handler twice (#15064).
    """

    def __init__(self) -> None:
        super().__init__()
        self.seen: weakref.WeakSet[LogRecord] = weakref.WeakSet()

    def filter(self, record: LogRecord) -> bool:
        if record in self.seen:
            return False
        self.seen.add(record)
        return True

catching_logs.__enter__ adds this filter to the handler only when it attached to at least one non-propagating logger, and __exit__ removes it. Because logging passes the same LogRecord object to every handler along the propagation path, removing duplicates by identity works no matter how the loggers are arranged. The WeakSet means we never keep records alive. In total it's about 28 lines added to logging.py compared with main.

I tried it locally:

• Your tests for #15064 pass with it: the plain and nested starts-propagating cases, subtests, and live log/log file. I also added one for propagating ancestors that share a handlers list. All the logging tests pass (98).
• Two tests from the PR would go: test_captures_sibling_when_ancestor_becomes_non_propagating and test_raising_handler_stops_capture_as_for_propagating_loggers. They check behaviour only the stand-in design provides. Catching loggers that become non-propagating mid-test is a separate limitation that main already documents as "not worth the trouble". With the direct handler, a record is captured at the first logger, before a parent handler can raise, which is the same as on main.

Trade-offs I'm aware of: the filter shows up in handler.filters while capture is active, and if user code passes the same record object through the handler twice on purpose, the second pass is dropped. Both seem acceptable to me.

---

I pushed the local changes to https://github.com/nicoddemus/pytest/commits/RonnyPfannschmidt/fix-15064-propagation-stand-in (43faeb1) if you want to take it from there. 👍

[nicoddemus]

I think a paragraph stating what this class solves (perhaps along with the issue number) would be useful to have.

[nicoddemus]

Use @override here?