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?

Mayle

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)

Tagalog

For completeness: I need this redirection for all my unit-tests. The best solution for me is to add the new handler in the setUp-method and to remove it in the tearDown-method. – Mayle

Great answer, I expanded this to a __metaclass__ so a wrapped setUp and tearDown automatically include this – Unification

Why is it better to add/remove handlers instead of keeping them outside of test case? – Agueweed

I think it's better because you can customize it for a specific function or add more info (instead of having to update the handler stream for each call). The final solution would use decorators or metaclasses anyway to wrap the tests, so, you're not really typing more code, just providing something which may be more customizable... – Tagalog

Is this better than just using print in the tests for user feedback? – Guitarist

It is if you actually have logging in your application -- for the sample in the code it isn't (still the API can definitely be better -- maybe using a decorator or with statements... consider the code just a sample where you can work upon). – Tagalog

Note that you may also have to add logger.setLevel(logging.INFO) – Hyperaesthesia

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.

Unification

@Michaelson Thanks, after reading this great explanation of __metaclass__ I just had to use it... – Unification

I found myself reading the same answer last week and it has already made it into my code base too. – Michaelson

Nice solution, but purely for informational purposes, you could do a superclass and inherit the run() to do your custom setup, call the original run() and then do your custom tearDown (if you want to create a subclass without having to call setUp/tearDown) -- not that metaclasses aren't useful, but I think the final code becomes more complex ;) – Tagalog

@FabioZadrozny True, though as mentioned at that time I just had to use metaclasses ;) – Unification

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).

Musteline

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

Clementclementas

I enjoyed that there is a package that takes care of it, so one does not need to write code for obviously a common problem. But unfortunately I ran into UTF problems when using "print(l)" that I don't have, when I use the logger usually. So my approach was "sys.stdout.buffer.write(l.__str__().encode('utf8'))" instead. This works well, so I wanted to share it. – Mudslinger

@IwanLD - I'd recommend using LogCapture().check() nowadays. How come you couldn't use that? – Clementclementas

@BearBrown - that links worked for over 10 years now, as it's author, I don't intend for that to change ;-) I'd also gently suggest that if it did change, the 'edit' feature could be used to correct it... – Clementclementas

NOTE: If you are using this package with Django please read the documentation here: testfixtures.readthedocs.io/en/latest/django.html – Inarch

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.

Sharyl

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.

Neptunian

Answer 7

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()

Scram

Answer 8

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.

Stingaree

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.

Aggappera

Although this will trigger the log display within the unittest output, adding nonsense errors could have unintended side effects if you forget to remove them. This is bad form and is not needed to solve the problem. – Inarch

It's not clear what you mean here. print will probably go through, and logging is captured by unittest. Right? – Hyperaesthesia

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