python subprocess: order of output changes when using subprocess.PIPE

Question

When I write a python script called outer.py containing

p = subprocess.Popen(['./inner.py'])
print('Called inner.py without options, waiting for process...')
p.wait()
print('Waited for inner.py without options')

p = subprocess.Popen(['./inner.py'], stdout=subprocess.PIPE)
print('Called inner.py with PIPE, communicating...')
b_out, b_err = p.communicate()
out = b_out.decode('utf8')
print('out is "{}"'.format(out))

And an inner.py containing

print("inner: Echoing Hallo")
p = subprocess.Popen(['echo', 'hallo'])
print("inner: Waiting for Echo to finish...")
p.wait()
print("inner: Waited for Echo")

I get the following when calling outer.py from a terminal:

Called inner.py without options, waiting for process...
inner: Echoing Hallo
inner: Waiting for Echo to finish...
hallo
inner: Waited for Echo
Waited for inner.py without options

Called inner.py with PIPE, communicating...
out is "hallo
inner: Echoing Hallo
inner: Waiting for Echo to finish...
inner: Waited for Echo
"

Why, when calling inner.py with stdout=subprocess.PIPE, does the "hallo" appear before the "inner: Echoing Hallo" in the captured output?

cannot reproduce on my mac - however I had to add the shebang and import statements for the code to work in the first place. Please include a complete example as well as the operating system you are using. — Tadhg McDonald-Jensen, Sep 27 '16 at 11:34
Sounds like it could be buffering on standard out of inner.py. Can you try disabling buffering, for instance with setting PYTHONUNBUFFERED? More techniques listed here: http://stackoverflow.com/a/107717/1062499 — wildwilhelm, Sep 27 '16 at 11:39
Communicate not single loop action and always returned string, not output ! — dsgdfg, Sep 27 '16 at 12:05
@wildwilhelm You are right, when I disable output buffering the output is displayed in the same order as the corresponding statements in the script. But why is the behaviour different depending on how inner.py is called from outer.py? — jan, Sep 27 '16 at 12:11

score 6 · Accepted Answer · edited May 23 '17 at 12:06

I would guess that, for some reason (related to pipes vs. ttys, see this comment), the output of the inner.py Python process is unbuffered the first time you call it, and buffered the second time you call it. The first time, with unbuffered output, you get the result in the expected order written to your tty. The second time, with buffering, the output from the echo command gets flushed first (because echo runs and terminates), and then all of the output from the inner.py process shows up at once, when python terminates. If you disable output buffering for inner.py, you should get the same output in both cases.

Disable output buffering by setting the PYTHONUNBUFFERED environment variable, or by calling python with the -u switch, or by explicitly calling sys.stdout.flush() after every print (or print(..., flush=True) on Python 3).

The difference between the behaviour of pipes and ttys seems to be a general behaviour of stdio: output to ttys is line-buffered (so, in your code, which reads line by line, it will seem to be unbuffered), whereas output to pipes is buffered.

python subprocess: order of output changes when using subprocess.PIPE

1 Answers1