How do I test if a certain log message is logged in a Django test case? How do I test if a certain log message is logged in a Django test case? django django

How do I test if a certain log message is logged in a Django test case?


Using the mock module for mocking the logging module or the logger object. When you've done that, check the arguments with which the logging function is called.

For example, if you code looks like this:

import logginglogger = logging.getLogger('my_logger')logger.error("Your log message here")

it would look like:

from unittest.mock import patch # For python 2.x use from mock import patch@patch('this.is.my.module.logger')def test_check_logging_message(self, mock_logger):    mock_logger.error.assert_called_with("Your log message here")


You can also use assertLogs from django.test.TestCase

When you code is

import logginglogger = logging.getLogger('my_logger')def code_that_throws_error_log():    logger.error("Your log message here")

This is the test code.

with self.assertLogs(logger='my_logger', level='ERROR') as cm:    code_that_throws_error_log()    self.assertIn(        "ERROR:your.module:Your log message here",        cm.output    )

This lets you avoid patching just for logs.


The common way of mocking out the logger object (see the splendid chap Simeon Visser's answer) is slightly tricky in that it requires the test to mock out the logging in all the places it's done. This is awkward if the logging comes from more than one module, or is in code you don't own. If the module the logging comes from changes name, it will break your tests.

The splendid 'testfixtures' package includes tools to add a logging handler which captures all generated log messages, no matter where they come from. The captured messages can later be interrogated by the test. In its simplest form:

Assuming code-under-test, which logs:

import logginglogger = logging.getLogger()logger.info('a message')logger.error('an error')

A test for this would be:

from testfixtures import LogCapturewith LogCapture() as l:    call_code_under_test()l.check(    ('root', 'INFO', 'a message'),    ('root', 'ERROR', 'an error'),)

The word 'root' indicates the logging was sent via a logger created using logging.getLogger() (i.e. with no args.) If you pass an arg to getLogger (__name__ is conventional), that arg will be used in place of 'root'.

The test does not care what module created the logging. It could be a sub-module called by our code-under-test, including 3rd party code.

The test asserts about the actual log message that was generated, as opposed to the technique of mocking, which asserts about the args that were passed. These will differ if the logging.info call uses '%s' format strings with additional arguments that you don't expand yourself (e.g. use logging.info('total=%s', len(items)) instead of logging.info('total=%s' % len(items)), which you should. It's no extra work, and allows hypothetical future logging aggregation services such as 'Sentry' to work properly - they can see that "total=12" and "total=43" are two instances of the same log message. That's the reason why pylint warns about the latter form of logging.info call.)

LogCapture includes facilities for log filtering and the like. Its parent 'testfixtures' package, written by Chris Withers, another splendid chap, includes many other useful testing tools. Documentation is here: http://pythonhosted.org/testfixtures/logging.html