pytest logbook logging to file and stdout

Question

I'm trying to setup logbook in a PyTest test to output everything to both stderr and a file. The file should get every log level, but stderr should have a higher threshold (which PyTest will manage with it's usual capture settings).

I've got the pytest-logbook plugin. That redirects stderr into PyTest capture, but I'm not sure how to add the file output.

This is (hopefully) obvious to someone that knows logbook, but it's new to me.

One more thing, I want the file logging to be real time. My tests are generally long running and PyTest's normal behavior of only showing output on failure isn't helping when I need to see if things are hung.

Here is code that I think should work, but doesn't. I get the log file, but nothing to stdout/stderr (even on fail):

conftest.py:

import os
import pytest
import logbook
import sys

@pytest.fixture(scope='module')
def modlog(request):
    """Logger that also writes to a file."""
    name = request.module.__name__
    if name.startswith('test_'):
        name = name[5:]
    logname = 'TEST-'+name+'.log'
    if os.path.exists(logname):
        os.rename(logname, logname+"~")
    logger = logbook.Logger(name)
    logger.handlers.append(logbook.FileHandler(logname, level='DEBUG'))
    logger.handlers.append(logbook.StreamHandler(sys.stdout, level='INFO'))
    logger.warn("Start of logging")
    return logger

test_loggy.py:

import pytest

def test_foo(modlog):
    modlog.info('hello')
    modlog.info('world')
    assert 0                       # logs will only print on test fail

Answer 1

Answering my own question (in case other run into the same thing).

The logging handlers form a stack and you have to allow messages to "bubble" through. This is done as an option when the handlers are created.

So the handler creation should be:

logger.handlers.append(logbook.FileHandler(logname, level='DEBUG', bubble=True))
logger.handlers.append(logbook.StreamHandler(sys.stderr, level='INFO', bubble=True))

If you run py.test -s, then you will see the info level messages in real time. If the test fails, the logbook plugin will show all log messages for the failed test (including debug). You will also get a copy in the file (in real time).