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

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 metho

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.

StackExchange Code Review Q#6567, answer score: 36