Get all logging output with mock

Question

I want to get all logging output with mock. I searched, but only found ways to mock explicitly logging.info or logging.warn.

I need all output, whatever logging level was set.

def test_foo():

   def my_log(...):
      logs.append(...)

   with mock.patch('logging.???', my_log):
        ...

In our libraries we use this:

import logging
logger=logging.getLogger(__name__)

def foo():
    logger.info(...)

Answer 1

stdlib

Since Python 3.4 the batteries' unittest has assertLogs. When used without logger and level arguments, it catches all logging (suppresses existing handlers). You can later access recorded entries from the context manager's records attribute. Text output strings are stored in output list.

import logging
import unittest


class TestLogging(unittest.TestCase):

    def test(self):
        with self.assertLogs() as ctx:
            logging.getLogger('foo').info('message from foo')
            logging.getLogger('bar').info('message from bar')
        print(ctx.records)

Tornado

For Python 2 I usually take Tornado's ExpectLog. It's self-contained and works for normal Python code. It's actually more elegant solution then stdlib's, because instead of several class, ExpectLog is just a normal logging.Filter (a class, source). But it lacks a couple of features, including access to recorded entries, so usually I also extend it a bit, like:

class ExpectLog(logging.Filter):

    def __init__(self, logger, regex, required=True, level=None):
        if isinstance(logger, basestring):
            logger = logging.getLogger(logger)
        self.logger = logger
        self.orig_level = self.logger.level
        self.level = level
        self.regex = re.compile(regex)
        self.formatter = logging.Formatter()
        self.required = required
        self.matched = []
        self.logged_stack = False

    def filter(self, record):
        if record.exc_info:
            self.logged_stack = True
        message = self.formatter.format(record)
        if self.regex.search(message):
            self.matched.append(record)
            return False
        return True

    def __enter__(self):
        self.logger.addFilter(self)
        if self.level:
            self.logger.setLevel(self.level)
        return self

    def __exit__(self, typ, value, tb):
        self.logger.removeFilter(self)
        if self.level:
            self.logger.setLevel(self.orig_level)
        if not typ and self.required and not self.matched:
            raise Exception("did not get expected log message")

Then you can have something like:

class TestLogging(unittest.TestCase):

    def testTornadoself):
        logging.basicConfig(level = logging.INFO)

        with ExpectLog('foo', '.*', required = False) as ctxFoo:
            with ExpectLog('bar', '.*', required = False) as ctxBar:
                logging.getLogger('foo').info('message from foo')
                logging.getLogger('bar').info('message from bar')
        print(ctxFoo.matched)
        print(ctxBar.matched)

However, note that for the filter approach current logging level is important (can be overridden with level argument), and also you need a filter per logger of interest. You can follow the approach and make something that fits your case better.

Update

Alternatively there's unittest2 backport for Python 2 which has assertLogs.

Answer 2

pytest

If you are writing your tests using pytest, take a look at a neat fixture named caplog that will capture log records for you. It captures all the emitted log records which you can then access via caplog.records list. Each element is an instance of logging.LogRecord, so you can easily access any of the LogRecords attributes. Example:

# spam.py

import logging
logger=logging.getLogger(__name__)

def foo():
    logger.info('bar')


# tests.py

import logging
from spam import foo

def test_foo(caplog):
    foo()
    assert len(caplog.records) == 1
    record = next(iter(caplog.records))
    assert record.message == 'bar'
    assert record.levelno == logging.INFO
    assert record.module == 'spam'
    # etc

Install

The fixture was first introduced in a pytest plugin named pytest-capturelog which is now abandoned. Luckily, it got a decent fork named pytest-catchlog, which has been merged into pytest==3.3.0 recently. So, if you use a recent version of pytest, you are already good to go; for older versions of pytest, install pytest-catchlog from PyPI.

Docs

At the moment, pytest doesn't provide any docs for the caplog fixture (or at least I couldn't find any), so you can refer to pytest-catchlog's documentation.

Plain unittest

If pytest is not an option, I wouldn't patch logging at all - you can simply add a custom handler instead that will record all the incoming logs. A small example:

# utils.py

import logging


class RecordsCollector(logging.Handler):

    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.records = []

    def emit(self, record):
        self.records.append(record)


# tests.py

import logging
import unittest
from utils import RecordsCollector
from spam import foo


class SpamTests(unittest.TestCase):

    def setUp(self):
        self.collector = RecordsCollector()
        logging.getLogger('spam').addHandler(self.collector)

    def tearDown(self):
        logging.getLogger('spam').removeHandler(self.collector)

    def test_foo(self):
        foo()
        # same checks as in the example above
        self.assertEqual(len(self.collector.records), 1)
        record = next(iter(self.collector.records))
        self.assertEqual(record.message, 'bar')
        self.assertEqual(record.levelno, logging.INFO)
        self.assertEqual(record.module, 'spam')


if __name__ == '__main__':
    unittest.main()

You can then extend the custom handler and implement any logic you need, like collecting the records in a dict that maps log levels to lists of records, or add a contextmanager implementation, so you can start and stop capturing records inside the test:

from contextlib import contextmanager

@contextmanager
def record_logs():
    collector = RecordsCollector()
    logging.getLogger('spam').addHandler(collector)
    yield collector
    logging.getLogger('spam').removeHandler(collector)


def test_foo(self):
    with utils.record_logs() as collector:
        foo()
        self.assertEqual(len(collector.records), 1)

Answer 3

The module testfixtures has a class to handle this:

>>> import logging
>>> from testfixtures import LogCapture
>>> with LogCapture() as l:
...     logger = logging.getLogger()
...     logger.info('a message')
...     logger.error('an error')

>>> l.check(
...     ('root', 'INFO', 'a message'),
...     ('root', 'ERROR', 'another error'),
...     )
Traceback (most recent call last):
 ...
AssertionError: sequence not as expected:

same:
(('root', 'INFO', 'a message'),)

expected:
(('root', 'ERROR', 'another error'),)

actual:
(('root', 'ERROR', 'an error'),)

Source: http://testfixtures.readthedocs.io/en/latest/logging.html

Answer 4

I found this solution:

def test_foo(self):

    logs=[]

    def my_log(self, *args, **kwargs):
        logs.append((args, kwargs))

    with mock.patch('logging.Logger._log', my_log):
        ...