Assert that logging has been called with specific string

Question

I'm trying to use unittest to test some functions of a SimpleXMLRPCServer I made. Togethere with Mock, I'm now trying to assert that a specific message has been logged when an if statement is reached, but I can't get it to work. I've tried implementing various answers I found here on StackOverflow or by Googling, but still no luck. The calls I make in the Test Case are as follows:

def test_listen_for_tasks(self):
    el = {'release': 'default', 'component': None}
    for i in range(50):
        self.server._queue.put(el)
    ServerThread.listen_for_tasks(self.server, 'bla', 'blabla')
    with mock.patch('queue_server.logging') as mock_logging:
        mock_logging.warning.assert_called_with('There are currently {}'
                                                ' items in the queue'.format(
                                                 str(len(self.server._queue.queue))))

The function in the server is as follows:

def listen_for_tasks(self, release, component):
    item = {'release': release, 'component': component}
    for el in list(self._queue.queue):
        if self.is_request_duplicate(el, item):
            logger.debug('Already have a request'
                         ' for this component: {}'.format(item))
            return
    self._queue.put(item, False)
    if len(self._queue.queue) > 50:
        logger.warning('There are currently {}'
                       ' items in the queue'.format(
                        str(len(self._queue.queue))))

Any idea why this is not working? I'm new to unit testing in Python and asserting that a logger has done something seems the biggest problem one could face, so I might have screwed up with something really simple in the code. Any kind of help will be greatly appreciated!

EDIT: for completeness, here's the test output and failure:

.No handlers could be found for logger "queue_server"
F


FAIL: test_listen_for_tasks (__main__.TestQueueServer)

Traceback (most recent call last):
  File "artifacts_generator/test_queue_server.py", line 46, in   test_listen_for_tasks
str(len(self.server._queue.queue))))
  File "/home/lugiorgi/Desktop/Code/publisher/env/local/lib/python2.7/site-packages/mock/mock.py", line 925, in assert_called_with
raise AssertionError('Expected call: %s\nNot called' % (expected,))
AssertionError: Expected call: warning('There are currently 51 items in the queue')
Not called

Ran 2 tests in 0.137s

FAILED (failures=1)

Solution 1

You need to first mock the object, then call the function you want to test.

When mocking the object, you also need to provide the full package and object/function name of the object you are mocking, not a variable name.

Finally, it's often more convenient to use the decorator form of patch.

So, for example:

logger = logging.getLogger(__name__)

def my_fancy_function():
    logger.warning('test')

@patch('logging.Logger.warning')
def test_my_fancy_function(mock):
    my_fancy_function()
    mock.assert_called_with('test')

# if you insist on using with:
def test_my_fancy_function_with_with():
    with patch('logging.Logger.warning') as mock:
        my_fancy_function()
        mock.assert_called_with('test')

Solution 2

Since python 3.4 you can use unittest.TestCase class method assertLogs

import logging
import unittest


class LoggingTestCase(unittest.TestCase):
    def test_logging(self):
        with self.assertLogs(level='INFO') as log:
            logging.info('Log message')
            self.assertEqual(len(log.output), 1)
            self.assertEqual(len(log.records), 1)
            self.assertIn('Log message', log.output[0])

Comments

[Steven Bluen]

Since this is tagged for Python 2.7, a complete answer should mention the backport at github.com/testing-cabal/mock while that isn't part of its built-in modules.

[Cerin]

This causes more problems than it solves, because if you mock your logger, than it hides all your logging info, making it very difficult to diagnose unittest failures. You should use patch.object() with the wraps option to allow logging to pass through so you still have a functional logger.