Captured output leaking

[The-Compiler]

I recently updated to pytest 2.8 and noticed I got output which should be captured on stdout.

This is during tests which launch a subprocess via QProcess which then does logging on stderr, which is printed during the tests (see testprocess.py / quteprocess.py).

I was able to reproduce this with this example:

import pytest
from PyQt5.QtCore import QTimer


@pytest.yield_fixture(scope='module')
def timer():
    t = QTimer()
    t.setInterval(10)
    t.timeout.connect(lambda: print("foo"))
    t.start()
    yield t
    t.stop()


@pytest.mark.parametrize('x', range(1000))
def test_foo(qtbot, timer, x):
    qtbot.waitSignal(timer.timeout)

When running it with pytest 2.7.3:

============================================= test session starts ==============================================
platform linux -- Python 3.5.0 -- py-1.4.31 -- pytest-2.7.3
PyQt5 5.5.1 -- Qt runtime 5.5.1 -- Qt compiled 5.5.1
rootdir: /home/florian/proj/pytest, inifile: tox.ini
plugins: qt
collected 1000 items 

testcap2.py ...[…]...

========================================= 1000 passed in 1.16 seconds ==========================================

with 2.8.2:

============================================= test session starts ==============================================
platform linux -- Python 3.5.0, pytest-2.8.2, py-1.4.31, pluggy-0.3.1
PyQt5 5.5.1 -- Qt runtime 5.5.1 -- Qt compiled 5.5.1
rootdir: /home/florian/proj/pytest, inifile: tox.ini
plugins: qt-1.9.0
collected 1000 items 

testcap2.py .........foo
.........foo
.........foo
..........foo
...................foo
[…]

========================================= 1000 passed in 1.17 seconds ==========================================

I bisected this to https://github.com/pytest-dev/pytest/commit/c54afbe42e7e47afb7605f4bc226af92dbeda0a7 ("deprecate and warn about __multicall__ usage in hooks, refine docs about hook ordering, make hookwrappers respect tryfirst/trylast").

I also tried reproducing it without pytest-qt but it only seems to happen with pytest-qt.

I'm guessing the event processing happens after pytest already has lifted the capturing, and that commit changed something about the order things are done?

[nicoddemus]

Thanks @The-Compiler, I will try to see what the problem might be tomorrow. Thanks a lot for the detailed investigation! :smile:

[The-Compiler]

Any update on this? :smile: Or do you have some idea what I could do as a workaround? I tried adding QApplication.instance().processEvents() in a yield_fixture after the tests, but that didn't help.

The only other alternative I can think of is to add my own report section for the output, but that'd probably be non-trivial as currently it's just some fixtures and not a real plugin.

[nicoddemus]

No yet @The-Compiler, didn't have time take a look yet. Hopefully I will have some time this week! :sweat_smile:

[nicoddemus]

Hmmm I did some investigation now while I waited on Travis... my first impression is that 2.8 is now working as it should.

This is how pytest's capture code is configured during tests:

    @pytest.hookimpl(hookwrapper=True)
    def pytest_runtest_setup(self, item):
        self.resumecapture()
        yield
        self.suspendcapture_item(item, "setup")

    @pytest.hookimpl(hookwrapper=True)
    def pytest_runtest_call(self, item):
        self.resumecapture()
        self.activate_funcargs(item)
        yield
        #self.deactivate_funcargs() called from suspendcapture()
        self.suspendcapture_item(item, "call")

    @pytest.hookimpl(hookwrapper=True)
    def pytest_runtest_teardown(self, item):
        self.resumecapture()
        yield
        self.suspendcapture_item(item, "teardown")

And here's pytest-qt's:

@pytest.mark.hookwrapper
@pytest.mark.tryfirst
def pytest_runtest_setup(item):
    """
    Hook called after before test setup starts, to start capturing exceptions
    as early as possible.
    """
    capture_enabled = _is_exception_capture_enabled(item)
    if capture_enabled:
        item.qt_exception_capture_manager = _QtExceptionCaptureManager()
        item.qt_exception_capture_manager.start()
    yield
    _process_events()
    if capture_enabled:
        item.qt_exception_capture_manager.fail_if_exceptions_occurred('SETUP')


@pytest.mark.hookwrapper
@pytest.mark.tryfirst
def pytest_runtest_call(item):
    yield
    _process_events()
    capture_enabled = _is_exception_capture_enabled(item)
    if capture_enabled:
        item.qt_exception_capture_manager.fail_if_exceptions_occurred('CALL')


@pytest.mark.hookwrapper
@pytest.mark.trylast
def pytest_runtest_teardown(item):
    """
    Hook called after each test tear down, to process any pending events and
    avoiding leaking events to the next test. Also, if exceptions have
    been captured during fixtures teardown, fail the test.
    """
    _process_events()
    _close_widgets(item)
    _process_events()
    yield
    _process_events()
    capture_enabled = _is_exception_capture_enabled(item)
    if capture_enabled:
        item.qt_exception_capture_manager.fail_if_exceptions_occurred('TEARDOWN')
        item.qt_exception_capture_manager.finish()

As you can see, because pytest-qt's is marked to always be priority over pytest capture's hooks, we end up executing several process_events() after pytest capture was already suspended, and at that point the timer events are processed and the string is printed to the console.

If I remove all trylast/tryfirst markers from pytest-qt's hooks, then the hooks seem to execute in the correct order. I'm a little wary though in changing that, as you and I know that part of the code which deals with events processing is quite sensitive to crashes :worried:

[The-Compiler]

Hmm, I see... I think I understand the issue now, but I don't know what a good solution would be... I guess we'd need more fine-grained ordering of hooks to solve this properly?

Alternatively, maybe pytest's hooks for capturing should be declared tryfirst as well, and always given precedence over plugins which use tryfirst, no matter what?

[nicoddemus]

I'm not sure, I think even in this case pytest's will be called later, because IIRC the plugins with the same ordering are called in FILO ordering, so pytest's hooks would be called last anyway (as they are registered first).

I might be wrong, but it may be that pluggy doesn't want to guarantee any order between hooks tryfirst/trylast hooks anyway, as this is indeed quite tricky and shouldn't be relied upon...

[The-Compiler]

To get the correct behaviour, we'd like to say "after capturing was set up (and before it's torn down), but before/after everything else", right?

But I see how this is difficult to get right... :worried:

Maybe I just should look into my own capturing for my test-subprocess usecase to have better control over this, as I can't think of a good general solution. I wonder what others think - @hpk42 @flub @RonnyPfannschmidt?

[flub]

So if you could order your hook like say @hookimpl(after='capture')then you would be able to solve this? I've wondered about adding functionality like this to pluggy before, but it's good to know if this is an actual use case for it.

[The-Compiler]

@flub let's see what @nicoddemus says - but if I understand the underlying issue correctly, indeed.

[nicoddemus]

@flub as far as I understand it, that would fix it.