stdout capture (capsys) does not seem to work with real-time cli logging

[Sup3rGeo]

• Minimal example if possible

Using the snippet from https://docs.pytest.org/en/latest/capture.html#accessing-captured-output-from-a-test-function, just adding a logging call before the second print:

import logging
import sys

logger = logging.getLogger(__name__)

def test_myoutput(capsys):  # or use "capfd" for fd-level
    print("hello")
    sys.stderr.write("world\n")
    captured = capsys.readouterr()
    assert captured.out == "hello\n"
    assert captured.err == "world\n"

    logging.info("something")

    print("next")
    captured = capsys.readouterr()
    assert captured.out == "next\n"

Running with pytest --log-cli-level=INFO makes the test fail as the captured.out variable comes empty.

---

• pip list of the virtual environment you are using

venv-clean-py1) D:\VM\pytest-capsys-logging-bug>pip list
DEPRECATION: The default format will switch to columns in the future. You can use --format=(legacy|columns) (or define a format=(legacy|columns) in your pip.conf under the [list] section) to disable this warning.
atomicwrites (1.1.5)
attrs (18.1.0)
colorama (0.3.9)
more-itertools (4.3.0)
pip (9.0.1)
pluggy (0.7.1)
py (1.5.4)
pytest (3.7.1)
setuptools (28.8.0)
six (1.11.0)

• pytest and operating system versions

• pytest (3.7.1)

• windows 10

[Sup3rGeo]

Investigating (it took a while, I find it rather complex) it seems that the problem is on this part on the logging module:

pytest/src/_pytest/logging.py

Lines 574 to 591 in 7d4c4c6

	def emit(self, record):
	if self.capture_manager is not None:
	self.capture_manager.suspend_global_capture()
	try:
	if not self._first_record_emitted:
	self.stream.write("\n")
	self._first_record_emitted = True
	elif self._when in ("teardown", "finish"):
	if not self._test_outcome_written:
	self._test_outcome_written = True
	self.stream.write("\n")
	if not self._section_name_shown and self._when:
	self.stream.section("live log " + self._when, sep="-", bold=True)
	self._section_name_shown = True
	logging.StreamHandler.emit(self, record)
	finally:
	if self.capture_manager is not None:
	self.capture_manager.resume_global_capture()

So, it seems that logging does suspend_global_capture() and then resume_global_capture() without taking into account that stdout and stderr might have the capsys streams in place.

When that is the case, logging (in the functions mentioned above) will remove the current capsys capture but mistakenly replace it back with the global capture, instead of the capsys that was in place.

Deactivating the fixture capture, changing the code to this would work in theory:

    def emit(self, record):
        if self.capture_manager is not None:
            self.capture_manager.deactivate_fixture()
            self.capture_manager.suspend_global_capture()
        try:
            (--- etc ---)
        finally:
            if self.capture_manager is not None:
                self.capture_manager.resume_global_capture()
                self.capture_manager.activate_fixture()```

However, deactivate_fixture() and activate_fixture() on CaptureManager need originally an item object as argument, which the logging handler above of course don't have.

The first solution I could think about was to add another attribute to CaptureManager to keep track of current item and change the activate/deactivate function to use this attribute whenever the function is called without arguments.

I actually implemented it and it makes the test I posted in the issue body pass, but it could be that a better solution exists, especially concerning tracking the last item in CaptureManager.

I will now make a PR so we can discuss better around the code.

[Sup3rGeo]

Unfortunately some glitches are still present - for instance it was always snapping (consuming) the output whenever we suspended global capture, therefore there was some loss of information along the way.

I have already made some a test case and some changes/refactoring and will create another PR for this.

[Sup3rGeo]

Closed by #3832