Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > comp.lang.python > #52321 > unrolled thread

How many times does unittest run each test?

Back to article view | Back to comp.lang.python

Contents

  How many times does unittest run each test? Josh English <Joshua.R.English@gmail.com> - 2013-08-10 13:00 -0700
    Re: How many times does unittest run each test? Roy Smith <roy@panix.com> - 2013-08-10 16:40 -0400
      Re: How many times does unittest run each test? Josh English <Joshua.R.English@gmail.com> - 2013-08-10 15:53 -0700
        Re: How many times does unittest run each test? Roy Smith <roy@panix.com> - 2013-08-10 19:14 -0400
          Re: How many times does unittest run each test? Chris Angelico <rosuav@gmail.com> - 2013-08-11 00:21 +0100
            Re: How many times does unittest run each test? Josh English <Joshua.R.English@gmail.com> - 2013-08-10 17:52 -0700
              Re: How many times does unittest run each test? Chris Angelico <rosuav@gmail.com> - 2013-08-11 02:10 +0100
          Re: How many times does unittest run each test? Josh English <Joshua.R.English@gmail.com> - 2013-08-10 17:47 -0700
      Re: How many times does unittest run each test? Josh English <joshua.r.english@gmail.com> - 2013-08-10 15:58 -0700
      Re: How many times does unittest run each test? Ned Batchelder <ned@nedbatchelder.com> - 2013-08-10 18:52 -0400

#52321 — 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

[toc] | [next] | [standalone]

#52325

In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412@googlegroups.com>,
 Josh English <Joshua.R.English@gmail.com> 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.

[toc] | [prev] | [next] | [standalone]

#52331

On Saturday, August 10, 2013 1:40:43 PM UTC-7, Roy Smith wrote:
> In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412@googlegroups.com>,
> 
>  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

[toc] | [prev] | [next] | [standalone]

#52333

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@googlegroups.com>,
 Josh English <Joshua.R.English@gmail.com> 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']

[toc] | [prev] | [next] | [standalone]

#52334

On Sun, Aug 11, 2013 at 12:14 AM, Roy Smith <roy@panix.com> 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

[toc] | [prev] | [next] | [standalone]

#52338

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

[toc] | [prev] | [next] | [standalone]

#52340

On Sun, Aug 11, 2013 at 1:52 AM, Josh English
<Joshua.R.English@gmail.com> 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

[toc] | [prev] | [next] | [standalone]

#52336

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

[toc] | [prev] | [next] | [standalone]

#52332

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@nedbatchelder.com> wrote:
> On 8/10/13 4:40 PM, Roy Smith wrote:
>>
>> In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412@googlegroups.com>,
>>   Josh English <Joshua.R.English@gmail.com> 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@gmail.com
http://www.joshuarenglish.com

[toc] | [prev] | [next] | [standalone]

#52335

On 8/10/13 4:40 PM, Roy Smith wrote:
> In article <f7b24010-f3f4-4e86-b6c4-9ddb503d0412@googlegroups.com>,
>   Josh English <Joshua.R.English@gmail.com> 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.

[toc] | [prev] | [standalone]

Back to top | Article view | comp.lang.python

csiph-web