How many times does unittest run each test?

[Josh English]

I am working on a library, and adding one feature broke a seemingly unrelated feature. As I already had Test Cases written, I decided to try to incorporate the logging module into my class, and turn on debugging at the logger before the newly-broken test.

Here is an example script:
# -----
#!/usr/bin/env python

import logging

def get_vals():
return ['a','b','c']

class SimpleChecker(object):
def __init__(self, callback=None):
self.callback = callback
self.logger = logging.getLogger(self.__class__.__name__)
h = logging.StreamHandler()
f = logging.Formatter("%(name)s - %(levelname)s - %(message)s")
h.setFormatter(f)
self.logger.addHandler(h)

def __call__(self, thing):
self.logger.debug('calling %s' % thing)
vals = self.callback()
return thing in vals

import unittest

class LoaderTC(unittest.TestCase):
def setUp(self):
self.checker = SimpleChecker(get_vals)

def tearDown(self):
del self.checker

def test_callable(self):
self.assertTrue(callable(self.checker),
'loader did not create callable object')
self.assertTrue(callable(self.checker.callback),
'loader did not create callable callback')

self.checker.logger.setLevel(logging.DEBUG)
self.assertTrue(self.checker('q') is False, "checker accepted bad input")

class NameSpaceTC(unittest.TestCase):
def setUp(self):
self.checker = SimpleChecker(get_vals)

def tearDown(self):
del self.checker

def test_callable(self):
self.assertTrue(callable(self.checker),
'loader did not create callable object')
self.assertTrue(callable(self.checker.callback),
'loader did not create callable callback')

self.checker.logger.setLevel(logging.DEBUG)
self.assertTrue(self.checker('a'), "checker did not accept good value")
self.assertFalse(self.checker('f'), "checker accepted bad value")

if __name__=='__main__':
unittest.main(verbosity=0)

# -------

When I run this, I get:
SimpleChecker - DEBUG - calling q
SimpleChecker - DEBUG - calling a
SimpleChecker - DEBUG - calling a
SimpleChecker - DEBUG - calling f
SimpleChecker - DEBUG - calling f
----------------------------------------------------------------------
Ran 2 tests in 0.013s

OK
Exit code: False

Why am I seeing those extra debugging lines? In the script I'm really trying to debug, I see 12-13 debug messages repeated, making actual debugging difficult.

Josh English

 

[Roy Smith]

I am working on a library, and adding one feature broke a seemingly unrelated
feature. As I already had Test Cases written, I decided to try to incorporate
the logging module into my class, and turn on debugging at the logger before
the newly-broken test.

Here is an example script:

[followed by 60 lines of code]

The first thing to do is get this down to some minimal amount of code
that demonstrates the problem.

For example, you drag in the logging module, and do some semi-complex
configuration. Are you SURE your tests are getting run multiple times,
or maybe it's just that they're getting LOGGED multiple times. Tear out
all the logging stuff. Just use a plain print statement.

You've got two different TestCases here. Does the problem happen with
just LoaderTC, or with just NameSpaceTC?

Keep tearing out code until you can no longer demonstrate the problem.
Keep at it until there is not a single line of code remaining which
isn't required to demonstrate. Then come back and ask your question
again.

 

[Ned Batchelder]

I am working on a library, and adding one feature broke a seemingly unrelated
feature. As I already had Test Cases written, I decided to try to incorporate
the logging module into my class, and turn on debugging at the logger before
the newly-broken test.

Here is an example script:

[followed by 60 lines of code]

The first thing to do is get this down to some minimal amount of code
that demonstrates the problem.

For example, you drag in the logging module, and do some semi-complex
configuration. Are you SURE your tests are getting run multiple times,
or maybe it's just that they're getting LOGGED multiple times. Tear out
all the logging stuff. Just use a plain print statement.

Roy is right: the problem isn't the tests, it's the logging. You are
calling .addHandler in the SimpleChecker.__init__, then you are
constructing two SimpleCheckers, each of which adds a handler. In the
LoaderTC test, you've only constructed one, adding only one handler, so
the "calling q" line only appears once. Then the NameSpaceTC tests
runs, constructs another SimplerChecker, which adds another handler, so
now there are two. That's why the "calling a" and "calling f" lines
appear twice.

Move your logging configuration to a place that executes only once.

Also, btw, you don't need the "del self.checker" in your tearDown
methods: the test object is destroyed after each test, so any objects it
holds will be released after each test with no special action needed on
your part.

--Ned.

 

[Josh English]

Josh English wrote:
The first thing to do is get this down to some minimal amount of code
that demonstrates the problem.



For example, you drag in the logging module, and do some semi-complex
configuration. Are you SURE your tests are getting run multiple times,
or maybe it's just that they're getting LOGGED multiple times. Tear out
all the logging stuff. Just use a plain print statement.

You've got two different TestCases here. Does the problem happen with
just LoaderTC, or with just NameSpaceTC?

Ok, then why would things get logged multiple times? The two test cases actually test a loader function that I could strip out, because it wasn't relevant. In these cases, the loader was being called with two different configurations in the individual setUp methods.

I left them there to show that in LoaderTC, there is one debug log coming from SimpleChecker, but in the NameSpaceTC, each debug message is printed twice. If I print statements on each test_ method, they are called once.

As far as stripping down the code, I suppose 15 lines can be culled:

#---------
import logging

class SimpleChecker(object):
def __init__(self,):
self.logger = logging.getLogger(self.__class__.__name__)
h = logging.StreamHandler()
f = logging.Formatter("%(name)s - %(levelname)s - %(message)s")
h.setFormatter(f)
self.logger.addHandler(h)

def __call__(self, thing):
self.logger.debug('calling %s' % thing)
return thing in ['a','b','c']

import unittest

class LoaderTC(unittest.TestCase):
def setUp(self):
self.checker = SimpleChecker()

def tearDown(self):
del self.checker

def test_callable(self):
self.checker.logger.setLevel(logging.DEBUG)
self.assertTrue(self.checker('q') is False, "checker accepted bad input")

class NameSpaceTC(unittest.TestCase):
def setUp(self):
self.checker = SimpleChecker()

def tearDown(self):
del self.checker

def test_callable(self):
print "testing callable"

self.checker.logger.setLevel(logging.DEBUG)
self.assertTrue(self.checker('a'), "checker did not accept good value")
self.assertFalse(self.checker('f'), "checker accepted bad value")

if __name__=='__main__':
unittest.main(verbosity=0)

#-----------
The output:

SimpleChecker - DEBUG - calling q
setting up NameSpace
testing callable
SimpleChecker - DEBUG - calling a
SimpleChecker - DEBUG - calling a
SimpleChecker - DEBUG - calling f
SimpleChecker - DEBUG - calling f
----------------------------------------------------------------------
Ran 2 tests in 0.014s

OK
Exit code: False

Josh

 

[Josh English]

Aha. Thanks, Ned. This is the answer I was looking for.

I use logging in the real classes, and thought that turning setting
the level to logging.DEBUG once was easier than hunting down four
score of print statements.

Josh

I am working on a library, and adding one feature broke a seemingly
unrelated
feature. As I already had Test Cases written, I decided to try to
incorporate
the logging module into my class, and turn on debugging at the logger
before
the newly-broken test.

Here is an example script:

[followed by 60 lines of code]

The first thing to do is get this down to some minimal amount of code
that demonstrates the problem.

For example, you drag in the logging module, and do some semi-complex
configuration. Are you SURE your tests are getting run multiple times,
or maybe it's just that they're getting LOGGED multiple times. Tear out
all the logging stuff. Just use a plain print statement.

Roy is right: the problem isn't the tests, it's the logging. You are
calling .addHandler in the SimpleChecker.__init__, then you are constructing
two SimpleCheckers, each of which adds a handler. In the LoaderTC test,
you've only constructed one, adding only one handler, so the "calling q"
line only appears once. Then the NameSpaceTC tests runs, constructs another
SimplerChecker, which adds another handler, so now there are two. That's
why the "calling a" and "calling f" lines appear twice.

Move your logging configuration to a place that executes only once.

Also, btw, you don't need the "del self.checker" in your tearDown methods:
the test object is destroyed after each test, so any objects it holds will
be released after each test with no special action needed on your part.

--Ned.

 

[Roy Smith]

Ok, then why would things get logged multiple times?

Maybe you've got two different handlers which are both getting the same
logging events and somehow they both end up in your stderr stream.
Likely? Maybe not, but if you don't have any logging code in the test
at all, it becomes impossible. You can't have a bug in a line of code
that doesn't exist (yeah, I know, that's a bit of a handwave).

When a test (or any other code) is doing something you don't understand,
the best way to start understanding it is to create a minimal test case;
the absolute smallest amount of code that demonstrates the problem.

I don't understand the whole SimpleChecker class. You've created a
class, and defined your own __call__(), just so you can check if a
string is in a list? Couldn't this be done much simpler with a plain
old function:

def checker(thing):
print "calling %s" % thing
return thing in ['a','b','c']

 

[Chris Angelico]

Maybe you've got two different handlers which are both getting the same
logging events and somehow they both end up in your stderr stream.
Likely? Maybe not, but if you don't have any logging code in the test
at all, it becomes impossible. You can't have a bug in a line of code
that doesn't exist (yeah, I know, that's a bit of a handwave).

Likely? Very much so, to the extent that it is, if not a FAQ,
certainly a Not All That Uncommonly Asked Question. So many times
someone places logging code in something that gets called twice, and
ends up with two handlers. Personally, I much prefer to debug with
straight-up 'print' - much less hassle. I'd turn to the logging module
only if I actually need its functionality (logging to some place other
than the console, or leaving the log statements in and {en|dis}abling
them at run-time).

ChrisA

 

[Josh English]

I don't understand the whole SimpleChecker class. You've created a
class, and defined your own __call__(), just so you can check if a
string is in a list? Couldn't this be done much simpler with a plain
old function:

def checker(thing):
print "calling %s" % thing
return thing in ['a','b','c']

SimpleCheck is an extremely watered down version of my XML checker (https://pypi.python.org/pypi/XMLCheck/0.6.7). I'm working a feature that allows the checker to call a function to get acceptable values, instead of defining them at the start of the program. I included all of that because it's the shape of the script I'm working with.

The real problem was setting additional handlers where they shouldn't be.

Josh

 

[Josh English]

Likely? Very much so, to the extent that it is, if not a FAQ,
certainly a Not All That Uncommonly Asked Question. So many times
someone places logging code in something that gets called twice, and
ends up with two handlers. Personally, I much prefer to debug with
straight-up 'print' - much less hassle. I'd turn to the logging module
only if I actually need its functionality (logging to some place other
than the console, or leaving the log statements in and {en|dis}abling
them at run-time).

Yes, I definitely need the NUATAQ sheet for Python.

I'm using logging for debugging, because it is pretty straightforward and can be activated for a small section of the module. My modules run long (3,000 lines or so) and finding all those dastardly print statements is a pain,and littering my code with "if debug: print message" clauses. Logging justmakes it simple.

Josh

 

[Chris Angelico]

I'm using logging for debugging, because it is pretty straightforward andcan be activated for a small section of the module. My modules run long (3,000 lines or so) and finding all those dastardly print statements is a pain, and littering my code with "if debug: print message" clauses. Logging just makes it simple.

So logging might be the right tool for your job. Tip: Sometimes it
helps, when trying to pin down an issue, to use an additional
debugging aid. You're already using logging? Add print calls. Already
got a heartbeat function? Run it through a single-stepping debugger as
well. Usually that sort of thing just gives you multiple probes at the
actual problem, but occasionally you'll get an issue like this, and
suddenly it's really obvious because one probe behaves completely
differently from the other.

ChrisA