From 2dc1fa44e7b4cb9ab532a688294a5d54722e5765 Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Fri, 12 Jan 2024 17:03:12 -0800 Subject: [PATCH 1/9] Make unique traceback message for easier grepping. --- framework/test_cases/base_testcase.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index d2990323..63666932 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -58,7 +58,8 @@ def _print_error_list( # the TestCase.assert*() methods. for err in errors: logging.error( - "%s Traceback in %s:\n%s", + "%s PSM Interop test failed: %s. PSM Traceback BEGIN \n%s" + "\nPSM Traceback END", "ERROR" if is_unexpected_error else "FAILURE", self.id(), err, From 4f0b578ba0645c136a8489570aa649388ad36156 Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Wed, 17 Jan 2024 16:56:36 -0800 Subject: [PATCH 2/9] Output improvements --- framework/test_cases/base_testcase.py | 44 +++++++++++++----- tests/fake_test.py | 66 +++++++++++++++++++++++++++ 2 files changed, 99 insertions(+), 11 deletions(-) create mode 100644 tests/fake_test.py diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index 63666932..f98e4f09 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -36,31 +36,53 @@ def run(self, result: Optional[unittest.TestResult] = None) -> None: ) # Assume one test case will only have one status. if test_errors or test_failures: - logging.info("----- TestCase %s FAILED -----", self.id()) + logging.info("----- TestCase %s FAILED -----", self.test_name) if test_errors: self._print_error_list(test_errors, is_unexpected_error=True) if test_failures: self._print_error_list(test_failures) elif test_unexpected_successes: logging.info( - "----- TestCase %s UNEXPECTEDLY SUCCEEDED -----", self.id() + "----- TestCase %s UNEXPECTEDLY SUCCEEDED -----\n", + self.test_name, ) elif test_skipped: - logging.info("----- TestCase %s SKIPPED -----", self.id()) + logging.info("----- TestCase %s SKIPPED -----\n", self.test_name) logging.info("Reason for skipping: %s", test_skipped) else: - logging.info("----- TestCase %s PASSED -----", self.id()) + logging.info("----- TestCase %s PASSED -----\n", self.test_name) + + @property + def test_name(self) -> str: + # Test id returned from self.id() can have two forms: + # 1. Regular: __main__.MyClassTest.test_method + # 2. Parametrized: __main__.MyClassTest.test_method{case} ('param'), + # where {case} is + # a) An integer for @parameterized.parameters: test_method0, + # test_method1, ... + # b) {testcase_name} for @parameterized.named_parameters: + # test_method_pass, test_method_fail, ... + # + # This method: + # 1. Removes "__main__." if it's present + # 2. Removes the " ('param')" if present + return self.id().removeprefix("__main__.").split(" ", 1)[0] def _print_error_list( self, errors: list[str], is_unexpected_error: bool = False ) -> None: - # FAILUREs are those errors explicitly signalled using - # the TestCase.assert*() methods. + # FAILURE is an errors explicitly signalled using one of the + # TestCase.assert*() methods, while ERROR means an unexpected exception. + fail_type: str = "ERROR" if is_unexpected_error else "FAILURE" for err in errors: logging.error( - "%s PSM Interop test failed: %s. PSM Traceback BEGIN \n%s" - "\nPSM Traceback END", - "ERROR" if is_unexpected_error else "FAILURE", - self.id(), - err, + "(%(fail_type)s) PSM Interop Test Failed: %(test_id)s" + "\n%(test_id)s | PSM Failed Test Traceback BEGIN" + "\n\n%(error)s" + "\n%(test_id)s | PSM Failed Test Traceback END\n", + { + "test_id": self.test_name, + "fail_type": fail_type, + "error": err, + }, ) diff --git a/tests/fake_test.py b/tests/fake_test.py new file mode 100644 index 00000000..0abd2438 --- /dev/null +++ b/tests/fake_test.py @@ -0,0 +1,66 @@ +# Copyright 2024 gRPC authors. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +import logging + +from absl import flags +from absl.testing import absltest +from absl.testing import parameterized + +from framework import xds_k8s_testcase + +logger = logging.getLogger(__name__) +flags.adopt_module_key_flags(xds_k8s_testcase) + + +class FakeTest(xds_k8s_testcase.XdsKubernetesBaseTestCase): + """A fake test with known failures to debug BaseTestCase logs. + + This test case won't do any infra provisioning, just parses the flags and + reads k8s contexts file. + """ + + def test_0_pass(self): + self.assertTrue(True, "I'm a passing test in the beginning") + + def test_1_error(self): + self.assertTrue(False, msg="Test 1 Assertion ERROR") + + def test_2_pass(self): + self.assertTrue(True, "I'm a passing test in the middle") + + def test_3_failure(self): + raise RuntimeError("Test 3 Uncaught Exception FAILURE") + + def test_4_pass(self): + self.assertTrue(True, "I'm a passing test at the end") + + +class FakeTestParametrized( + xds_k8s_testcase.XdsKubernetesBaseTestCase, + parameterized.TestCase, +): + @parameterized.parameters(True, False) + def test_true(self, is_true): + self.assertTrue(is_true) + + @parameterized.named_parameters( + {"testcase_name": "pass", "is_true": True}, + {"testcase_name": "fail", "is_true": False}, + ) + def test_true_named(self, is_true): + self.assertTrue(is_true) + + +if __name__ == "__main__": + absltest.main() From b75a1c699627929e5cfd4b8146fb452070ed9438 Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Wed, 17 Jan 2024 18:20:56 -0800 Subject: [PATCH 3/9] Minor formatting improvements --- framework/test_cases/base_testcase.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index f98e4f09..6c9d3c09 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -77,9 +77,10 @@ def _print_error_list( for err in errors: logging.error( "(%(fail_type)s) PSM Interop Test Failed: %(test_id)s" - "\n%(test_id)s | PSM Failed Test Traceback BEGIN" - "\n\n%(error)s" - "\n%(test_id)s | PSM Failed Test Traceback END\n", + "\n^^^^^" + "\n[%(test_id)s] PSM Failed Test Traceback BEGIN" + "\n%(error)s" + "[%(test_id)s] PSM Failed Test Traceback END\n", { "test_id": self.test_name, "fail_type": fail_type, From cf181255b0ba7b59986867259e1e1254cdfc27a4 Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Wed, 17 Jan 2024 18:23:42 -0800 Subject: [PATCH 4/9] failures log level --- framework/test_cases/base_testcase.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index 6c9d3c09..affd0e5f 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -36,13 +36,13 @@ def run(self, result: Optional[unittest.TestResult] = None) -> None: ) # Assume one test case will only have one status. if test_errors or test_failures: - logging.info("----- TestCase %s FAILED -----", self.test_name) + logging.error("----- TestCase %s FAILED -----", self.test_name) if test_errors: self._print_error_list(test_errors, is_unexpected_error=True) if test_failures: self._print_error_list(test_failures) elif test_unexpected_successes: - logging.info( + logging.error( "----- TestCase %s UNEXPECTEDLY SUCCEEDED -----\n", self.test_name, ) From df5dc0f4b1f29d018f5448dddd61a30c8fe50679 Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Wed, 17 Jan 2024 18:30:50 -0800 Subject: [PATCH 5/9] some more formatting --- framework/test_cases/base_testcase.py | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index affd0e5f..0f9a0a15 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -36,21 +36,30 @@ def run(self, result: Optional[unittest.TestResult] = None) -> None: ) # Assume one test case will only have one status. if test_errors or test_failures: - logging.error("----- TestCase %s FAILED -----", self.test_name) + logging.error( + "----- PSM Test Case FAILED: %s -----", self.test_name + ) if test_errors: self._print_error_list(test_errors, is_unexpected_error=True) if test_failures: self._print_error_list(test_failures) elif test_unexpected_successes: logging.error( - "----- TestCase %s UNEXPECTEDLY SUCCEEDED -----\n", + "----- PSM Test Case UNEXPECTEDLY SUCCEEDED: %s -----\n", self.test_name, ) elif test_skipped: - logging.info("----- TestCase %s SKIPPED -----\n", self.test_name) - logging.info("Reason for skipping: %s", test_skipped) + logging.info( + "----- PSM Test Case SKIPPED: %s -----" + "\nReason for skipping: %s", + self.test_name, + test_skipped, + ) else: - logging.info("----- TestCase %s PASSED -----\n", self.test_name) + logging.info( + "----- PSM Test Case PASSED: %s -----\n", + self.test_name, + ) @property def test_name(self) -> str: From 3cb977ee035dd2bd999a741f3fbcc730d9ed9cc2 Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Thu, 18 Jan 2024 10:48:53 -0800 Subject: [PATCH 6/9] Add error count, notes, and use self.test_name in subTest, tearDown --- framework/test_cases/base_testcase.py | 8 ++++++-- framework/xds_k8s_testcase.py | 13 ++++++++++--- tests/fake_test.py | 11 ++++++++++- 3 files changed, 26 insertions(+), 6 deletions(-) diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index 0f9a0a15..245c009a 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -22,7 +22,8 @@ class BaseTestCase(absltest.TestCase): def run(self, result: Optional[unittest.TestResult] = None) -> None: - super().run(result) + # TODO(sergiitk): should this method be returning result? See + # super().run and xds_k8s_testcase.XdsKubernetesBaseTestCase.subTest test_errors = [error for test, error in result.errors if test is self] test_failures = [ failure for test, failure in result.failures if test is self @@ -36,8 +37,11 @@ def run(self, result: Optional[unittest.TestResult] = None) -> None: ) # Assume one test case will only have one status. if test_errors or test_failures: + total_errors = len(test_errors) + len(test_failures) logging.error( - "----- PSM Test Case FAILED: %s -----", self.test_name + "----- PSM Test Case FAILED: %s%s -----", + self.test_name, + f" | Errors count: {total_errors}" if total_errors > 1 else "", ) if test_errors: self._print_error_list(test_errors, is_unexpected_error=True) diff --git a/framework/xds_k8s_testcase.py b/framework/xds_k8s_testcase.py index 55743de1..00fc125e 100644 --- a/framework/xds_k8s_testcase.py +++ b/framework/xds_k8s_testcase.py @@ -252,6 +252,7 @@ def setUp(self): def handle_sigint( self, signalnum: _SignalNum, frame: Optional[FrameType] ) -> None: + # TODO(sergiitk): move to base_testcase.BaseTestCase logger.info("Caught Ctrl+C, cleaning up...") self._handling_sigint = True # Force resource cleanup by their name. Addresses the case where ctrl-c @@ -266,12 +267,18 @@ def handle_sigint( @contextlib.contextmanager def subTest(self, msg, **params): # noqa pylint: disable=signature-differs - logger.info("--- Starting subTest %s.%s ---", self.id(), msg) + # TODO(sergiitk): move to base_testcase.BaseTestCase + # Important side-effect: this halts test execution on first subtest + # failure, even if failfast is enabled. + # TODO(sergiitk): This is desired, but not understood. Figure out why. + logger.info("--- Starting subTest %s.%s ---", self.test_name, msg) try: yield super().subTest(msg, **params) finally: if not self._handling_sigint: - logger.info("--- Finished subTest %s.%s ---", self.id(), msg) + logger.info( + "--- Finished subTest %s.%s ---", self.test_name, msg + ) def setupTrafficDirectorGrpc(self): self.td.setup_for_grpc( @@ -684,7 +691,7 @@ def initKubernetesClientRunner(self) -> KubernetesClientRunner: raise NotImplementedError def tearDown(self): - logger.info("----- TestMethod %s teardown -----", self.id()) + logger.info("----- TestMethod %s teardown -----", self.test_name) logger.debug("Getting pods restart times") client_restarts: int = 0 server_restarts: int = 0 diff --git a/tests/fake_test.py b/tests/fake_test.py index 0abd2438..7f7e0670 100644 --- a/tests/fake_test.py +++ b/tests/fake_test.py @@ -46,7 +46,7 @@ def test_4_pass(self): self.assertTrue(True, "I'm a passing test at the end") -class FakeTestParametrized( +class FakeParametrizedTest( xds_k8s_testcase.XdsKubernetesBaseTestCase, parameterized.TestCase, ): @@ -62,5 +62,14 @@ def test_true_named(self, is_true): self.assertTrue(is_true) +class FakeSubtestTest(xds_k8s_testcase.XdsKubernetesBaseTestCase): + # TODO(sergiitk): add subtest examples + def test_even(self): + for num in range(0, 6): + with self.subTest(i=num, msg=f"num_{num}"): + if num & 1: + self.fail(f"Integer {num} is odd") + + if __name__ == "__main__": absltest.main() From f9dc0624fe43359e140b88d96b6a604770ccedbd Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Thu, 18 Jan 2024 11:31:51 -0800 Subject: [PATCH 7/9] Fix accidentally removed super().run(result) --- framework/test_cases/base_testcase.py | 1 + 1 file changed, 1 insertion(+) diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index 245c009a..66ced39d 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -22,6 +22,7 @@ class BaseTestCase(absltest.TestCase): def run(self, result: Optional[unittest.TestResult] = None) -> None: + super().run(result) # TODO(sergiitk): should this method be returning result? See # super().run and xds_k8s_testcase.XdsKubernetesBaseTestCase.subTest test_errors = [error for test, error in result.errors if test is self] From c00c60191b7ba8cd01b192be8b95ea3a74c09b9e Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Thu, 18 Jan 2024 16:19:24 -0800 Subject: [PATCH 8/9] Replace missing self.id() --- tests/bootstrap_generator_test.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/bootstrap_generator_test.py b/tests/bootstrap_generator_test.py index ef6ef14e..dba6e1f7 100644 --- a/tests/bootstrap_generator_test.py +++ b/tests/bootstrap_generator_test.py @@ -130,7 +130,7 @@ def tearDownClass(cls): super().tearDownClass() def tearDown(self): - logger.info("----- TestMethod %s teardown -----", self.id()) + logger.info("----- TestMethod %s teardown -----", self.test_name) retryer = retryers.constant_retryer( wait_fixed=_timedelta(seconds=10), attempts=3, @@ -175,7 +175,7 @@ class BootstrapGeneratorServerTest( test_server: XdsTestServer def tearDown(self): - logger.info("----- TestMethod %s teardown -----", self.id()) + logger.info("----- TestMethod %s teardown -----", self.test_name) retryer = retryers.constant_retryer( wait_fixed=_timedelta(seconds=10), attempts=3, From 60c4a14bea46d20ddee3e1124181dabadd3eb6bd Mon Sep 17 00:00:00 2001 From: Sergii Tkachenko Date: Thu, 18 Jan 2024 16:23:11 -0800 Subject: [PATCH 9/9] Add some docs --- framework/test_cases/base_testcase.py | 27 +++++++++++++++------------ tests/fake_test.py | 13 +++++++++++-- 2 files changed, 26 insertions(+), 14 deletions(-) diff --git a/framework/test_cases/base_testcase.py b/framework/test_cases/base_testcase.py index 66ced39d..f2dbcab4 100644 --- a/framework/test_cases/base_testcase.py +++ b/framework/test_cases/base_testcase.py @@ -68,18 +68,21 @@ def run(self, result: Optional[unittest.TestResult] = None) -> None: @property def test_name(self) -> str: - # Test id returned from self.id() can have two forms: - # 1. Regular: __main__.MyClassTest.test_method - # 2. Parametrized: __main__.MyClassTest.test_method{case} ('param'), - # where {case} is - # a) An integer for @parameterized.parameters: test_method0, - # test_method1, ... - # b) {testcase_name} for @parameterized.named_parameters: - # test_method_pass, test_method_fail, ... - # - # This method: - # 1. Removes "__main__." if it's present - # 2. Removes the " ('param')" if present + """Pretty test name (details in the description). + + Test id returned from self.id() can have two forms: + 1. Regular: __main__.MyClassTest.test_method + 2. Parametrized: __main__.MyClassTest.test_method{case} ('param'), + where {case} is + a) An integer for @parameterized.parameters: test_method0, + test_method1, ... + b) {testcase_name} for @parameterized.named_parameters: + test_method_pass, test_method_fail, ... + + This method: + 1. Removes "__main__." if it's present + 2. Removes the " ('param')" if present + """ return self.id().removeprefix("__main__.").split(" ", 1)[0] def _print_error_list( diff --git a/tests/fake_test.py b/tests/fake_test.py index 7f7e0670..7be8fc6a 100644 --- a/tests/fake_test.py +++ b/tests/fake_test.py @@ -24,7 +24,7 @@ class FakeTest(xds_k8s_testcase.XdsKubernetesBaseTestCase): - """A fake test with known failures to debug BaseTestCase logs. + """A fake test class with known failures to debug BaseTestCase logs. This test case won't do any infra provisioning, just parses the flags and reads k8s contexts file. @@ -50,6 +50,11 @@ class FakeParametrizedTest( xds_k8s_testcase.XdsKubernetesBaseTestCase, parameterized.TestCase, ): + """A fake class to debug BaseTestCase logs produced by parametrized tests. + + See FakeTest for notes on provisioning. + """ + @parameterized.parameters(True, False) def test_true(self, is_true): self.assertTrue(is_true) @@ -63,7 +68,11 @@ def test_true_named(self, is_true): class FakeSubtestTest(xds_k8s_testcase.XdsKubernetesBaseTestCase): - # TODO(sergiitk): add subtest examples + """A fake class to debug BaseTestCase logs produced by tests with subtests. + + See FakeTest for notes on provisioning. + """ + def test_even(self): for num in range(0, 6): with self.subTest(i=num, msg=f"num_{num}"):