python subprocess.call output is not interleaved

Question

I have a python (v3.3) script that runs other shell scripts. My python script also prints message like "About to run script X" and "Done running script X".

When I run my script I'm getting all the output of the shell scripts separate from my print statements. I see something like this:

All of script X's output
All of script Y's output
All of script Z's output
About to run script X
Done running script X
About to run script Y
Done running script Y
About to run script Z
Done running script Z

My code that runs the shell scripts looks like this:

print( "running command: " + cmnd )
ret_code = subprocess.call( cmnd, shell=True )
print( "done running command")

I wrote a basic test script and do *not* see this behaviour. This code does what I would expect:

print("calling")
ret_code = subprocess.call("/bin/ls -la", shell=True )
print("back")

Any idea on why the output is not interleaved?

Answer 1

It has to do with STDOUT and STDERR buffering. You should be using subprocess.Popen to redirect STDOUT and STDERR from your child process into your application. Then, as needed, output them. Example:

import subprocess

cmd = ['ls', '-la']
print('running command: "{0}"'.format(cmd))  # output the command.
# Here, we join the STDERR of the application with the STDOUT of the application.
process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
process.wait()  # Wait for the underlying process to complete.
out, err = process.communicate()  # Capture what it outputted on STDOUT and STDERR
errcode = process.returncode  # Harvest its returncode, if needed.
print(out)
print('done running command')

Additionally, I wouldn't use shell = True unless it's really required. It forces subprocess to fire up a whole shell environment just to run a command. It's usually better to inject directly into the env parameter of Popen.

Answer 2

Thanks. This works but has one limitation - you can't see any output until after the command completes. I found an answer from another question (here) that uses popen but also lets me see the output in real time. Here's what I ended up with this:

import subprocess
import sys

cmd = ['/media/sf_git/test-automation/src/SalesVision/mswm/shell_test.sh', '4', '2']
print('running command: "{0}"'.format(cmd))  # output the command.
# Here, we join the STDERR of the application with the STDOUT of the application.
process = subprocess.Popen(cmd, bufsize=1, universal_newlines=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
for line in iter(process.stdout.readline, ''):
    line = line.replace('\n', '')
    print(line)
    sys.stdout.flush()
process.wait()                   #  Wait for the underlying process to complete.
errcode = process.returncode      #  Harvest its returncode, if needed.
print( 'Script ended with return code of: ' + str(errcode) )

This uses Popen and allows me to see the progress of the called script.