X neotest/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 and using only
line-buffered mode inside.

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():
@@ -76,19 +76,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 +116,17 @@ 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 readline, not read, because file.read(N) actually waits for N
+        data = fin.readline(4096)
+        if not(data):
+            return  # EOF
+
+        fout.write(data)
+        buf.append(data)
+
 
 if __name__ == '__main__':
     main()

[Kirill Smelkov]

/cc @Tyagov, @jm for similar places in other runTestSuitees

[Julien Muchembled]

That looks a good idea.

I plan to continue reviewing the code for our unit test infrastructure, and probably extend erp5.util to avoid repeating too much code in the runTestSuite script of each project. For the moment, everyone hacks and assumes any breakage.

I'll keep this change in mind, but I won't do premature changes like this in existing runTestSuite scripts.

[Ivan Tyagov]

+1

[Kirill Smelkov]

for cherry-pickers: fixup: 63956f43

[Kirill Smelkov]

More fixups: 096550b1, aa370ca3.

[Kirill Smelkov]

For the reference: full patch for teeing stdout/stderr to testnode log: f67c147d.