Python StringIO is not correctly capturing data from stderr

Question

I have written some unittests that analyze data that is logged with the standard python logging function. Using some of the ideas that I found here: Capture stdout from a script in Python about how to capture data from stderr, I have come up with the following script, which I have simplified down to the bare minimum to illustrate a problem that I have encountered. (the loop below is simulates the fact that this function might be called from various unittests)

import logging, sys
from StringIO import StringIO

def get_stderr():
    saved_stderr = sys.stderr

    stderr_string_io = StringIO()
    sys.stderr = stderr_string_io
    try:
        logging.error("Foobar!!!")

    finally:
        # set the stdout and stderr back to their original values
        sys.stderr = saved_stderr

    err_output = stderr_string_io.getvalue()
    return err_output

for x in [1, 2]:
    err_output = get_stderr()
    print  "Run %d: %s" % (x, err_output)

If you run the script it will give the following output, in which the logging output from the second loop iteration is totally lost:

Run 1: ERROR:root:Foobar!!!
Run 2: 
Process finished with exit code 0

While I would expect it to give the following output:

Run 1: ERROR:root:Foobar!!!
Run 2: ERROR:root:Foobar!!!
Process finished with exit code 0

Note: that executing stderr_string_io.close() at the end of the function does not work, as the script then throws an ValueError the next time the function is executed.

Why does this code not behave as expected, and what is the solution to correct this problem?

This is odd behaviour indeed. If you put a `logging.error("practicing")` at the top of the file, everything works... but ignores you replacing `stderr`. — Veedrac, Sep 23 '14 at 07:39

Veedrac · Accepted Answer · 2014-09-23T19:29:51.227

When you call

logging.error

it runs

def error(msg, *args, **kwargs):
    if len(root.handlers) == 0:
        basicConfig()
    root.error(msg, *args, **kwargs)

Since there are no root handlers at the start, it runs basicConfig with no arguments, which does:

def basicConfig():
    _acquireLock()
    try:
        if len(root.handlers) == 0:
            h = StreamHandler(None)
            handlers = [h]
            dfs = None
            style = '%'
            fs = kwargs.get("format", _STYLES[style][1])
            fmt = Formatter(fs, dfs, style)
            for h in handlers:
                if h.formatter is None:
                    h.setFormatter(fmt)
                root.addHandler(h)
    finally:
        _releaseLock()

I've removed code that can't run when you have no arguments.

So this has set handlers = [StreamHandler(None)]:

class StreamHandler(Handler):
    def __init__(self, stream=None):
        Handler.__init__(self)
        if stream is None:
            stream = sys.stderr
        self.stream = stream

which means that you have the top level logger permanantly attached to whatever was stdout at the time you called it.

This causes your problem, because you throw away that output. This means that the output will go to a dead StringIO object, and be lost.

One way to deal with this is to go through handlers when updating stderr and also replace anything that refers to stderr:

import logging, sys
from StringIO import StringIO

def get_stderr():
    saved_stderr = sys.stderr
    stderr_string_io = StringIO()

    for handler in logging.root.handlers:
        if handler.stream is sys.stderr:
            handler.stream = stderr_string_io

    sys.stderr = stderr_string_io

    try:
        logging.error("Foobar!!!")

    finally:
        # set the stdout and stderr back to their original values
        for handler in logging.root.handlers:
            if handler.stream is sys.stderr:
                handler.stream = saved_stderr

        sys.stderr = saved_stderr

    err_output = stderr_string_io.getvalue()
    return err_output

for x in [1, 2]:
    err_output = get_stderr()
    print  "Run %d: %s" % (x, err_output)

I don't know how well this will work. It also won't catch any loggers that aren't root loggers. Personally the idea of capturing sys.stdout by value is absurd, and this seems like an inevitable result.

I agree that you would not normally want to capture the sys.stdout and sys.stderr, however in this particular case I am writing a unit-test for error handling code that writes to stderr. The unittest must analyze that the the correct logs are being written for different error conditions. — Alexander Marquardt, Sep 23 '14 at 14:48
@AlexanderMarquardt I'm not referring to *you*, I'm saying that `logging` is the one being absurd! — Veedrac, Sep 23 '14 at 19:28
In the end I decided to go with a different approach for capturing the logs. Python has some decent mock and patch functionality for unit testing that allows you to override the default logging functionality without having to mess around with stdio/stderr. — Alexander Marquardt, Sep 23 '14 at 19:49

Python StringIO is not correctly capturing data from stderr

1 Answers1