# 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

"""
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

"""

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

# Initialize the superclass

# 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

# 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
while True:

# Read a line of text from the pipe

# 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:
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!

• You should use super() to call superclass methods. So instead of threading.Thread.__init__(self), write super(LoggerWrapper, self).__init__(). 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. Jan 12 '12 at 15:47

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 os
import subprocess

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

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

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

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

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.

• sys.exit does not call sys.exit the value of the function is discarded. add () to actually call the function Sep 8 '15 at 18:15
• How can the pipe be opened with fdopen, before the thread is started? Why isnt it blocked? Oct 19 '15 at 10:19
• @Caridorc: fixed Oct 29 '15 at 10:48
• @hakanc: blocking doesn't impact opening. That's an issue when reading and writing potentially which is why those parts are done in the thread. Also fdopen is just wrapping the already open pipe with a File like object. It's not actually doing anything to the file as far as I know. Oct 29 '15 at 10:58
• advice: os.fdopen(self.fdRead) cannot handle unicode output. To support unicode, rewrite it to os.fdopen(self.fdRead, encoding='utf-8', errors='ignore'). Sep 22 '17 at 2:39

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.

• Thanks for the simpler way of doing this. However, for some reason.. even after the system_command finishes, the text file remains busy.. Is there a reason for this? Jun 4 '18 at 2:30