test_communication puts stack trace and its failure in different test cases #418
Description
Bug report
System info:
https://ci.ros2.org/view/nightly/job/nightly_win_deb/1589/
Steps to reproduce issue
Expected behavior
The crash fails the test case associated with it.
Actual behavior
The useful stack trace appears in the passing test case "test_subscriber_terminates_in_a_finite_amount_of_time[WStrings]"
139: test_subscriber_terminates_in_a_finite_amount_of_time[WStrings] (test_communication.TestPublisherSubscriber)
139: Test that the subscriber terminates after a finite amount of time. ... [INFO] [test_publisher-23]: process started with pid [5128]
139: [INFO] [test_subscriber-24]: process started with pid [1732]
139: [test_subscriber-24] exception in subscriber:
139: [test_subscriber-24] Traceback (most recent call last):
139: [test_subscriber-24] File "C:/ci/ws/src/ros2/system_tests/test_communication/test/subscriber_py.py", line 81, in <module>
139: [test_subscriber-24] listener(message_name=args.message_name, namespace=args.namespace)
139: [test_subscriber-24] File "C:/ci/ws/src/ros2/system_tests/test_communication/test/subscriber_py.py", line 65, in listener
139: [test_subscriber-24] rclpy.spin_once(node)
139: [test_subscriber-24] File "C:\ci\ws\install\Lib\site-packages\rclpy\__init__.py", line 171, in spin_once
139: [test_subscriber-24] executor.spin_once(timeout_sec=timeout_sec)
139: [test_subscriber-24] File "C:\ci\ws\install\Lib\site-packages\rclpy\executors.py", line 685, in spin_once
139: [test_subscriber-24] raise handler.exception()
139: [test_subscriber-24] File "C:\ci\ws\install\Lib\site-packages\rclpy\task.py", line 239, in __call__
139: [test_subscriber-24] self._handler.send(None)
139: [test_subscriber-24] File "C:\ci\ws\install\Lib\site-packages\rclpy\executors.py", line 397, in handler
139: [test_subscriber-24] arg = take_from_wait_list(entity)
139: [test_subscriber-24] File "C:\ci\ws\install\Lib\site-packages\rclpy\executors.py", line 325, in _take_subscription
139: [test_subscriber-24] msg = _rclpy.rclpy_take(capsule, sub.msg_type, sub.raw)
139: [test_subscriber-24] UnicodeDecodeError: 'utf-16-le' codec can't decode bytes in position 0-1: illegal encoding
139: [ERROR] [test_subscriber-24]: process has died [pid 1732, exit code 1, cmd 'C:\Python37\python_d.exe C:/ci/ws/src/ros2/system_tests/test_communication/test/subscriber_py.py WStrings /test_time_11_49_47'].
139: [WARNING] [test_publisher-23]: 'SIGINT' sent to process[test_publisher-23] not supported on Windows, escalating to 'SIGTERM'
139: [INFO] [test_publisher-23]: sending signal 'SIGTERM' to process[test_publisher-23]
139: [ERROR] [test_publisher-23]: process has died [pid 5128, exit code 1, cmd 'C:\Python37\python_d.exe C:/ci/ws/src/ros2/system_tests/test_communication/test/publisher_py.py WStrings /test_time_11_49_47'].
139: ok
A useless stack trace appears in the failed test case:
139: test_processes_finished_gracefully[WStrings] (test_communication.TestPublisherSubscriberAfterShutdown)
139: Test that both executables finished gracefully. ... FAIL
139:
139: ======================================================================
139: FAIL: test_processes_finished_gracefully[WStrings] (test_communication.TestPublisherSubscriberAfterShutdown)
139: Test that both executables finished gracefully.
139: ----------------------------------------------------------------------
139: Traceback (most recent call last):
139: File "C:\ci\ws\build\test_communication\test_publisher_subscriber__rclpy__rmw_fastrtps_cpp_Debug.py", line 77, in test_processes_finished_gracefully
139: 'test_subscriber'
139: File "C:\ci\ws\install\Lib\site-packages\launch_testing\asserts\assert_exit_codes.py", line 64, in assertExitCodes
139: info.returncode
139: AssertionError: Proc test_subscriber-24 exited with code 1
Additional information
Unfortunately, searching these logs for the string "[ERROR]" is made somewhat less useful since even a passing test cases send a SIGTERM to the subprocess, causing it to log an error.