CODEWITHSUNDEEP
pythonnoseunit-testing
Nathaniel Ford
Nathaniel Ford

Reputation: 21220

Nose test fails when Unittest does not

We are seeing a strange difference between the results of Python nose tests versus unittests. Here is the code that causes the problem, in particular the last line:

import logging

class ClassThatLogsBadly:
    log = logging.getLogger(__name__)

    def method_that_logs_badly(self):
        self.log.error('A message', 'Another string')
        return ('I ran')

The above log is retrieved from Python's logging library, and creates a problem when called because of the following (from the Python library: logging/__init__.py:328):

def getMessage(self):
    """
    Return the message for this LogRecord.

    Return the message for this LogRecord after merging any user-supplied
    arguments with the message.
    """
    msg = str(self.msg)
    if self.args:
        msg = msg % self.args
    return msg

As you can see, it attempts to splice in Another string to A message, but the latter has no valid slots (of the type %s) to be filled, so it can't do it. This is a known problem, and the solution is to format your stuff outside the logger. However, our problem is testing to ensure this is done.

Running a test against code that calls the logging library with unittest or py.test raises no failure. Running the same test with nose causes an error, and the test to fail. Most of our build stuff is built around the py.test library, and not having this test fail is concerning: we are uncertain if this is expected behavior for some reason, what the root difference between the handling between those libraries are, and generally what to do about it.

We are using Python 3.4. Here is a sample test that runs this code:

import logging
import unittest

from mycode import ClassThatLogsBadly

class TestClassThatLogsBadly(unittest.TestCase):
    def setUp(self):
        pass

    def tearDown(self):
        pass

    def test_method_that_logs_badly(self):
        clz = ClassThatLogsBadly()
        result = clz.method_that_logs_badly()
        self.assertEquals('I ran', result)

Upvotes: 4

Views: 853

Answers (1)

Oleksiy
Oleksiy

Reputation: 6567

Because logging configuration is global, in order to properly exercise logging functionality you have to configure logging properly. In your particular case, no handlers are configured at the root level, and you do not have handlers configured for self.log, and as result no logging messages will be emitted (just "No handlers could be found for logger "mycode"). This message is designed to indicate that there was a mistake in logging configuration, since your logging tree looks like this:

<--""
   Level WARNING
   |
   o<--"mycode"
       Level NOTSET so inherits level WARNING

Since you have no handlers, nothing is done with your log.error message, and your code is not exercised when running under unittest or py.test.

nose by default adds a log capture handler at the root level, so the final logging configuration is properly configured, and your log.error code is executed properly.

A quick fix would be to add logging.basicConfig() on top of the code in ClassThatLogsBadly or add proper handler to the log class member on initialization. This way, both unittest and py.test will catch it.

Finally, you really should not format your stuff outside the logger: if the level is not configured, you should not do formatting at all and just skip the whole logging speeding up execution.

Upvotes: 2

Related Questions