Skip to content

--log-cli discards a sys.stdout swap made after capture started (redirect_stdout, CliRunner.isolation) #14995

Description

@livingstaccato

Under log_cli = true, a stream swap installed after capturing started — contextlib.redirect_stdout,
click.testing.CliRunner.isolation, a fixture of one's own — is discarded the first time a log record
suspends capturing. Everything written afterwards goes to pytest's own buffer rather than the stream the
caller installed, so the caller sees nothing while the text appears under Captured stdout call. No error
is raised, and assertions about absent output pass vacuously.

The cause is that SysCaptureBase.resume reinstates the stream capture installed at start rather than
the one that was in place when suspend ran.

Reproduction

Standard library only — no third-party packages:

# test_swap.py
import contextlib
import io
import logging


def test_redirect_stdout_survives_a_log_record() -> None:
    captured = io.StringIO()
    with contextlib.redirect_stdout(captured):
        logging.getLogger("some.library").warning("a record reaches the root logger")
        print("inside the redirect")
    assert captured.getvalue() == "inside the redirect\n"
$ pytest test_swap.py -o log_cli=false
1 passed

$ pytest test_swap.py -o log_cli=true
1 failed
E       AssertionError: assert '' == 'inside the redirect\n'

The print lands in pytest's capture buffer instead of captured. Nothing is lost — it
appears under Captured stdout call — but the code that installed the redirect never sees it.

Cause

SysCaptureBase.suspend restores the stream saved at __init__, and resume reinstates
self.tmpfile, the stream capture installed at start. Neither reads what is actually in
sys.stdout at the time:

# src/_pytest/capture.py
def suspend(self) -> None:
    self._assert_state("suspend", ("started", "suspended"))
    setattr(sys, self.name, self._old)
    self._state = "suspended"

def resume(self) -> None:
    self._assert_state("resume", ("started", "suspended"))
    if self._state == "started":
        return
    setattr(sys, self.name, self.tmpfile)
    self._state = "started"

So a stream swap installed after capture started is dropped by the first suspend/resume cycle:

capture.start()      # sys.stdout = capture.tmpfile
sys.stdout = mine    # redirect_stdout, CliRunner.isolation, a fixture of your own
capture.suspend()    # sys.stdout = the stream saved at __init__
capture.resume()     # sys.stdout = capture.tmpfile      <- `mine` is gone

--log-cli turns that from a corner case into a per-record event. Traced by replacing
sys.__class__ with a ModuleType subclass whose __setattr__ records a stack, so every
assignment to sys.stdout during a failing test is captured. The assignment that drops the
swap arrives through (line numbers from 9.1.1; the same frames on main):

_pytest/logging.py:946   _LiveLoggingStreamHandler.emit
_pytest/capture.py:848   CaptureManager.global_and_fixture_disabled
_pytest/capture.py:790   CaptureManager.suspend_global_capture
_pytest/capture.py:671   MultiCapture.suspend_capturing
_pytest/capture.py:546   FDCaptureBase.suspend
_pytest/capture.py:418   SysCaptureBase.suspend   ->  setattr(sys, self.name, self._old)

_LiveLoggingStreamHandler sits on the root logger, so any record reaching it from inside
a redirect ends the swap — from any library, at any depth.

A test in pytest's own idiom

This fails on 9.1.1 and on main:

from _pytest.pytester import Pytester


def test_capture_suspend_preserves_a_stream_swapped_in_after_start(
    pytester: Pytester,
) -> None:
    """A live-log record must not cost a test the stream it redirected to."""
    pytester.makepyfile(
        """
        import contextlib
        import io
        import logging

        def test_redirect_stdout_survives_a_log_record():
            captured = io.StringIO()
            with contextlib.redirect_stdout(captured):
                logging.getLogger("some.library").warning("reaches the root logger")
                print("inside the redirect")
            assert captured.getvalue() == "inside the redirect\\n"
        """
    )

    result = pytester.runpytest_subprocess("-o", "log_cli=true")

    result.assert_outcomes(passed=1)

Suggested fix

Have suspend record the stream actually in place and resume return it, which is what the
two methods already read as doing — global_and_fixture_disabled describes itself as
"temporarily disable", and temporary implies returning to what was displaced:

def suspend(self) -> None:
    self._assert_state("suspend", ("started", "suspended"))
    # Suspending while suspended is legal, and the stream sitting there then
    # is the one suspend itself installed -- not a swap worth remembering.
    if self._state == "started":
        self._swapped_in = getattr(sys, self.name)
    setattr(sys, self.name, self._old)
    self._state = "suspended"

def resume(self) -> None:
    self._assert_state("resume", ("started", "suspended"))
    if self._state == "started":
        return
    setattr(sys, self.name, getattr(self, "_swapped_in", self.tmpfile))
    self._state = "started"

done is deliberately untouched: it still restores the stream capture replaced, so a swap
left behind by a test cannot outlive it.

Dropping exactly that into a conftest.py turns the failing test above green, which is
reproducible without applying a patch to a checkout:

def test_the_proposed_change_makes_it_pass(pytester: Pytester) -> None:
    pytester.makepyfile(TEST)          # the test file above
    pytester.makeconftest(PATCH)       # the two methods above

    result = pytester.runpytest_subprocess("-o", "log_cli=true")

    result.assert_outcomes(passed=1)   # passes

Verified against a pytest-dev/pytest checkout at main (9.2.0.dev293, commit 3fd8675d6),
with the change applied to src/_pytest/capture.py and five regression tests added to
testing/test_capture.py:

baseline with the change
full suite 1 failed, 4549 passed, 51 skipped, 15 xfailed, 5 xpassed, 1 error 1 failed, 4554 passed, 51 skipped, 15 xfailed, 5 xpassed, 1 error
testing/test_capture.py + testing/logging/ 219 passed, 1 skipped, 1 xfailed 219 passed, 1 skipped, 1 xfailed
pre-commit on both files ruff check, ruff format, mypy, codespell: all pass

The only delta is the five added tests. The one failure and one error are present on main
before the change and are unrelated to capture:
testing/test_doctest.py::TestDoctests::test_fixture_doctest_skip_has_line_number and
testing/test_legacypath.py::test_cache_makedir.

Three of the five added tests fail without the change and two pass either way, those two being
the ones asserting the existing behaviour is preserved.

Separately, run as a monkeypatch across a downstream suite, capsys, capfd, caplog,
capsys.disabled() and repeated suspend/resume behave identically under --capture=fd,
sys and tee-sys, with log_cli on and off.

Where this shows up in practice

click.testing.CliRunner.isolation() swaps sys.stdout, so a single log line emitted anywhere
inside an invoked command leaves result.output empty while the command's output is real and
visible in pytest's own capture. The failure is silent, and assertions of the form
assert "--debug" not in result.output pass vacuously once the output is empty. That is what
led here; it is context rather than evidence — the reproductions above stand on their own.

Relation to #7148

Same context manager, different defect. #7148 was global_and_fixture_disabled resuming
capture it had not suspended, fixed in #7651 for 6.0.2. This one is the suspend/resume pair not
preserving a stream swap it did not install, and is present on 9.1.1 and on main.

Environment

pytest 9.1.1 (reported), and main at 9.2.0.dev293 / 3fd8675d6 (verified)
Python 3.13.3
macOS 26.6.2 (arm64)

The change and its tests are written and pass against main; a PR can follow as soon as
there is an issue number to name the changelog file after.

Activity

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions