Output appears in "Captured stderr call" but is unavailable in capsys or capfd

[butla]

Environment

Pytest version: 5.2.1
Operating system: Kubuntu 18.04.3 LTS
Pip list:

Package            Version
------------------ -------
atomicwrites       1.3.0
attrs              19.3.0
importlib-metadata 0.23
more-itertools     7.2.0
packaging          19.2
pip                19.3.1
pluggy             0.13.0
py                 1.8.0
pyparsing          2.4.2
pytest             5.2.1
setuptools         41.4.0
six                1.12.0
wcwidth            0.1.7
wheel              0.33.6
zipp               0.6.0

Description

It seems that output can appear in "Captured stderr call" but be unavailable to capsys or capfd, which can be a bug? It's definitely weird.

I came accross this issue while trying to test my logging setup. This is a minimal example I came up with (available at https://github.com/butla/experiments/tree/master/pytest_capture_log_error):

# a_file.py
import logging

logging.basicConfig(level=logging.INFO)

LOG_MESSAGE = "the message we'll look for in the test"

_log = logging.getLogger(__name__)


def bla():
    _log.info(LOG_MESSAGE)
    return 5

# test_file.py
import a_file

def test_a(capsys):
    assert a_file.bla() == 5
    assert a_file.LOG_MESSAGE in capsys.readouterr().err

The test fails and it shows

------------------------------------------ Captured stderr call ------------------------------------------
INFO:a_file:the message we'll look for in the test

but both capsys and capfd show out and err to be empty.

I would use caplog, but the messages I get from it don't conform to the log configuration that I have set up in my original app, so I decided to just use stderr.

[asottile]

this is pretty strange, it probably should work with capfd (I could see why it wouldn't with capsys due the way the logging module works)

the test passes with -s -- definitely feels like some sort of bug

[butla]

Oh yeah, passing -s and using capfd fixture makes it pass...

[blueyed]

Related (I think): #3448

[MarcoGorelli]

This is just for stderr - if I modify a_file.py to have

def bla():
    print("foo")
    _log.info(LOG_MESSAGE)
    return 5

and test_file.py to have

def test_a(capsys):
    assert a_file.bla() == 5
    assert "foo" in capsys.readouterr().out
    assert a_file.LOG_MESSAGE in capsys.readouterr().err

then only the third assertion fails.

Currently looking into this

[blueyed]

@MarcoGorelli
This is due to logging using stderr, isn't it?
It picks up the mocked away stderr from pytest's capturing likely, i.e. it would also work if you'd do the logging setup in the test.

[MarcoGorelli]

Just as an update - I've been studying capture.py, but still haven't figured out where the issue might lie. If this is urgent, anyone more experienced following along is welcome to take over.

Else I'll keep hacking away :)

[ahal]

I'm seeing this issue with stdout logged via a custom logging module we have. Our logger is basically just calling sys.stdout.write(); sys.stdout.flush() at the end of the day.

[larsks]

@MarcoGorelli did you ever figure this one out? I just ran into the same problem and found this issue :).

[MarcoGorelli]

Nope, I gave up on this 😳

[taranlu-houzz]

I am also having this issue. Would like to be able to use capsys.readouterr to test format of log messages that change format based on whether or not the message contains a newline.

[asottile]

I have a simpler reproduction that only succeeds with -s -- I'll see what I can do to fix this:

import sys

x = sys.stdout.buffer

def test(capfd):
    x.write(b'wat\n')
    x.flush()
    assert capfd.readouterr().out

[RonnyPfannschmidt]

@asottile as structurally the issue is - user broke the weak wys we have in python, im inclined to condier this one as something to only warn about

@asottile i also do wonder about closing the issue as invalid stdio usage instead of using logcapture

[asottile]

@RonnyPfannschmidt my reproduction above does not use logging -- this is definitely something capfd should be able to handle. pytest almost-mockingly displays "Captured stdout" "wat" when it fails so pytest definitely could capture it properly!

[asottile]

ok so I took a bit of a look at this on stream. I can get it to do what I want by disabling the syscapture part of capfd / capfdbinary. This has one downside in that flushing needs to happen whenever the file descriptors are changed when dealing with print because buffering.

I have a bit of a work-in-progress version of this branch, but it requires a lot of changes to the testsuite (not sure whether it's actually a good change or not given how many tests it broke?) -- I also have to change a lot of tests to run in a subprocess so they don't interfere with the tests themselves (because syscapture is no longer being reset)

here's that patch though, or at least the start of it: https://github.com/pytest-dev/pytest/pull/new/wip_fix_capfd

[chamini2]

I am wondering what happend with this @asottile ?

[asottile]

I got busy and never got around to finishing that branch above -- I also wasn't 100% on whether it's ultimately the right decision (since the test adjustments really point out how much it potentially would break consumers)

[chamini2]

I understand. turning off the syscapture part maybe does not really make sense and this needs a different solution?

[Kache]

I think I ran into the same issue, my repro:

# foo.py
print("hello")

Surprisingly:

from importlib import import_module

def test_prints_hello(capfd):
    import_module('foo')
    out, err = capfd.readouterr()

    assert out == ""  # will pass
    # assert out == "hello\n"  # and so will this one (expected), but only if above line is commented out

edit Although this is still happening in the particular project I used, I'm not able to reproduce this in an fresh & independent venv. Very strange...

[vakorol]

I've bumped into this, too. The STDERR output is shown in pytest's output in the "Captured stderr call", but capsys does not seem to have captured it.

platform linux -- Python 3.10.8, pytest-7.2.1, pluggy-1.0.0
plugins: django-4.5.2, Faker-16.8.1, cov-4.0.0, celery-0.0.0

And as was noted above, the test passes when using capfd and running with the -s command-line argument.

[mauvilsa]

Any reason why it is not possible to pass a logger instance to pytest's caplog? The only option is to give a logger name. However, that does not work in some cases as seen in this long thread. And capsys or capfd is not what I need either. In unittest assertLogs it is possible to give a logger. Just wonder why it wasn't done similarly in pytest.

For the record, what I ended up doing was the following context manager:

@contextmanager
def capture_logs(logger: logging.Logger):
    with ExitStack() as stack:
        captured = StringIO()
        for handler in logger.handlers:
            if isinstance(handler, logging.StreamHandler):
                stack.enter_context(patch.object(handler, "stream", captured))
        yield captured

And then in a test:

with capture_logs(logger_being_tested) as logs:
    ...
assert ... in logs.getvalue()

[PaleNeutron]

Add this snippet to pyproject.toml fix this problem.

[tool.pytest.ini_options]
addopts = "--capture=tee-sys"

But why it is so hard to fix it in passed 3 years?

[asottile]

if it's so easy why don't you fix it?

[Feuermurmel]

@asottile You're not helping by lashing out at people. You could have constructively encouraged them to provide input on fixing this issue instead.

[RonnyPfannschmidt]

i think we need to split this issue a bit - the initial issue is no longer valid - configuring logging with just the defaults is broken and non-fixable + disables pytests logcapture

logcapture fixtures should be used

logging should onl be configured by an application, not for testrunning

pytest will not do logcapture if logging is configured as the footguns from the past still haunt me at least

[suhasdotcom]

I got the same unexpected behavior of capsys in my project . After going through this discussion I tried the following approaches:

1. Use the -s flag with capfd

   I used the hack given by @asottile

   this is pretty strange, it probably should work with capfd (I could see why it wouldn't with capsys due the way the logging module works)

   the test passes with -s -- definitely feels like some sort of bug

   to get get it working and it worked.

2. Configure pyproject.toml to --capture=tee-sys

   I used the hack given by @PaleNeutron and added:

   [tool.pytest.ini_options]
   addopts = "--capture=tee-sys"

   in pyproject.toml and it worked.

3. Implement custom marker to mark the test which'll need this

   I have also tried to implement markers to mark the test that'd be needing this so that I wouldn't need to make a global change in the configuration of pytest, here's the marker:
   conftest.py:

   # conftest.py
   def pytest_runtest_setup(item):
       """
       Effectively sets the -s flag on the test function
       """
       if "needs_output" in item.keywords:
           item.config.option.capture = "no"

   pyproject.toml:

   # pyproject.toml
   # ...
   [tool.pytest.ini_options]
   markers = [
     # Creating htis marker because facing the issue detailed in this GitHub discussion:
     #   https://github.com/pytest-dev/pytest/issues/5997
     "needs_output: Tests that require the -s flag"
   ]

   test_file.py:

   # test_file.py
   # ...
       @pytest.mark.needs_output
       def test_does_not_accept_a_non_directory(self, capfd, dummy_file):
           # Had to use capfd with -s instead of capsys because of a bug in capsys where it doesn't capture
           # logger's stderr. The bug is being discussed on https://github.com/pytest-dev/pytest/issues/5997
           with pytest.raises(SystemExit):
               implant_process_stage(dummy_file)
           stderr = capfd.readouterr().err
           assert NOT_A_DIRECTORY in stderr

   The marker approach didn't work

Since I don't want to make a global change in my project's pytest configuration I am more biased towards an approach which wouldn't need global setting, like the marker approach. Is there a better way to do this?
Or better yet, is the issue fixed now?

[zhiweigan]

I ran into an issue where I was expecting this test to pass:

<some code that logs stuff>
...
out, err = capsys.readouterr()
assert len(out) > 0    

Where the following code failed:

from sys import sysout as sys_stdout
...
console_handler = StreamHandler(sys_stdout)
console_handler.setFormatter(formatter)
console_handler.setLevel(self._log_level)
self._logger.addHandler(console_handler)

But this passed:

import sys
...
console_handler = StreamHandler(sys.stdout)
console_handler.setFormatter(formatter)
console_handler.setLevel(self._log_level)
self._logger.addHandler(console_handler)

I haven't had a chance to look into why this might be the case but I figure I'll put this here in case other people run into a similar issue. Before arriving at this solution, I tried the -s and --capture=tee-sys solutions mentioned above and they both worked for me, which was consistent with @suhasdotcom's comment.

[RonnyPfannschmidt]

Never use non lazy/recomputed references to sys.stdout

Studio recapture replaces those and closes old ones dozens of times

[Hibbie89]

Any reason why it is not possible to pass a logger instance to pytest's caplog? The only option is to give a logger name. However, that does not work in some cases as seen in this long thread. And capsys or capfd is not what I need either. In unittest assertLogs it is possible to give a logger. Just wonder why it wasn't done similarly in pytest.

For the record, what I ended up doing was the following context manager:

I ran into the problem of capsys/capfd not capturing log entries if the log was written to sys.stdout by a StreamHandler while also writing to file. All other solutions in this thread (and many others) did not work, so I wanted to highlight this also in conclusion with the setup I am needing (which I also did not found yet in issues).

File minimal_example_pytest_fail.py

import logging
import pathlib
import sys

_main_log_path = pathlib.Path.home() / f'Desktop/TMP/log.log'
_main_log_path.parent.mkdir(exist_ok=True)
logging.basicConfig(
    filename=_main_log_path, 
    filemode='w',
    level=logging.INFO,
    force=True,
)
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
\# Add handler that also prints everything above level "WARNING" to stdout
handler_stdout = logging.StreamHandler(sys.stdout)
handler_stdout.setLevel(logging.WARNING)
logger.addHandler(handler_stdout)
    
def logger_error():
    logger.error('Errormessage')

file test_minimal_example.py

import logging
from . import minimal_example_pytest_fail
from io import StringIO
from contextlib import ExitStack, contextmanager
from unittest.mock import patch

@contextmanager
def capture_logs(logger: logging.Logger):
    with ExitStack() as stack:
        captured = StringIO()
        for handler in logger.handlers:
            if isinstance(handler, logging.StreamHandler):
                stack.enter_context(patch.object(handler, "stream", captured))
        yield captured

def test_error(caplog):
    with capture_logs(minimal_example_pytest_fail.logger) as logs:
        minimal_example_pytest_fail.logger_error()
        assert 'Errormessage' in caplog.text
        assert 'Errormessage' in logs.getvalue()
        
def test_error_fails(caplog, capfd):
    minimal_example_pytest_fail.logger_error()
    out, err = capfd.readouterr()
    assert 'Errormessage' in caplog.text
    assert 'Errormessage' in out

test_error passes, while test_error_fails fails with the following output:

============================= test session starts =============================
platform win32 -- Python 3.11.7, pytest-8.2.2, pluggy-1.5.0
PySide6 6.6.1 -- Qt runtime 6.6.1 -- Qt compiled 6.6.1
Using --randomly-seed=3440409508
rootdir: c:\Users\jakob\Documents\Python\test
plugins: cov-5.0.0, qt-4.4.0, randomly-3.15.0
collected 2 items

test_minimal_example.py .F                                               [100%]

================================== FAILURES ===================================
______________________________ test_error_fails _______________________________

caplog = <_pytest.logging.LogCaptureFixture object at 0x000001CCB1B74050>
capfd = <_pytest.capture.CaptureFixture object at 0x000001CCB1B74150>

    def test_error_fails(caplog, capfd):
        minimal_example_pytest_fail.logger_error()
        out, err = capfd.readouterr()
        assert 'Errormessage' in caplog.text
>       assert 'Errormessage' in out
E       AssertionError: assert 'Errormessage' in ''

test_minimal_example.py:36: AssertionError
---------------------------- Captured stdout call -----------------------------
Errormessage
------------------------------ Captured log call ------------------------------
ERROR    test.minimal_example_pytest_fail:minimal_example_pytest_fail.py:33 Errormessage
=========================== short test summary info ===========================
FAILED test_minimal_example.py::test_error_fails - AssertionError: assert 'Er...
========================= 1 failed, 1 passed in 0.10s =========================
Finished running tests!

So I got a workaround. But using fixtures would be better, as they are basically also context managers. Passing data to fixtures is possible with markers and the request fixture, so I modified my tests accordingly.

import logging
from io import StringIO
from contextlib import ExitStack, contextmanager
from unittest.mock import patch
import pytest
from . import minimal_example_pytest_fail

@pytest.fixture
def capture_stdout(request):
    logger = request.node.get_closest_marker("fixt_data").args[0]
    with ExitStack() as stack:
        captured = StringIO()
        for handler in logger.handlers:
            if isinstance(handler, logging.StreamHandler):
                stack.enter_context(patch.object(handler, "stream", captured))
        yield captured
        
@pytest.mark.fixt_data(minimal_example_pytest_fail.logger)
def test_error_with_fixture(caplog, capture_stdout):
    with capture_stdout as logs:
        minimal_example_pytest_fail.logger_error()
        assert 'Errormessage' in caplog.text
        assert 'Errormessage' in logs.getvalue()

Edit 1: Formatting issues resolved
Edit 2: Adding solution for fixture