logging-test-case

logging-test-case

Production systems rely heavily upon logging. Unit tests should verify logs are correct. unittest.assertLogs() allows developers to verify logs are correct. Including this context manager in every test case becomes tiresome. Also, if the test fails, the logs are not displayed.

This project provides the function decorator @capturelogs. @capturelogs is similar to unittest.assertLogs(), but it is a function decorator, reducing the clutter inside the test function.

This project provides the class LoggingTestCase, which inherits from unittest.TestCase. For every test run, logs are automatically captured to self.captured_logs. If the test fails, the contents of self.captured_logs are written to the test output for easy debugging. LoggingTestCase provides context manager assertNoLogs to verify no logs were emitted within the context.

• Use @capturelogs if only a few tests involve log files.
• Use LoggingTestCase if most of the tests involve logs. This avoids putting a function decorator for each function.

Installation

This package is at pypi at:

https://pypi.python.org/pypi/logging-test-case

To install using pip:

pip install logging-test-case

Requirements

• Python 3.4 or higher.

@capturelogs

capturelogs(logger=None, level=None, display_logs=DisplayLogs.FAILURE, assert_no_logs=False)

• logger: Name of logger, or an actual logger. Defaults to root logger.
• level: Log level as a text string. Defaults to 'INFO'.
• display_logs: Determines when to display logs
  • DisplayLogs.NEVER: Never display the logs. The logs will always be discarded.
    • This is the current behavior of unittest.assertLogs().
  • DisplayLogs.FAILURE: Display the logs only if the test case fails. (default)
    • This can be useful for debugging test failures because the logs are still written out.
  • DisplayLogs.ALWAYS: Always displays the logs - pass or fail.
    • This can be useful when manually running the tests and the developer wants to visually inspect the logging output.
• assert_no_logs: If True, raise an AssertionError if any logs are emitted.

Examples are located at: examples/capturelogs_example.py

unittest.assertLogs example

::

class CaptureLogsExample(unittest.TestCase):
    def test_assert_logs(self):
        """Verify logs using built-in self.assertLogs()."""
        with self.assertLogs('foo', level='INFO') as logs:
            logging.getLogger('foo').info('first message')
            logging.getLogger('foo.bar').error('second message')
        self.assertEqual(logs.output, ['INFO:foo:first message',
                                       'ERROR:foo.bar:second message'])

@capturelogs example

::

import unittest
import logging

import loggingtestcase


class CaptureLogsExample(unittest.TestCase):
    @loggingtestcase.capturelogs('foo', level='INFO')
    def test_capture_logs(self, logs):
        """Verify logs using @capturelogs decorator."""
        logging.getLogger('foo').info('first message')
        logging.getLogger('foo.bar').error('second message')

        self.assertEqual(logs.output, ['INFO:foo:first message',
                                       'ERROR:foo.bar:second message'])

In the above example, there is less clutter and indenting inside of the test function. For this simple example, it doesn't matter. But if the test involves multiple patches and self.assertRaises and many other context managers, the function becomes crowded very quickly. The @capturelogs function decorator allows the developer to reduce the contents and indent level inside of the function.

@capturelogs display example

::

import unittest
import logging

import loggingtestcase


class CaptureLogsExample(unittest.TestCase):
    @loggingtestcase.capturelogs('foo', level='INFO',
                                 display_logs=loggingtestcase.DisplayLogs.ALWAYS)
    def test_always_display_logs(self, logs):
        """The logs are always written to the original handler(s)."""
        logging.getLogger('foo').info('first message')
        self.assertTrue(False)
        self.assertEqual(logs.output, ['INFO:foo:first message'])

In the above example, the test fails, the logs are be displayed.

@capturelogs assert_no_logs example

::

import unittest
import logging

import loggingtestcase


class CaptureLogsExample(unittest.TestCase):
    @loggingtestcase.capturelogs('foo', level='INFO', assert_no_logs=True)
    def test_assert_no_logs(self, logs):
        """This test fails because logs are emitted.

        Output::

            AssertionError: In test_assert_no_logs(), the follow messages were unexpectedly logged:
                INFO:foo:first message
                ERROR:foo.bar:second message

        """
        logging.getLogger('foo').info('first message')
        logging.getLogger('foo.bar').error('second message')

LoggingTestCase Examples

Example1

examples/loggingtestcase_example.py

::

import unittest
import logging

import loggingtestcase


class LoggingTestCaseExample(loggingtestcase.LoggingTestCase):

    def __init__(self, methodName='runTest', testlogger=None, testlevel=None):
        """
        To change the logger or log level, override __init__.
        By default, the root logger is used and the log level is logging.INFO.
        """
        # testlevel = logging.ERROR
        super().__init__(methodName, testlogger, testlevel)

    def setUp(self):
        self.logger = logging.getLogger(__name__)
        pass

    def test_pass(self):
        """
        Run a test that logs an info message and
        verify the info is correctly logged.

        Notice that the info message is not logged to the console.
        When all your tests pass, your console output is nice and clean.
        """
        self.logger.info("Starting request...")
        self.logger.info("Done with request.")
        self.assertListEqual(self.captured_logs.output,
                             ['INFO:examples.loggingtestcase_example:Starting request...',
                              'INFO:examples.loggingtestcase_example:Done with request.'])

    def test_fail(self):
        """
        Run a test that fails.

        Notice that the error message is logged to the console.
        This allows for easier debugging.

        Here is the output:
        ======================================================================
        ERROR: test_fail (examples.example1.Example1)
        ----------------------------------------------------------------------
        Traceback (most recent call last):
          File "D:\Git\logging-test-case\examples\loggingtestcase_example.py.py", line 61,
          in test_fail raise FileNotFoundError("Failed to open file.")
        FileNotFoundError: Failed to open file.

        ERROR:examples.example1:Failed to open file.
        ----------------------------------------------------------------------
        """
        self.logger.error("Failed to open file.")
        raise FileNotFoundError("Failed to open file.")


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

In the above example, notice how test_pass() and test_fail() do not have any function decorators or context managers. The captured logs are automatically available in self.captured_logs.output.

Example2 - assertNoLogs

examples/assertnologs_example1.py

::

import unittest
import logging

import loggingtestcase


class AssertNoLogsExample(loggingtestcase.LoggingTestCase):
    """Example on how to use LoggingTestCase and no logging."""

    def __init__(self, methodName='runTest', testlogger=None, testlevel=None):
        """
        To change the logger or log level, override __init__.
        By default, the root logger is used and the log level is logging.INFO.
        """
        # testlevel = logging.ERROR
        super().__init__(methodName, testlogger, testlevel)

    def setUp(self):
        self.logger = logging.getLogger(__name__)

    def test_assert_no_logs_fail(self):
        """The test fails because logs are emitted.

        Here is the output:
        E               AssertionError: The follow messages were unexpectedly logged:
        E                   ERROR:examples.assertnologs_example1:first message
        E                   ERROR:examples.assertnologs_example1:second message

        """
        with self.assertNoLogs():
            self.logger.error('first message')
            self.logger.error('second message')

    def test_assert_no_logs_pass(self):
        """The test passes because no logs are emitted inside the context manager."""
        self.logger.error('first message')
        with self.assertNoLogs():
            pass
        self.logger.error('second message')


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

Changelog

release-1.4.1

• Fixed example in README.rst. Thanks to julianstirling!

release-1.4

• Added support for verifying no logs are emitted during a test.
  • Added method assertNoLogs() to class LoggingTestCase.
  • Added parameter assert_no_logs to function decorator capturelogs.

release-1.3

• Support for Python 3.4, 3.5, and 3.6.
  • Previously only Python 3.6 worked.
• Support for pytest.
  • Previously only unittest worked. Now both unittest and pytest work.

Thanks to jayvdb on GitHub for providing both fixes!

release-1.2

Fixed the following error on Python < 3.6:

::

/usr/local/lib/python3.5/dist-packages/loggingtestcase/capturelogs.py:31: in <module>
    from enum import Enum, auto
E   ImportError: cannot import name 'auto'

This is because enum.auto() is new in Python 3.6. To preserve backward compatibility, auto() is no longer used.

release-1.1.2

Added README.rst so this readme shows up on PyPI.

release-1.1

Added @capturelogs.

release-1.0

Added LoggingTestCase.

Tests

Manual Tests

tests/manual.py

Run this file manually. All the tests are commented out. Uncomment and
run each test one at a time. Verify the console output.

This module is not named ``manual_test.py`` because these tests are not
meant to be run automatically.

Automated Tests
---------------

To run all the tests from the command line, simply use pytest:

::

    pytest

tests/loggingtestcase\_test.py

This module tests class LoggingTestCase. It uses subprocess.check_output to run each test case one at a time, capturing the output. The output is examined to verify it is correct. loggingtestcase_test.py run tests in module simpleloggingtests.py.

Even though automated tests are included, it is still a good idea to run the manual tests and visually look at the output of each test case.

tests/assertnologs_test.py

Tests context manager ``assertNoLogs`` in class ``LoggingTestCase``.

tests/capturelogs\_test.py
~~~~~~~~~~~~~~~~~~~~~~~~~~

This module tests ``@capturelogs``, defined in
``loggingtestcase/capturelogs.py``.