Fix python test (#8)

* Fix stdouterr issue when shutdown storage node

* Fix random failure for submission test

* add more info for failed rpc

* use single file instead of subprocess pipe to launch CLI

* Opt test_all for windows

* wait for log entry before file sync by admin

tests/cli_submission_test.py

@@ -84,6 +84,7 @@ class CliSubmissionTest(TestFramework):
                 continue
 
             self.log.info("wait node %d", i)
+            wait_until(lambda: self.nodes[i].zgs_get_file_info(root) is not None)
             self.nodes[i].admin_start_sync_file(submission_index - 1)
             wait_until(
                 lambda: self.nodes[i].sycn_status_is_completed_or_unknown(
@@ -91,7 +92,6 @@ class CliSubmissionTest(TestFramework):
                 )
             )
 
-            wait_until(lambda: self.nodes[i].zgs_get_file_info(root) is not None)
             wait_until(lambda: self.nodes[i].zgs_get_file_info(root)["finalized"])
 
             # start_idx = random.randint(0, num_of_entris - 1)

tests/crash_test.py

@@ -22,11 +22,11 @@ class CrashTest(TestFramework):
         self.log.info("segment: %s", segment)
 
         for i in range(self.num_nodes):
-            self.nodes[i].admin_start_sync_file(0)
-            self.log.info("wait for node: %s", i)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root) is not None
             )
+            self.nodes[i].admin_start_sync_file(0)
+            self.log.info("wait for node: %s", i)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root)["finalized"]
             )
@@ -48,22 +48,26 @@ class CrashTest(TestFramework):
 
         self.start_storage_node(1)
         self.nodes[1].wait_for_rpc_connection()
-        self.nodes[1].admin_start_sync_file(1)
         wait_until(lambda: self.nodes[1].zgs_get_file_info(data_root) is not None)
+        self.nodes[1].admin_start_sync_file(1)
         wait_until(lambda: self.nodes[1].zgs_get_file_info(data_root)["finalized"])
 
         for i in range(2, self.num_nodes):
             self.start_storage_node(i)
             self.nodes[i].wait_for_rpc_connection()
+            wait_until(
+                lambda: self.nodes[i].zgs_get_file_info(data_root) is not None
+            )
             self.nodes[i].admin_start_sync_file(1)
 
             self.nodes[i].stop(kill=True)
             self.start_storage_node(i)
             self.nodes[i].wait_for_rpc_connection()
-            self.nodes[i].admin_start_sync_file(1)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root) is not None
             )
+            self.nodes[i].admin_start_sync_file(1)
+            
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root)["finalized"]
             )
@@ -91,10 +95,10 @@ class CrashTest(TestFramework):
             self.log.info("wait for node: %s", i)
             self.start_storage_node(i)
             self.nodes[i].wait_for_rpc_connection()
-            self.nodes[i].admin_start_sync_file(2)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root) is not None
             )
+            self.nodes[i].admin_start_sync_file(2)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root)["finalized"]
             )
@@ -132,18 +136,18 @@ class CrashTest(TestFramework):
             self.log.info("wait for node: %s", i)
             self.start_storage_node(i)
             self.nodes[i].wait_for_rpc_connection()
-            self.nodes[i].admin_start_sync_file(4)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root1) is not None
             )
+            self.nodes[i].admin_start_sync_file(4)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root1)["finalized"]
             )
 
-            self.nodes[i].admin_start_sync_file(3)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root) is not None
             )
+            self.nodes[i].admin_start_sync_file(3)
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root)["finalized"]
             )

tests/rpc_test.py

@@ -81,6 +81,7 @@ class RpcTest(TestFramework):
 
             for i in range(1, self.num_nodes):
                 self.log.info("wait node %d", i)
+                wait_until(lambda: self.nodes[i].zgs_get_file_info(root) is not None)
                 self.nodes[i].admin_start_sync_file(n_files - 1)
                 wait_until(
                     lambda: self.nodes[i].sycn_status_is_completed_or_unknown(
@@ -88,7 +89,6 @@ class RpcTest(TestFramework):
                     )
                 )
 
-                wait_until(lambda: self.nodes[i].zgs_get_file_info(root) is not None)
                 wait_until(
                     lambda: self.nodes[i].zgs_get_file_info(root)["finalized"]
                 )

tests/submission_test.py

@@ -76,16 +76,19 @@ class SubmissionTest(TestFramework):
             if node_idx == i:
                 continue
 
+            # Wait for log entry before file sync, otherwise, admin_startSyncFile will be failed.
+            wait_until(
+                lambda: self.nodes[i].zgs_get_file_info(data_root) is not None
+            )
+
             self.nodes[i].admin_start_sync_file(submission_index - 1)
+
             wait_until(
                 lambda: self.nodes[i].sycn_status_is_completed_or_unknown(
                     submission_index - 1
                 )
             )
 
-            wait_until(
-                lambda: self.nodes[i].zgs_get_file_info(data_root) is not None
-            )
             wait_until(
                 lambda: self.nodes[i].zgs_get_file_info(data_root)["finalized"]
             )

tests/test_all.py

@@ -5,6 +5,7 @@ import shutil
 import stat
 import subprocess
 import sys
+import time
 
 from concurrent.futures import ProcessPoolExecutor
 
@@ -18,6 +19,9 @@ __file_path__ = os.path.dirname(os.path.realpath(__file__))
 
 CONFLUX_BINARY = "conflux.exe" if is_windows_platform() else "conflux"
 
+def print_testcase_result(color, glyph, script, start_time):
+    print(color[1] + glyph + " Testcase " + script + "\telapsed: " + str(int(time.time() - start_time)) + " seconds" + color[0], flush=True)
+
 def run_single_test(py, script, test_dir, index, port_min, port_max):
     try:
         # Make sure python thinks it can write unicode to its stdout
@@ -31,17 +35,16 @@ def run_single_test(py, script, test_dir, index, port_min, port_max):
         CIRCLE = "o "
 
     BOLD, BLUE, RED, GREY = ("", ""), ("", ""), ("", ""), ("", "")
-    if os.name == "posix":
+    if os.name == "posix" or os.name == "nt":
         # primitive formatting on supported
         # terminal via ANSI escape sequences:
         BOLD = ("\033[0m", "\033[1m")
         BLUE = ("\033[0m", "\033[0;34m")
         RED = ("\033[0m", "\033[0;31m")
         GREY = ("\033[0m", "\033[1;30m")
-    print("Running " + script)
+    print("Running " + script, flush=True)
     port_min = port_min + (index * PORT_RANGE) % (port_max - port_min)
-    color = BLUE
-    glyph = TICK
+    start_time = time.time()
     try:
         subprocess.check_output(
             args=[py, script, "--randomseed=1", f"--port-min={port_min}"],
@@ -49,15 +52,13 @@ def run_single_test(py, script, test_dir, index, port_min, port_max):
             cwd=test_dir,
         )
     except subprocess.CalledProcessError as err:
-        color = RED
-        glyph = CROSS
-        print(color[1] + glyph + " Testcase " + script + color[0])
-        print("Output of " + script + "\n" + err.output.decode("utf-8"))
+        print_testcase_result(RED, CROSS, script, start_time)
+        print("Output of " + script + "\n" + err.output.decode("utf-8"), flush=True)
         raise err
-    print(color[1] + glyph + " Testcase " + script + color[0])
-
+    print_testcase_result(BLUE, TICK, script, start_time)
 
 def run():
+    start_time = time.time()
     dir_name = os.path.join(__file_path__, "tmp")
     if not os.path.exists(dir_name):
         os.makedirs(dir_name, exist_ok=True)
@@ -95,7 +96,7 @@ def run():
         "",  # include test_dir itself
     ]
 
-    slow_tests = {}
+    slow_tests = {"random_test.py", "same_root_test.py"}
     long_manual_tests = {"fuzz_test.py"}
 
     for subdir in test_subdirs:
@@ -136,6 +137,8 @@ def run():
             print("CalledProcessError " + repr(err))
             failed.add(script)
 
+    print("Elapsed: " + str(int(time.time() - start_time)) + " seconds", flush=True)
+
     if len(failed) > 0:
         print("The following test fails: ")
         for c in failed:

tests/test_framework/blockchain_node.py

@@ -149,7 +149,7 @@ class TestNode:
         else:
             self.process.terminate()
         if wait:
-            self.wait_until_stopped()
+            self.wait_until_stopped(close_stdout_stderr=False)
         # Check that stderr is as expected
         self.stderr.seek(0)
         stderr = self.stderr.read().decode("utf-8").strip()
@@ -169,12 +169,18 @@ class TestNode:
                 )
             )
 
-        self.stdout.close()
-        self.stderr.close()
-        self.stdout = None
-        self.stderr = None
+        self.__safe_close_stdout_stderr__()
 
-    def is_node_stopped(self):
+    def __safe_close_stdout_stderr__(self):
+        if self.stdout is not None:
+            self.stdout.close()
+            self.stdout = None
+
+        if self.stderr is not None:
+            self.stderr.close()
+            self.stderr = None
+
+    def __is_node_stopped__(self):
         """Checks whether the node has stopped.
 
         Returns True if the node has stopped. False otherwise.
@@ -196,8 +202,10 @@ class TestNode:
         self.return_code = return_code
         return True
 
-    def wait_until_stopped(self, timeout=20):
-        wait_until(self.is_node_stopped, timeout=timeout)
+    def wait_until_stopped(self, close_stdout_stderr=True, timeout=20):
+        wait_until(self.__is_node_stopped__, timeout=timeout)
+        if close_stdout_stderr:
+            self.__safe_close_stdout_stderr__()
 
 
 class BlockchainNode(TestNode):

tests/test_framework/test_framework.py

@@ -326,25 +326,35 @@ class TestFramework:
             "--file",
         ]
 
-        proc = subprocess.Popen(
-            upload_args + [file_to_upload.name],
-            text=True,
-            stdout=subprocess.PIPE,
-            stderr=subprocess.STDOUT,
-        )
-        proc.wait()
+        output = tempfile.NamedTemporaryFile(dir=self.root_dir, delete=False, prefix="zgs_client_output_")
+        output_name = output.name
+        output_fileno = output.fileno()
 
-        root = None
-        lines = proc.stdout.readlines()
-        for line in lines:
-            self.log.debug("line: %s", line)
-            if "root" in line:
-                index = line.find("root=")
-                root = line[index + 5 : -1]
-                self.log.info("root: %s", root)
+        try:
+            proc = subprocess.Popen(
+                upload_args + [file_to_upload.name],
+                text=True,
+                stdout=output_fileno,
+                stderr=output_fileno,
+            )
+            
+            return_code = proc.wait(timeout=60)
 
-        assert proc.returncode == 0, "%s upload file failed, log: %s" % (self.cli_binary, lines)
-        self.log.info("file uploaded")
+            output.seek(0)
+            lines = output.readlines()
+            for line in lines:
+                line = line.decode("utf-8")
+                self.log.debug("line: %s", line)
+                if "root" in line:
+                    index = line.find("root=")
+                    root = line[index + 5 : -1]
+        except Exception as ex:
+            self.log.error("Failed to upload file via CLI tool, output: %s", output_name)
+            raise ex
+        finally:
+            output.close()
+
+        assert return_code == 0, "%s upload file failed, output: %s, log: %s" % (self.cli_binary, output_name, lines)
 
         return root
 

tests/utility/simple_rpc_proxy.py

@@ -25,7 +25,7 @@ class RpcCaller:
             if isinstance(parsed, Ok):
                 return parsed.result
             else:
-                print(parsed)
+                print("Failed to call RPC, method = %s(%s), error = %s" % (self.method, *args, parsed))
         except Exception as ex:
-            print(ex)
+            print("Failed to call RPC, method = %s(%s), exception = %s" % (self.method, *args, ex))
         return None