36

I want to ensure that a certain condition in my code causes a log message to be written to the django log. How would I do this with the Django unit testing framework?

Is there a place where I can check logged messages, similarly to how I can check sent emails? My unit test extends django.test.TestCase.

Simeon Visser
  • 118,920
  • 18
  • 185
  • 180
Krystian Cybulski
  • 10,789
  • 12
  • 67
  • 98

5 Answers5

48

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 logging

logger = 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")
Bufke
  • 3,195
  • 3
  • 28
  • 28
Simeon Visser
  • 118,920
  • 18
  • 185
  • 180
  • 4
    Small thing... from Python 3.3 onwards the import for the test should be `from unittest.mock import patch`. Otherwise, still good! – Phil Gyford Jul 18 '16 at 15:39
  • @Simeon Visser how to do it with mock, if inside the logging call, we're passing an exception ? Something like "logger.exception(KeyError('test'))" This way the "assert_called_with" won't catch it since I guess the references for KeyError object's are different. (i.e. they're not simple strings anymore). – SpiXel Jul 31 '16 at 13:14
  • 4
    @SpiXel: you could look at the contents of mock_logger.error.call_args_list and make assertions about the arguments. For example, it would be something like: `assert "Test" in str(my_logging_argument)` or `self.assertEqual(str(my_logging_argument), "KeyError('test')"`. See: https://docs.python.org/3/library/unittest.mock.html#unittest.mock.Mock.call_args_list – Simeon Visser Jul 31 '16 at 13:22
  • @SimeonVisser Yes ! That works. thank you :) (Have to admit it's a little bit messy though, since the message strings, inside the exception, are escaped 'KeyError(\\'test\\')' and ..., but definitely works!) – SpiXel Jul 31 '16 at 13:57
  • 1
    @SpiXel: it should be possible to clean that up by changing the code that constructs the string that gets passed to `logger.exception(...).` That's where the string gets passed so what you see in the call_args_list is just the same as that. – Simeon Visser Jul 31 '16 at 14:00
  • @SimeonVisser: How would it work if the logger was defined in a class? I have in my class's `__init__` the following line: `self.logger = logging.getLogger(__name__)` and want to mock that specific logger. – physicalattraction Sep 12 '17 at 11:21
  • I found that I could move the initialization outside the `__init__` (without `self`) and then use `with patch.object(MyClass, 'logger') as mock_logger:` – physicalattraction Sep 12 '17 at 11:28
43

You can also use assertLogs from django.test.TestCase

When you code is

import logging

logger = 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.

manu
  • 1,072
  • 1
  • 14
  • 26
  • 8
    Note: as of python 3.4, unittest provides assertLogs(): https://docs.python.org/3/library/unittest.html#unittest.TestCase.assertLogs – Steve Tarver Sep 29 '18 at 07:56
  • 3
    `django.test.TestCase.assertLogs` is being provided by `unittest.TestCase.assertLogs` in Python 3.4+ and isn't polyfilled for Python 2.7, FWIW. The `patch_logger` util from below is the only option for Python 2.7 users. See https://github.com/django/django/pull/9905 – AL the X Feb 12 '19 at 21:17
9

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 logging
logger = logging.getLogger()
logger.info('a message')
logger.error('an error')

A test for this would be:

from testfixtures import LogCapture
with 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

soulshake
  • 780
  • 8
  • 12
Jonathan Hartley
  • 15,462
  • 9
  • 79
  • 80
6

Django has a nice context manager function called patch_logger.

from django.test.utils import patch_logger

then in your test case:

with patch_logger('logger_name', 'error') as cm:
    self.assertIn("Error message", cm)

where:

  • logger_name is the logger name (duh)
  • error is the log level
  • cm is the list of all log messages

More details:

https://github.com/django/django/blob/2.1/django/test/utils.py#L638

It should work the same for django < 2.0, independently of python version (as long as it's supported by dj)

mariodev
  • 13,928
  • 3
  • 49
  • 61
  • 3
    There's no official docs for this. It's a just a habit of mine to look into django utils source code when I'm really bored.. ;) – mariodev Feb 13 '19 at 13:59
0

If you're using test classes, you can use following solution:

import logger

from django.test import TestCase


class MyTest(TestCase):
    @classmethod
    def setUpClass(cls):
        super(MyTest, cls).setUpClass()
        cls.logging_error = logging.error
        logging.error = cls._error_log

    @classmethod
    def tearDownClass(cls):
        super(MyTest, cls).tearDownClass()
        logging.error = cls.logging_error

    @classmethod
    def _error_log(cls, msg):
      cls.logger = msg

    def test_logger(self):
        self.assertIn('Message', self.logger)

This method replaces error function of logging module with your custom method only for test purposes and put stdout into cls.logger variable which is available in every test case by calling self.logger. At the end it reverts changes by placing error function from logging module back.

turkus
  • 4,637
  • 2
  • 24
  • 28