Logging StreamHandler fails when set up in fixture with capsys

[tobinus]

Bug description

I'm running into an issue where an instance of logging.StreamHandler fails to write to its assigned stream, but only when we initialise it in a fixture. If we initialise it inside the test itself, it works as expected.

It seems to me that the issue here is the value of sys.stdout. It seems to change some time between the fixtures being run and the test itself running. When StreamHandler is set up during a fixture, we give it a value of sys.stdout which is later closed, since sys.stdout is superseded by a new value.

Expected behaviour

I thought I could just move my setup code to a fixture instead of needing to call the setup code in every test, without any big changes to how that setup code is run. In my thinking, capsys will do its magic with sys.stdout when it is run, so that when I create fixtures that depend on capsys, sys.stdout should already be set to the value it will have during the test (since that is how any other user-created fixture works).

Minimal example with StreamHandler

Minimal example:

import logging
import sys

import pytest

ROOT_LOGGER = logging.getLogger()


def set_up_logging():
    stream_handler = logging.StreamHandler(sys.stdout)

    ROOT_LOGGER.addHandler(stream_handler)
    ROOT_LOGGER.setLevel(logging.INFO)


@pytest.fixture()
def logger_setup(capsys, reset_handlers_for_each_test):
    set_up_logging()


@pytest.fixture(autouse=True)
def reset_handlers_for_each_test(capsys):
    existing_handlers = list(ROOT_LOGGER.handlers)
    yield
    ROOT_LOGGER.handlers = existing_handlers


def test_with_setup_in_test(capsys):
    set_up_logging()  # works!

    ROOT_LOGGER.info("Hi")

    check_captured_output(capsys)


def test_with_setup_in_fixture(logger_setup, capsys):
    ROOT_LOGGER.info("Hi")  # fails (error message printed to stderr)

    check_captured_output(capsys)


def check_captured_output(capsys):
    outerr = capsys.readouterr()
    out = outerr.out
    err = outerr.err
    assert err == ""
    assert out != ""

test_with_setup_in_test passes, while test_with_setup_in_fixture fails. Its error message:

logger_setup = None, capsys = <_pytest.capture.CaptureFixture object at 0x7f45e208f1f0>

    def test_with_setup_in_fixture(logger_setup, capsys):
        ROOT_LOGGER.info("Hi")

>       check_captured_output(capsys)

test_config_in_test_minimal.py:39:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

capsys = <_pytest.capture.CaptureFixture object at 0x7f45e208f1f0>

    def check_captured_output(capsys):
        outerr = capsys.readouterr()
        out = outerr.out
        err = outerr.err
>       assert err == ""
E       assert '--- Logging ...guments: ()\n' == ''
E         + --- Logging error ---
E         + Traceback (most recent call last):
E         +   File "/usr/lib/python3.10/logging/__init__.py", line 1103, in emit
E         +     stream.write(msg + self.terminator)
E         + ValueError: I/O operation on closed file.
E         + Call stack:
E         +   File "/redacted/venv/bin/pytest", line 8, in <module>...
E
E         ...Full output truncated (66 lines hidden), use '-vv' to show

test_config_in_test_minimal.py:46: AssertionError
-------------------------------------------------------------------------------------------------------- Captured log call ---------------------------------------------------------------------------------------------------------
INFO     root:test_config_in_test_minimal.py:37 Hi
===================================================================================================== short test summary info ======================================================================================================
FAILED test_config_in_test_minimal.py::test_with_setup_in_fixture - assert '--- Logging ...guments: ()\n' == ''

Minimal example demonstrating that sys.stdout changes

import sys

import pytest


@pytest.fixture()
def stdout(capsys):
    return sys.stdout


def test_stdout_fixture(stdout, capsys):
    assert stdout is sys.stdout

The test fails.

Interestingly, this test passes if I remove capsys.

My environment

Output of pip list:

Package        Version
-------------- -------
attrs          22.1.0
exceptiongroup 1.0.1
iniconfig      1.1.1
packaging      21.3
pip            22.2.2
pluggy         1.0.0
pyparsing      3.0.9
pytest         7.2.0
setuptools     63.2.0
tomli          2.0.1

I'm running Ubuntu 20.0.5 in Windows Subsystem for Linux

[RonnyPfannschmidt]

It's a expected breakage with output capture that cleans up after itself, use log capture directly

[tobinus]

It's a expected breakage with output capture that cleans up after itself, use log capture directly

Using the log capture would not test what we wish to test. We have an elaborate logging setup with structured logging (JSON) and wish to test that the application is configured to log properly. I did not include this in the minimal example.

If this is expected breakage, then that expectation is not communicated at all. I'm surprised by this because all fixtures I've used up to this point do some work to return a value, and then they may do some work when the test is done running. In the case of capsys, it suddenly starts doing work after it has returned a value, but before the test is run. Since the logger setup fixture depended on capsys, I thought capsys obviously wouldn't make any changes before the test was done running. Is this fixture functionality explained anywhere..? How would I write a fixture that does some work between fixture initialisation and the test starting to run? You cannot do that with the yield style of fixture definition, I assume?

[tobinus]

For most tests, I think it's fine to use the log capture fixture to test what is logged. For the one test that tests whether the log handlers are set up correctly, I'll just do the setup inside the test itself and not in a fixture, so that sys.stdout is set by capsys already.

There may be good reasons for capsys making changes to sys.stdout right when the test is about to start, so I do not know if moving those changes to before the capsys fixture returns/yields a value is the right solution or not. But at the very least I hope the documentation can mention this quirk, since capsys seems to break all the established rules for how fixtures work, and that caused me and a colleague a lot of time figuring out why our test failed in mysterious ways.

Perhaps sys.stdout and sys.stderr could be set to a dummy stream between capsys running and the test starting, which could throw an exception with a specific message about how using those streams in fixtures is not supported when combined with capsys?

[tysonholub]

We have an elaborate logging setup with structured logging (JSON) and wish to test that the application is configured to log properly.

We are noticing the exact same issue implementing tests for our JSON logging to stdout using the capsys fixture.

[RonnyPfannschmidt]

I recommend using a stream handler that dynamically fetches the stream

[tysonholub]

Thanks for the suggestion. It inspired toward this approach. I'm not sure if this is what you meant exactly, but I'll share a gist:

Logging setup

BASE_LOG_HANDLER = logging.StreamHandler(sys.stdout)
logging.root.handlers = [BASE_LOG_HANDLER]

Test fixture

@pytest.fixture
def mock_log(app):
    with mock.patch.object(BASE_LOG_HANDLER.stream, "write") as _mock_log:
        yield _mock_log

Test

def test_base_log_handler(mock_log):
    logging.root.debug("test")
    assert "test\n" in mock_log.call_args.args

[RonnyPfannschmidt]

https://github.com/python/cpython/blob/3b4f8fc83dcea1a9d0bc5bd33592e5a3da41fa71/Lib/logging/__init__.py#L1237-L1251