Dumping logs on test failures

21 December 2013 (updated 22 January 2016)

In some situations it would be very nice to have some extra (external) logging output when unittest failures happen. Suppose these logs can be potentially big - you would only want them outputted if something actually failed.

The tearDown can't help you much here - you don't have access to the result. Ideally we would have a custom TestCase class that provides this functionality and subclass it whenever we need this behavior. We could override the run method like described here but unfortunately that's not very robust - for example nose will not call it (nose rewrapps all your test methods in different TestCase instances).

We could write a nose plugin but that's a bad idea ... we would have to tag all our tests with a flag that activates this special behavior and, well, we're getting locked in.

Here's a base TestCase that provides said behavior:

from logging import getLogger
from unittest.case import TestCase, SkipTest

logger = getLogger(__name__)

class LogfileRecordingTestCase(TestCase):
    _log_offset = 0
    log_limit = 1024*1024 # no more than 1mb
    log_name = 'foobar.log'

    def __init__(self, methodName='runTest'):
        meth = getattr(self, methodName)
        @wraps(meth)
        def wrapper():
            try:
                return meth()
            except SkipTest:
                raise
            except:
                self._print_logs()
                raise
        wrapper.__name__ = wrapper.description = wrapper.__doc__ = methodName
        setattr(self, methodName, wrapper)

        super(LogfileRecordingTestCase, self).__init__(methodName)

    def _print_logs(self):
        try:
            if os.path.isfile(self.log_name):
                with open(self.log_name, 'r') as fh:
                    fh.seek(self._log_offset)
                    output = fh.read()
                    if output:
                        print("*"*80)
                        print((" " + self.log_name + " ").center(80))
                        print(output[-self.log_limit:])
                        print("*"*80)
        except Exception:
            logger.exception("Failed to extract logfile data.")

    def setUp(self):
        super(LogfileRecordingTestCase, self).setUp()
        if os.path.isfile(self.log_name):
            with open(self.log_name, 'r') as fh:
                fh.seek(0, os.SEEK_END)
                self._log_offset = fh.tell()

Notes:

  • If you're running some external service that generates this logs (you probably are if you really need this) you can have buffering issues. Worth taking a look at PYTHONUNBUFFERED and unbuffer if you're doing some shell pipe redirects.
  • You might want to from unittest2.case import SkipTest if you're using unittest2 - the classes will differ, and nose prefers the unittest2 import.

This entry was tagged as debugging logging nose python testing