Redirecting subprocesses' output (stdout and stderr) to the logging module

Question

I'm working on a Python script and I was searching for a method to redirect stdout and stderr of a subprocess to the logging module. The subprocess is created using the subprocess.call() method.

The difficulty I faced is that with subprocess I can redirect stdout and stderr only using a file descriptor. I did not find any other method, but if there is one please let me know!

To solve this problem I wrote the following code which basically creates a pipe and uses a thread to read from the pipe and generates a log message using the Python logging method:

import subprocess
import logging
import os
import threading

class LoggerWrapper(threading.Thread):
    """
    Read text message from a pipe and redirect them
    to a logger (see python's logger module),
    the object itself is able to supply a file
    descriptor to be used for writing

    fdWrite ==> fdRead ==> pipeReader
    """

    def __init__(self, logger, level):
        """
        Setup the object with a logger and a loglevel
        and start the thread
        """

        # Initialize the superclass
        threading.Thread.__init__(self)

        # Make the thread a Daemon Thread (program will exit when only daemon
        # threads are alive)
        self.daemon = True

        # Set the logger object where messages will be redirected
        self.logger = logger

        # Set the log level
        self.level = level

        # Create the pipe and store read and write file descriptors
        self.fdRead, self.fdWrite = os.pipe()

        # Create a file-like wrapper around the read file descriptor
        # of the pipe, this has been done to simplify read operations
        self.pipeReader = os.fdopen(self.fdRead)

        # Start the thread
        self.start()
    # end __init__

    def fileno(self):
        """
        Return the write file descriptor of the pipe
        """
        return self.fdWrite
    # end fileno

    def run(self):
        """
        This is the method executed by the thread, it
        simply read from the pipe (using a file-like
        wrapper) and write the text to log.
        NB the trailing newline character of the string
           read from the pipe is removed
        """

        # Endless loop, the method will exit this loop only
        # when the pipe is close that is when a call to
        # self.pipeReader.readline() returns an empty string
        while True:

            # Read a line of text from the pipe
            messageFromPipe = self.pipeReader.readline()

            # If the line read is empty the pipe has been
            # closed, do a cleanup and exit
            # WARNING: I don't know if this method is correct,
            #          further study needed
            if len(messageFromPipe) == 0:
                self.pipeReader.close()
                os.close(self.fdRead)
                return
            # end if

            # Remove the trailing newline character frm the string
            # before sending it to the logger
            if messageFromPipe[-1] == os.linesep:
                messageToLog = messageFromPipe[:-1]
            else:
                messageToLog = messageFromPipe
            # end if

            # Send the text to the logger
            self._write(messageToLog)
        # end while

        print 'Redirection thread terminated'

    # end run

    def _write(self, message):
        """
        Utility method to send the message
        to the logger with the correct loglevel
        """
        self.logger.log(self.level, message)
    # end write

# end class LoggerWrapper

# # # # # # # # # # # # # #
# Code to test the class  #
# # # # # # # # # # # # # #
logging.basicConfig(filename='command.log',level=logging.INFO)
logWrap = LoggerWrapper( logging, logging.INFO)

subprocess.call(['cat', 'file_full_of_text.txt'], stdout = logWrap, stderr = logWrap)

print 'Script terminated'

For logging subprocesses' output, Google suggests to directly redirect the output to a file in a way similar to this:

sobprocess.call( ['ls'] stdout = open( 'logfile.log', 'w') ) 

This is not an option for me since I need to use the formatting and loglevel facilities of the logging module. I also suppose that having a file open in write mode but two different entities is not permitted / not a sane thing to do.

I would now like to see your comments and enhancement proposal. I would also like to know if there is already a similar object in the Python library since I found nothing to accomplish this task!

Answer 1

Great idea. I was having the same problem and this helped me solve it. Your method for doing cleanup though is wrong (as you mentioned it might be). Basically, you need to close the write end of the pipes after passing them to the subprocess. That way when the child process exits and closes it's end of the pipes, the logging thread will get a SIGPIPE and return a zero length message as you expected.

Otherwise, the main process will keep the write end of the pipe open forever, causing readline to block indefinitely, which will cause your thread to live forever as well as the pipe. This becomes a major problem after a while because you'll reach the limit on the number of open file descriptors.

Also, the thread shouldn't be a daemon thread because that creates the risk of losing log data during process shutdown. If you properly cleanup as a described, all the threads will exit properly removing the need to mark them as daemons.

Lastly, the while loop can be simplified using a for loop.

Implementing all of these changes gives:

import logging
import threading
import os
import subprocess

logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.INFO)

class LogPipe(threading.Thread):

    def __init__(self, level):
        """Setup the object with a logger and a loglevel
        and start the thread
        """
        threading.Thread.__init__(self)
        self.daemon = False
        self.level = level
        self.fdRead, self.fdWrite = os.pipe()
        self.pipeReader = os.fdopen(self.fdRead)
        self.start()

    def fileno(self):
        """Return the write file descriptor of the pipe
        """
        return self.fdWrite

    def run(self):
        """Run the thread, logging everything.
        """
        for line in iter(self.pipeReader.readline, ''):
            logging.log(self.level, line.strip('\n'))

        self.pipeReader.close()

    def close(self):
        """Close the write end of the pipe.
        """
        os.close(self.fdWrite)

# For testing
if __name__ == "__main__":
    import sys

    logpipe = LogPipe(logging.INFO)
    with subprocess.Popen(['/bin/ls'], stdout=logpipe, stderr=logpipe) as s:
        logpipe.close()

    sys.exit()

I used different names in a couple of spots, but otherwise it's the same idea, except a little cleaner and more robust.

Setting close_fds=True for the subprocess call (which is actually the default) won't help because that causes the file descriptor to be closed in the forked (child) process before calling exec. We need the file descriptor to be closed in the parent process (i.e. before the fork) though.

The two streams still end up not being synchronized correctly. I'm pretty sure the reason is that we're using two separate threads. I think if we only used one thread underneath for the logging, the problem would be solved.

The problem is that we're dealing with two different buffers (pipes). Having two threads (now I remember) gives an approximate synchronization by writing the data as it becomes available. It's still a race condition, but there are two "servers", so it's normally not a big deal. With only one thread, there's only one "server" so the race condition shows up pretty bad in the form of unsynchronized output. The only way I can think to solve the problem is to extend os.pipe() instead, but I have no idea how feasible that is.

Answer 2

If you don't mind STDOUT and STDERR being logged under the same logging level, you can do something like this:

import logging
import subprocess

logger = logging.getLogger(__name__)


def execute(system_command, **kwargs):
    """Execute a system command, passing STDOUT and STDERR to logger.

    Source: https://stackoverflow.com/a/4417735/2063031
    """
    logger.info("system_command: '%s'", system_command)
    popen = subprocess.Popen(
        shlex.split(system_command),
        stdout=subprocess.PIPE,
        stderr=subprocess.STDOUT,
        universal_newlines=True,
        **kwargs)
    for stdout_line in iter(popen.stdout.readline, ""):
        logger.debug(stdout_line.strip())
    popen.stdout.close()
    return_code = popen.wait()
    if return_code:
        raise subprocess.CalledProcessError(return_code, system_command)

This way you don't have to mess around with threads.