Run subprocess and print output to logging

Question

I am looking for the way to call shell scripts from python and write their stdout and stderr to file using logging. Here is my code:

import logging
import tempfile
import shlex
import os

def run_shell_command(command_line):
    command_line_args = shlex.split(command_line)

    logging.info('Subprocess: \"' + command_line + '\"')

    process_succeeded = True
    try:
        process_output_filename = tempfile.mktemp(suffix = 'subprocess_tmp_file_')
        process_output = open(process_output_filename, 'w')

        command_line_process = subprocess.Popen(command_line_args,\
                                                stdout = process_output,\
                                                stderr = process_output)
        command_line_process.wait()
        process_output.close()

        process_output = open(process_output_filename, 'r')
        log_subprocess_output(process_output)
        process_output.close()

        os.remove(process_output_filename)
    except:
        exception = sys.exc_info()[1]
        logging.info('Exception occured: ' + str(exception))
        process_succeeded = False

    if process_succeeded:
        logging.info('Subprocess finished')
    else:
        logging.info('Subprocess failed')

    return process_succeeded

And I am sure that there is the way to do it without creating temporary file to store process output. Any ideas?

Anamorphosis

Does log_subprocess_output expect a file object or a string object? – Swenson

Answer 1

I am sure that there is the way to do it without creating temporary file to store process output

You simply have to check for the documentation of Popen, in particular about stdout and stderr:

stdin, stdout and stderr specify the executed program’s standard input, standard output and standard error file handles, respectively. Valid values are PIPE, an existing file descriptor (a positive integer), an existing file object, and None. PIPE indicates that a new pipe to the child should be created. With the default settings of None, no redirection will occur; the child’s file handles will be inherited from the parent. Additionally, stderr can be STDOUT, which indicates that the stderr data from the child process should be captured into the same file handle as for stdout.

So you can see that you can either use a file object, or the PIPE value. This allows you to use the communicate() method to retrieve the output:

from StringIO import StringIO
process = subprocess.Popen(arguments, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
output, error = process.communicate()
log_subprocess_output(StringIO(output))

---

I'd rewrite your code as:

import shlex
import logging
import subprocess
from StringIO import StringIO

def run_shell_command(command_line):
    command_line_args = shlex.split(command_line)

    logging.info('Subprocess: "' + command_line + '"')

    try:
        command_line_process = subprocess.Popen(
            command_line_args,
            stdout=subprocess.PIPE,
            stderr=subprocess.STDOUT,
        )

        process_output, _ =  command_line_process.communicate()

        # process_output is now a string, not a file,
        # you may want to do:
        # process_output = StringIO(process_output)
        log_subprocess_output(process_output)
    except (OSError, CalledProcessError) as exception:
        logging.info('Exception occured: ' + str(exception))
        logging.info('Subprocess failed')
        return False
    else:
        # no exception was raised
        logging.info('Subprocess finished')

    return True

Linder

If you don't need to seek inside the file; the pipe could be used as is to log subprocess' output – Gastronome

What does the log_suprocess_output look like for your code sample? – Proprietress

That results in the entire stdout/stderr content to reside in memory as strings, which may not be ideal for processes that do a lot of writing to stdout / stderr. – Enwreathe

Sir you are an absolute genius. Thank you so much for this lovely piece of code. I wish I could upvote twice! – Dib

Same here, it will block until subprocess finishes... – Felloe

@Felloe I'm not sure to whom you are replying? Maybe a deleted comment? Anyway I guess you are referring to the communicate behaviour. Yes, by default it waits the process to exit. It is possible to put a timeout on communicate, in that case an exception is raised which contains the stdout/stderr up to that point. Anyway if you want to write interactive code (e.g. interacting with a shell session) you should really use some other tool like Twisted Conch or paramiko or similar. – Linder

Answer 2

You could try to pass the pipe directly without buffering the whole subprocess output in memory:

from subprocess import Popen, PIPE, STDOUT

process = Popen(command_line_args, stdout=PIPE, stderr=STDOUT)
with process.stdout:
    log_subprocess_output(process.stdout)
exitcode = process.wait() # 0 means success

where log_subprocess_output() could look like:

def log_subprocess_output(pipe):
    for line in iter(pipe.readline, b''): # b'\n'-separated lines
        logging.info('got line from subprocess: %r', line)

Gastronome

if the output is expected to be large, then this can hand the subprocess: thraxil.org/users/anders/posts/2008/03/13/… – Kitsch

@IoannisFilippidis: the code in the answer works for any output no matter how large it is. The article that you've linked does not apply here. – Gastronome

@J.F.Sebastian - curious is there a need to worry about p.wait()? Docs have a warning about Popen.wait which seems to relate to the issue @IoannisFilippidis brought up. – Inositol

@knoight: it is ok to call it after I/O is done (note: p.stdout.close()). Again, the blog post does not apply to the code in the answer (it would apply if you move (DO NOT DO IT!!!) p.wait() before log_subprocess_ouput() call in this case). – Gastronome

not sure why but this code does not work. I have "cmd = 'ls';p = Popen(... log.info(p.stdout)" but still does not work. exitcode is always 2 – Outgeneral

@mark create a complete but minimal code example (show the exact code that you use). Mention OS you use (Windows, macOS, etc), python version (python -V). And post it as a new question. – Gastronome

@J.F.Sebastian sure, I can post my OS version and other details... but did you consider that the code you provide in your answer might be inadequate? I do not see how opening a new question helps with that. like for example where does p come from? – Outgeneral

for those who run into the same snafu here is a working solution: #18774976 – Outgeneral

@mark: you are right about p name. It meant command_line_process which is too long for a small code example, I've renamed both to process¶ Your code log.info(p.stdout) does not make sense (it was not from my answer) that is why I've suggested a new question with a complete code example (there could be other errors in your code)¶ Your link accumulates the whole subprocess output in memory before logging anything. The code in my answer allows to log while the child process is still running without exhausting all available memory. – Gastronome

Now it is easier to follow for me. thank you. The memory aspect is very interesting to me. If I understand correctly, you propose a trick to pipe the errors onto stdout. Consequently errors are logged as info but it is more efficient in terms of memory. Is it possible to log errors as errors and be memory efficient, too? – Outgeneral

@mark if you are about stderr=STDOUT then it is one of the assumptions in the question (notice that both stdout, stderr are redirected to the same process_output file). – Gastronome

@J.F.Sebastian Actually, mark's query is of interest to me too. Arguably, it should be reposted as a proper question. But we're all lazy here. For the sake of argument, is logging stdout with logging level INFO and stderr with logging level ERROR in realtime (i.e., without buffering) even feasible? If so, my working assumption is that multiple non-trivial coroutines would be required. Which really sounds like a lot of work. – Meekins

Ah-ha! You've already answered a similar question with a relevant multithreading solution. Since the logging module is thread-safe by design, refactoring that solution to log rather than queue process output should be fairly straightforward. Thanks for the intrepid insights. You are a wizard among men. – Meekins

the terminal prints out b'my message'. How can I get rid of the b'' ? – Potts

@thanos.a: Convert bytes to a string – Gastronome

@Gastronome is there a simple way to distinguish between stdout and stderr with this method? This would for instance allow to log stdout with logging.info() and stderr with logging.warning() – Bignonia

@Bignonia stderr=STDOUT above merges stdout/stderr into a single stream, thus at the log_subprocess_output they are the same. To get them separately, you have to read them separately. If the output is small, then the simple option is to read all at once: p = subprocess.run(cmd, capture_output=True) (use p.stdout, p.stderr strings, to get results) – Gastronome

@Gastronome It took me some time to figure out how to distinguish between stderr and stdout and still use with to enjoy live printing. Eventually, I kept Popen, sent both stderr and stdout to PIPE, added a new kwarg err to log_subprocess_output() which enables choosing between logging.warning and logging.info, and had one with for stdout and stderr respectively calling log_subprocess_output() with err=False and err=True. Hope that helps others! – Bignonia

@Bignonia no, it won't work for unlimited output. Your code may dead lock eventually when OS pipe buffer is full. To avoid it, you have to read concurrently from both stdout and stderr at the same time (requires async. I/O (e.g., threads or asyncio). – Gastronome

Erm... doesn't your solution blocking main thread, until spawned process finishes and exits? What if it is a long running process, like ffmpeg? – Felloe

@Felloe The code in the answer runs a subprocess and logs its output while it is still running. If you have some additional constraints such as "don't block the main thread", then it can done too. If you don't know how, ask. – Gastronome

Answer 3

I was trying to achieve the same on check_call and check_ouput. I found this solution to be working.

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)

   def write(self):
       """If your code has something like sys.stdout.write"""
       logging.log(self.level, message)

   def flush(self):
       """If you code has something like this sys.stdout.flush"""
       pass

After implementing it, I performed the below steps:

try:
    # It works on multiple handlers as well
    logging.basicConfig(handlers=[logging.FileHandler(log_file), logging.StreamHandler()])
    sys.stdout = LogPipe(logging.INFO)
    sys.stderr = LogPipe(logging.ERROR)
...
    subprocess.check_call(subprocess_cmd, stdout=sys.stdout, stderr=sys.stderr)
    export_output = subprocess.check_output(subprocess_cmd, stderr=sys.stderr)
...
finally:
    sys.stdout.close()
    sys.stderr.close()
    # It is neccessary to close the file handlers properly.
    sys.stdout = sys.__stdout__
    sys.stderr = sys.__stderr__
    logging.shutdown()
    os.remove(log_file)

Sternlight

Answer 4

This worked for me:

from subprocess import Popen, PIPE, STDOUT

command = f"shell command with arguments"
process = Popen(command, shell=True, stdout=PIPE, stderr=STDOUT)

with process.stdout:
    for line in iter(process.stdout.readline, b''):
        print(line.decode("utf-8").strip())

With exception handling:

from subprocess import Popen, PIPE, STDOUT, CalledProcessError

command = f"shell command with arguments"
process = Popen(command, shell=True, stdout=PIPE, stderr=STDOUT)

with process.stdout:
    try:
        for line in iter(process.stdout.readline, b''):
            print(line.decode("utf-8").strip())
            
    except CalledProcessError as e:
        print(f"{str(e)}")

Potts

Answer 5

Handling the live output stream of a command can be achieved by iterating over stdout as the subprocess.Popen runs.

This implementation:

• uses a with-statement such that standard file descriptors are closed, and the process is waited for
• propagates keyword arguments to the subprocess constructor
• defaults to text=True to automatically decode bytestrings into strings
• raises a CalledProcessError upon failure if check=True like subprocess.run does
• returns a CompletedProcess upon success like subprocess.run does
• redirects stderr to stdout (to handle them separately see my multithreaded answer)

import logging
from subprocess import PIPE, STDOUT, CalledProcessError, CompletedProcess, Popen


def stream_command(
    args,
    *,
    stdout_handler=logging.info,
    check=True,
    text=True,
    stdout=PIPE,
    stderr=STDOUT,
    **kwargs,
):
    """Mimic subprocess.run, while processing the command output in real time."""
    with Popen(args, text=text, stdout=stdout, stderr=stderr, **kwargs) as process:
        for line in process.stdout:
            stdout_handler(line[:-1])
    retcode = process.poll()
    if check and retcode:
        raise CalledProcessError(retcode, process.args)
    return CompletedProcess(process.args, retcode)

Logging to a file then becomes as simple as setting up logging:

logging.basicConfig(
    level=logging.INFO,
    filename="./capture.log",
    filemode="w",
    encoding="utf-8",
)
logging.info("test from python")
stream_command(["echo", "test from subprocess"])

With the resulting file:

$ cat ./capture.log
INFO:root:test from python
INFO:root:test from subprocess

The behaviour can be tweaked to preference (print instead of logging.info, or both, etc.):

stream_command(["echo", "test"])
# INFO:root:test
stream_command("cat ./nonexist", shell=True, check=False)
# ERROR:root:cat: ./nonexist: No such file or directory
stream_command(["echo", "test"], stdout_handler=print)
# test
stdout_lines = []
def handler(line):
    print(line)
    logging.info(line)
    stdout_lines.append(line)
stream_command(["echo", "test"], stdout_handler=handler)
print(stdout_lines)
# test
# INFO:root:test
# ['test']

Narcho