search

ros2 / rcl

Library to support implementation of language specific ROS Client Libraries.
Apache License 2.0
128 stars 162 forks source link

:farmer: Flaky `test_action_interaction__rmw_connextdds` in Windows debug and release #1162

Open Crola1702 opened 2 months ago

Crola1702 commented 2 months ago

Bug report

Required Info:

Steps to reproduce issue

  1. Run a build in nightly_win_deb
  2. See test regressions fail

Additional information

Reference build: https://ci.ros2.org/view/nightly/job/nightly_win_deb/3136/

Test regressions:

Log output: ``` -- run_test.py: extra environment variables: - RCL_ASSERT_RMW_ID_MATCHES=rmw_connextdds - RMW_IMPLEMENTATION=rmw_connextdds -- run_test.py: invoking following command in 'C:\ci\ws\build\rcl_action': - C:/ci/ws/build/rcl_action/Debug/test_action_interaction__rmw_connextdds.exe --gtest_output=xml:C:/ci/ws/build/rcl_action/test_results/rcl_action/test_action_interaction__rmw_connextdds.gtest.xml Running main() from C:\ci\ws\install\src\gtest_vendor\src\gtest_main.cc [==========] Running 2 tests from 1 test suite. [----------] Global test environment set-up. [----------] 2 tests from TestActionClientServerInteraction__rmw_connextdds [ RUN ] TestActionClientServerInteraction__rmw_connextdds.test_interaction C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(227): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(238): error: Value of: this->is_goal_request_ready Actual: false Expected: true error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(246): error: Expected equality of these values: ret Which is: 2201 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(249): error: Expected equality of these values: this->outgoing_goal_request.goal.order Which is: 10 this->incoming_goal_request.goal.order Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(253): error: Value of: (0 == memcmp(this->outgoing_goal_request.goal_id.uuid, this->incoming_goal_request.goal_id.uuid, 16)) Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(274): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(287): error: Value of: this->is_goal_response_ready Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(296): error: Expected equality of these values: ret Which is: 2103 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(299): error: Expected equality of these values: this->outgoing_goal_response.accepted Which is: true this->incoming_goal_response.accepted Which is: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(300): error: Expected equality of these values: this->outgoing_goal_response.stamp.sec Which is: 123 this->incoming_goal_response.stamp.sec Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(301): error: Expected equality of these values: this->outgoing_goal_response.stamp.nanosec Which is: 456789 this->incoming_goal_response.stamp.nanosec Which is: 3452816845 [ FAILED ] TestActionClientServerInteraction__rmw_connextdds.test_interaction (2548 ms) [ RUN ] TestActionClientServerInteraction__rmw_connextdds.test_interaction_with_cancel C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(500): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(511): error: Value of: this->is_goal_request_ready Actual: false Expected: true error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(519): error: Expected equality of these values: ret Which is: 2201 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(522): error: Expected equality of these values: this->outgoing_goal_request.goal.order Which is: 10 this->incoming_goal_request.goal.order Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(526): error: Value of: (0 == memcmp(this->outgoing_goal_request.goal_id.uuid, this->incoming_goal_request.goal_id.uuid, 16)) Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(547): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(560): error: Value of: this->is_goal_response_ready Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(569): error: Expected equality of these values: ret Which is: 2103 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(572): error: Expected equality of these values: this->outgoing_goal_response.accepted Which is: true this->incoming_goal_response.accepted Which is: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(573): error: Expected equality of these values: this->outgoing_goal_response.stamp.sec Which is: 123 this->incoming_goal_response.stamp.sec Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(574): error: Expected equality of these values: this->outgoing_goal_response.stamp.nanosec Which is: 456789 this->incoming_goal_response.stamp.nanosec Which is: 3452816845 [ FAILED ] TestActionClientServerInteraction__rmw_connextdds.test_interaction_with_cancel (2414 ms) [----------] 2 tests from TestActionClientServerInteraction__rmw_connextdds (4964 ms total) [----------] Global test environment tear-down [==========] 2 tests from 1 test suite ran. (4964 ms total) [ PASSED ] 0 tests. [ FAILED ] 2 tests, listed below: [ FAILED ] TestActionClientServerInteraction__rmw_connextdds.test_interaction [ FAILED ] TestActionClientServerInteraction__rmw_connextdds.test_interaction_with_cancel 2 FAILED TESTS -- run_test.py: return code 1 -- run_test.py: inject classname prefix into gtest result file 'C:/ci/ws/build/rcl_action/test_results/rcl_action/test_action_interaction__rmw_connextdds.gtest.xml' -- run_test.py: verify result file 'C:/ci/ws/build/rcl_action/test_results/rcl_action/test_action_interaction__rmw_connextdds.gtest.xml' ```

Flaky report (last 15 days):

job_name last_fail first_fail build_count failure_count failure_percentage
nightly_win_deb 2024-06-26 2024-06-12 14 4 28.57
nightly_win_rel 2024-06-25 2024-06-25 16 1 6.25
Crola1702 commented 2 months ago

The flaky ratio of these tests has grown up considerably:

job_name last_fail first_fail build_count failure_count failure_percentage
nightly_win_rel 2024-07-05 2024-06-25 16 8 50.0
nightly_win_deb 2024-07-05 2024-06-21 12 9 75.0
Crola1702 commented 1 month ago

This is still hapenning in Windows Debug: nightly_win_deb#3169. Test failure: https://ci.ros2.org/view/nightly/job/nightly_win_deb/3169/testReport/(root)/projectroot/test_action_interaction__rmw_connextdds/

Crola1702 commented 1 month ago

These tests are failing consistently in Windows Debug:

Log output: ``` -- run_test.py: extra environment variables: - RMW_IMPLEMENTATION=rmw_connextdds -- run_test.py: invoking following command in 'C:\ci\ws\build\rcl_action': - C:/ci/ws/build/rcl_action/Debug/test_action_interaction.exe --gtest_output=xml:C:/ci/ws/build/rcl_action/test_results/rcl_action/test_action_interaction__rmw_connextdds.gtest.xml Running main() from C:\ci\ws\install\src\gtest_vendor\src\gtest_main.cc [==========] Running 2 tests from 1 test suite. [----------] Global test environment set-up. [----------] 2 tests from TestActionClientServerInteraction [ RUN ] TestActionClientServerInteraction.test_interaction C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(222): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(233): error: Value of: this->is_goal_request_ready Actual: false Expected: true error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(241): error: Expected equality of these values: ret Which is: 2201 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(244): error: Expected equality of these values: this->outgoing_goal_request.goal.order Which is: 10 this->incoming_goal_request.goal.order Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(248): error: Value of: (0 == memcmp(this->outgoing_goal_request.goal_id.uuid, this->incoming_goal_request.goal_id.uuid, 16)) Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(269): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(282): error: Value of: this->is_goal_response_ready Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(291): error: Expected equality of these values: ret Which is: 2103 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(294): error: Expected equality of these values: this->outgoing_goal_response.accepted Which is: true this->incoming_goal_response.accepted Which is: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(295): error: Expected equality of these values: this->outgoing_goal_response.stamp.sec Which is: 123 this->incoming_goal_response.stamp.sec Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(296): error: Expected equality of these values: this->outgoing_goal_response.stamp.nanosec Which is: 456789 this->incoming_goal_response.stamp.nanosec Which is: 3452816845 [ FAILED ] TestActionClientServerInteraction.test_interaction (20567 ms) [ RUN ] TestActionClientServerInteraction.test_interaction_with_cancel C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(494): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(505): error: Value of: this->is_goal_request_ready Actual: false Expected: true error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(513): error: Expected equality of these values: ret Which is: 2201 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(516): error: Expected equality of these values: this->outgoing_goal_request.goal.order Which is: 10 this->incoming_goal_request.goal.order Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(520): error: Value of: (0 == memcmp(this->outgoing_goal_request.goal_id.uuid, this->incoming_goal_request.goal_id.uuid, 16)) Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(541): error: Expected equality of these values: ret Which is: 2 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(554): error: Value of: this->is_goal_response_ready Actual: false Expected: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(563): error: Expected equality of these values: ret Which is: 2103 0 error not set C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(566): error: Expected equality of these values: this->outgoing_goal_response.accepted Which is: true this->incoming_goal_response.accepted Which is: true C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(567): error: Expected equality of these values: this->outgoing_goal_response.stamp.sec Which is: 123 this->incoming_goal_response.stamp.sec Which is: -842150451 C:\ci\ws\src\ros2\rcl\rcl_action\test\rcl_action\test_action_interaction.cpp(568): error: Expected equality of these values: this->outgoing_goal_response.stamp.nanosec Which is: 456789 this->incoming_goal_response.stamp.nanosec Which is: 3452816845 [ FAILED ] TestActionClientServerInteraction.test_interaction_with_cancel (20526 ms) [----------] 2 tests from TestActionClientServerInteraction (41094 ms total) [----------] Global test environment tear-down [==========] 2 tests from 1 test suite ran. (41094 ms total) [ PASSED ] 0 tests. [ FAILED ] 2 tests, listed below: [ FAILED ] TestActionClientServerInteraction.test_interaction ```

CC @clalancette

MichaelOrlov commented 4 weeks ago

@clalancette A friendly ping to follow up