rosbag2 icon indicating copy to clipboard operation
rosbag2 copied to clipboard

Published 20 hours ago • verified publisher icon ros2

'Problem reserving CacheChange in reader' error message when using recorder

Open mwcondino opened this issue 2 years ago • 1 comments

Description

I have observed some instances of this error message while using ros2 bag record -

2022-11-09 10:11:42.636 [RTPS_MSG_IN Error] (ID:140490539038272) Problem reserving CacheChange in reader: 01.0f.17.88.af.2a.6c.46.01.00.00.00|0.0.11.4 -> Function processDataMsg

It looks like the issue may be in the underlying transport layer, but the error message here is extremely opaque, and so far this only occurs when using the record verb. It looks like the issue may manifest when a bag recorder is stopped and started several times with other nodes running.

This looks like it could be related to https://github.com/eProsima/Fast-DDS/pull/2942/files, but I am still seeing the issue on Humble ( with ros-humble-fastrtps=2.6.2-1jammy.20220729.132941

Expected Behavior

Multiple calls to ros2 bag record -a should each subscribe to discovered topics.

Actual Behavior

On the 2nd or 3rd call to record, with other nodes publishing data continuously, the mysterious RTPS error appears.

To Reproduce

  1. Run test.launch.py:
from launch import LaunchDescription
from launch.actions import ExecuteProcess
from launch.substitutions import FindExecutable
from launch_ros.actions import Node


def generate_launch_description():
    """Generate the args and items to launch."""

    # Create the launch description and populate
    ld = LaunchDescription()

    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker1'))
    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker2'))
    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker3'))
    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker4'))
    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker5'))
    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker6'))
    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker7'))
    ld.add_action(Node(executable='talker', package='demo_nodes_cpp', name='talker8'))
    return ld
  1. In a separate terminal, run ros2 bag record -a
  2. Ctrl-C on the recorder
  3. Run record again - ros2 bag record -a

This is the output I get on my system from running these steps:

matt@PC2H5J9T:~/working_dir$ ros2 bag record -a 
[INFO] [1668017815.847978199] [rosbag2_recorder]: Press SPACE for pausing/resuming
[INFO] [1668017815.849051968] [rosbag2_storage]: Opened database 'rosbag2_2022_11_09-10_16_55/rosbag2_2022_11_09-10_16_55_0.db3' for READ_WRITE.
[INFO] [1668017815.849105849] [rosbag2_recorder]: Listening for topics...
[INFO] [1668017815.850389463] [rosbag2_recorder]: Subscribed to topic '/rosout'
[INFO] [1668017815.851206109] [rosbag2_recorder]: Subscribed to topic '/parameter_events'
[INFO] [1668017815.852274438] [rosbag2_recorder]: Subscribed to topic '/chatter'
[INFO] [1668017817.968355036] [rclcpp]: signal_handler(signum=2)
[INFO] [1668017818.038663066] [rosbag2_cpp]: Writing remaining messages from cache to the bag. It may take a while
matt@PC2H5J9T:~/working_dir$ ros2 bag record -a 
[INFO] [1668017819.339177238] [rosbag2_recorder]: Press SPACE for pausing/resuming
[INFO] [1668017819.340166298] [rosbag2_storage]: Opened database 'rosbag2_2022_11_09-10_16_59/rosbag2_2022_11_09-10_16_59_0.db3' for READ_WRITE.
[INFO] [1668017819.340221562] [rosbag2_recorder]: Listening for topics...
[INFO] [1668017819.341555361] [rosbag2_recorder]: Subscribed to topic '/rosout'
[INFO] [1668017819.342413985] [rosbag2_recorder]: Subscribed to topic '/parameter_events'
[INFO] [1668017819.343533922] [rosbag2_recorder]: Subscribed to topic '/chatter'
2022-11-09 10:16:59.351 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.351 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.351 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.351 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.351 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.351 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.352 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
2022-11-09 10:16:59.421 [RTPS_MSG_IN Error] (ID:140130310182464) Problem reserving CacheChange in reader: 01.0f.17.88.6a.2c.82.69.01.00.00.00|0.0.11.4 -> Function processDataMsg
[INFO] [1668017820.732013510] [rclcpp]: signal_handler(signum=2)
[INFO] [1668017820.790826910] [rosbag2_cpp]: Writing remaining messages from cache to the bag. It may take a while
matt@PC2H5J9T:~/working_dir$

System (please complete the following information)

  • OS: Ubuntu 22, kernel 5.15.0-39-generic
  • ROS 2 Distro: Humble
  • Version: ros-humble-ros2bag: 0.15.2-1jammy.20220620.235821

Additional context

On a production system, I see fewer instances of that RTPS error when --qos-profile-overrides-path is specified. This behavior persists even if the overrides file doesn't contain entries related to topics in the system; it appears that providing the file alone might modify the QoS of unrelated subscribers in the bag recorder.

mwcondino avatar Nov 09 '22 18:11 mwcondino

@mwcondino The errors coming from Fast-DDS transport layer. Indeed It looks like https://github.com/eProsima/Fast-DDS/pull/2942/files has not been released with Humble in your ROS2 distro version. I've just tried to review relevant code in rosbag2 recorder and haven't found anything suspicious or something which could lead to this issue.

In case when you see those error messages - does rosbag2 recorder still recording messages as previous calls without error messages?

MichaelOrlov avatar Nov 11 '22 03:11 MichaelOrlov

  • Closing this issue as wouldn't fix since the problem on the transport layer i.e., FAST-DDS

MichaelOrlov avatar May 05 '24 03:05 MichaelOrlov