PyDev unittesting: How to capture text logged to a

Question

I am using PyDev for development and unit-testing of my Python application. As for unit-testing, everything works great behalf the fact that content logged to any logging. Logger is not captured by the "Captured output" of PyDev.

I already forward everything logged to the standard output like this:

import sys
logger = logging.getLogger()
logger.level = logging.DEBUG
logger.addHandler(logging.StreamHandler(sys.stdout))

Nevertheless the "Captured output" does not display stuff logged to loggers.

Here an example unittest-script: test.py

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG
logger.addHandler(logging.StreamHandler(sys.stdout))

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        print("AA")
        logging.getLogger().info("BB")

The console output is:

Finding files... done.
Importing test modules ... done.

testSimpleMsg (itf.lowlevel.tests.hl7.TestCase) ... AA
2011-09-19 16:48:00,755 - root - INFO - BB
BB
ok

----------------------------------------------------------------------
Ran 1 test in 0.001s

OK

But the CAPTURED OUTPUT for the test is:

======================== CAPTURED OUTPUT =========================
AA

Does anybody knows how to capture everything is logged to a logging.Logger during the execution of this test?

Answer 1

The issue is that the unittest runner replaces sys.stdout/sys.stderr before the testing starts, and the StreamHandler is still writing to the original sys.stdout.

If you assign the 'current' sys.stdout to the handler, it should work (see the code below).

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG
stream_handler = logging.StreamHandler(sys.stdout)
logger.addHandler(stream_handler)

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        stream_handler.stream = sys.stdout
        print("AA")
        logging.getLogger().info("BB")

Although, a better approach would be adding/removing the handler during the test:

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        stream_handler = logging.StreamHandler(sys.stdout)
        logger.addHandler(stream_handler)
        try:
            print("AA")
            logging.getLogger().info("BB")
        finally:
            logger.removeHandler(stream_handler)

Answer 2

I grew tired of having to manually add Fabio's great code to all setUps, so I subclassed unittest.TestCase with some __metaclass__ing:

class LoggedTestCase(unittest.TestCase):
    __metaclass__ = LogThisTestCase
    logger = logging.getLogger("unittestLogger")
    logger.setLevel(logging.DEBUG) # or whatever you prefer

class LogThisTestCase(type):
    def __new__(cls, name, bases, dct):
        # if the TestCase already provides setUp, wrap it
        if 'setUp' in dct:
            setUp = dct['setUp']
        else:
            setUp = lambda self: None
            print "creating setUp..."

        def wrappedSetUp(self):
            # for hdlr in self.logger.handlers:
            #    self.logger.removeHandler(hdlr)
            self.hdlr = logging.StreamHandler(sys.stdout)
            self.logger.addHandler(self.hdlr)
            setUp(self)
        dct['setUp'] = wrappedSetUp

        # same for tearDown
        if 'tearDown' in dct:
            tearDown = dct['tearDown']
        else:
            tearDown = lambda self: None

        def wrappedTearDown(self):
            tearDown(self)
            self.logger.removeHandler(self.hdlr)
        dct['tearDown'] = wrappedTearDown

        # return the class instance with the replaced setUp/tearDown
        return type.__new__(cls, name, bases, dct)

Now your test case can simply inherit from LoggedTestCase, i.e. class TestCase(LoggedTestCase) instead of class TestCase(unittest.TestCase) and you're done. Alternatively, you can add the __metaclass__ line and define the logger either in the test or a slightly modified LogThisTestCase.

Answer 3

I came across this problem also. I ended up subclassing StreamHandler, and overriding the stream attribute with a property that gets sys.stdout. That way, the handler will use the stream that the unittest.TestCase has swapped into sys.stdout:

class CapturableHandler(logging.StreamHandler):

    @property
    def stream(self):
        return sys.stdout

    @stream.setter
    def stream(self, value):
        pass

You can then setup the logging handler before running tests like so (this will add the custom handler to the root logger):

def setup_capturable_logging():
    if not logging.getLogger().handlers:
        logging.getLogger().addHandler(CapturableHandler())

If, like me, you have your tests in separate modules, you can just put a line after the imports of each unit test module that will make sure the logging is setup before tests are run:

import logutil

logutil.setup_capturable_logging()

This might not be the cleanest approach, but it's pretty simple and worked well for me.

Answer 4

I'd suggest using a LogCapture and testing that you really are logging what you expect to be logging:

http://testfixtures.readthedocs.org/en/latest/logging.html