go/neo/t/nxd/runTestSuite: Tee tested process stdout,stderr to testnode logs incrementally

We send output from tested process to master. We also print it to
stdout,stderr so it appears in testnode logs.

However till now it was like, whole output first read, and only then
emitted to log as a whole, thus not allowing to oversee current test
progress by watching testnode log tail.

Fix it by implementing the teeing process manually.

Some draft history related to this patch:

	lab.nexedi.com/kirr/neo/commit/aa370ca3        fixup! X neotest/runTestSuite: Tee tested process stdout,stderr to testnode logs incrementally
	lab.nexedi.com/kirr/neo/commit/096550b1        fixup! X neotest/runTestSuite: Tee tested process stdout,stderr to testnode logs incrementally
	lab.nexedi.com/kirr/neo/commit/63956f43        fixup! X neotest/runTestSuite: Tee tested process stdout,stderr to testnode logs incrementally
	lab.nexedi.com/kirr/neo/commit/b9819d0e        X neotest/runTestSuite: Tee tested process stdout,stderr to testnode logs incrementally

go/neo/t/nxd/runTestSuite

@@ -25,7 +25,7 @@ neotest must be on $PATH.
 from erp5.util.taskdistribution import TaskDistributor
 from subprocess import Popen, PIPE
 from time import time, strftime, gmtime
-import os, sys, argparse, logging, traceback
+import os, sys, threading, argparse, logging, traceback
 
 
 def main():
@@ -62,6 +62,11 @@ def main():
         # a test run for given name and revision has already been completed
         return
 
+    # make sure we get output from subprocesses without delay.
+    # go does not buffer stdout/stderr by default, but python does for stdout.
+    # tell python not to buffer anything.
+    os.environ['PYTHONUNBUFFERED'] = 'y'
+
     # run the tests
     devnull = open(os.devnull)
     while 1:
@@ -76,19 +81,29 @@ def main():
 
         try:
             # NOTE runs with unchanged cwd. Instance wrapper cares to set cwd before running us.
-            p = Popen(argv, stdin=devnull, stdout=PIPE, stderr=PIPE)
+            # bufsize=1 means 'line buffered'
+            p = Popen(argv, stdin=devnull, stdout=PIPE, stderr=PIPE, bufsize=1)
         except:
             stdout, stderr = '', traceback.format_exc()
+            sys.stderr.write(stderr)
             ok = False
         else:
-            stdout, stderr = p.communicate()
+            # tee >stdout,stderr so we can also see in testnode logs
+            # (explicit teeing instead of p.communicate() to be able to see incremental progress)
+            buf_out = []
+            buf_err = []
+            tout = threading.Thread(target=tee, args=(p.stdout, sys.stdout, buf_out))
+            terr = threading.Thread(target=tee, args=(p.stderr, sys.stderr, buf_err))
+            tout.start()
+            terr.start()
+
+            tout.join(); stdout = ''.join(buf_out)
+            terr.join(); stderr = ''.join(buf_err)
+            p.wait()
             ok = (p.returncode == 0)
 
         tend = time()
 
-        # tee >stdout,stderr so we can also see in testnode logs
-        sys.stdout.write(stdout)
-        sys.stderr.write(stderr)
 
         # report result of test run back to master
         test_result_line.stop(
@@ -106,6 +121,24 @@ def main():
             #html_test_result
         )
 
+# tee, similar to tee(1) utility, copies data from fin to fout appending them to buf.
+def tee(fin, fout, buf):
+    while 1:
+        # NOTE use raw os.read because it does not wait for full data to be available.
+        # ( we could use fin.readline(), but there are cases when e.g. progress
+        #   is reported via printing consequent dots on the same line and
+        #   readline() won't work for that.
+        #
+        #   besides when a lot of output is available it would be a waste to
+        #   read/flush it line-by-line. )
+        data = os.read(fin.fileno(), 4096)
+        if not(data):
+            return  # EOF
+
+        fout.write(data)
+        fout.flush()
+        buf.append(data)
+
 
 if __name__ == '__main__':
     main()