Using subprocess to launch hadoop job but can't get log from stdout

Question

To simplify my question, here'a a python script:

from subprocess import Popen, PIPE
proc = Popen(['./mr-task.sh'], shell=True, stdout=PIPE, stderr=PIPE)
while True:
    out = proc.stdout.readline()
    print(out)

Here's mr-task.sh, it starts a mapreduce job:

hadoop jar xxx.jar some-conf-we-don't-need-to-care

When I run ./mr-task, I could see log printed on the screen, something like:

14/12/25 14:56:44 INFO util.NativeCodeLoader: Loaded the native-hadoop library
14/12/25 14:56:44 INFO snappy.LoadSnappy: Snappy native library loaded
14/12/25 14:57:01 INFO mapred.JobClient: Running job: job_201411181108_16380
14/12/25 14:57:02 INFO mapred.JobClient:  map 0% reduce 0%
14/12/25 14:57:28 INFO mapred.JobClient:  map 100% reduce 0%

But I can't get these output running python script. I tried removing shell=True or fetch stderr, still got nothing.

Does anyone have any idea why this happens?

Answer 1

You could redirect stderr to stdout:

from subprocess import Popen, PIPE, STDOUT

proc = Popen(['./mr-task.sh'], stdout=PIPE, stderr=STDOUT, bufsize=1)
for line in iter(proc.stdout.readline, b''):
    print line,
proc.stdout.close()
proc.wait()

See Python: read streaming input from subprocess.communicate().

---

in my real program I redirect stderr to stdout and read from stdout, so bufsize is not needed, is it?

The redirection of stderr to stdout and bufsize are unrelated. Changing bufsize might affect the time performance (the default bufsize=0 i.e., unbuffered on Python 2). Unbuffered I/O might be 10..100 times slower. As usual, you should measure the time performance if it is important.

Calling Popen.wait/communicate after the subprocess has terminated is just for clearing zombie process, and these two methods have no difference in such case, correct?

The difference is that proc.communicate() closes the pipes before reaping the child process. It releases file descriptors (a finite resource) to be used by a other files in your program.

about buffer, if output fill buffer maxsize, will subprocess hang? Does that mean if I use the default bufsize=0 setting I need to read from stdout as soon as possible so that subprocess don't block?

No. It is a different buffer. bufsize controls the buffer inside the parent that is filled/drained when you call .readline() method. There won't be a deadlock whatever bufsize is.

The code (as written above) won't deadlock no matter how much output the child might produce.

The code in @falsetru's answer can deadlock because it creates two pipes (stdout=PIPE, stderr=PIPE) but it reads only from one pipe (proc.stderr).

There are several buffers between the child and the parent e.g., C stdio's stdout buffer (a libc buffer inside child process, inaccessible from the parent), child's stdout OS pipe buffer (inside kernel, the parent process may read the data from here). These buffers are fixed they won't grow if you put more data into them. If stdio's buffer overflows (e.g., during a printf() call) then the data is pushed downstream into the child's stdout OS pipe buffer. If nobody reads from the pipe then then this OS pipe buffer fills up and the child blocks (e.g., on write() system call) trying to flush the data.

To be concrete, I've assumed C stdio's based program and POSIXy OS.

The deadlock happens because the parent tries to read from the stderr pipe that is empty because the child is busy trying to flush its stdout. Thus both processes hang.

Answer 2

One possible reaosn is that the output is printed to standard error instead of standard output.

Try to replace stdout with stderr:

from subprocess import Popen, PIPE
proc = Popen(['./mr-task.sh'], stdout=PIPE, stderr=PIPE)
while True:
    out = proc.stderr.readline()  # <----
    if not out:
        break
    print(out)