From 8b225fde43247ae97ce3bc9b0d850f4c31914a95 Mon Sep 17 00:00:00 2001 From: Bo QIU <35757521+boqiu@users.noreply.github.com> Date: Wed, 24 Jan 2024 20:42:25 +0800 Subject: [PATCH] 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 | 2 +- tests/crash_test.py | 18 ++++++---- tests/rpc_test.py | 2 +- tests/submission_test.py | 9 +++-- tests/test_all.py | 25 +++++++------- tests/test_framework/blockchain_node.py | 24 +++++++++----- tests/test_framework/test_framework.py | 44 +++++++++++++++---------- tests/utility/simple_rpc_proxy.py | 4 +-- 8 files changed, 78 insertions(+), 50 deletions(-) diff --git a/tests/cli_submission_test.py b/tests/cli_submission_test.py index 8f1c5b5..0a37157 100755 --- a/tests/cli_submission_test.py +++ b/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) diff --git a/tests/crash_test.py b/tests/crash_test.py index 2eaf29b..503e614 100644 --- a/tests/crash_test.py +++ b/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"] ) diff --git a/tests/rpc_test.py b/tests/rpc_test.py index f6edc6b..ff64a39 100755 --- a/tests/rpc_test.py +++ b/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"] ) diff --git a/tests/submission_test.py b/tests/submission_test.py index 376f13f..4bfed6e 100755 --- a/tests/submission_test.py +++ b/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"] ) diff --git a/tests/test_all.py b/tests/test_all.py index 5f7236b..74addc7 100755 --- a/tests/test_all.py +++ b/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: diff --git a/tests/test_framework/blockchain_node.py b/tests/test_framework/blockchain_node.py index bcbb5ca..684213c 100644 --- a/tests/test_framework/blockchain_node.py +++ b/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): diff --git a/tests/test_framework/test_framework.py b/tests/test_framework/test_framework.py index 0b140b4..7e36160 100644 --- a/tests/test_framework/test_framework.py +++ b/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 diff --git a/tests/utility/simple_rpc_proxy.py b/tests/utility/simple_rpc_proxy.py index 26db293..322617b 100644 --- a/tests/utility/simple_rpc_proxy.py +++ b/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