python unit tests with -b flag and logging
python tests offer the -b
flag to suppress output on success. The documentation says:
The standard output and standard error streams are buffered during the test run. Output during a passing test is discarded. Output is echoed normally on test fail or error and is added to the failure messages.
https://docs.python.org/3/library/unittest.html#cmdoption-unittest-b
unittests are part of the standard library, and so is logging
Logging accepts configuration. Depending on how the logging is configured, messages can go to the standard output or standard error. A very minimal configuration looks like this:
import logging.config
logging_conf = { "version": 1,
"handlers": { "console": { "class": "logging.StreamHandler", }, },
"root": { "handlers": ["console"], }, }
logging.config.dictConfig(logging_conf)
The unexpected behaviour
Assuming this program:
import unittest
import logging
import logging.config
configure_logging = True
if configure_logging:
logging_conf = { "version": 1,
"handlers": { "console": { "class": "logging.StreamHandler", }, },
"root": { "handlers": ["console"], }, }
logging.config.dictConfig(logging_conf)
class MyCase(unittest.TestCase):
def test_logging(self):
try: raise Exception
except Exception: logging.exception("AAAA")
if I run python -m unittest -b test.py
, should I display the logging error?
$ python -m unittest test.py
AAAA
Traceback (most recent call last):
File "/home/nesaro/test.py", line 16, in test_logging
try: raise Exception
Exception
.
----------------------------------------------------------------------
Ran 1 test in 0.000s
OK
If I run the same program but with configure_logging = False
, the output is:
$ python -m unittest -b test.py
.
----------------------------------------------------------------------
Ran 1 test in 0.000s
OK
The explanation and fixes
If we print sys.stdout
before and after the test,
import unittest
import logging
import logging.config
import sys
print(sys.stdout) # print 1
configure_logging = False
if configure_logging:
logging_conf = { "version": 1,
"handlers": { "console": { "class": "logging.StreamHandler", }, },
"root": { "handlers": ["console"], }, }
logging.config.dictConfig(logging_conf)
class MyCase(unittest.TestCase):
def test_logging(self):
print(sys.stdout) # print2
try: raise Exception
except Exception: logging.exception("AAAA")
self.assertTrue(False)
the output looks like this
======================================================================
FAIL: test_logging (test.MyCase)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/nesaro/test.py", line 21, in test_logging
self.assertTrue(False)
AssertionError: False is not true
Stdout:
<_io.StringIO object at 0x7f9ac74e9ab0>
Stderr:
ERROR:root:AAAA
Traceback (most recent call last):
File "/home/nesaro/test.py", line 19, in test_logging
try: raise Exception
Exception
----------------------------------------------------------------------
Ran 1 test in 0.000s
FAILED (failures=1)
The flag -b
has replaced sys.stdout with a StringIo object.
If we print the handler stream:
class MyCase(unittest.TestCase):
def test_logging(self):
print(sys.stderr)
print(logging.getLogger('root').handlers[0].stream)
...
the output looks like this
Stdout:
<_io.StringIO object at 0x7f0a18db7e20>
<_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
And the solution assuming keeping logging enabled is needed:
class MyCase(unittest.TestCase):
def test_logging(self):
logging.getLogger('root').handlers[0].setStream(sys.stderr)
...
Which is way more complicated than disabling logging.
There are other variations of the same solution described in https://stackoverflow.com/questions/7472863/pydev-unittesting-how-to-capture-text-logged-to-a-logging-logger-in-captured-o
The problem
The problem is a consequence these 2 implementations:
-b
is implemented by patching sys.stdout and sys.stderr- logging configuration doesn’t have any mechanism to defer the reading of the stream
There isn’t a good error message explaining any of this.
An easy but not great solution is to add a flag or a callable to the logging configuration to defer the read of the stream.
A draconian solution would be not to start the tests if the -b flag is set and the logging configured.
A warning on this condition would help, although it would only affect if the errors go through sys.stdout
or sys.stderr
Quite an unexpected behaviour
- Comments in mastodon