rclcpp_components: test_component_manager_api consistently times out

[mjcarroll]

Bug report

Required Info:

• Operating System:
  • Linux
• Installation type:
  • Source
• Version or commit hash:
  • Dashing
  • Eloquent
• DDS implementation:
  • Fast-RTPS
• Client library (if applicable):
  • rclcpp

Steps to reproduce issue

• Execute test_component_manager_api

Expected behavior

Test does not time out

Actual behavior

Test times out

Additional information

This was originally reported as a build_cop issue: ros2/build_farmer#184

It's recently become more flaky, causing issues with PR builders and CI jobs (#857) with an attempted fix here #862

[hidmic]

So, it's reported for Fast-RTPS and I cannot reproduce it locally using any other rmw implementation i.e. RTI Connext and ADLink Opensplice work just fine. I suspect it has to do with the time it takes for Fast-RTPS to bring up / tear down node state, but I have to dig in further.

[hidmic]

Alright, some debugging suggests it's a race. Running just two tests, the first one passes and the second gets as far as sending a service request. The service server never gets that request, spinning times out and the test ends up waiting for an std::future that never comes (no pun intended).

I went into Fast-RTPS, looking for global state that could explain an interaction between consecutively run tests but I couldn't find any. Maybe eProsima folks can shed some light.

[hidmic]

@richiware maybe?

[richiware]

We are backporting fixed issues on FastRTPS 1.9 to 1.8. ROS2 Dashing is using FastRTPS 1.8.x releases. Can you test with this branch? It will be next 1.8.2 release. In case it still fails, I will try to reproduce the problem and take a look.

[hidmic]

Thanks for reaching out @richiware! But it seems to me you're suggesting that this is specific to Fast-RTPS 1.8.x and, by extension, to Dashing. This is also happening on Eloquent. I just noticed the issue was not clear in this regard -- it's updated now.

[hidmic]

FYI no other flakes have happened after #876. We could close this issue BUT I think it'd be good to track the underlying race which we are simply working around now.

[richiware]

Yesterday I was able to reproduce it. I will try to figure out what's going on.

[richiware]

I was testing modifying the default Durability QoS for services. Testing with TRANSIENT_LOCAL instead of VOLATILE makes pass all tests.
Therefore the service's request is sent before services are discovered between them (at DDS level). When the discovered is complete, due to Durability QoS is VOLATILE, there is no request to be sent again.

[richiware]

It is weird because looking in the test's source code I've found wait_for_service() is being used. I'm not familiar with ROS services API, but this function should wait until the discovery is complete between client and server.

[hidmic]

Therefore the service's request is sent before services are discovered between them (at DDS level).

Well, to prevent this from ever happening in the first place, each test does check for service server availability before moving forward e.g.:

rclcpp/rclcpp_components/test/test_component_manager_api.cpp

Lines 48 to 53 in b8f7237

	auto client = node->create_client<composition_interfaces::srv::LoadNode>(
	"/ComponentManager/_container/load_node");
	if (!client->wait_for_service(20s)) {
	ASSERT_TRUE(false) << "service not available after waiting";
	}

I can confirm that (1) it does pass that sanity check right before losing the request and (2) the entire issue goes away if enough time is spent between node tear down and bring up.

---

All of this seems to suggest that graph updates are driven solely by network discovery. In other words, there's no intraprocess optimization. Thus the graph is essentially out-of-date until a full discovery is performed. Is that reasoning sound to you @richiware ?

[richiware]

Sounds plausible. If the graph doesn't have time to be informed about the teardown of the service, maybe wait_for_service() is returning immediately, when it shouldn't.