Why is my output from a subprocess delayed, when i

This an extension to my posting from yesterday, which is still unsolved: Why does my Python thread with subprocess not work as expected?

In the meantime I found some interesting details, so I decided to create a new posting. To bring it to the point: There are some issues, when a subprocess is generated out of a thread.

Platform: Windows 7 Enterprise, Python 3.6.1

In the following code I want to run a C-executable and get its output to stdout into a string. For test purposes the executable accepts two parameters: a delay and a filename (not used here). The program writes Sleep now to stdout, sleeps for the given number of milliseconds and finally writes after sleep and END.

This is the C-source of the executable:

int main(int argc, char *argv[])
{
    int sleep = 0;
    FILE * outfile = NULL;

    if (argc > 1)
    {
        sleep = atoi(argv[1]);
    }

    if (argc > 2)
    {
        outfile = fopen(argv[2], "w");
    }

    printf("Sleep now...\n");

    Sleep(sleep);

    if (outfile) fprintf(outfile, "output-1");
    printf("after sleep\n");
    printf("END\n");

    if (outfile) fclose(outfile);
    fclose(stdout);
    exit (0);
}

This is the Python code:

import subprocess
import threading
import time
import os
import sys


def worker_nok(*args):

    exe, delay, filename = args
    proc = subprocess.Popen([exe, delay, filename], shell=False, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
    out, err = proc.communicate()
    print("%s:" % (filename,), out)
    sys.stdout.flush()


def worker(*args):
    exe, delay, filename = args
    flag = True
    proc = subprocess.Popen([exe, delay, filename], shell=False, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
    while flag is True:
        str = proc.stdout.readline()
        if str == b"":
            print("%s: got EOF" % (filename,))
            flag = False
        else:
            print("%s:" % (filename,), str)
    print ("%s: END" % (filename,))
    sys.stdout.flush()


all = []    

"""
# 4 seconds
job_thread1 = threading.Thread(target = worker, args=(["../testapp.exe", "4000", "w4sec.txt"]))
job_thread1.start()
all.append(job_thread1)

# 8 seconds
job_thread2 = threading.Thread(target = worker, args=(["../testapp.exe", "8000", "w8sec.txt"]))
job_thread2.start()
all.append(job_thread1)
"""

# 4 seconds
job_thread3 = threading.Thread(target = worker_nok, args=(["../testapp.exe", "4000", "w4sec.nok"]))
job_thread3.start()
all.append(job_thread3)

# 8 seconds
job_thread3 = threading.Thread(target = worker_nok, args=(["../testapp.exe", "8000", "w8sec.nok"]))
job_thread3.start()
all.append(job_thread3)



for t in all:
    t.join()

The jobs have delays of 4, 8, and 1 seconds, respectively.

worker_nok calls proc.communicate() - it was my original approach, which is not working: When running the two jobs, I get the following output:

w4sec.nok: b'Sleep now...\r\nafter sleep\r\nEND\r\n'
w8sec.nok: b'Sleep now...\r\nafter sleep\r\nEND\r\n'

The whole bunch is received after 8 seconds. Instead I would expect

... 4 sec ...
w4sec.nok: b'Sleep now...\r\nafter sleep\r\nEND\r\n'

... 4 sec ...
w8sec.nok: b'Sleep now...\r\nafter sleep\r\nEND\r\n'

Although the process with 4 seconds is definitely finished, its output is available only after the second job has also finished.

This was the state from my last posting.

To find out whats wrong, I tried to replace communicate() by direct reading of stdout, which is implemented in the worker function. The EOF condition is identified when read returns an empty string. When calling it, I get:

... 4 seconds ...

w4sec.txt: b'Sleep now...\r\n'
w4sec.txt: b'after sleep\r\n'
w4sec.txt: b'END\r\n'

... 4 seconds ...

w8sec.txt: b'Sleep now...\r\n'
w8sec.txt: b'after sleep\r\n'
w8sec.txt: b'END\r\n'
w8sec.txt: got EOF
w8sec.txt: END
w4sec.txt: got EOF
w4sec.txt: END

However I would expect:

w4sec.txt: b'Sleep now...\r\n'
w8sec.txt: b'Sleep now...\r\n'

... 4 seconds ...

w4sec.txt: b'after sleep\r\n'
w4sec.txt: b'END\r\n'
w4sec.txt: got EOF
w4sec.txt: END

... 4 seconds ...   

w8sec.txt: b'after sleep\r\n'
w8sec.txt: b'END\r\n'
w8sec.txt: got EOF
w8sec.txt: END

The big Questions are:

(1) Why at all is there a delay before I get sleep now ? The executable makes this output available without delay. Is the stdout only available after the process has terminated?

(2) More important: Why is the EOF for the 4sec available only after the 8sec call has finished?

I hope this input makes clear, why the original version showed the observed behavior: The stdout is in the EOF-condition much too late and leaves the call to communicate() blocking!

I appreciate any inputs, since I'm working on that already for more than 12 hours...