Ros bag reindex failed to generate topic inside metadata.yaml if the message_count is 0

KoolElmout commented 4 weeks ago

Description

On re-indexing a sqllite3 rosbag which originally contains a topic with 0 data inside (message_count:0), the metadata.yaml is not generated properly. The full topic is absent.

This bug was discovered using the python Teranis rosbags reader's library. (Confer https://gitlab.com/ternaris/rosbags/-/issues/91).

Expected Behavior

The reindex rosbag 's metadata.yaml file shall contains the topic with message_count:0 eg:

    - topic_metadata:
        name: /tract/control_signals
        type:msgs/msg/ControlSignal
        serialization_format: cdr
        offered_qos_profiles: "- history: 3\n  depth: 0\n  reliability: 1\n  durability: 2\n  deadline:\n    sec: 9223372036\n    nsec: 854775807\n  lifespan:\n    sec: 9223372036\n    nsec: 854775807\n  liveliness: 1\n  liveliness_lease_duration:\n    sec: 9223372036\n    nsec: 854775807\n  avoid_ros_namespace_conventions: false"
      message_count: 0

Actual Behavior

Actually, the full topic section is not present after re-index.

To Reproduce

Steps to reproduce the behavior: 1) Take a sqlite bag with at least a topic which has a message_count at 0. 2) Remove the metadata.yaml 3) Launch the command ros2 bag reindex -s sqlite3 mybag 4) Check the generated metadata.yaml, all topics with 0 message count have disappeared.

PS: This permit to re-generate the problem. In the true world, it shall permit to generate the metadata.yaml in case it has not been generated (which happens several time a day in my case.)

System (please complete the following information)

OS: [e.g. Ubuntu 22.04]
ROS 2 Distro: [Humble]
Install Method: [APT, release ]
Version: ros-humble-ros2bag 0.15.9-1jammy.20240217.104352 amd6

Additional context

If we place back from the original data to the re-indexed one the topic section, the python Teranis rosbags reader's library read the file properly. If not it failed. We conclude that the information shall be present inside the db3 but not reported in metadata.yaml.

MichaelOrlov commented 4 weeks ago

Preliminary analysis. The problem is not really in the reindexer but rather in the SqliteStorage::get_metadata() function. This could be fixed in the https://github.com/ros2/rosbag2/blob/579fddfae72f371aa00aae144cb8069645afb43b/rosbag2_storage_default_plugins/src/rosbag2_storage_default_plugins/sqlite/sqlite_storage.cpp#L491-L548

KoolElmout commented 3 weeks ago

Thank. Yes you are right, the JOIN statement eliminate the 0 message count topic. I added a dedicated SQL query to specifically detect this case. : https://github.com/KoolElmout/rosbag2/blob/humble/rosbag2_storage_default_plugins/src/rosbag2_storage_default_plugins/sqlite/sqlite_storage.cpp

KoolElmout commented 3 weeks ago

This generates the topics with message_count:0 inside the metadate.yaml. (I notice some error with colcon test, i am working on it but my patch already solve the problem)

KoolElmout commented 3 weeks ago

I solve all but 1 problem during colcon test. https://github.com/KoolElmout/rosbag2/blob/humble/rosbag2_storage_default_plugins/src/rosbag2_storage_default_plugins/sqlite/sqlite_storage.cpp

And here it is a dilemma that should be assert by the team working on the ros2 play. The awaited primitive_message > 3 or array_messages >=2 is not respected anymore and this is normal due to the patch that also sendback topic with no message when playing. So it is a philosophy problem. How do you propose to solve it ? 1) add another command line options for re-index which allow the 0 message count to be taken into account ? 2) add an optional argument to getMetadata which detect if play or re-index ? <= My prefered 3) others ?


colcon test-result --verbose
build/rosbag2_tests/Testing/20240619-1502/Test.xml: 12 tests, 0 errors, 1 failure, 0 skipped
- test_rosbag2_play_end_to_end
  <<< failure message
    -- run_test.py: invoking following command in '/home/user/project/ros2bag/build/rosbag2_tests':
     - /home/user/project/ros2bag/build/rosbag2_tests/test_rosbag2_play_end_to_end --gtest_output=xml:/home/user/project/ros2bag/build/rosbag2_tests/test_results/rosbag2_tests/test_rosbag2_play_end_to_end.gtest.xml
    Running main() from gmock_main.cc
    [==========] Running 4 tests from 1 test suite.
    [----------] Global test environment set-up.
    [----------] 4 tests from PlayEndToEndTestFixture
    [ RUN      ] PlayEndToEndTestFixture.play_end_to_end_test
    [INFO] [1718809387.834169082] [rosbag2_storage]: Opened database 'cdr_test/cdr_test_0.db3' for READ_ONLY.
    [INFO] [1718809387.834260770] [rosbag2_player]: Set rate to 1
    [INFO] [1718809387.837349289] [rosbag2_player]: Adding keyboard callbacks.
    [INFO] [1718809387.837375090] [rosbag2_player]: Press SPACE for Pause/Resume
    [INFO] [1718809387.837381044] [rosbag2_player]: Press CURSOR_RIGHT for Play Next Message
    [INFO] [1718809387.837385247] [rosbag2_player]: Press CURSOR_UP for Increase Rate 10%
    [INFO] [1718809387.837388854] [rosbag2_player]: Press CURSOR_DOWN for Decrease Rate 10%
    [INFO] [1718809387.837666500] [rosbag2_storage]: Opened database 'cdr_test/cdr_test_0.db3' for READ_ONLY.
    /home/user/project/ros2bag/src/rosbag2_tests/test/rosbag2_tests/test_rosbag2_play_end_to_end.cpp:78: Failure
    Value of: primitive_messages
    Expected: size is >= 3
      Actual: {}, whose size 0 doesn't match
    /home/user/project/ros2bag/src/rosbag2_tests/test/rosbag2_tests/test_rosbag2_play_end_to_end.cpp:83: Failure
    Value of: array_messages
    Expected: size is >= 2
      Actual: {}, whose size 0 doesn't match
    [  FAILED  ] PlayEndToEndTestFixture.play_end_to_end_test (10012 ms)
    [ RUN      ] PlayEndToEndTestFixture.play_fails_gracefully_if_bag_does_not_exist
    [       OK ] PlayEndToEndTestFixture.play_fails_gracefully_if_bag_does_not_exist (209 ms)
    [ RUN      ] PlayEndToEndTestFixture.play_fails_gracefully_if_needed_coverter_plugin_does_not_exist
    [       OK ] PlayEndToEndTestFixture.play_fails_gracefully_if_needed_coverter_plugin_does_not_exist (435 ms)
    [ RUN      ] PlayEndToEndTestFixture.play_end_to_end_exits_gracefully_on_sigint
    [INFO] [1718809398.455366086] [rosbag2_storage]: Opened database '/home/user/project/ros2bag/src/rosbag2_tests/resources/cdr_test/cdr_test_0.db3' for READ_ONLY.
    [INFO] [1718809398.455480502] [rosbag2_player]: Set rate to 1
    [INFO] [1718809398.459619238] [rosbag2_player]: Adding keyboard callbacks.
    [INFO] [1718809398.459658353] [rosbag2_player]: Press SPACE for Pause/Resume
    [INFO] [1718809398.459667430] [rosbag2_player]: Press CURSOR_RIGHT for Play Next Message
    [INFO] [1718809398.459673495] [rosbag2_player]: Press CURSOR_UP for Increase Rate 10%
    [INFO] [1718809398.459678420] [rosbag2_player]: Press CURSOR_DOWN for Decrease Rate 10%
    [INFO] [1718809398.460145469] [rosbag2_storage]: Opened database '/home/user/project/ros2bag/src/rosbag2_tests/resources/cdr_test/cdr_test_0.db3' for READ_ONLY.
    [INFO] [1718809398.562184405] [rclcpp]: signal_handler(signum=2)
    [       OK ] PlayEndToEndTestFixture.play_end_to_end_exits_gracefully_on_sigint (539 ms)
    [----------] 4 tests from PlayEndToEndTestFixture (11195 ms total)

    [----------] Global test environment tear-down
    [==========] 4 tests from 1 test suite ran. (11203 ms total)
    [  PASSED  ] 3 tests.
    [  FAILED  ] 1 test, listed below:
    [  FAILED  ] PlayEndToEndTestFixture.play_end_to_end_test

     1 FAILED TEST
    -- run_test.py: return code 1
    -- run_test.py: inject classname prefix into gtest result file '/home/user/project/ros2bag/build/rosbag2_tests/test_results/rosbag2_tests/test_rosbag2_play_end_to_end.gtest.xml'
    -- run_test.py: verify result file '/home/user/project/ros2bag/build/rosbag2_tests/test_results/rosbag2_tests/test_rosbag2_play_end_to_end.gtest.xml'
  >>>
build/rosbag2_tests/test_results/rosbag2_tests/test_rosbag2_play_end_to_end.gtest.xml: 4 tests, 0 errors, 1 failure, 0 skipped
- rosbag2_tests.PlayEndToEndTestFixture play_end_to_end_test
  <<< failure message
    /home/user/project/ros2bag/src/rosbag2_tests/test/rosbag2_tests/test_rosbag2_play_end_to_end.cpp:78
    Value of: primitive_messages
    Expected: size is >= 3
      Actual: {}, whose size 0 doesn't match
    /home/user/project/ros2bag/src/rosbag2_tests/test/rosbag2_tests/test_rosbag2_play_end_to_end.cpp:83
    Value of: array_messages
    Expected: size is >= 2
      Actual: {}, whose size 0 doesn't match
  >>>

Summary: 2699 tests, 0 errors, 2 failures, 626 skipped

KoolElmout commented 3 weeks ago

OK, i truly needed this function that i took the lead over the team (sorry). I implement the 2nd solution. On re-index only the patch is applied. All colcon test are working now without any errors or warnings. Thank again MichaelOrlov for your help, your direction was really help-full. Here is the pull request: https://github.com/ros2/rosbag2/pull/1720

fujitatomoya commented 3 weeks ago

Preliminary analysis. The problem is not really in the reindexer but rather in the SqliteStorage::get_metadata() function. This could be fixed in the

https://github.com/ros2/rosbag2/blob/579fddfae72f371aa00aae144cb8069645afb43b/rosbag2_storage_default_plugins/src/rosbag2_storage_default_plugins/sqlite/sqlite_storage.cpp#L491-L548

this is correct, just sharing that this does not happen with mcap. (the following is with rolling)

root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 bag info -v rosbag2_2024_06_22-11_00_14

Files:             rosbag2_2024_06_22-11_00_14_0.mcap
Bag size:          26.4 KiB
Storage id:        mcap
ROS Distro:        rolling
Duration:          0.10s
Start:             Jun 22 2024 11:00:14.320 (1719079214.320)
End:               Jun 22 2024 11:00:14.331 (1719079214.331)
Messages:          10
Topic information: Topic: /events/write_split | Type: rosbag2_interfaces/msg/WriteSplitEvent | Count: 0 | Serialization Format: cdr
                   Topic: /greetings | Type: example_interfaces/msg/String | Count: 0 | Serialization Format: cdr
                   Topic: /rosout | Type: rcl_interfaces/msg/Log | Count: 9 | Serialization Format: cdr
                   Topic: /some_topic | Type: std_msgs/msg/Bool | Count: 1 | Serialization Format: cdr
                   Topic: /parameter_events | Type: rcl_interfaces/msg/ParameterEvent | Count: 0 | Serialization Format: cdr
Service:           0
Service information:

root@tomoyafujita:~/ros2_ws/colcon_ws# rm rosbag2_2024_06_22-11_00_14/metadata.yaml

root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 bag info -v rosbag2_2024_06_22-11_00_14
Could not find metadata in bag directory rosbag2_2024_06_22-11_00_14

root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 bag reindex rosbag2_2024_06_22-11_00_14/
[INFO] [1719079320.832050674] [rosbag2_cpp]: Beginning reindexing bag in directory: "rosbag2_2024_06_22-11_00_14/"

closing.
[INFO] [1719079320.846152483] [rosbag2_cpp]: Reindexing complete.

root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 bag reindex rosbag2_2024_06_22-11_00_14/
[INFO] [1719079320.832050674] [rosbag2_cpp]: Beginning reindexing bag in directory: "rosbag2_2024_06_22-11_00_14/"

closing.
[INFO] [1719079320.846152483] [rosbag2_cpp]: Reindexing complete.
root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 bag info -v rosbag2_2024_06_22-11_00_14

Files:             rosbag2_2024_06_22-11_00_14_0.mcap
Bag size:          26.3 KiB
Storage id:        mcap
ROS Distro:        rolling
Duration:          0.10s
Start:             Jun 22 2024 11:00:14.320 (1719079214.320)
End:               Jun 22 2024 11:00:14.331 (1719079214.331)
Messages:          10
Topic information: Topic: /events/write_split | Type: rosbag2_interfaces/msg/WriteSplitEvent | Count: 0 | Serialization Format: cdr
                   Topic: /greetings | Type: example_interfaces/msg/String | Count: 0 | Serialization Format: cdr
                   Topic: /parameter_events | Type: rcl_interfaces/msg/ParameterEvent | Count: 0 | Serialization Format: cdr
                   Topic: /rosout | Type: rcl_interfaces/msg/Log | Count: 9 | Serialization Format: cdr
                   Topic: /some_topic | Type: std_msgs/msg/Bool | Count: 1 | Serialization Format: cdr
Service:           0
Service information:

ros2 / rosbag2