BUG: live log interferes with doctests

[nazarewk]

I'm having trouble mixing live-logs (log_cli = true) with --doctest-modules,
namely doctest reports that there was no output at all, but in fact there is True on stdout reported.

Full setup demonstrating the issue available at this gist https://gist.github.com/nazarewk/5c10b1c1842ee8561ace45976d1211c6

Commenting out log_cli line in pytest.ini makes the tests pass

[twmr]

Thx for this report @nazarewk.

I think the only way to fix this issue is to disable live logging for doctests. The problem is that the live log handler writes to sys.stdout, which is overridden in the docest stdlib module.

[pavel-kirienko]

I was about to open a new issue when GitHub informed me that there is a similar one. Thank you, GitHub. For the benefit of posterity, please find my MWE below.

---

Create a Python module containing the following doctest:

"""
>>> print('a')
a
>>> import logging
>>> logging.getLogger('fgsfds').warning('whatever')
>>> print('b')
b
"""

Run PyTest against the file:

pytest --doctest-modules test.py

As expected, the test passes successfully. Now, run the test with live CLI logging enabled:

pytest --doctest-modules --log-cli-level=DEBUG test.py

The test fails with a bogus error:

$ pytest --doctest-modules --log-cli-level=DEBUG test.py
=========================== test session starts ===========================
platform linux -- Python 3.7.3, pytest-5.3.5, py-1.8.0, pluggy-0.13.1
rootdir: /.../pytest-mwe
plugins: asyncio-0.10.0
collected 1 item                                                          

test.py::test 
------------------------------ live log call ------------------------------
WARNING  test:<doctest test[2]>:1 whatever
FAILED                                                              [100%]

================================ FAILURES =================================
_____________________________ [doctest] test ______________________________
001 
002 >>> print('a')
003 a
004 >>> import logging
005 >>> logging.getLogger(__name__).warning('whatever')
006 >>> print('b')
Expected:
    b
Got nothing

/.../pytest-mwe/test.py:6: DocTestFailure
-------------------------- Captured stdout call ---------------------------
b
---------------------------- Captured log call ----------------------------
WARNING  test:<doctest test[2]>:1 whatever
============================ 1 failed in 0.02s ============================

When CLI logging is enabled, the first occurrence of a captured log message breaks all future doctest statements.

If the log level threshold is higher than the severity of emitted log messages, then the test also passes successfully. For example, the following works as expected:

pytest --doctest-modules --log-cli-level=ERROR test.py

[akaihola]

There's also an unanswered Stack Overflow question about this: pytest log_cli + standard logging = breaks doctest.

[theY4Kman]

One way to work around this is to disable capturing for doctest items, using the pytest_runtest_call hook:

import sys

from _pytest.config import hookimpl
from _pytest.doctest import DoctestItem
from _pytest.nodes import Item


@hookimpl(hookwrapper=True)
def pytest_runtest_call(item: Item) -> None:
    """Hook to suspend global capture when running doctests"""
    if isinstance(item, DoctestItem):
        capman = item.config.pluginmanager.getplugin('capturemanager')
        if capman:
            capman.suspend_global_capture(in_=True)
            out, err = capman.read_global_capture()
            sys.stdout.write(out)
            sys.stderr.write(err)

    yield