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

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!
–
DracoJemJan 20 '12 at 11:32

You can also log stderr: line = s.stderr.readline() and add to logging with: logging.warning(line).
–
lbollaJan 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
–
DracoJemJan 20 '12 at 14:43

1

@DracoJem, subprocess.Popen(['ls', '-l'], stdout=subprocess.PIPE, stderr = subprocess.STDOUT) will combine stdout and stderr and I think give you what you want. You could also use subprocess.check_output([..], stderr = subprocess.STDOUT) which I think will just return everything as a string.
–
Winston EwertJan 20 '12 at 18:33

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.

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.