Numerous test failures for Nav2 when using rmw_connextdds

[ruffsl]

System Info

• OS
  • Ubuntu 20.04
• ROS version and installation type
  • rolling/source
• RTI Connext DDS version and installation type
  • rti-connext-dds-5.3.1/focal,now 5.3.1-nc.x64Linux3gcc5.4.0+2 amd64
• RMW version or commit hash
  • f46c39d

Bug Description

Numerous failures in Nav2 when testing with rmw_connextdds that don't occur with other RMWs. To list a few:

• An abnormal number of rmw_dds_common warnings are encountered during testing of nav2:

Details

[controller_server-7] [WARN] [1617199619.684671125] [rmw_dds_common]: nanoseconds value too large for 32-bits, saturated at UINT_MAX
[controller_server-7] [WARN] [1617199619.684736997] [rmw_dds_common]: nanoseconds value too large for 32-bits, saturated at UINT_MAX
[controller_server-7] [WARN] [1617199619.684755779] [rmw_dds_common]: nanoseconds value too large for 32-bits, saturated at UINT_MAX
...

• Expected lexeme type not found as handle's typesupport identifier (rosidl_typesupport_cpp) is not supported by this library:

Details

[planner_server-8] >>> [rcutils|error_handling.c:108] rcutils_set_error_state()
[planner_server-8] This error state is being overwritten:
[planner_server-8] 
[planner_server-8]   'Handle's typesupport identifier (rosidl_typesupport_cpp) is not supported by this library, at /home/jenkins-agent/workspace/packaging_linux/ws/src/ros2/rosidl_typesupport/rosidl_typesupport_cpp/src/type_support_dispatch.hpp:111'
[planner_server-8] 
[planner_server-8] with this new error message:
[planner_server-8] 
[planner_server-8]   'Expected lexeme type (19) not found, search ended at index 21, at /home/jenkins-agent/workspace/packaging_linux/ws/src/ros2/rcl/rcl/src/rcl/lexer_lookahead.c:233'
[planner_server-8] 
[planner_server-8] rcutils_reset_error() should be called after error handling to avoid this.
[planner_server-8] <<<

• Cannot delete and wait on the same object

Details

[gzserver-1] [ERROR] [1617200184.378385234] [rmw_connextdds]: cannot delete and wait on the same object
[gzserver-1] [ERROR] [1617200184.381227447] [rmw_connextdds]: cannot delete and wait on the same object
[gzserver-1] [ERROR] [1617200184.381472426] [rmw_connextdds]: cannot delete and wait on the same object

See test failure logs for complete error messages:

https://app.circleci.com/pipelines/github/ros-planning/navigation2/5045/workflows/062fb8a4-bf43-4bbe-8dbe-4cf54a698abc/jobs/18610

Expected Behavior

No test failures encountered like with other alternative RMW.

How to Reproduce

export IMAGE_NAME=rosplanning/navigation2:main.release
export FROM_IMAGE=osrf/ros2:nightly-rmw-nonfree

docker pull $IMAGE_NAME

#OR

git clone https://github.com/ros-planning/navigation2.git
cd navigation2
docker build \
    --tag ${IMAGE_NAME} \
    --build-arg FROM_IMAGE \
    --file Dockerfile .

mkdir -p /tmp/overlay_ws/log
docker run -it --rm \
    -v /tmp/overlay_ws/log:/opt/overlay_ws/log \
    rosplanning/navigation2:main.release \
    bash
export RMW_IMPLEMENTATION=rmw_connextdds
colcon test
colcon test-result --verbose

cd /tmp/overlay_ws/log/latest_test/

Workarounds

Switching to alternative RMWs such as rmw_fastrtps_cpp or rmw_cyclonedds_cpp.

Additional context

With the recent release announcement, the nav2 project has re-enabled rmw_connextdds to its rmw matrix of nightly tests.

[asorbini]

Hi @ruffsl, thank you for this report, I will try to reproduce locally and start investigating.

Meanwhile, a couple of comments:

* An abnormal number of rmw_dds_common warnings are encountered during testing of nav2:

These warnings are printed by this utility function in rmw_dds_common which was recently introduced and maybe isn't used by other RMWs yet (maybe because they don't need it/implement the conversion themselves).

One solution would be to downgrade the warning in clamp_rmw_time_to_dds_time(), but I also wonder why these overflow are happening in the first place. In DDS, the nanosec field of a Duration is never expected to be >= 1s, so overflows are never expected on a "normalized" value. See DDS v1.4 section 2.3.2:

The two types used to represent time: Duration_t and Time_t are mapped into structures that contain fields for the second and the nanosecond parts. These types are further constrained to always use a ‘normalized’ representation for the time, that is, the nanosec field must verify 0 <= nanosec < 1000000000.

I wonder if this is not the case in the ROS 2 API, in which case there is probably some more work to be done to perform a proper conversion of rmw_time_t into DDS_Duration_t than just "clamping" the value...

* Expected lexeme type not found as handle's typesupport identifier (rosidl_typesupport_cpp) is not supported by this library:

This is something that I've seen before show up in some unit test logs, but I haven't been able to understand/resolve yet. I think it has to be related to this call in rmw_graph.cpp (because there is no other mention of rosidl_typesupport_cpp anywhere else in the repository) but I'm not sure if that call has any problems, because this error doesn't show up under "normal conditions".

* Cannot delete and wait on the same object

I personally think rmw_connextdds is (at least partially) right here in forbidding this operation, unless of course there is a bug in the implementation, but let me try to explain why.

The error comes from here, and it's being triggered because an object being deleted (a "publisher" or a "subscriber", maybe owned by a "client" or "service", or maybe a "guard condition") is still marked attached to a waitset that is currently in the midst of beginning a wait(). This could be (what I would consider) a user error, because they are trying to delete something while, e.g., an executor is "spinning on it", but it may also happen because the waitset implementation based on DDS WaitSets tries to compensate the lack of attach/detach in the ROS 2 API by "caching" the attached references, and only detaching them upon the next wait() (or deletion of one of the attached objects).

Now, if you think the deletion is legitimate (i.e. whatever object is being deleted is not currently associated with a waitset), then it might be that there is a problem in the current implementation of RMW_Connext_WaitSet::invalidate(), which should wait for the wait() call to transition to the next state (from ACQUIRING to BLOCKED), and only return an error if the condition that was invalidating the WaitSet is still attached (because it will have been cleared by the concurrent wait() during that transition, if the object was not part of the current set of "waitables"), instead of immediately returning an error like it does now. I'll investigate this "race condition" while reproducing locally, but it would be great if you could confirm that the object deletion doesn't have any of the possible problems that I mentioned.

[asorbini]

This is something that I've seen before show up in some unit test logs, but I haven't been able to understand/resolve yet. I think it has to be related to this call in rmw_graph.cpp (because there is no other mention of rosidl_typesupport_cpp anywhere else in the repository) but I'm not sure if that call has any problems, because this error doesn't show up under "normal conditions".

I think I may have found the reason for the rosidl_typesupport_cpp error messages and the associated fix.

[asorbini]

I'm still investigating, but one thing I've noticed is that the default implementation used by rmw_connextdds for WaitSets (based on DDS WaitSets) might be generating too much CPU usage, and causing some tests to fail.

I'm currently focusing on nav2_system_tests and, while I still have failures, I get much better results when I compile the RMW with an alternative WaitSet implementation based on the standard C++ library. Still getting to the bottom of it, but I'm starting to suspect the resolution to this issue will include switching that implementation.

[asorbini]

I've been doing some extensive testing locally (by building a "minimal" Rolling tree and the nav2 stack in Debug mode), and created #22 to address some of the issues that I was able to identify.

I have been running tests from nav2_system_tests with them and was able to see all tests reported failing by CI pass at least a few times each. So far, I have also been running tests with some larger default timeouts to help me debug other non-time related issues (server_timeout from 10ms to 10s, bond_timeout from 4s to 10s).

In general, the failures seem to me to be mostly related to:

• Slow default discovery: lifecycle_manager aborts the test because bond_timeout expires with some component.
• Slow default reliability: these application all run on very tight loops and expect very quick response from the middleware. Connext's default QoS parameters controlling the DDS reliability protocol might not be tuned to provide the expected performance, particularly when it comes to promptly detect and resend missed samples. This might cause tests to fail if some "test deadline" is missed (e.g. some short timeout).
• High CPU usage caused by the current implementation of WaitSets.

There is also the possibility for these tests to run into a discovery race condition that exists for all "volatile" ROS 2 clients: there is a fundamental race condition in the client operation is_service_available() which stems from DDS' peer to peer nature and the way its discovery phase works. When a client detects a remote service as "alive" because both its request writer and reply reader have been matched by the corresponding entities in a remote application, there is no guarantee that the same is also true for the remote application. For this reason, a client using "volatile" durability (the default in ROS 2) runs the risk to be blocked indefinitely for a reply that will never come, if it sends a request right after a service is locally detected as enabled but the service's request reader has not yet been matched locally. The message will not be repaired by the writer, because of the "volatile" durability.

There is also another potential race condition which may lead to a reply not being sent by a service because the local writer had not yet matched the client's reader when the reply was written. This is addressed by the DDS-RPC specification by prescribing that the "reply writer" always be matched by an implementation before its associated "request reader" when matching the endpoint's of a remote client, but this requires the propagation of additional information via discovery, and, as far as I know, no DDS vendor yet implements this behavior.

The solution to the first race condition is, imho, simple: always use at least "transient local" durability for clients. But maybe I'm not considering some adverse effect of that decision.

Anyway, these race conditions should only be relevant for applications which create and delete clients very often, since that triggers discovery and matching. This shouldn't be the case for a "typical" DDS application (because endpoint creation/deletion is an expensive operation, with system-wide consequences because of discovery, and should not be carried out continuously if possible), but I'm not sure if the same it's true for a ROS 2 application making extensive use of actions like the nav2 components seem to be (I'm not that familiar with the client API exposed by rclcpp and how it's used by a typical ROS 2 application).

I was able to confirm that the issues with "slow discovery" and "slow reliability" can be mitigated by tuning the QoS via XML (since the required parameters are not exposed by ROS). Increasing the "announcement period" makes component able to discover each other more quickly, while increasing the "heartbeat period" will help making sure that writers will be quicker to repair missed samples.

I did some experiments running with the XML configuration below saved as NDDS_QOS_PROFILES.xml in the workspace directory where I ran the tests. The configuration might give some better results than the "out of the box" experience, particularly for speeding up discovery. I think the actual "optimal" solution though can only be to craft a configuration file that specifies the correct parameters for each topic (using "topic filters") instead of changing defaults for all reliable topics, which I'm pretty sure causes a lot of unnecessary work to dispatch periodic messages for unused topics.

At this point, I'm validating the changes in #22 and look forward to have them in master ASAP.

After that, I guess we'll run them through another set of your CI and see what comes out of it.

<?xml version="1.0" encoding="UTF-8"?>
<dds xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="http://community.rti.com/schema/6.0.1/rti_dds_profiles.xsd" version="6.0.1">
    <!-- Qos Library -->
    <qos_library name="Issue21">
      <qos_profile name="BaseProfile" base_name="BuiltinQosLib::Generic.Common" is_default_qos="true">
        <participant_qos>
          <discovery_config>
            <initial_participant_announcements>10</initial_participant_announcements>
            <min_initial_participant_announcement_period>
              <sec>0</sec>
              <nanosec>200000000</nanosec>
            </min_initial_participant_announcement_period>
            <max_initial_participant_announcement_period>
              <sec>0</sec>
              <nanosec>400000000</nanosec>
            </max_initial_participant_announcement_period>
          </discovery_config>
        </participant_qos>
        <datareader_qos>
          <protocol>
            <rtps_reliable_reader>
              <min_heartbeat_response_delay>
                <sec>0</sec>
                <nanosec>0</nanosec>
              </min_heartbeat_response_delay>
              <max_heartbeat_response_delay>
                <sec>0</sec>
                <nanosec>0</nanosec>
              </max_heartbeat_response_delay>
            </rtps_reliable_reader>
          </protocol>
        </datareader_qos>
        <datawriter_qos>
          <protocol>
            <rtps_reliable_writer>
              <low_watermark>0</low_watermark>
              <high_watermark>2</high_watermark>
              <heartbeats_per_max_samples>100</heartbeats_per_max_samples>
              <min_send_window_size>10</min_send_window_size>
              <max_send_window_size>10</max_send_window_size>
              <max_heartbeat_retries>500</max_heartbeat_retries>
              <heartbeat_period>
                <sec>0</sec>
                <nanosec>10000000</nanosec>
              </heartbeat_period>
              <fast_heartbeat_period>
                <sec>0</sec>
                <nanosec>500000</nanosec>
              </fast_heartbeat_period>
              <late_joiner_heartbeat_period>
                <sec>0</sec>
                <nanosec>500000</nanosec>
              </late_joiner_heartbeat_period>
              <max_nack_response_delay>
                <sec>0</sec>
                <nanosec>0</nanosec>
              </max_nack_response_delay>
            </rtps_reliable_writer>
          </protocol>
        </datawriter_qos>
      </qos_profile>
    </qos_library>
</dds>

[asorbini]

I forgot to mention that the issue with the "typesupport" error is caused by an error message in rosidl_typesupport_cpp which should really be a debug statement at best.

I had opened a PR to remove it (rosidl_typesupport#107) but closed it for now, because it seems like @clalancette has already one (draft) open to address the same issue (rosidl_typesupport#102).

The other one about "saturated time" will be removed by the alternative WaitSet implementation. It is nevertheless curious because I kept seeing it pop up with the other implementation even after re-implementing the logic to convert rmw_time_t to DDS_Duration_t, and making it accept RMW_DURATION_INFINITE, which I assumed was the culprit for the "extremely large values". It looked like some of the components still passed these unexpectedly large values, and I'm not sure why (I would think that, 99 out of a 100 cases at least, an application that needs to wait for something larger than [INT_MAX sec, 10^9-1 nanosec] should actually be waiting for "infinite", but maybe I'm wrong...).