title: Why is my output from a subprocess delayed, when it is generated from a Python thread?
body: <p>This an extension to my posting from yesterday, which is still unsolved: <a href="https://stackoverflow.com/questions/46688923/why-does-my-python-thread-with-subprocess-not-work-as-expected">Why does my Python thread with subprocess not work as expected?</a></p>
  
  <p>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. </p>
  
  <p>Platform: Windows 7 Enterprise, Python 3.6.1</p>
  
  <p>In the following code I want to run a C-executable and get its output to <code>stdout</code> into a string. For test purposes the executable accepts two parameters: a delay and a filename (not used here). The program writes <code>Sleep now</code> to <code>stdout</code>, sleeps for the given number of milliseconds and finally writes <code>after sleep</code> and <code>END</code>.</p>
  
  <p>This is the C-source of the executable:</p>
  
  <pre><code>int main(int argc, char *argv[])
  {
      int sleep = 0;
      FILE * outfile = NULL;
  
      if (argc &gt; 1)
      {
          sleep = atoi(argv[1]);
      }
  
      if (argc &gt; 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);
  }
  </code></pre>
  
  <p>This is the Python code:</p>
  
  <pre><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()
  </code></pre>
  
  <p>The jobs have delays of 4, 8, and 1 seconds, respectively. </p>
  
  <p><code>worker_nok</code> calls <code>proc.communicate()</code> - it was my original approach, which is not working: When running the two jobs, I get the following output:</p>
  
  <pre><code>w4sec.nok: b'Sleep now...\r\nafter sleep\r\nEND\r\n'
  w8sec.nok: b'Sleep now...\r\nafter sleep\r\nEND\r\n'
  </code></pre>
  
  <p>The whole bunch is received after 8 seconds. Instead I would expect</p>
  
  <pre><code>... 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'
  </code></pre>
  
  <p>Although the process with 4 seconds is definitely finished, its output is available only after the second job has also finished.</p>
  
  <p>This was the state from my last posting.</p>
  
  <p>To find out whats wrong, I tried to replace <code>communicate()</code> by direct reading of stdout, which is implemented in the <code>worker</code> function. The EOF condition is identified when read returns an empty string. When calling it, I get:</p>
  
  <pre><code>... 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
  </code></pre>
  
  <p>However I would expect:</p>
  
  <pre><code>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
  </code></pre>
  
  <p>The big <strong>Questions</strong> are:</p>
  
  <p>(<strong>1</strong>) Why at all is there a delay before I get <code>sleep now</code> ? The executable makes this output available without delay. Is the stdout only available after the process has terminated?</p>
  
  <p>(<strong>2</strong>) More important: Why is the EOF for the 4sec available only after the 8sec call has finished?</p>
  
  <p>I hope this input makes clear, why the original version showed the observed behavior: The <code>stdout</code> is in the EOF-condition much too late and leaves the call to communicate() blocking!</p>
  
  <p>I appreciate any inputs, since I'm working on that already for more than 12 hours...</p>