How to use doctest with logging?

Question

The following doctest fails:

import logging
logging.basicConfig(level=logging.DEBUG,format='%(message)s')

def say_hello():
  '''
  >>> say_hello()
  Hello!
  '''
  logging.info('Hello!')

if __name__ == '__main__':
    import doctest
    doctest.testmod()

These pages

• doctest & logging
• use doctest and logging in python program

seem to suggest logging.StreamHandler(sys.stdout) and logger.addHandler(handler) but my attempts failed in this respect. (I am new to python, if it wasn't obvious .)

Please help me fix the above code so that the test passes.

---

Update on Jun 4, 2017: To answer 00prometheus' comments: The accepted answer to use doctest and logging in python program, when I asked this question, seemed unnecessarily complicated. And indeed it is, as the accepted answer here gives a simpler solution. In my highly biased opinion, my question is also clearer than the one I already linked in the original post.

Slagle

Please show your failed attempts. – Inwards

@Inwards Among others: (1) logging.StreamHandler(sys.stdout) before calling doctest.testmod(); (2) logging.getLogger().addHandler(logging.StreamHandler(sys.stdout)) before calling doctest.testmod(). I don't know what these do exactly, I was just monkeying around. – Slagle

Possible duplicate of use doctest and logging in python program – Spectacles

This is a duplicate of: #2718334 This question is a bit more clearly asked, but the other one has working answers. – Spectacles

@Spectacles "but the other one has working answers" Doesn't the accepted answer of this question work for you? It used to work when I accepted it... Note that your suggested solution (at the linked question), if I understand it correctly, requires me to pollute my doctest, so I don't see why it is any better than the accepted answer here. Also note that my question already linked that other question. – Slagle

You are right, this one does have working answers too. The main reason for designating this one the duplicate is that it was asked 2014, and the other one 2010. – Spectacles

@Spectacles OK, I edited the question. As far as I am concerned, this discussion is not helping anybody, and with that edit to the question, I consider this case closed. – Slagle

@Slagle Whoa! You don't need to munge up your question like that! A comment is fine regarding this discussion. – Spectacles

Related: #899567 – Waterman

Answer 1

You need to define a "logger" object. This is usually done after import with:

import sys
import logging
log = logging.getLogger(__name__)

When you want to log a message:

log.info('Hello!')

In the code that gets run like a script you set the basicConfig:

if __name__ == '__main__':
    import doctest
    logging.basicConfig(level=logging.DEBUG, stream=sys.stdout, format='%(message)s')
    doctest.testmod()

Edit:

Ok, you were right. It doesn't work, but I got it to work...BUT DO NOT DO THIS! Just use print statements or return what you actually need to check. As your second link says this is just a bad idea. You shouldn't be checking logging output (its for logging). Even the original poster for that second link said they got it to work by switching their logging to using print. But here is the evil code that seems to work:

class MyDocTestRunner(doctest.DocTestRunner):
    def run(self, test, compileflags=None, out=None, clear_globs=True):
        if out is None:
            handler = None
        else:
            handler = logging.StreamHandler(self._fakeout)
            out = sys.stdout.write
        logger = logging.getLogger() # root logger (say)
        if handler:
            logger.addHandler(handler)
        try:
            doctest.DocTestRunner.run(self, test, compileflags, out, clear_globs)
        finally:
            if handler:
                logger.removeHandler(handler)
                handler.close()
    
if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG, format='%(message)s')
    tests = doctest.DocTestFinder().find(say_hello, __name__)
    dt_runner = MyDocTestRunner()
    for t in tests:
        dt_runner.run(t, out=True)

Edit (continued):

My attempts also failed when trying what your second link suggested. This is because internally doctest reassigns sys.stdout to self._fakeout. That's why nothing short of my hack will work. I actually tell the logger to write to this "fakeout".

Edit (answer to comment):

It's not exactly the code from the link. If it was the code from the link I would say it's not that bad of an option because its not doing anything too complex. My code, however, is using a "private" internal instance attribute that shouldn't be used by a normal user. That is why it is evil.

And yes, logging can be used for testing output, but it does not make much sense to do so in a unittest/doctest and is probably why doctest doesn't include functionality like this out of the box. The TextTest stuff you linked to is all about functional or integration testing. Unittests (and doctests) should be testing small individual components. If you have to capture logged output to make sure your unittest/doctest is correct then you should maybe think about separating things out or not doing these checks in a doctest.

I personally only use doctests for simple examples and verifications. Mostly for usage examples since any user can see an inline doctest.

Edit (ok last one):

Same solution, simpler code. This code doesn't require that you create a custom runner. You still have to create the default runner and stuff because you need to access the "_fakeout" attribute. There is no way to use doctest to check logging output without logging to this attribute as a stream.

if __name__ == '__main__':
    dt_runner = doctest.DocTestRunner()
    tests = doctest.DocTestFinder().find(sys.modules[__name__])
    logging.basicConfig(level=logging.DEBUG, format='%(message)s', stream=dt_runner._fakeout)
    for t in tests:
        dt_runner.run(t)

Brokaw

That still fails on my machine. Please check it on yours. – Slagle

Ok check my edit...but just use print statements please. – Brokaw

Yes, that's the code from the answer I linked and that's what I was trying to avoid. "You shouldn't be checking logging output (its for logging)." I beg to differ. I see that doctest is probably not meant to be used like this. However, depending on your application, checking logs can be an appropriate way of testing. "here is the evil code that seems to work" What makes it "evil"? It's so ugly that I wouldn't want to use it but why do you call it evil? – Slagle

OK, thanks. As I said before, I see that doctest is probably not meant to be used like this. I leave this question still open for a while. – Slagle

Ok I thought of one more way to do it that doesn't require the custom class. Still not pretty and still not recommended, but check it out in the edit. This also finds all of the tests in the module instead of just one function. – Brokaw

I greatly appreciate your efforts and I apologize that it took so long; I have been extremely busy lately. – Slagle

Answer 2

One way to do this is by monkey-patching the logging module (my code; docstring contents from import logging are relevant to your question):

@classmethod
def yield_int(cls, field, text):
    """Parse integer values and yield (field, value)

    >>> test = lambda text: dict(Monster.yield_int('passive', text))
    >>> test(None)
    {}
    >>> test('42')
    {'passive': 42}
    >>> import logging
    >>> old_warning = logging.warning
    >>> warnings = []
    >>> logging.warning = lambda msg: warnings.append(msg)
    >>> test('seven')
    {}
    >>> warnings
    ['yield_int: failed to parse text "seven"']
    >>> logging.warning = old_warning
    """
    if text == None:
        return

    try:
        yield (field, int(text))
    except ValueError:
        logging.warning(f'yield_int: failed to parse text "{text}"')

However, a much cleaner approach uses the unittest module:

    >>> from unittest import TestCase
    >>> with TestCase.assertLogs(_) as cm:
    ...     print(test('seven'))
    ...     print(cm.output)
    {}
    ['WARNING:root:yield_int: failed to parse text "seven"']

Technically you should probably instantiate a TestCase object rather than passing _ to assertLogs as self, since there's no guarantee that this method won't attempt to access the instance properties in the future.

Waterman

Answer 3

I use the following technique:

1. Set the logging stream to a StringIO object.
2. Log away...
3. Print the contents for the StringIO object and expect the output.
4. Or: Assert against the contents of the StringIO object.

This should do it.

Here is some example code.

First it just does the whole setup for the logging within the doctest - just to show how it's working.

Then the code shows how the setup can be put into as seperate function setup_doctest_logging that does the setup ànd returns itself a function that prints the log. This keeps the test code more focused and moves the ceremonial part out of the test.

import logging


def func(s):
    """
    >>> import io
    >>> string_io = io.StringIO()
    >>> # Capture the log output to a StringIO object
    >>> # Use force=True to make this configuration stick
    >>> logging.basicConfig(stream=string_io, format='%(message)s', level=logging.INFO, force=True)

    >>> func('hello world')

    >>> # print the contents of the StringIO. I prefer that. Better visibility.
    >>> print(string_io.getvalue(), end='')
    hello world
    >>> # The above needs the end='' because print will otherwise add an new line to the
    >>> # one that is already in the string from logging itself

    >>> # Or you can just expect an extra empty line like this:
    >>> print(string_io.getvalue())
    hello world
    <BLANKLINE>

    >>> func('and again')

    >>> # Or just assert on the contents.
    >>> assert 'and again' in string_io.getvalue()
    """
    logging.info(s)


def setup_doctest_logging(format='%(levelname)s %(message)s', level=logging.WARNING):
    """ 
    This could be put into a separate module to make the logging setup easier
    """
    import io
    string_io = io.StringIO()
    logging.basicConfig(stream=string_io, format=format, level=level, force=True)

    def log_printer():
        s = string_io.getvalue()
        print(s, end='')
    return log_printer


def other_logging_func(s, e=None):
    """
    >>> print_whole_log = setup_doctest_logging(level=logging.INFO)
    >>> other_logging_func('no error')
    >>> print_whole_log()
    WARNING no error
    >>> other_logging_func('I try hard', 'but I make mistakes')
    >>> print_whole_log()
    WARNING no error
    WARNING I try hard
    ERROR but I make mistakes
    """
    logging.warning(s)
    if e is not None:
        logging.error(e)


if __name__ == '__main__':
    import doctest
    doctest.testmod()

Dismast

Answer 4

As mentioned by others, the issue is that doctest modifies sys.stdout after basicConfig created a StreamHandler that holds its own copy. One way to deal with this is to create a stream object that dispatches write and flush to sys.stdout. Another is to bypass the issue altogether by creating your own handler:

class PrintHandler(logging.Handler):
  def emit(self, record):
    print(self.format(record))

logging.basicConfig(level=logging.DEBUG, format='%(message)s',
  handlers=[PrintHandler()])

Roulers

This is my favorite solution, except for doctest now thinks the printed logging output is the output from all my tests. So all tests fail. Any ideas? – Cordes