pytest-dev / pytest-dev/pytest

Logging StreamHandler fails when set up in fixture with capsys

Open
#10,486 7 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

plugin: capture
Dominant language
Python
Stars
14.5k
Forks
3.4k
Avg merge
2d 9h
Merged PRs (30d)
35

Description

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

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by running the two minimal examples, especially the fixture using capsys and the StreamHandler assigned to sys.stdout. Read the pytest fixture and capture behavior involved in capsys to determine why sys.stdout differs between fixture setup and the test. Done means the reported fixture scenario behaves consistently and has a regression test.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
testing
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.