Take the 2-minute tour ×
Code Review Stack Exchange is a question and answer site for peer programmer code reviews. It's 100% free, no registration required.

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 createdusing 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 generate 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'

This is my solution to a problem. 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!

PS: googling around I found many answer to the question "How can I log subprocesses output in python?" but almost all of the answers suggest 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 ....also I suppose that having a file open in write mode bu two different entities is not permitted / not a sane thing to do :P

share|improve this question

migrated from stackoverflow.com Dec 6 '11 at 13:52

This question came from our site for professional and enthusiast programmers.

    
You should use super() to call superclass methods. So instead of threading.Thread.__init__(self), write super(LoggerWrapper, self).__init__(). –  Attila O. Dec 9 '11 at 21:36
    
When I tried this, in Python 2.6 on Ubuntu 10.04, the thread never closed. self.pipeReader.readline() keeps returning newlines. –  Jeff Dege Jan 12 '12 at 15:47
add comment

2 Answers 2

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.

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

EDIT 2 I've used this a bit longer and realized that 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. I don't have time to try it out right now, but will try to remember to post back if I do.

EDIT 3 Wait, that doesn't make any sense! I'm out of ideas I think. 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.

share|improve this answer
add comment

What about something as simple as this?

import logging
import subprocess

logging.basicConfig(level=logging.DEBUG)
s = subprocess.Popen(['ls', '-l'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
while True:
    line = s.stdout.readline()
    if not line:
        break
    logging.info(line)

UPDATE: Added stderr redirection to include both stdout and stderr, in the order they are output, in the logging capture, per the discussion in comments.

share|improve this answer
    
better yet, use s.communicate() –  Winston Ewert Dec 9 '11 at 22:36
    
Hello lbolla, thank for the suggestion! Your code is slightly simple BUT it does not redirect stderr, which is really important to me. In case something goes wrong I want to be able to open my log file and see what goes wrong, having only stdout redirected to the logger may be insufficient to solve the problem! –  DracoJem Jan 20 '12 at 11:32
    
You can also log stderr: line = s.stderr.readline() and add to logging with: logging.warning(line). –  lbolla Jan 20 '12 at 13:44
    
Hi Ibolla! Yes you could add the stderr inside the while loop, I used this technique many times but I feel there are a couple of problems: 1) that the code you obtain this way is a little bit bloated 2) I would like to get the output in the exact order the program produced it to have a superdetailed logging of the external program activity. By using stderr.readline() and stdout.readline() inside a while loop you have to check one first and the other later so you could came out with out of order messages in the log, this could be a minor problem but I prefer having the output in the right order –  DracoJem Jan 20 '12 at 14:43
    
AFAIK, stdout and stderr are separate files, therefore buffered independently. There is no assurance that the order with which they are printed to screen corespond to the order when they have been emitted. This is best handled by having a timestamp as first line in the log message. So, you could do: for line in sorted(s.stdout.readlines() + s.stderr.readlines()): etc. etc. –  lbolla Jan 20 '12 at 16:34
show 2 more comments

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.