Flaky test test_n_nodes__rmw_fastrtps_cpp

[sloretz]

Bug report

Required Info:

• Operating System:
  • Ubuntu Focal
• Installation type:
  • source
• Version or commit hash:
  • fab8e95
• DDS implementation:
  • FastDDS
• Client library (if applicable):
  • rclcpp

Actual behavior

projectroot.test_n_nodes__rmw_fastrtps_cpp
test_rclcpp.TestNNodesAfterShutdown.test_10_nodes

The test appears to complete successfully, but then fails to shutdown afterwards. launch escalates to a SIGTERM signal.

https://ci.ros2.org/job/nightly_linux_repeated/2416

Console output

      Start 70: test_n_nodes__rmw_fastrtps_cpp

70: Test command: /home/jenkins-agent/workspace/nightly_linux_repeated/venv/bin/python3.8 "-u" "/home/jenkins-agent/workspace/nightly_linux_repeated/ws/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/test_results/test_rclcpp/test_n_nodes__rmw_fastrtps_cpp.xunit.xml" "--package-name" "test_rclcpp" "--output-file" "/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/launch_test/test_n_nodes__rmw_fastrtps_cpp.txt" "--env" "RCL_ASSERT_RMW_ID_MATCHES=rmw_fastrtps_cpp" "RMW_IMPLEMENTATION=rmw_fastrtps_cpp" "--append-env" "LD_LIBRARY_PATH=/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp" "--command" "/home/jenkins-agent/workspace/nightly_linux_repeated/venv/bin/python3" "-m" "launch_testing.launch_test" "/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/test_n_nodes__rmw_fastrtps_cpp_Release.py" "--junit-xml=/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/test_results/test_rclcpp/test_n_nodes__rmw_fastrtps_cpp.xunit.xml" "--package-name=test_rclcpp"
70: Test timeout computed to be: 60
70: -- run_test.py: extra environment variables:
70:  - RCL_ASSERT_RMW_ID_MATCHES=rmw_fastrtps_cpp
70:  - RMW_IMPLEMENTATION=rmw_fastrtps_cpp
70: -- run_test.py: extra environment variables to append:
70:  - LD_LIBRARY_PATH+=/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp
70: -- run_test.py: invoking following command in '/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp':
70:  - /home/jenkins-agent/workspace/nightly_linux_repeated/venv/bin/python3 -m launch_testing.launch_test /home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/test_n_nodes__rmw_fastrtps_cpp_Release.py --junit-xml=/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/test_results/test_rclcpp/test_n_nodes__rmw_fastrtps_cpp.xunit.xml --package-name=test_rclcpp
70: [INFO] [launch]: All log files can be found below /home/rosbuild/.ros/log/2021-09-20-14-45-01-952454-3241f705c46b-406396
70: [INFO] [launch]: Default logging verbosity is set to INFO
70: test_10_nodes (test_rclcpp.TestNNodes) ... [INFO] [node_with_name_0-1]: process started with pid [406399]
70: [INFO] [node_with_name_1-2]: process started with pid [406401]
70: [INFO] [node_with_name_2-3]: process started with pid [406403]
70: [INFO] [node_with_name_3-4]: process started with pid [406405]
70: [INFO] [node_with_name_4-5]: process started with pid [406407]
70: [INFO] [node_with_name_5-6]: process started with pid [406441]
70: [INFO] [node_with_name_6-7]: process started with pid [406445]
70: [INFO] [node_with_name_7-8]: process started with pid [406447]
70: [INFO] [node_with_name_8-9]: process started with pid [406457]
70: [INFO] [node_with_name_9-10]: process started with pid [406470]
70: [INFO] [node_check_names-11]: process started with pid [406479]
70: [INFO] [node_check_names-11]: process has finished cleanly [pid 406479]
70: [INFO] [node_with_name_9-10]: sending signal 'SIGINT' to process[node_with_name_9-10]
70: [INFO] [node_with_name_8-9]: sending signal 'SIGINT' to process[node_with_name_8-9]
70: [INFO] [node_with_name_7-8]: sending signal 'SIGINT' to process[node_with_name_7-8]
70: [INFO] [node_with_name_6-7]: sending signal 'SIGINT' to process[node_with_name_6-7]
70: [INFO] [node_with_name_5-6]: sending signal 'SIGINT' to process[node_with_name_5-6]
70: [INFO] [node_with_name_4-5]: sending signal 'SIGINT' to process[node_with_name_4-5]
70: [INFO] [node_with_name_3-4]: sending signal 'SIGINT' to process[node_with_name_3-4]
70: [INFO] [node_with_name_2-3]: sending signal 'SIGINT' to process[node_with_name_2-3]
70: [INFO] [node_with_name_1-2]: sending signal 'SIGINT' to process[node_with_name_1-2]
70: [INFO] [node_with_name_0-1]: sending signal 'SIGINT' to process[node_with_name_0-1]
70: [node_with_name_9-10] [INFO] [1632149102.241335443] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_8-9] [INFO] [1632149102.245046493] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_7-8] [INFO] [1632149102.247834727] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_6-7] [INFO] [1632149102.250542139] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_5-6] [INFO] [1632149102.252687954] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_4-5] [INFO] [1632149102.255035717] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_3-4] [INFO] [1632149102.264126567] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_2-3] [INFO] [1632149102.266437111] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_1-2] [INFO] [1632149102.269126543] [rclcpp]: signal_handler(signal_value=2)
70: [node_with_name_0-1] [INFO] [1632149102.270640193] [rclcpp]: signal_handler(signal_value=2)
70: [INFO] [node_with_name_7-8]: process has finished cleanly [pid 406447]
70: [INFO] [node_with_name_5-6]: process has finished cleanly [pid 406441]
70: [INFO] [node_with_name_8-9]: process has finished cleanly [pid 406457]
70: [INFO] [node_with_name_9-10]: process has finished cleanly [pid 406470]
70: [INFO] [node_with_name_6-7]: process has finished cleanly [pid 406445]
70: [INFO] [node_with_name_4-5]: process has finished cleanly [pid 406407]
70: [INFO] [node_with_name_3-4]: process has finished cleanly [pid 406405]
70: [INFO] [node_with_name_2-3]: process has finished cleanly [pid 406403]
70: [INFO] [node_with_name_0-1]: process has finished cleanly [pid 406399]
70: [ERROR] [node_with_name_1-2]: process[node_with_name_1-2] failed to terminate '5' seconds after receiving 'SIGINT', escalating to 'SIGTERM'
70: [INFO] [node_with_name_1-2]: sending signal 'SIGTERM' to process[node_with_name_1-2]
70: [ERROR] [node_with_name_1-2]: process has died [pid 406401, exit code -15, cmd '/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/node_with_name'].
70: ok
70: 
70: ----------------------------------------------------------------------
70: Ran 1 test in 0.270s
70: 
70: OK
70: test_10_nodes (test_rclcpp.TestNNodesAfterShutdown) ... FAIL
70: 
70: ======================================================================
70: FAIL: test_10_nodes (test_rclcpp.TestNNodesAfterShutdown)
70: ----------------------------------------------------------------------
70: Traceback (most recent call last):
70:   File "/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/test_n_nodes__rmw_fastrtps_cpp_Release.py", line 61, in test_10_nodes
70:     launch_testing.asserts.assertExitCodes(
70:   File "/home/jenkins-agent/workspace/nightly_linux_repeated/ws/install/launch_testing/lib/python3.8/site-packages/launch_testing/asserts/assert_exit_codes.py", line 62, in assertExitCodes
70:     assert info.returncode in allowable_exit_codes, 'Proc {} exited with code {}'.format(
70: AssertionError: Proc node_with_name_1-2 exited with code -15
70: 
70: ----------------------------------------------------------------------
70: Ran 1 test in 0.001s
70: 
70: FAILED (failures=1)
70: -- run_test.py: return code 1
70: -- run_test.py: verify result file '/home/jenkins-agent/workspace/nightly_linux_repeated/ws/build/test_rclcpp/test_results/test_rclcpp/test_n_nodes__rmw_fastrtps_cpp.xunit.xml'

[mjcarroll]

https://ci.ros2.org/view/nightly/job/nightly_win_rep/2963/testReport/junit/(root)/projectroot/test_n_nodes__rmw_fastrtps_cpp/