PyDev unittesting: How to capture text logged to a logging.Logger in "Captured Output"

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

I'm already forwarding 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 the stuff logged to loggers.

Here's 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 know how to capture everything that is logged to a logging.Logger during the execution of this test?

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)

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.

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

After reading the answers in this and a few other related threads (thank you!), here is the context manager I put together, that will capture the logger's output (if any was sent).

from io import StringIO
import logging
class CaptureLogger:
    """Context manager to capture `logging` streams

    Args:
        - logger: 'logging` logger object

    Results:
        The captured output is available via `self.out`

    """

    def __init__(self, logger):
        self.logger = logger
        self.io = StringIO()
        self.sh = logging.StreamHandler(self.io)
        self.out = ''

    def __enter__(self):
        self.logger.addHandler(self.sh)
        return self

    def __exit__(self, *exc):
        self.logger.removeHandler(self.sh)
        self.out = self.io.getvalue()

    def __repr__(self):
        return f"captured: {self.out}\n"

Usage example:

logger = logging.getLogger()
msg = "Testing 1, 2, 3"
with CaptureLogger(logger) as cl:
    logger.error(msg)
assert cl.out, msg+"\n"

As the OP asked for getting it into the captured stdout stream, you can print it to stdout in __exit__, so adding one extra line as follows:

    def __exit__(self, *exc):
        self.logger.removeHandler(self.sh)
        self.out = self.io.getvalue()
        print(self.out)

This solution is different in that it will gather the logging output and dump it out at the end all at once, after all the normal print() calls if any. So it may or may not be what OP is after, but this worked well for my needs.

PyDev unittesting: How to capture text logged to a logging.Logger in "Captured Output"

Related

Recent Posts