How can I temporarily redirect the output of logging in Python?

Question

There's already a question that answers how to do this regarding sys.stdout and sys.stderr here: https://stackoverflow.com/a/14197079/198348

But that doesn't work everywhere. The logging module seems to output to sys.stdout and sys.stderr, but I can't capture it with the context manager above.

In the following example code, I'm trying to capture all output inside the context manager, failing to do so for the logger statements:

from __future__ import print_function
import contextlib
import sys
import logging
from StringIO import StringIO

# taken from https://stackoverflow.com/a/14197079/198348
@contextlib.contextmanager
def stdout_redirect(where):
    prev_stdout = sys.stdout
    prev_stderr = sys.stderr
    prev_stdout.flush()
    sys.stdout = where
    sys.stderr = where
    try:
        yield where
    finally:
        where.flush()
        sys.stdout = prev_stdout
        sys.stderr = prev_stderr

logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger()

print("\t\tOUTSIDE: stdout", file=sys.stdout)
print("\t\tOUTSIDE: stderr", file=sys.stderr)
logger.info("\tOUTSIDE: info")
logger.debug("\tOUTSIDE: debug")
logger.warn("\tOUTSIDE: warn")
logger.error("\tOUTSIDE: error")
logger.critical("\tOUTSIDE: critical")

print("=============== DIVIDER ================")

s = ""
with stdout_redirect(StringIO()) as new_stdout:
    print("\t\tINSIDE: stdout", file=sys.stdout)
    print("\t\tINSIDE: stderr", file=sys.stderr)
    logger.info("\tINSIDE: info")
    logger.debug("\tINSIDE: debug")
    logger.warn("\tINSIDE: warn")
    logger.error("\tINSIDE: error")
    logger.critical("\tINSIDE: critical")


print("=============== DIVIDER ===============")
print(new_stdout.getvalue())

print("=============== LOGGING ===============")

print(logger.handlers)
print(logger.root.handlers)

How can I temporarily redirect the output of the logger(s) that spit out to stdout and capture them? I took a look at logging/init.py, but it doesn't immediately tell me what I need to do.

My motivation for doing this is that I want to equip a crufty big codebase with tests, each of which captures the spurious amounts of logging output that each test invokes. I can capture external programs, but I can't seem to capture the tests that I run inside nose.

Rewriting the verbose parts isn't an option right now, but is definitely a goal for further down the road.

Edit, regarding ubuntu

Here's what I've tried running with nosetests:

from __future__ import print_function
import sys

def test_funky_shurane():
    import logging
    logging.basicConfig(level=logging.DEBUG)
    logging.info("===== shurane info")
    logging.warn("===== shurane warn")
    logging.error("===== shurane error")
    logging.critical("===== shurane critical")
    print("===== shurane stdout", file=sys.stdout)
    print("===== shurane stderr", file=sys.stderr)
    assert True

And then running the above with:

nosetests test_logging.py
nosetests --nocapture test_logging.py

Answer 1

the logging.basicConfig() is a convenience that sets up some logger handling in a very simple way. If you need a little more than that, you shouldn't use basicConfig(). That's not a big deal, because it doesn't do a whole lot. What we need is to configure logging for both streams;

import logging, sys
fmt = logging.Formatter(BASIC_FORMAT)

hdlr_stderr = logging.StreamHandler(sys.stderr)
hdlr_stderr.setFormatter(fmt)
hdlr_stdout = logging.StreamHandler(sys.stdout)
hdlr_stdout.setFormatter(fmt)
root.addHandler(hdlr_stderr)
root.addHandler(hdlr_stdout)
root.setLevel(logging.DEBUG)

By default, loggers log all messages that they receive; but initially, we don't want to log any messages to sys.stdout:

hdlr_stdout.level = float('inf')  # larger than any log level; nothing gets logged

Then, your context manager might look a bit like:

@contextlib.contextmanager
def redirect_stderr_logging(where):
    hdlr_stderr.level = float('inf')
    hdlr_stdout.level = logging.NOTSET
    try:
        yield where
    finally:
        hdlr_stderr.level = logging.NOTSET
        hdlr_stdout.level = float('inf')

Answer 2

The redirect does not work because the logger that you set up initially has a pointer directly to stdout. See below.

logging_test.py

import logging
import sys

SIMPLE_LOG_FORMAT = '[%(asctime)s] {%(filename)s:%(lineno)d} %(levelname)s - %(message)s'
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
formatter = logging.Formatter(SIMPLE_LOG_FORMAT)
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setFormatter(formatter)
logger.addHandler(console_handler)

logger.info("Message before redirecting stdout and stderr")
# Checking what logger is writing to
logger.info('Before Redirection. logger writing to {} '.format(logger.handlers[0].stream))

log_file = open('log_file.log', 'w')
sys.stdout = log_file
sys.stderr = log_file
# Checking what logger is writing to
logger.info('After Redirection. logger writing to {} '.format(logger.handlers[0].stream))
logger.info("Message after redirecting stdout and stderr")

log_file.close()

Output:

[2018-06-01 16:27:10,670] {logging_test.py:12} INFO - Message before redirecting stdout and stderr
[2018-06-01 16:27:10,670] {logging_test.py:14} INFO - Before Redirection. logger writing to <open file '<stdout>', mode 'w' at 0x10cd74150> 
[2018-06-01 16:27:10,670] {logging_test.py:20} INFO - After Redirection. logger writing to <open file '<stdout>', mode 'w' at 0x10cd74150> 
[2018-06-01 16:27:10,670] {logging_test.py:21} INFO - Message after redirecting stdout and stderr

As you can see on the second and third lines of the output that logger still refers to directly.

One of the ways to fix this is to do something like this

logger.handlers[0].stream = open('log_file.log', 'w')

Note that if you are using multiple threads a change like this in one will cause output from other threads to also start redirecting output.