Outputting data from unit test in Python
Asked Answered
A

14

139

If I'm writing unit tests in Python (using the unittest module), is it possible to output data from a failed test, so I can examine it to help deduce what caused the error?

I am aware of the ability to create a customized message, which can carry some information, but sometimes you might deal with more complex data, that can't easily be represented as a string.

For example, suppose you had a class Foo, and were testing a method bar, using data from a list called testdata:

class TestBar(unittest.TestCase):
    def runTest(self):
        for t1, t2 in testdata:
            f = Foo(t1)
            self.assertEqual(f.bar(t2), 2)

If the test failed, I might want to output t1, t2 and/or f, to see why this particular data resulted in a failure. By output, I mean that the variables can be accessed like any other variables, after the test has been run.

Adjustment answered 12/11, 2008 at 14:10 Comment(0)
B
85

We use the logging module for this.

For example:

import logging
class SomeTest( unittest.TestCase ):
    def testSomething( self ):
        log= logging.getLogger( "SomeTest.testSomething" )
        log.debug( "this= %r", self.this )
        log.debug( "that= %r", self.that )
        self.assertEqual( 3.14, pi )

if __name__ == "__main__":
    logging.basicConfig( stream=sys.stderr )
    logging.getLogger( "SomeTest.testSomething" ).setLevel( logging.DEBUG )
    unittest.main()

That allows us to turn on debugging for specific tests which we know are failing and for which we want additional debugging information.

My preferred method, however, isn't to spend a lot of time on debugging, but spend it writing more fine-grained tests to expose the problem.

Blemish answered 12/11, 2008 at 15:38 Comment(4)
What if I call a method foo inside testSomething and it logs something. How can I see the output for that without passing the logger to foo?Sst
@simao: What is foo? A separate function? A method function of SomeTest? In the first case, a function can have it's own logger. In the second case, the other method function can have it's own logger. Are you aware of how the logging package works? Multiple loggers is the norm.Blemish
I setup logging the exact way you specified. I assume it's working, but where do I see the output? It's not outputting to the console. I tried configuring it with logging to a file, but that doesn't produce any output either.Lollygag
"My preferred method, however, isn't to spent a lot of time on debugging, but spend it writing more fine-grained tests to expose the problem." -- well said!Napper
C
84

In Python 2.7 you could use an additional parameter, msg, to add information to the error message like this:

self.assertEqual(f.bar(t2), 2, msg='{0}, {1}'.format(t1, t2))

The official documentation is here.

Cupcake answered 3/12, 2012 at 17:17 Comment(5)
Works in Python 3 too.Maintain
The docs hint at this but it's worth mentioning explicitly: by default, if msg is used, it will replace the normal error message. To get msg appended to the normal error message, you also need to set TestCase.longMessage to TrueHomerhomere
good to know we can pass a custom error message, but I was interested in printing some message regardless of error.Chris
The comment by @CatalinIacob applies to Python 2.x. In Python 3.x, TestCase.longMessage defaults to True.Miscarriage
Thanks! This is simple and helpful.Fibrous
A
34

You can use simple print statements, or any other way of writing to standard output. You can also invoke the Python debugger anywhere in your tests.

If you use nose to run your tests (which I recommend), it will collect the standard output for each test and only show it to you if the test failed, so you don't have to live with the cluttered output when the tests pass.

nose also has switches to automatically show variables mentioned in asserts, or to invoke the debugger on failed tests. For example, -s (--nocapture) prevents the capture of standard output.

Artis answered 12/11, 2008 at 14:33 Comment(5)
Unfortunately, nose doesn't seem to collect log written to stdout/err using the logging framework. I have the print and log.debug() next to each other, and explicitly turn on DEBUG logging at the root from the setUp() method, but only the print output shows up.Secretariat
nosetests -s shows the contents of stdout whether there is an error or not - something I find useful.Thorvald
I can't find the switches to automatically show variables in the nose docs. Can you point me to something describing them?Brick
I don't know of a way to automatically show variables from nose or unittest. I print the things I want to see in my tests.Artis
“[nose] will collect the standard output for each test and only show it to you if the test failed…” This behavior can be enabled for unittest using the -b / --buffer option.Timothytimour
P
20

I don't think this is quite what you're looking for. There's no way to display variable values that don't fail, but this may help you get closer to outputting the results the way you want.

You can use the TestResult object returned by the TestRunner.run() for results analysis and processing. Particularly, TestResult.errors and TestResult.failures

About the TestResults Object:

http://docs.python.org/library/unittest.html#id3

And some code to point you in the right direction:

>>> import random
>>> import unittest
>>>
>>> class TestSequenceFunctions(unittest.TestCase):
...     def setUp(self):
...         self.seq = range(5)
...     def testshuffle(self):
...         # make sure the shuffled sequence does not lose any elements
...         random.shuffle(self.seq)
...         self.seq.sort()
...         self.assertEqual(self.seq, range(10))
...     def testchoice(self):
...         element = random.choice(self.seq)
...         error_test = 1/0
...         self.assert_(element in self.seq)
...     def testsample(self):
...         self.assertRaises(ValueError, random.sample, self.seq, 20)
...         for element in random.sample(self.seq, 5):
...             self.assert_(element in self.seq)
...
>>> suite = unittest.TestLoader().loadTestsFromTestCase(TestSequenceFunctions)
>>> testResult = unittest.TextTestRunner(verbosity=2).run(suite)
testchoice (__main__.TestSequenceFunctions) ... ERROR
testsample (__main__.TestSequenceFunctions) ... ok
testshuffle (__main__.TestSequenceFunctions) ... FAIL

======================================================================
ERROR: testchoice (__main__.TestSequenceFunctions)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "<stdin>", line 11, in testchoice
ZeroDivisionError: integer division or modulo by zero

======================================================================
FAIL: testshuffle (__main__.TestSequenceFunctions)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "<stdin>", line 8, in testshuffle
AssertionError: [0, 1, 2, 3, 4] != [0, 1, 2, 3, 4, 5, 6, 7, 8, 9]

----------------------------------------------------------------------
Ran 3 tests in 0.031s

FAILED (failures=1, errors=1)
>>>
>>> testResult.errors
[(<__main__.TestSequenceFunctions testMethod=testchoice>, 'Traceback (most recent call last):\n  File "<stdin>"
, line 11, in testchoice\nZeroDivisionError: integer division or modulo by zero\n')]
>>>
>>> testResult.failures
[(<__main__.TestSequenceFunctions testMethod=testshuffle>, 'Traceback (most recent call last):\n  File "<stdin>
", line 8, in testshuffle\nAssertionError: [0, 1, 2, 3, 4] != [0, 1, 2, 3, 4, 5, 6, 7, 8, 9]\n')]
>>>
Pachydermatous answered 12/11, 2008 at 14:56 Comment(0)
L
8

The method I use is really simple. I just log it as a warning so it will actually show up.

import logging

class TestBar(unittest.TestCase):
    def runTest(self):

       #this line is important
       logging.basicConfig()
       log = logging.getLogger("LOG")

       for t1, t2 in testdata:
         f = Foo(t1)
         self.assertEqual(f.bar(t2), 2)
         log.warning(t1)
Lorna answered 5/3, 2014 at 3:34 Comment(2)
Will this work if the test succeed? In my case the warning is showing only if the test failsTamarin
@ShreyaMaria yes it willLorna
W
7

In these cases I use a log.debug() with some messages in my application. Since the default logging level is WARNING, such messages don't show in the normal execution.

Then, in the unit test I change the logging level to DEBUG, so that such messages are shown while running them.

import logging

log.debug("Some messages to be shown just when debugging or unit testing")

In the unit tests:

# Set log level
loglevel = logging.DEBUG
logging.basicConfig(level=loglevel)



See a full example:

This is daikiri.py, a basic class that implements a daikiri with its name and price. There is method make_discount() that returns the price of that specific daikiri after applying a given discount:

import logging

log = logging.getLogger(__name__)

class Daikiri(object):
    def __init__(self, name, price):
        self.name = name
        self.price = price

    def make_discount(self, percentage):
        log.debug("Deducting discount...")  # I want to see this message
        return self.price * percentage

Then, I create a unit test, test_daikiri.py, that checks its usage:

import unittest
import logging
from .daikiri import Daikiri


class TestDaikiri(unittest.TestCase):
    def setUp(self):
        # Changing log level to DEBUG
        loglevel = logging.DEBUG
        logging.basicConfig(level=loglevel)

        self.mydaikiri = Daikiri("cuban", 25)

    def test_drop_price(self):
        new_price = self.mydaikiri.make_discount(0)
        self.assertEqual(new_price, 0)

if __name__ == "__main__":
    unittest.main()

So when I execute it I get the log.debug messages:

$ python -m test_daikiri
DEBUG:daikiri:Deducting discount...
.
----------------------------------------------------------------------
Ran 1 test in 0.000s

OK
Warbeck answered 23/3, 2016 at 12:24 Comment(0)
U
5

Another option - start a debugger where the test fails.

Try running your tests with Testoob (it will run your unit test suite without changes), and you can use the '--debug' command line switch to open a debugger when a test fails.

Here's a terminal session on Windows:

C:\work> testoob tests.py --debug
F
Debugging for failure in test: test_foo (tests.MyTests.test_foo)
> c:\python25\lib\unittest.py(334)failUnlessEqual()
-> (msg or '%r != %r' % (first, second))
(Pdb) up
> c:\work\tests.py(6)test_foo()
-> self.assertEqual(x, y)
(Pdb) l
  1     from unittest import TestCase
  2     class MyTests(TestCase):
  3       def test_foo(self):
  4         x = 1
  5         y = 2
  6  ->     self.assertEqual(x, y)
[EOF]
(Pdb)
Unstoppable answered 13/11, 2008 at 22:28 Comment(2)
Nose (nose.readthedocs.org/en/latest/index.html) is another framework that provides 'start a debugger session' options. I run it with '-sx --pdb --pdb-failures', which doesn't eat output, stops after the first failure, and drops into pdb on exceptions and test failures. This has removed my need for rich error messages, unless I'm lazy and testing in a loop.Soundless
What is Testoob? Is it only for Windows? Included by default? Can you add a reference for it (without "Edit:", "Update:", or similar - the answer should appear as if it was written today)?Tanbark
A
4

I think I might have been overthinking this. One way I've come up with that does the job, is simply to have a global variable that accumulates the diagnostic data.

Something like this:

log1 = dict()
class TestBar(unittest.TestCase):
    def runTest(self):
        for t1, t2 in testdata:
            f = Foo(t1)
            if f.bar(t2) != 2:
                log1("TestBar.runTest") = (f, t1, t2)
                self.fail("f.bar(t2) != 2")
Adjustment answered 12/11, 2008 at 17:38 Comment(0)
L
4

Use logging:

import unittest
import logging
import inspect
import os

logging_level = logging.INFO

try:
    log_file = os.environ["LOG_FILE"]
except KeyError:
    log_file = None

def logger(stack=None):
    if not hasattr(logger, "initialized"):
        logging.basicConfig(filename=log_file, level=logging_level)
        logger.initialized = True
    if not stack:
        stack = inspect.stack()
    name = stack[1][3]
    try:
        name = stack[1][0].f_locals["self"].__class__.__name__ + "." + name
    except KeyError:
        pass
    return logging.getLogger(name)

def todo(msg):
    logger(inspect.stack()).warning("TODO: {}".format(msg))

def get_pi():
    logger().info("sorry, I know only three digits")
    return 3.14

class Test(unittest.TestCase):

    def testName(self):
        todo("use a better get_pi")
        pi = get_pi()
        logger().info("pi = {}".format(pi))
        todo("check more digits in pi")
        self.assertAlmostEqual(pi, 3.14)
        logger().debug("end of this test")
        pass

Usage:

# LOG_FILE=/tmp/log python3 -m unittest LoggerDemo
.
----------------------------------------------------------------------
Ran 1 test in 0.047s

OK
# cat /tmp/log
WARNING:Test.testName:TODO: use a better get_pi
INFO:get_pi:sorry, I know only three digits
INFO:Test.testName:pi = 3.14
WARNING:Test.testName:TODO: check more digits in pi

If you do not set LOG_FILE, logging will got to stderr.

Limeade answered 16/2, 2015 at 16:38 Comment(0)
C
3

You can use logging module for that.

So in the unit test code, use:

import logging as log

def test_foo(self):
    log.debug("Some debug message.")
    log.info("Some info message.")
    log.warning("Some warning message.")
    log.error("Some error message.")

By default warnings and errors are outputted to /dev/stderr, so they should be visible on the console.

To customize logs (such as formatting), try the following sample:

# Set-up logger
if args.verbose or args.debug:
    logging.basicConfig( stream=sys.stdout )
    root = logging.getLogger()
    root.setLevel(logging.INFO if args.verbose else logging.DEBUG)
    ch = logging.StreamHandler(sys.stdout)
    ch.setLevel(logging.INFO if args.verbose else logging.DEBUG)
    ch.setFormatter(logging.Formatter('%(asctime)s %(levelname)s: %(name)s: %(message)s'))
    root.addHandler(ch)
else:
    logging.basicConfig(stream=sys.stderr)
Correna answered 4/5, 2015 at 19:42 Comment(0)
D
1

inspect.trace will let you get local variables after an exception has been thrown. You can then wrap the unit tests with a decorator like the following one to save off those local variables for examination during the post mortem.

import random
import unittest
import inspect


def store_result(f):
    """
    Store the results of a test
    On success, store the return value.
    On failure, store the local variables where the exception was thrown.
    """
    def wrapped(self):
        if 'results' not in self.__dict__:
            self.results = {}
        # If a test throws an exception, store local variables in results:
        try:
            result = f(self)
        except Exception as e:
            self.results[f.__name__] = {'success':False, 'locals':inspect.trace()[-1][0].f_locals}
            raise e
        self.results[f.__name__] = {'success':True, 'result':result}
        return result
    return wrapped

def suite_results(suite):
    """
    Get all the results from a test suite
    """
    ans = {}
    for test in suite:
        if 'results' in test.__dict__:
            ans.update(test.results)
    return ans

# Example:
class TestSequenceFunctions(unittest.TestCase):

    def setUp(self):
        self.seq = range(10)

    @store_result
    def test_shuffle(self):
        # make sure the shuffled sequence does not lose any elements
        random.shuffle(self.seq)
        self.seq.sort()
        self.assertEqual(self.seq, range(10))
        # should raise an exception for an immutable sequence
        self.assertRaises(TypeError, random.shuffle, (1,2,3))
        return {1:2}

    @store_result
    def test_choice(self):
        element = random.choice(self.seq)
        self.assertTrue(element in self.seq)
        return {7:2}

    @store_result
    def test_sample(self):
        x = 799
        with self.assertRaises(ValueError):
            random.sample(self.seq, 20)
        for element in random.sample(self.seq, 5):
            self.assertTrue(element in self.seq)
        return {1:99999}


suite = unittest.TestLoader().loadTestsFromTestCase(TestSequenceFunctions)
unittest.TextTestRunner(verbosity=2).run(suite)

from pprint import pprint
pprint(suite_results(suite))

The last line will print the returned values where the test succeeded and the local variables, in this case x, when it fails:

{'test_choice': {'result': {7: 2}, 'success': True},
 'test_sample': {'locals': {'self': <__main__.TestSequenceFunctions testMethod=test_sample>,
                            'x': 799},
                 'success': False},
 'test_shuffle': {'result': {1: 2}, 'success': True}}
Devonadevondra answered 13/9, 2013 at 17:1 Comment(0)
M
0

I find using simple, normal print inside a unit test to be really useful for debugging, the simplest way that works for me (in Python 3.12) is to just change stdout when it runs

import sys as sys
import unittest as unittest

class testMyClass(unittest.TestCase):
    def testMyClassWorks(self):
        print("Everything is broken")
        self.assertEqual(True, True)

if __name__ == "main":
    sys.stdout = sys.__stdout__ # allow print statements to show
    inittest.main()
Mishmash answered 14/2 at 16:31 Comment(0)
S
-1

Catch the exception that gets generated from the assertion failure. In your catch block you could output the data however you wanted to wherever. Then when you were done you could rethrow the exception. The test runner probably wouldn't know the difference.

Disclaimer: I haven't tried this with Python's unit test framework, but I have with other unit test frameworks.

Smallsword answered 12/11, 2008 at 15:25 Comment(0)
D
-1

Expanding on Facundo Casco's answer, this works quite well for me:

class MyTest(unittest.TestCase):
    def messenger(self, message):
        try:
            self.assertEqual(1, 2, msg=message)
        except AssertionError as e:      
            print "\nMESSENGER OUTPUT: %s" % str(e),
Dickman answered 23/10, 2013 at 9:50 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.