Skip to content
Back to top
View this page

# Testing logging

Python includes a `logging` package, and while it is widely used, many people assume that logging calls do not need to be tested or find the prospect too daunting. To help with this, testfixtures allows you to easily capture the output of calls to Python’s logging framework and make sure they were as expected.

Note

The `LogCapture` class is useful for checking that your code logs the right messages. If you want to check that the configuration of your handlers is correct, please see the section below.

## Methods of capture

When using the tools provided by Testfixtures, there are three different techniques for capturing messages logged to the Python logging framework, depending on the type of test you are writing. They are all described in the sections below.

### The context manager

The context manager can be used as follows:

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

For the duration of the `with` block, log messages are captured. The context manager provides a check method that raises an exception if the logging wasn’t as you expected:

    >>> 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'),)

It also has a string representation that allows you to see what has been logged, which is useful for doc tests:

    >>> print(l)
    root INFO
      a message
    root ERROR
      an error

### The decorator

If you only want to capture logging for a particular test function, you may find the decorator suits your needs better:

    from testfixtures import log_capture

    @log_capture()
    def test_function(capture):
        logger = logging.getLogger()
        logger.info('a message')
        logger.error('an error')

        capture.check(
            ('root', 'INFO', 'a message'),
            ('root', 'ERROR', 'an error'),
        )

Note

This method is not compatible with pytest’s fixture discovery stuff. Instead, put a fixture such as the following in your `conftest.py`:

    import pytest

    @pytest.fixture(autouse=True)
    def capture():
        with LogCapture() as capture:
            yield capture

### Manual usage

If you want to capture logging for the duration of a doctest or in every test in a `TestCase`, then you can use the `LogCapture` manually.

The instantiation, which also starts the capturing, is done in the set-up step of the `TestCase` or equivalent:

    >>> from testfixtures import LogCapture
    >>> l = LogCapture()

You can then execute whatever will log the messages you want to test for:

    >>> from logging import getLogger
    >>> getLogger().info('a message')

At any point, you can check what has been logged using the check method:

    >>> l.check(('root', 'INFO', 'a message'))

Alternatively, you can use the string representation of the `LogCapture`:

    >>> print(l)
    root INFO
      a message

Then, in the tear-down step of the `TestCase` or equivalent, you should make sure you stop the capturing:

    >>> l.uninstall()

The `uninstall()` method can also be added as an `addCleanup()` if that is easier or more compact in your test suite.

If you have multiple `LogCapture` objects in use, you can easily uninstall them all:

    >>> LogCapture.uninstall_all()

## Checking captured log messages

Regardless of how you use the `LogCapture` to capture messages, there are three ways of checking that the messages captured were as expected.

The following example is useful for showing these:

    from testfixtures import LogCapture
    from logging import getLogger
    logger = getLogger()

    with LogCapture() as log:
        logger.info('start of block number %i', 1)
        try:
            logger.debug('inside try block')
            raise RuntimeError('No code to run!')
        except:
            logger.error('error occurred', exc_info=True)

### The check methods

`LogCapture` instances have `check()` and `check_present()` methods to make assertions about entries that have been logged.

`check()` will compare the log messages captured with those you expect. Expected messages are expressed, by default, as three-element tuples where the first element is the name of the logger to which the message should have been logged, the second element is the string representation of the level at which the message should have been logged and the third element is the message that should have been logged after any parameter interpolation has taken place.

If things are as you expected, the method will not raise any exceptions:

    >>> log.check(
    ...     ('root', 'INFO', 'start of block number 1'),
    ...     ('root', 'DEBUG', 'inside try block'),
    ...     ('root', 'ERROR', 'error occurred'),
    ... )

However, if the actual messages logged were different, you’ll get an `AssertionError` explaining what happened:

    >>> log.check(('root', 'INFO', 'start of block number 1'))
    Traceback (most recent call last):
     ...
    AssertionError: sequence not as expected:

    same:
    (('root', 'INFO', 'start of block number 1'),)

    expected:
    ()

    actual:
    (('root', 'DEBUG', 'inside try block'), ('root', 'ERROR', 'error occurred'))

In contrast, `check_present()` will only check that the messages you specify are present, and that their order is as specified. Other messages will be ignored:

    >>> log.check_present(
    ...     ('root', 'INFO', 'start of block number 1'),
    ...     ('root', 'ERROR', 'error occurred'),
    ... )

If the order of messages is non-deterministic, then you can be explict that the order doesn’t matter:

    >>> log.check_present(
    ...     ('root', 'ERROR', 'error occurred'),
    ...     ('root', 'INFO', 'start of block number 1'),
    ...     order_matters=False
    ... )

### Printing

The `LogCapture` has a string representation that shows what messages it has captured. This can be useful in doc tests:

    >>> print(log)
    root INFO
      start of block number 1
    root DEBUG
      inside try block
    root ERROR
      error occurred

This representation can also be used to check that no logging has occurred:

    >>> empty = LogCapture()
    >>> print(empty)
    No logging captured

### Inspecting

The `LogCapture` also keeps a list of the `LogRecord` instances it captures. This is useful when you want to check specifics of the captured logging that aren’t available from either the string representation or the `check()` method.

A common case of this is where you want to check that exception information was logged for certain messages:

    from testfixtures import compare, Comparison as C

    compare(log.records[-1].exc_info[1], expected=C(RuntimeError('No code to run!')))

If you wish the extraction specified in the `attributes` parameter to the `LogCapture` constructor to be taken into account, you can examine the list of recorded entries returned by the `actual()` method:

    assert log.actual()[-1][-1] == 'error occurred'

## Only capturing specific logging

Some actions that you want to test may generate a lot of logging, only some of which you actually need to care about.

The logging you care about is often only that above a certain log level. If this is the case, you can configure `LogCapture` to only capture logging at or above a specific level:

    >>> with LogCapture(level=logging.INFO) as l:
    ...     logger = getLogger()
    ...     logger.debug('junk')
    ...     logger.info('something we care about')
    ...     logger.error('an error')
    >>> print(l)
    root INFO
      something we care about
    root ERROR
      an error

In other cases this problem can be alleviated by only capturing a specific logger:

    >>> with LogCapture('specific') as l:
    ...     getLogger('something').info('junk')
    ...     getLogger('specific').info('what we care about')
    ...     getLogger().info('more junk')
    >>> print(l)
    specific INFO
      what we care about

However, it may be that while you don’t want to capture all logging, you do want to capture logging from multiple specific loggers:

    >>> with LogCapture(('one', 'two')) as l:
    ...     getLogger('three').info('3')
    ...     getLogger('two').info('2')
    ...     getLogger('one').info('1')
    >>> print(l)
    two INFO
      2
    one INFO
      1

It may also be that the simplest thing to do is only capture logging for part of your test. This is particularly common with long doc tests. To make this easier, `LogCapture` supports manual installation and un-installation as shown in the following example:

    >>> l = LogCapture(install=False)
    >>> getLogger().info('junk')
    >>> l.install()
    >>> getLogger().info('something we care about')
    >>> l.uninstall()
    >>> getLogger().info('more junk')
    >>> l.install()
    >>> getLogger().info('something else we care about')
    >>> print(l)
    root INFO
      something we care about
    root INFO
      something else we care about

Once you have the filtered to the entries you would like to make assertions about, you may also want to look at a different set of attributes that the defaults for `LogCapture`:

    >>> with LogCapture(attributes=('levelname', 'getMessage')) as log:
    ...     logger = getLogger()
    ...     logger.debug('a debug message')
    ...     logger.info('something %s', 'info')
    ...     logger.error('an error')
    >>> log.check(
    ...     ('DEBUG', 'a debug message'),
    ...     ('INFO', 'something info'),
    ...     ('ERROR', 'an error')
    ... )

As you can see, if a specified attribute is callable, it will be called and the result used to form part of the entry. If you need even more control, you can pass a callable to the `attributes` parameter, which can extract any required information from the records and return it in the most appropriate form:

    def extract(record):
        return {'level': record.levelname, 'message': record.getMessage()}

    >>> with LogCapture(attributes=extract) as log:
    ...     logger = getLogger()
    ...     logger.debug('a debug message')
    ...     logger.error('an error')
    >>> log.check(
    ...     {'level': 'DEBUG', 'message': 'a debug message'},
    ...     {'level': 'ERROR', 'message': 'an error'},
    ... )

## Checking the configuration of your log handlers

`LogCapture` is good for checking that your code is logging the correct messages; just as important is checking that your application has correctly configured log handers. This can be done using a unit test such as the following:

    from testfixtures import Comparison as C, compare
    from unittest import TestCase
    import logging
    import sys

    class LoggingConfigurationTests(TestCase):

        # We mock out the handlers list for the logger we're
        # configuring in such a way that we have no handlers
        # configured at the start of the test and the handlers our
        # configuration installs are removed at the end of the test.

        def setUp(self):
            self.logger = logging.getLogger()
            self.orig_handlers = self.logger.handlers
            self.logger.handlers = []
            self.level = self.logger.level

        def tearDown(self):
            self.logger.handlers = self.orig_handlers
            self.logger.level = self.level

        def test_basic_configuration(self):
            # Our logging configuration code, in this case just a
            # call to basicConfig:
            logging.basicConfig(format='%(levelname)s %(message)s',
                                level=logging.INFO)

            # Now we check the configuration is as expected:

            compare(self.logger.level, 20)
            compare([
                C('logging.StreamHandler',
                  stream=sys.stderr,
                  formatter=C('logging.Formatter',
                              _fmt='%(levelname)s %(message)s',
                              partial=True),
                  level=logging.NOTSET,
                  partial=True)
                ], self.logger.handlers)