classification
Title: subprocess pipe can't see EOF from a child in case of a few children run with subprocess
Type: behavior Stage: resolved
Components: Library (Lib), Windows Versions: Python 2.7
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: Vyacheslav Grigoryev, eryksun, paul.moore, steve.dower, tim.golden, zach.ware
Priority: normal Keywords:

Created on 2016-10-17 15:38 by Vyacheslav Grigoryev, last changed 2021-02-26 19:51 by eryksun. This issue is now closed.

Messages (2)
msg278809 - (view) Author: Vyacheslav Grigoryev (Vyacheslav Grigoryev) Date: 2016-10-17 15:38
I'm creating a master stand-alone module on Python which should run some children via subprocess module. Working with children is done in separate worker threads. Additionally I need to receive real-time output from a child so in a worker thread I also create reader helper thread which reads on a pipe from the child.

All is working correctly while I have only one worker thread and run only one child. When the child finishes the reader helper thread gets EOF and exits. But when I have two worker threads and run two children, a pipe from early child doesn't see EOF until the second child is finished. Though they are completely unrelated.

Let's take a look on simplest example for reproducing the problem. There is a simplest child:
------------------------------
import time, sys

# first arg is an ID. Second arg is how long to work in seconds
sys.stdout.write("start slave %s\n" % sys.argv[1])
sys.stdout.flush()

time.sleep(int(sys.argv[2]))

sys.stdout.write("finish slave %s\n" % sys.argv[1])
sys.stdout.flush()
------------------------------

And there is a master module:
------------------------------
import subprocess, sys, os, threading, time

g_logLock = threading.Lock()

def log(msg):
    with g_logLock:
        t = time.time()
        print "%s.%03d %-5s %s" % \
            (time.strftime('%H:%M:%S', time.localtime(t)), int((t - t // 1) * 1000), threading.currentThread().name, msg)

def thread1Proc():
    def reader(stdout):
        while True:
            line = stdout.readline()
            if not line:
                break
            log('slave said: %s' % line.strip())
        log('finish slave reader thread')

    log('thread 1 started')
    timeToWork = '1'
    util = subprocess.Popen((sys.executable, 'slave.py', '1', timeToWork), stdout=subprocess.PIPE)
    readerT = threading.Thread(target=reader, args=(util.stdout,), name='t1-r')
    readerT.start()
    log('slave 1 returned %d' % util.wait())
    readerT.join()
    log('thread 1 finished')

def thread2Proc():
    log('thread 2 started')
    timeToWork = '3'
    util = subprocess.Popen((sys.executable, 'slave.py', '2', timeToWork))
    log('slave 2 returned %d' % util.wait())
    log('thread 2 finished')

#---------------------------
log('starting test')

threads = (threading.Thread(target=thread1Proc, name='t1'), threading.Thread(target=thread2Proc, name='t2'))
for t in threads:
    t.start()
for t in threads:
    t.join()

log('finished test')
------------------------------

Here is what I see on the output (note - slave 1 outputs to the master via pipe, while slave 2 outputs to a console because its output is not redirected):

>master.py
08:57:31.342 MainThread starting test
08:57:31.342 t1    thread 1 started
08:57:31.342 t2    thread 2 started
08:57:31.405 t1-r  slave said: start slave 1
start slave 2
08:57:32.420 t1-r  slave said: finish slave 1
08:57:32.420 t1    slave 1 returned 0
finish slave 2
08:57:34.415 t1-r  finish slave reader thread
08:57:34.415 t2    slave 2 returned 0
08:57:34.415 t1    thread 1 finished
08:57:34.431 t2    thread 2 finished
08:57:34.431 MainThread finished test

Here you can see that even if the slave 1 finishes at 32.420, its reader thread receives EOF and exits only when the slave 2 finishes also - at 34.415 (slave 1 works 1 second, slave 2 - 3 seconds).

Why the reader thread doesn't see EOF just in time?

The issue is reproduced in Python 2.7.12 x86 on Windows 7. On Linux Ubuntu 16.04 with system Python 2.7 all works as expected.
msg278842 - (view) Author: Eryk Sun (eryksun) * (Python triager) Date: 2016-10-18 05:32
Due to a race condition, the Popen call in the second process is inadvertently inheriting the handle for the write end of the pipe that's created for the first process. Thus stdout.readline() in the first thread doesn't see EOF until that handle is closed. 

For the 2nd process, since you don't need to inherit standard handles, you can pass close_fds=True. In general if you do need to inherit standard handles in processes that are created concurrently, you can synchronize on a lock to ensure Popen properly closes inheritable handles. For example:

    import threading
    import subprocess

    class Popen(subprocess.Popen):
        _execute_lock = threading.Lock()
        def __init__(self, *args, **kwds):
            with self._execute_lock:
                super(Popen, self).__init__(*args, **kwds)

In Python 3 this should be addressed by implementing the suggestion in issue 19764 to use PROC_THREAD_ATTRIBUTE_HANDLE_LIST.
History
Date User Action Args
2021-02-26 19:51:54eryksunsetstatus: open -> closed
resolution: out of date
stage: resolved
2016-10-18 05:32:04eryksunsetnosy: + eryksun
messages: + msg278842
2016-10-17 20:06:00martin.pantersetnosy: + paul.moore, tim.golden, zach.ware, steve.dower
components: + Windows
2016-10-17 15:38:04Vyacheslav Grigoryevcreate