[Python test] Add log to print test start time and duration (#37761)

Some of our tests failed because RPC was canceled by server, error message:
```
I0000 00:00:1726598495.788119   64528 chttp2_transport.cc:1182] ipv4:127.0.0.1:41825: Got goaway [2] err=UNAVAILABLE:GOAWAY received; Error code: 2; Debug Text: Cancelling all calls {grpc_status:14, http2_error:2, created_time:"2024-09-17T18:41:35.78810597+00:00"}
```

It's possible that the request waited too long to be processed and thus canceled by server (default maximum time gRPC server allows a request to be received by the server but not handled is `30s`, controlled by `grpc.server_max_unrequested_time_in_server`).

This PR will print the test start/finish time so we know if we should increase `grpc.server_max_unrequested_time_in_server` time.

Example before change:
```
Testing gRPC Python...
SUCCESS       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_default
Running       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_disabled
SUCCESS       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_disabled
Running       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_enabled
```

Example after change:
```
 [2024-09-20 18:32:15.228947]Testing gRPC Python...
 [2024-09-20 18:32:15.237855]START         tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_default
 [2024-09-20 18:32:15.265477]SUCCESS       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_default[Duration: 0:00:00.027622s]
Running       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_disabled
 [2024-09-20 18:32:15.278142]START         tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_disabled
 [2024-09-20 18:32:15.316065]FAILURE       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_disabled[Duration: 0:00:00.037911]
Running       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_enabled
 [2024-09-20 18:32:15.328680]START         tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_enabled
 [2024-09-20 18:32:16.938745]SUCCESS       tests.unit._metadata_flags_test.MetadataFlagsTest.test_call_wait_for_ready_enabled[Duration: 0:00:01.610065s]
```

<!--

If you know who should review your pull request, please assign it to that
person, otherwise the pull request would get assigned randomly.

If your pull request is for a specific language, please add the appropriate
lang label.

-->

Closes #37761

COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37761 from XuanWang-Amos:add_time_to_unit_test d2ecd8ce22
PiperOrigin-RevId: 677805375
pull/37565/head^2
Xuan Wang 2 months ago committed by Copybara-Service
parent cbccf975d0
commit a9114ff9e4
  1. 36
      src/python/grpcio_tests/tests/_result.py

@ -291,16 +291,28 @@ class TerminalResult(CoverageResult):
"""
super(TerminalResult, self).__init__(id_map=id_map)
self.out = out
self.start_time = None
def startTestRun(self):
"""See unittest.TestResult.startTestRun."""
super(TerminalResult, self).startTestRun()
self.out.write(
_Colors.HEADER
+ "[{}]Testing gRPC Python...\n".format(datetime.datetime.now())
+ " [{}]Testing gRPC Python...\n".format(datetime.datetime.now())
+ _Colors.END
)
def startTest(self, test):
"""See unittest.TestResult.startTest."""
super(TerminalResult, self).startTest(test)
self.start_time = datetime.datetime.now()
self.out.write(
_Colors.INFO
+ " [{}]START {}\n".format(self.start_time, test.id())
+ _Colors.END
)
self.out.flush()
def stopTestRun(self):
"""See unittest.TestResult.stopTestRun."""
super(TerminalResult, self).stopTestRun()
@ -310,26 +322,40 @@ class TerminalResult(CoverageResult):
def addError(self, test, err):
"""See unittest.TestResult.addError."""
super(TerminalResult, self).addError(test, err)
end_time = datetime.datetime.now()
duration = end_time - self.start_time
self.out.write(
_Colors.FAIL + "ERROR {}\n".format(test.id()) + _Colors.END
_Colors.FAIL
+ " [{}]ERROR {}[Duration: {}]\n".format(
datetime.datetime.now(), test.id(), duration
)
+ _Colors.END
)
self.out.flush()
def addFailure(self, test, err):
"""See unittest.TestResult.addFailure."""
super(TerminalResult, self).addFailure(test, err)
end_time = datetime.datetime.now()
duration = end_time - self.start_time
self.out.write(
_Colors.FAIL + "FAILURE {}\n".format(test.id()) + _Colors.END
_Colors.FAIL
+ " [{}]FAILURE {}[Duration: {}]\n".format(
datetime.datetime.now(), test.id(), duration
)
+ _Colors.END
)
self.out.flush()
def addSuccess(self, test):
"""See unittest.TestResult.addSuccess."""
super(TerminalResult, self).addSuccess(test)
end_time = datetime.datetime.now()
duration = end_time - self.start_time
self.out.write(
_Colors.OK
+ "[{}]SUCCESS {}\n".format(
datetime.datetime.now(), test.id()
+ " [{}]SUCCESS {}[Duration: {}]\n".format(
end_time, test.id(), duration
)
+ _Colors.END
)

Loading…
Cancel
Save