test_communication puts stack trace and its failure in different test cases

[rotu]

Bug report

System info:
https://ci.ros2.org/view/nightly/job/nightly_win_deb/1589/

Steps to reproduce issue

run CI https://ci.ros2.org/view/nightly/job/nightly_win_deb/1589/testReport/(root)/projectroot/test_publisher_subscriber__rclpy__rmw_cyclonedds_cpp/

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.

[hidmic]

@rotu what you see is a result of fixture and tests execution not being synchronous but concurrent. That is why launch_testing cannot correlate test and Executable actions' output. For many cases though we could make up for it by somehow capturing loggers output, but that'll be best-effort unless we instantiate one fixture per test. CC @dirk-thomas for thoughts on launch_testing refactor.

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.

That is unfortunately true, and there's nothing we can currently do about it. There's no Unix-like SIGINT on Windows, and attempts in the past to use CTRL_C_EVENT have failed to deliver. That's why launch resorts to SIGTERM.