Mailing List Archive: Python: Python

How many times does unittest run each test?

Index | Next | Previous | View Threaded

Joshua.R.English at gmail

Aug 10, 2013, 1:00 PM

Post #1 of 10 (30 views)
Permalink

How many times does unittest run each test?

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
--
http://mail.python.org/mailman/listinfo/python-list

roy at panix

Aug 10, 2013, 1:40 PM

Post #2 of 10 (29 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412 [at] googlegroups>,
Josh English <Joshua.R.English [at] gmail> wrote:

> 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.
--
http://mail.python.org/mailman/listinfo/python-list

ned at nedbatchelder

Aug 10, 2013, 3:52 PM

Post #3 of 10 (21 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

On 8/10/13 4:40 PM, Roy Smith wrote:
> In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412 [at] googlegroups>,
> Josh English <Joshua.R.English [at] gmail> wrote:
>
>> 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.
--
http://mail.python.org/mailman/listinfo/python-list

Joshua.R.English at gmail

Aug 10, 2013, 3:53 PM

Post #4 of 10 (26 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

On Saturday, August 10, 2013 1:40:43 PM UTC-7, Roy Smith wrote:
> In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412 [at] googlegroups>,
>
> 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
--
http://mail.python.org/mailman/listinfo/python-list

joshua.r.english at gmail

Aug 10, 2013, 3:58 PM

Post #5 of 10 (26 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

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

On Sat, Aug 10, 2013 at 3:52 PM, Ned Batchelder <ned [at] nedbatchelder> wrote:
> On 8/10/13 4:40 PM, Roy Smith wrote:
>>
>> In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412 [at] googlegroups>,
>> Josh English <Joshua.R.English [at] gmail> wrote:
>>
>>> 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
Joshua.R.English [at] gmail
http://www.joshuarenglish.com
--
http://mail.python.org/mailman/listinfo/python-list

roy at panix

Aug 10, 2013, 4:14 PM

Post #6 of 10 (26 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

On Saturday, August 10, 2013 1:40:43 PM UTC-7, Roy Smith wrote:
> > 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.

In article <35d12db6-c367-4a45-a68e-8ed4c0ae1ee7 [at] googlegroups>,
Josh English <Joshua.R.English [at] gmail> wrote:

> 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']
--
http://mail.python.org/mailman/listinfo/python-list

rosuav at gmail

Aug 10, 2013, 4:21 PM

Post #7 of 10 (21 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

On Sun, Aug 11, 2013 at 12:14 AM, Roy Smith <roy [at] panix> wrote:
> 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
--
http://mail.python.org/mailman/listinfo/python-list

Joshua.R.English at gmail

Aug 10, 2013, 5:47 PM

Post #8 of 10 (21 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

On Saturday, August 10, 2013 4:14:09 PM UTC-7, Roy Smith wrote:

>
>
> 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
--
http://mail.python.org/mailman/listinfo/python-list

Joshua.R.English at gmail

Aug 10, 2013, 5:52 PM

Post #9 of 10 (21 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

On Saturday, August 10, 2013 4:21:35 PM UTC-7, Chris Angelico wrote:
> On Sun, Aug 11, 2013 at 12:14 AM, Roy Smith <> wrote:
>
> > Maybe you've got two different handlers which are both getting the same
> > loggingvents 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).

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 just makes it simple.

Josh
--
http://mail.python.org/mailman/listinfo/python-list

rosuav at gmail

Aug 10, 2013, 6:10 PM

Post #10 of 10 (21 views)
Permalink

Re: How many times does unittest run each test? [In reply to]

On Sun, Aug 11, 2013 at 1:52 AM, Josh English
<Joshua.R.English [at] gmail> wrote:
> 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 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
--
http://mail.python.org/mailman/listinfo/python-list

Index | Next | Previous | View Threaded

Interested in having your list archived? Contact Gossamer Threads