A Solution for the Sample Code
Just before the test runs we need to update the stream on the log handler to point to the buffer unittest has set up for capturing the test output.
import logging
import unittest
import sys
logger = logging.getLogger('abc')
logging.basicConfig(
format = '%(asctime)s %(module)s %(levelname)s: %(message)s',
level = logging.INFO,
stream = sys.stdout)
class LoggerRedirector:
# Keep a reference to the real streams so we can revert
_real_stdout = sys.stdout
_real_stderr = sys.stderr
@staticmethod
def all_loggers():
loggers = [logging.getLogger()]
loggers += [logging.getLogger(name) for name in logging.root.manager.loggerDict]
return loggers
@classmethod
def redirect_loggers(cls, fake_stdout=None, fake_stderr=None):
if ((not fake_stdout or fake_stdout is cls._real_stdout)
and (not fake_stderr or fake_stderr is cls._real_stderr)):
return
for logger in cls.all_loggers():
for handler in logger.handlers:
if hasattr(handler, 'stream'):
if handler.stream is cls._real_stdout:
handler.setStream(fake_stdout)
if handler.stream is cls._real_stderr:
handler.setStream(fake_stderr)
@classmethod
def reset_loggers(cls, fake_stdout=None, fake_stderr=None):
if ((not fake_stdout or fake_stdout is cls._real_stdout)
and (not fake_stderr or fake_stderr is cls._real_stderr)):
return
for logger in cls.all_loggers():
for handler in logger.handlers:
if hasattr(handler, 'stream'):
if handler.stream is fake_stdout:
handler.setStream(cls._real_stdout)
if handler.stream is fake_stderr:
handler.setStream(cls._real_stderr)
class TestABC(unittest.TestCase):
def setUp(self):
# unittest has reassigned sys.stdout and sys.stderr by this point
LoggerRedirector.redirect_loggers(fake_stdout=sys.stdout, fake_stderr=sys.stderr)
def tearDown(self):
LoggerRedirector.reset_loggers(fake_stdout=sys.stdout, fake_stderr=sys.stderr)
# unittest will revert sys.stdout and sys.stderr after this
def test_abc_pass(self):
logger.info('log abc in pass')
print('print abc in pass')
self.assertTrue(True)
def test_abc_fail(self):
logger.info('log abc in fail')
print('print abc in fail')
self.assertTrue(False)
The How and Why
The issue is a side effect from both how unittest is capturing the stdout and stderr for the test and how logging is usually set up. Usually logging is set up very early in the program execution and this means the log handlers will store a reference to sys.stdout and sys.stderr in their instances (code link). However, just before the test runs, unittest creates a io.StringIO() buffer for both streams and reassigns sys.stdout and sys.stderr to the new buffers (code link).
So right before the test runs, in order to get unittest to capture the log output, we need to tell the log handlers to point their streams to the buffer that unittest has set up. After the test has finished, the streams are reverted back to normal. However, unittest creates a new buffer for each test so we need to update the log handlers both before and after each test.
Since the log handlers are pointed to the buffer that unittest set up, if there was a failed test, then all the logs for that test will be displayed when using the --buffer option.
The LoggerRedirector class in the solution above just offers convenience methods to reassign all the handlers that might be pointed to sys.stdout or sys.stderr to the new buffer that unittest has set up and then an easy way to revert them. Since by the time setUp() runs, unittest has already reassigned sys.stdout and sys.stderr we are using these to reference the new buffer unittest has set up.
