Python unit test -b flag issues
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 https://docs.python.org/3/library/logging.html?highlight=loggging
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
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
#python