How to print stuff in a py.test finalizer

Question

I'm testing a function that writes to a logfile (it doesn't matter that it writes to a logfile specifically, it could be doing anything, it's just what gave rise to this question)

Something like this:

def do_stuff():
    with open('/tmp/mylogs.txt', 'a') as f:
        f.write(str(time.time()))
        f.write(' stuff done! \n')
    return 42

And I can test it a bit like this:

def test_doing_stuff(watch_logs):
    assert do_stuff() == 42
    assert do_stuff() == 43

For debugging purposes, when a test fails, I want to be able to print out the new contens of the logs -- I can make a fixture a bit like this:

@pytest.fixture()
def watch_logs(request):
    with open('/tmp/mylogs.txt') as f:
        log_before = f.read()

    def get_new_logs():
        with open('/tmp/mylogs.txt') as f:
            log_after = f.read()
            return log_after.replace(log_before, '')

    return get_new_logs

Great - now I can check the log contents at any point in my tests:

def test_doing_stuff(watch_logs):
    assert do_stuff() == 42
    print(watch_logs())
    assert do_stuff() == 43
    print(watch_logs())

Hm - ah, but that second print isn't going to work, it's after the test failure.

What if my test fixture just always printed the logs out at the end of the test? Then pytest's stdout capture would show it to me when it fails, but not when it passes!

@pytest.fixture()
def watch_logs(request):
    with open('/tmp/mylogs.txt') as f:
        log_before = f.read()

    def get_new_logs():
        with open('/tmp/mylogs.txt') as f:
            log_after = f.read()
            return log_after.replace(log_before, '')

    def print_new_logs():
        print('~' * 20 + ' logs ' + '~' * 20)
        print(get_new_logs())
        print('~' * 50)
    request.addfinalizer(print_new_logs)

    return get_new_logs

Oh, but that doesn't work because pytests's log capture isn't happening during test finalizers.

So the question is: how can I make a test finalizer that can print stuff?

Here's an ultra-minimal gist without the (irrelevant) writing-to-a-logfile stuff: https://gist.github.com/hjwp/5154ec40a476a5c01ba6

Answer 1

There is no documented or clean way to achieve it but here is a hack:

# conftest.py

def pytest_runtest_call(item):
    if hasattr(item, "_request"):
        if hasattr(item._request, "_addoutput_on_failure"):
            item._request._addoutput_on_failure()

# test_x.py
import pytest

@pytest.fixture
def print_on_fail(request):
    def add():
        print ("test failed")
    request._parent_request._addoutput_on_failure = add

def test_doing_stuff(print_on_fail):
    assert False

We could think about a proper request.addcall_on_failure(callback) API.

Making the yield_fixture case work requires some internal probably non-trivial refactoring.

Answer 2

Thanks to help from Holger himself (thanks @hpk42!), I've got something that works. Only slightly magic/hacky.

The solution is to use a py.test hook called pytest_pyfunc_call, alongside a decorator called hookwrapper. They give me a way to hook in some code both before and after the test runs, but also without being affected by the stdout hijacking.

We define a new function in conftest.py:

# conftest.py

@pytest.mark.hookwrapper
def pytest_pyfunc_call(pyfuncitem):
    yield
    print('this happens after the test runs')
    if 'watch_logs' in pyfuncitem.funcargs:
        print(pyfuncitem.funcargs['watch_logs']())

And now, if pytest spots any test which uses the watch_logs fixture, it will print its output after the test runs.

Full example: https://gist.github.com/hjwp/4294f0acbef5345a7d46