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

Question

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?

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

Some people probably visit this thread to find a way to forward the logs created during testing to the console or to PyDev. The above answers already provide some solutions.

If one wants to capture particular logs within an actual test, I found that since Python 3.4, unittest.TestCase offers assertLogs(), which returns a context manager that captures current log messages. From the unittest docs:

with self.assertLogs('foo', level='INFO') as cm:
   logging.getLogger('foo').info('first message')
   logging.getLogger('foo.bar').error('second message')
self.assertEqual(cm.output, ['INFO:foo:first message',
                             'ERROR:foo.bar:second message'])

The messages are captured in cm.output. For more detailed information (like timing, file, line-number etc., cm.records contains a list of LogRecords.

All this does not directly address the OP faced with PyDev, but offers a way to examine the created messages programmatically.

For those familiar with pytest, one can forward nicely formatted log messages to the console using the --log-cli-level=LEVEL flag, (for instance pytest --log-cli-level=info).

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

Answer 5

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.

Answer 6

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 7

If you have different initaliser modules for test, dev and production then you can disable anything or redirect it in the initialiser.

I have local.py, test.py and production.py that all inherit from common.y

common.py does all the main config including this snippet :

    LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'django.server': {
            '()': 'django.utils.log.ServerFormatter',
            'format': '[%(server_time)s] %(message)s',
        },
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
    },
    'filters': {
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        'django.server': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'django.server',
        },
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler'
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': True,
        },
        'celery.tasks': {
            'handlers': ['console'],
            'level': 'DEBUG',
            'propagate': True,
        },
        'django.server': {
            'handlers': ['django.server'],
            'level': 'INFO',
            'propagate': False,
        },
    }

Then in test.py I have this:

console_logger = Common.LOGGING.get('handlers').get('console')
console_logger['class'] = 'logging.FileHandler
console_logger['filename'] = './unitest.log

This replaces the console handler with a FileHandler and means still get logging but I do not have to touch the production code base.

Answer 8

I created this unit test:

import logging
from io import StringIO

def test_stream():
    logger = logging.getLogger()
    logger.level = logging.DEBUG
    strStream = StringIO()
    streamHandler = logging.StreamHandler(strStream)
    logger.addHandler(streamHandler)
    logger.info('Hello World!')

    assert strStream.getvalue() == 'Hello World!\n'

    strStream.close()

Answer 9

This is a small hack but it works for me. Add this code when you want to display captured logs. Remove it after no needed.

self.assertEqual(1, 0)

Example:

def test_test_awesome_function():
    print("Test 1")
    logging.info("Test 2")
    logging.warning("Test 3")

    self.assertEqual(1, 0)

Updated:

By the way, this is not a long term solution, this solution is helpful when you want to quick debug something on target functions.

Once assert is fail, unittest will throw which functions are getting errors and also capture and display print, logging.* content.