From bb75df651dae969ecee4cb9ac2fa78f7dca88b16 Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:03:37 -0500 Subject: [PATCH 01/18] swap STDOUT with PIPE --- test/test_base.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/test_base.py b/test/test_base.py index 9ba017fb9..d19d099f0 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -5,7 +5,7 @@ import os import threading from pathlib import Path -from subprocess import PIPE, STDOUT, Popen, run +from subprocess import PIPE, Popen, run from tempfile import mkdtemp from time import sleep @@ -100,7 +100,7 @@ def start_server(self): self.server = Popen( ["kubectl", "logs", "-f", "rpc-0"], stdout=PIPE, - stderr=STDOUT, + stderr=PIPE, bufsize=1, universal_newlines=True, ) From d99c17b4ade39d0d3ac4b819abd7fffe49478168 Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:05:35 -0500 Subject: [PATCH 02/18] introduce assert_log --- test/test_base.py | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/test/test_base.py b/test/test_base.py index d19d099f0..4b49335e0 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -3,6 +3,7 @@ import logging import logging.config import os +import re import threading from pathlib import Path from subprocess import PIPE, Popen, run @@ -176,3 +177,26 @@ def get_scenario_return_code(self, scenario_name): if len(scns) == 0: raise Exception(f"Scenario {scenario_name} not found in running scenarios") return scns[0]["return_code"] + + +def assert_equal(thing1, thing2, *args): + if thing1 != thing2 or any(thing1 != arg for arg in args): + raise AssertionError( + "not({})".format(" == ".join(str(arg) for arg in (thing1, thing2) + args)) + ) + + +def assert_log(log_message, expected_msgs, unexpected_msgs=None) -> bool: + if unexpected_msgs is None: + unexpected_msgs = [] + assert_equal(type(expected_msgs), list) + assert_equal(type(unexpected_msgs), list) + + found = True + for unexpected_msg in unexpected_msgs: + if re.search(re.escape(unexpected_msg), log_message, flags=re.MULTILINE): + raise AssertionError(f"Unexpected message found in log: {unexpected_msg}") + for expected_msg in expected_msgs: + if re.search(re.escape(expected_msg), log_message, flags=re.MULTILINE) is None: + found = False + return found From f23ff7baa4b71bff7027e54618877dafc3f53b47 Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:07:10 -0500 Subject: [PATCH 03/18] add handling of message asserts Also, print as usual --- test/test_base.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/test/test_base.py b/test/test_base.py index 4b49335e0..afd7da3f0 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -21,6 +21,9 @@ def __init__(self): self.setup_environment() self.setup_logging() atexit.register(self.cleanup) + self.log_expected_msgs: None | [str] = None + self.log_unexpected_msgs: None | [str] = None + self.log_msg_assertions_passed = False self.log.info("Warnet test base initialized") def setup_environment(self): @@ -43,6 +46,15 @@ def setup_logging(self): self.log = logging.getLogger("test") self.log.info("Logging started") + def print_and_assert_msgs(self, message): + if ( + self.log_expected_msgs + or self.log_unexpected_msgs + and assert_log(self.log_expected_msgs, self.log_unexpected_msgs) + ): + self.log_msg_assertions_passed = True + print(message) + def cleanup(self, signum=None, frame=None): if self.server is None: return From 2f8e64cfcf253f273d200409e36e65dcdc24ed34 Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:08:17 -0500 Subject: [PATCH 04/18] incorporate printing and asserting into thread --- test/test_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_base.py b/test/test_base.py index afd7da3f0..4bec08de1 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -119,7 +119,7 @@ def start_server(self): ) self.server_thread = threading.Thread( - target=self.output_reader, args=(self.server.stdout, print) + target=self.output_reader, args=(self.server.stdout, self.print_and_assert_msgs) ) self.server_thread.daemon = True self.server_thread.start() From 040a566c1c7a317792cf96ce16346ad7bd7a9b05 Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:08:47 -0500 Subject: [PATCH 05/18] add easy assertion instance method --- test/test_base.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/test/test_base.py b/test/test_base.py index 4bec08de1..179b3bcf5 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -55,6 +55,11 @@ def print_and_assert_msgs(self, message): self.log_msg_assertions_passed = True print(message) + def assert_log_msgs_passed(self): + assert ( + self.log_msg_assertions_passed + ), f"Log assertion failed: {self.log_expected_msgs}, {self.log_unexpected_msgs}" + def cleanup(self, signum=None, frame=None): if self.server is None: return From 8742f7a3423f7ccc3905df20a46e17e370848979 Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:09:31 -0500 Subject: [PATCH 06/18] incorporate assert_log into test --- test/dag_connection_test.py | 24 ++++++------------------ 1 file changed, 6 insertions(+), 18 deletions(-) diff --git a/test/dag_connection_test.py b/test/dag_connection_test.py index feecbf290..cb4ecc120 100755 --- a/test/dag_connection_test.py +++ b/test/dag_connection_test.py @@ -1,7 +1,6 @@ #!/usr/bin/env python3 import os -import time from pathlib import Path from test_base import TestBase @@ -13,7 +12,6 @@ def __init__(self): self.graph_file_path = ( Path(os.path.dirname(__file__)) / "data" / "ten_semi_unconnected.graphml" ) - self.scenario_timeout = 180 # seconds def run_test(self): self.start_server() @@ -32,23 +30,13 @@ def setup_network(self): def run_connect_dag_scenario(self): self.log.info("Running connect_dag scenario") self.warcli("scenarios run-file test/framework_tests/connect_dag.py") - - start_time = time.time() - while time.time() - start_time < self.scenario_timeout: - running_scenarios = self.rpc("scenarios_list_running") - if not running_scenarios: - self.log.info("Scenario completed successfully") - return - - if len(running_scenarios) == 1 and not running_scenarios[0]["active"]: - self.log.info("Scenario completed successfully") - return - - time.sleep(1) - - self.log.error(f"Scenario did not complete within {self.scenario_timeout} seconds") + self.log_expected_msgs = [ + "Successfully ran the connect_dag.py scenario using a temporary file" + ] + self.log_unexpected_msgs = ["Test failed."] + self.wait_for_all_scenarios() + self.assert_log_msgs_passed() self.stop_running_scenario() - raise AssertionError(f"Scenario timed out after {self.scenario_timeout} seconds") def stop_running_scenario(self): running_scenarios = self.rpc("scenarios_list_running") From d8d2184cbbfa57a14762cc4450fad3a04e2fe616 Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:55:17 -0500 Subject: [PATCH 07/18] remove stop running scenario function --- test/dag_connection_test.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/test/dag_connection_test.py b/test/dag_connection_test.py index cb4ecc120..6e87b794b 100755 --- a/test/dag_connection_test.py +++ b/test/dag_connection_test.py @@ -36,14 +36,6 @@ def run_connect_dag_scenario(self): self.log_unexpected_msgs = ["Test failed."] self.wait_for_all_scenarios() self.assert_log_msgs_passed() - self.stop_running_scenario() - - def stop_running_scenario(self): - running_scenarios = self.rpc("scenarios_list_running") - if running_scenarios: - pid = running_scenarios[0]["pid"] - self.log.warning(f"Stopping scenario with PID {pid}") - self.warcli(f"scenarios stop {pid}", False) if __name__ == "__main__": From c1c6d279a9b84b961c5dd4fb19d807cd71178edf Mon Sep 17 00:00:00 2001 From: Grant Date: Thu, 11 Jul 2024 14:09:19 -0500 Subject: [PATCH 08/18] grammar nit --- test/test_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_base.py b/test/test_base.py index 179b3bcf5..e16092031 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -112,7 +112,7 @@ def start_server(self): # TODO: check for conflicting warnet process # maybe also ensure that no conflicting docker networks exist - # For kubernetes we assume the server is started outside test base + # For kubernetes we assume the server is started outside test base, # but we can still read its log output self.log.info("Starting Warnet server") self.server = Popen( From b35cfb25f760c27fcf59c648a9be881b06dfd9e4 Mon Sep 17 00:00:00 2001 From: Grant Date: Fri, 12 Jul 2024 14:27:32 -0500 Subject: [PATCH 09/18] fix assert_log and boolean logic --- test/test_base.py | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/test/test_base.py b/test/test_base.py index e16092031..22da82e85 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -47,10 +47,8 @@ def setup_logging(self): self.log.info("Logging started") def print_and_assert_msgs(self, message): - if ( - self.log_expected_msgs - or self.log_unexpected_msgs - and assert_log(self.log_expected_msgs, self.log_unexpected_msgs) + if (self.log_expected_msgs or self.log_unexpected_msgs) and assert_log( + message, self.log_expected_msgs, self.log_unexpected_msgs ): self.log_msg_assertions_passed = True print(message) From be345fe9bebda34c0b51f277b9bfe7c5ed4f3c0d Mon Sep 17 00:00:00 2001 From: Grant Date: Fri, 12 Jul 2024 14:42:10 -0500 Subject: [PATCH 10/18] add "since" to clear messages --- test/test_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_base.py b/test/test_base.py index 22da82e85..bcb780f0f 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -114,7 +114,7 @@ def start_server(self): # but we can still read its log output self.log.info("Starting Warnet server") self.server = Popen( - ["kubectl", "logs", "-f", "rpc-0"], + ["kubectl", "logs", "-f", "rpc-0", "--since=1s"], stdout=PIPE, stderr=PIPE, bufsize=1, From c6539c62f8eebe08c8b2e8b1e04fb88e4e6f6b0f Mon Sep 17 00:00:00 2001 From: mplsgrant <58152638+mplsgrant@users.noreply.github.com> Date: Fri, 12 Jul 2024 15:58:38 -0500 Subject: [PATCH 11/18] make assert message explicit Co-authored-by: Matthew Zipkin --- test/test_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_base.py b/test/test_base.py index bcb780f0f..4ea43c28d 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -56,7 +56,7 @@ def print_and_assert_msgs(self, message): def assert_log_msgs_passed(self): assert ( self.log_msg_assertions_passed - ), f"Log assertion failed: {self.log_expected_msgs}, {self.log_unexpected_msgs}" + ), f"Log assertion failed. Expected message not found: {self.log_expected_msgs}" def cleanup(self, signum=None, frame=None): if self.server is None: From 9f2279e70e3525d0f7275a30ae302a87ded19d34 Mon Sep 17 00:00:00 2001 From: Grant Date: Fri, 12 Jul 2024 19:48:53 -0500 Subject: [PATCH 12/18] reset assertions_passed status --- test/test_base.py | 1 + 1 file changed, 1 insertion(+) diff --git a/test/test_base.py b/test/test_base.py index 4ea43c28d..d2478f666 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -57,6 +57,7 @@ def assert_log_msgs_passed(self): assert ( self.log_msg_assertions_passed ), f"Log assertion failed. Expected message not found: {self.log_expected_msgs}" + self.log_msg_assertions_passed = False def cleanup(self, signum=None, frame=None): if self.server is None: From d4fde4a00f0190cc55096f405813c44e681c3564 Mon Sep 17 00:00:00 2001 From: Grant Date: Fri, 12 Jul 2024 20:22:24 -0500 Subject: [PATCH 13/18] add a post-connection run This second run includes slightly modified expected and unexpected messages --- test/dag_connection_test.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/test/dag_connection_test.py b/test/dag_connection_test.py index 6e87b794b..7367c1323 100755 --- a/test/dag_connection_test.py +++ b/test/dag_connection_test.py @@ -18,6 +18,7 @@ def run_test(self): try: self.setup_network() self.run_connect_dag_scenario() + self.run_connect_dag_scenario_post_connection() finally: self.stop_server() @@ -37,6 +38,14 @@ def run_connect_dag_scenario(self): self.wait_for_all_scenarios() self.assert_log_msgs_passed() + def run_connect_dag_scenario_post_connection(self): + self.log.info("Running connect_dag scenario") + self.warcli("scenarios run-file test/framework_tests/connect_dag.py") + self.log_expected_msgs = ["Successfully ran the connect_dag.py scenario"] + self.log_unexpected_msgs = ["Test failed"] + self.wait_for_all_scenarios() + self.assert_log_msgs_passed() + if __name__ == "__main__": test = DAGConnectionTest() From 9e16a20b4585865adf72410f4f7218b72bf186d0 Mon Sep 17 00:00:00 2001 From: Grant Date: Sat, 13 Jul 2024 11:32:55 -0500 Subject: [PATCH 14/18] make _print_and_assert_msgs private --- test/test_base.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/test_base.py b/test/test_base.py index d2478f666..d1bc4013f 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -46,7 +46,7 @@ def setup_logging(self): self.log = logging.getLogger("test") self.log.info("Logging started") - def print_and_assert_msgs(self, message): + def _print_and_assert_msgs(self, message): if (self.log_expected_msgs or self.log_unexpected_msgs) and assert_log( message, self.log_expected_msgs, self.log_unexpected_msgs ): @@ -123,7 +123,7 @@ def start_server(self): ) self.server_thread = threading.Thread( - target=self.output_reader, args=(self.server.stdout, self.print_and_assert_msgs) + target=self.output_reader, args=(self.server.stdout, self._print_and_assert_msgs) ) self.server_thread.daemon = True self.server_thread.start() From 52f04c9357eaee7acbd01a30b1a2163c6a72754a Mon Sep 17 00:00:00 2001 From: Grant Date: Sat, 13 Jul 2024 11:33:33 -0500 Subject: [PATCH 15/18] rename to assert_log_msgs --- test/dag_connection_test.py | 4 ++-- test/test_base.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/test/dag_connection_test.py b/test/dag_connection_test.py index 7367c1323..508a38fac 100755 --- a/test/dag_connection_test.py +++ b/test/dag_connection_test.py @@ -36,7 +36,7 @@ def run_connect_dag_scenario(self): ] self.log_unexpected_msgs = ["Test failed."] self.wait_for_all_scenarios() - self.assert_log_msgs_passed() + self.assert_log_msgs() def run_connect_dag_scenario_post_connection(self): self.log.info("Running connect_dag scenario") @@ -44,7 +44,7 @@ def run_connect_dag_scenario_post_connection(self): self.log_expected_msgs = ["Successfully ran the connect_dag.py scenario"] self.log_unexpected_msgs = ["Test failed"] self.wait_for_all_scenarios() - self.assert_log_msgs_passed() + self.assert_log_msgs() if __name__ == "__main__": diff --git a/test/test_base.py b/test/test_base.py index d1bc4013f..a3b6f29e0 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -53,7 +53,7 @@ def _print_and_assert_msgs(self, message): self.log_msg_assertions_passed = True print(message) - def assert_log_msgs_passed(self): + def assert_log_msgs(self): assert ( self.log_msg_assertions_passed ), f"Log assertion failed. Expected message not found: {self.log_expected_msgs}" From f9c57132dd5fc07b7176591161c2d99d8e2dcb34 Mon Sep 17 00:00:00 2001 From: Grant Date: Sat, 13 Jul 2024 11:35:19 -0500 Subject: [PATCH 16/18] set log msgs before running the scenario --- test/dag_connection_test.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/dag_connection_test.py b/test/dag_connection_test.py index 508a38fac..dba9b8bfb 100755 --- a/test/dag_connection_test.py +++ b/test/dag_connection_test.py @@ -30,19 +30,19 @@ def setup_network(self): def run_connect_dag_scenario(self): self.log.info("Running connect_dag scenario") - self.warcli("scenarios run-file test/framework_tests/connect_dag.py") self.log_expected_msgs = [ "Successfully ran the connect_dag.py scenario using a temporary file" ] self.log_unexpected_msgs = ["Test failed."] + self.warcli("scenarios run-file test/framework_tests/connect_dag.py") self.wait_for_all_scenarios() self.assert_log_msgs() def run_connect_dag_scenario_post_connection(self): self.log.info("Running connect_dag scenario") - self.warcli("scenarios run-file test/framework_tests/connect_dag.py") self.log_expected_msgs = ["Successfully ran the connect_dag.py scenario"] self.log_unexpected_msgs = ["Test failed"] + self.warcli("scenarios run-file test/framework_tests/connect_dag.py") self.wait_for_all_scenarios() self.assert_log_msgs() From 96c7978c1e978abb3e2bd79bc7209a7cdf587350 Mon Sep 17 00:00:00 2001 From: Grant Date: Sat, 13 Jul 2024 11:36:13 -0500 Subject: [PATCH 17/18] move msgs functions below the setup/cleanup funcs --- test/test_base.py | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/test/test_base.py b/test/test_base.py index a3b6f29e0..e8ae320d8 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -46,19 +46,6 @@ def setup_logging(self): self.log = logging.getLogger("test") self.log.info("Logging started") - def _print_and_assert_msgs(self, message): - if (self.log_expected_msgs or self.log_unexpected_msgs) and assert_log( - message, self.log_expected_msgs, self.log_unexpected_msgs - ): - self.log_msg_assertions_passed = True - print(message) - - def assert_log_msgs(self): - assert ( - self.log_msg_assertions_passed - ), f"Log assertion failed. Expected message not found: {self.log_expected_msgs}" - self.log_msg_assertions_passed = False - def cleanup(self, signum=None, frame=None): if self.server is None: return @@ -76,6 +63,19 @@ def cleanup(self, signum=None, frame=None): self.server_thread.join() self.server = None + def _print_and_assert_msgs(self, message): + if (self.log_expected_msgs or self.log_unexpected_msgs) and assert_log( + message, self.log_expected_msgs, self.log_unexpected_msgs + ): + self.log_msg_assertions_passed = True + print(message) + + def assert_log_msgs(self): + assert ( + self.log_msg_assertions_passed + ), f"Log assertion failed. Expected message not found: {self.log_expected_msgs}" + self.log_msg_assertions_passed = False + def warcli(self, cmd, network=True): self.log.debug(f"Executing warcli command: {cmd}") command = ["warcli"] + cmd.split() From 4098f6eb97e223b462d0c348af593211073884db Mon Sep 17 00:00:00 2001 From: Grant Date: Mon, 15 Jul 2024 09:25:39 -0500 Subject: [PATCH 18/18] move print above the assertion --- test/test_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_base.py b/test/test_base.py index e8ae320d8..2591cb69f 100644 --- a/test/test_base.py +++ b/test/test_base.py @@ -64,11 +64,11 @@ def cleanup(self, signum=None, frame=None): self.server = None def _print_and_assert_msgs(self, message): + print(message) if (self.log_expected_msgs or self.log_unexpected_msgs) and assert_log( message, self.log_expected_msgs, self.log_unexpected_msgs ): self.log_msg_assertions_passed = True - print(message) def assert_log_msgs(self): assert (