How to use logging, pytest fixture and capsys?

Question

I am trying to unit-test some algorithm that uses logging library.

I have a fixture that creates a logger.

In my 1st test case, I do not use this fixture and uses a print to log to stdout. This test case passes.

In my 2nd test case, I use this fixture, but not as documented in pytest doc. I just call the associated function in my test to get the logger. Then I use the logger to log to stdout. This test case passes.

In my 3rd test case, I use this fixture as documented in pytest doc. The fixture is passed as an argument to the test function. Then I use the logger to log to stdout. This test case fails! It does not find anything in stdout. But in the error message, it says that my log is in the captured stdout call.

What am I doing wrong?

import pytest

import logging
import sys

@pytest.fixture()
def logger():

    logger = logging.getLogger('Some.Logger')
    logger.setLevel(logging.INFO)
    stdout = logging.StreamHandler(sys.stdout)
    logger.addHandler(stdout)

    return logger

def test_print(capsys):

    print 'Bouyaka!'

    stdout, stderr = capsys.readouterr()
    assert 'Bouyaka!' in stdout

    # passes

def test_logger_without_fixture(capsys):

    logger().info('Bouyaka!')

    stdout, stderr = capsys.readouterr()
    assert 'Bouyaka!' in stdout

    # passes

def test_logger_with_fixture(logger, capsys):

    logger.info('Bouyaka!')

    stdout, stderr = capsys.readouterr()
    assert 'Bouyaka!' in stdout

    # fails with this error:
    # >       assert 'Bouyaka!' in stdout
    # E       assert 'Bouyaka!' in ''
    #
    # tests/test_logging.py:21: AssertionError
    # ---- Captured stdout call ----
    # Bouyaka!

There is no change if I reorder the test cases by the way.

Answer 1

Thanks a lot for your ideas!

Reverse logger, capsys, make logger request the capsys fixture and use capfd do not change anything.

I tried pytest-catchlog plugin and it works fine!

import pytest

import logging

@pytest.fixture()
def logger():

    logger = logging.getLogger('Some.Logger')
    logger.setLevel(logging.INFO)

    return logger

def test_logger_with_fixture(logger, caplog):

    logger.info('Bouyaka!')

    assert 'Bouyaka!' in caplog.text

    # passes!

In my original tests, I logged to stdout and stderr and captured them. This is an even better solution, as I do not need this tweak to check that my logs work fine.

Well, now I just need to rework all my tests to use caplog, but this is my own business ;)

The only thing left, now that I have a better solution, is to understand what is wrong in my original test case def test_logger_with_fixture(logger, capsys).

Answer 2

As of pytest 3.3, the functionality of capturing log message was added to pytest core. This is supported by the caplog fixture:

def test_baz(caplog):
    func_under_test()
    for record in caplog.records:
        assert record.levelname != 'CRITICAL'
    assert 'wally' not in caplog.text

More information can be found at the documentation

Answer 3

I'm guessing the logger gets created (via the fixture) before the capsys fixture is set up.

Some ideas:

• Use the pytest-catchlog plugin
• Maybe reverse logger, capsys
• Make logger request the capsys fixture
• Use capfd which is more lowlevel capturing without altering sys