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

[Crola1702]

Bug report

Required Info:

• Operating System:
  • Windows
• Installation type:
  • Source
• Version or commit hash:
  • Rolling
• DDS implementation:
  • ConnextDDS

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:

• projectroot.test_action_interaction__rmw_connextdds
• rcl_action.TestActionClientServerInteraction.test_interaction
• rcl_action.TestActionClientServerInteraction.test_interaction_with_cancel

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]

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]

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]

These tests are failing consistently in Windows Debug:

• rcl_action.TestActionClientServerInteraction.test_interaction
• rcl_action.TestActionClientServerInteraction.test_interaction_with_cancel
• projectroot.test_action_interaction__rmw_connextdds

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]

@clalancette A friendly ping to follow up

[Blast545]

🧑‍🌾 @clalancette friendly ping

[Crola1702]

Friendly ping @clalancette