Make test failure messages/tracebacks unique to PSM Interop #21

sergiitk · 2024-01-17T23:30:44Z

This PR:

Make test failure messages/tracebacks unique to PSM Interop to allow for easier grepping/matchers (more details below.
Replaces self.id() calls in the framework logs with custom self.test_name. For example,
--- Starting subTest __main__.AppNetTest.test_ping_pong.0_create_health_check ---
becomes
--- Starting subTest AppNetTest.test_ping_pong.0_create_health_check ---.
Changes the log level of ----- TestCase ... FAILED ----- message from info to error.
Adds FakeTest to make future work on the log messages easier

The new error format:

E0118 09:59:38.289015 140704433060736 base_testcase.py:39] ----- PSM Test Case FAILED: ClassName.test_method -----
E0118 09:59:38.289084 140704433060736 base_testcase.py:87] ($failure_type) PSM Interop Test Failed: ClassName.test_method
^^^^^
[ClassName.test_method] PSM Failed Test Traceback BEGIN
Traceback (most recent call last):
...
AssertionError: description
[ClassName.test_method] PSM Failed Test Traceback END

This format will allow us to drastically simplify buggrep matchers that search within the stack traces of our framework, which also resulted in a test failure (e.g. didn't recover after retrying).
Now we can do a plain-text grep for PSM Failed Test Traceback BEGIN instead of an extended regex grep for E[0-9]{4}.*base_testcase.*ERROR Traceback in.
Text PSM Failed Test Traceback BEGIN is guaranteed to be only produced on test failure. Additionally, this allows to restrict matchers to a specific test in the same swoop, just do a plain-text search for [TestClass.test_method] PSM Failed Test Traceback BEGIN.

Initial PR that added the traceback: grpc/grpc#34023.

Examples

Click here for log examples

Regular

❯ ./run.sh tests/fake_test.py FakeTest
Running tests under Python 3.9.18: /Users/sergiitk/Development/psm-interop/venv/bin/python
I0118 09:59:38.165148 140704433060736 xds_k8s_testcase.py:157] ----- Testing FakeTest -----
I0118 09:59:38.165239 140704433060736 xds_k8s_testcase.py:158] Logs timezone: PST
I0118 09:59:38.165450 140704433060736 xds_k8s_testcase.py:106] Detected language and version: TestConfig(client_lang='cpp', server_lang='cpp', version=None)
I0118 09:59:38.278228 140704433060736 k8s.py:243] Using kubernetes context "gke_sergiitk-grpc-gke_us-west1-a_sergii-gamma", active host: https://34.83.62.236
[ RUN      ] FakeTest.test_0_pass
[       OK ] FakeTest.test_0_pass
I0118 09:59:38.288280 140704433060736 base_testcase.py:59] ----- PSM Test Case PASSED: FakeTest.test_0_pass -----

[ RUN      ] FakeTest.test_1_error
[  FAILED  ] FakeTest.test_1_error
E0118 09:59:38.289015 140704433060736 base_testcase.py:39] ----- PSM Test Case FAILED: FakeTest.test_1_error -----
E0118 09:59:38.289084 140704433060736 base_testcase.py:87] (FAILURE) PSM Interop Test Failed: FakeTest.test_1_error
^^^^^
[FakeTest.test_1_error] PSM Failed Test Traceback BEGIN
Traceback (most recent call last):
  File "/Users/sergiitk/Development/psm-interop/tests/fake_test.py", line 37, in test_1_error
    self.assertTrue(False, msg="Test 1 Assertion ERROR")
AssertionError: False is not true : Test 1 Assertion ERROR
[FakeTest.test_1_error] PSM Failed Test Traceback END

[ RUN      ] FakeTest.test_2_pass
[       OK ] FakeTest.test_2_pass
I0118 09:59:38.289330 140704433060736 base_testcase.py:59] ----- PSM Test Case PASSED: FakeTest.test_2_pass -----

[ RUN      ] FakeTest.test_3_failure
[  FAILED  ] FakeTest.test_3_failure
E0118 09:59:38.289599 140704433060736 base_testcase.py:39] ----- PSM Test Case FAILED: FakeTest.test_3_failure -----
E0118 09:59:38.289654 140704433060736 base_testcase.py:87] (ERROR) PSM Interop Test Failed: FakeTest.test_3_failure
^^^^^
[FakeTest.test_3_failure] PSM Failed Test Traceback BEGIN
Traceback (most recent call last):
  File "/Users/sergiitk/Development/psm-interop/tests/fake_test.py", line 43, in test_3_failure
    raise RuntimeError("Test 3 Uncaught Exception FAILURE")
RuntimeError: Test 3 Uncaught Exception FAILURE
[FakeTest.test_3_failure] PSM Failed Test Traceback END

[ RUN      ] FakeTest.test_4_pass
[       OK ] FakeTest.test_4_pass
I0118 09:59:38.289771 140704433060736 base_testcase.py:59] ----- PSM Test Case PASSED: FakeTest.test_4_pass -----
...

Parametrized

❯ ./run.sh tests/fake_test.py FakeTestParametrized
Running tests under Python 3.9.18: /Users/sergiitk/Development/psm-interop/venv/bin/python
I0118 10:01:10.861198 140704433060736 xds_k8s_testcase.py:157] ----- Testing FakeTestParametrized -----
I0118 10:01:10.861293 140704433060736 xds_k8s_testcase.py:158] Logs timezone: PST
I0118 10:01:10.861488 140704433060736 xds_k8s_testcase.py:106] Detected language and version: TestConfig(client_lang='cpp', server_lang='cpp', version=None)
I0118 10:01:10.967642 140704433060736 k8s.py:243] Using kubernetes context "gke_sergiitk-grpc-gke_us-west1-a_sergii-gamma", active host: https://34.83.62.236
[ RUN      ] FakeTestParametrized.test_true0 (True)
[       OK ] FakeTestParametrized.test_true0 (True)
I0118 10:01:10.975589 140704433060736 base_testcase.py:59] ----- PSM Test Case PASSED: FakeTestParametrized.test_true0 -----

[ RUN      ] FakeTestParametrized.test_true1 (False)
[  FAILED  ] FakeTestParametrized.test_true1 (False)
E0118 10:01:10.977038 140704433060736 base_testcase.py:39] ----- PSM Test Case FAILED: FakeTestParametrized.test_true1 -----
E0118 10:01:10.977118 140704433060736 base_testcase.py:87] (FAILURE) PSM Interop Test Failed: FakeTestParametrized.test_true1
^^^^^
[FakeTestParametrized.test_true1] PSM Failed Test Traceback BEGIN
Traceback (most recent call last):
  File "/Users/sergiitk/Development/psm-interop/venv/lib/python3.9/site-packages/absl/testing/parameterized.py", line 318, in bound_param_test
    return test_method(self, testcase_params)
  File "/Users/sergiitk/Development/psm-interop/tests/fake_test.py", line 55, in test_true
    self.assertTrue(is_true)
AssertionError: False is not true
[FakeTestParametrized.test_true1] PSM Failed Test Traceback END

[ RUN      ] FakeTestParametrized.test_true_named_fail
[  FAILED  ] FakeTestParametrized.test_true_named_fail
E0118 10:01:10.977355 140704433060736 base_testcase.py:39] ----- PSM Test Case FAILED: FakeTestParametrized.test_true_named_fail -----
E0118 10:01:10.977529 140704433060736 base_testcase.py:87] (FAILURE) PSM Interop Test Failed: FakeTestParametrized.test_true_named_fail
^^^^^
[FakeTestParametrized.test_true_named_fail] PSM Failed Test Traceback BEGIN
Traceback (most recent call last):
  File "/Users/sergiitk/Development/psm-interop/venv/lib/python3.9/site-packages/absl/testing/parameterized.py", line 314, in bound_param_test
    return test_method(self, **testcase_params)
  File "/Users/sergiitk/Development/psm-interop/tests/fake_test.py", line 62, in test_true_named
    self.assertTrue(is_true)
AssertionError: False is not true
[FakeTestParametrized.test_true_named_fail] PSM Failed Test Traceback END

[ RUN      ] FakeTestParametrized.test_true_named_pass
[       OK ] FakeTestParametrized.test_true_named_pass
I0118 10:01:10.977713 140704433060736 base_testcase.py:59] ----- PSM Test Case PASSED: FakeTestParametrized.test_true_named_pass -----

...

Multiple errors attached to a single test (faked):

...
[ RUN      ] FakeTest.test_3_failure
[  FAILED  ] FakeTest.test_3_failure
E0118 10:12:54.482913 140704433060736 base_testcase.py:43] ----- PSM Test Case FAILED: FakeTest.test_3_failure | Errors count: 2 -----
E0118 10:12:54.482974 140704433060736 base_testcase.py:93] (ERROR) PSM Interop Test Failed: FakeTest.test_3_failure
^^^^^
[FakeTest.test_3_failure] PSM Failed Test Traceback BEGIN
Traceback (most recent call last):
  File "/Users/sergiitk/Development/psm-interop/tests/fake_test.py", line 43, in test_3_failure
    raise RuntimeError("Test 3 Uncaught Exception FAILURE")
RuntimeError: Test 3 Uncaught Exception FAILURE
[FakeTest.test_3_failure] PSM Failed Test Traceback END

E0118 10:12:54.483037 140704433060736 base_testcase.py:93] (FAILURE) PSM Interop Test Failed: FakeTest.test_3_failure
^^^^^
[FakeTest.test_3_failure] PSM Failed Test Traceback BEGIN
Traceback (most recent call last):
  File "/Users/sergiitk/Development/psm-interop/tests/fake_test.py", line 43, in test_3_failure
    raise RuntimeError("Test 3 Uncaught Exception FAILURE")
RuntimeError: Test 3 Uncaught Exception FAILURE
[FakeTest.test_3_failure] PSM Failed Test Traceback END

[ RUN      ] FakeTest.test_4_pass
...

sergiitk · 2024-01-17T23:35:01Z

sergiitk · 2024-01-18T02:14:01Z

sergiitk · 2024-01-18T19:18:23Z

sergiitk · 2024-01-18T19:33:58Z

sergiitk · 2024-01-19T00:51:16Z

FYI @gnossen @yashykt @murgatroid99

XuanWang-Amos

Just one minor comment.

This is a great improvement, thanks for the work!

framework/test_cases/base_testcase.py

sergiitk changed the title ~~Make unique traceback message for easier grepping.~~ Make test failure messages/tracebacks unique to PSM Interop Jan 19, 2024

sergiitk marked this pull request as ready for review January 19, 2024 00:50

sergiitk requested a review from XuanWang-Amos January 19, 2024 00:50

XuanWang-Amos approved these changes Jan 19, 2024

View reviewed changes

framework/test_cases/base_testcase.py Show resolved Hide resolved

sergiitk added 9 commits January 19, 2024 11:09

Make unique traceback message for easier grepping.

2dc1fa4

Output improvements

4f0b578

Minor formatting improvements

b75a1c6

failures log level

cf18125

some more formatting

df5dc0f

Add error count, notes, and use self.test_name in subTest, tearDown

3cb977e

Fix accidentally removed super().run(result)

f9dc062

Replace missing self.id()

c00c601

Add some docs

60c4a14

sergiitk force-pushed the psm-traceback branch from 12755bf to 60c4a14 Compare January 19, 2024 19:09

sergiitk merged commit 62c8a9e into grpc:main Jan 19, 2024
6 checks passed

sergiitk deleted the psm-traceback branch January 19, 2024 19:12

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make test failure messages/tracebacks unique to PSM Interop #21

Make test failure messages/tracebacks unique to PSM Interop #21

sergiitk commented Jan 17, 2024 •

edited

Loading

sergiitk commented Jan 17, 2024 •

edited

Loading

sergiitk commented Jan 18, 2024 •

edited

Loading

sergiitk commented Jan 18, 2024

sergiitk commented Jan 18, 2024 •

edited

Loading

sergiitk commented Jan 19, 2024

XuanWang-Amos left a comment

Make test failure messages/tracebacks unique to PSM Interop #21

Make test failure messages/tracebacks unique to PSM Interop #21

Conversation

sergiitk commented Jan 17, 2024 • edited Loading

Examples

Regular

Parametrized

Multiple errors attached to a single test (faked):

sergiitk commented Jan 17, 2024 • edited Loading

sergiitk commented Jan 18, 2024 • edited Loading

sergiitk commented Jan 18, 2024

sergiitk commented Jan 18, 2024 • edited Loading

sergiitk commented Jan 19, 2024

XuanWang-Amos left a comment

Choose a reason for hiding this comment

sergiitk commented Jan 17, 2024 •

edited

Loading

sergiitk commented Jan 17, 2024 •

edited

Loading

sergiitk commented Jan 18, 2024 •

edited

Loading

sergiitk commented Jan 18, 2024 •

edited

Loading