search

eclipse-zenoh / zenoh-plugin-ros2dds

A Zenoh plug-in for ROS2 with a DDS RMW. See https://discourse.ros.org/t/ros-2-alternative-middleware-report/ for the advantages of using this plugin over other DDS RMW implementations.
https://zenoh.io
Other
118 stars 27 forks source link

[Bug] Issue with nav2 when using the bridge #31

Closed samiamlabs closed 8 months ago

samiamlabs commented 10 months ago

Describe the bug

When the zenoh bridge is running and I launch navigation2, the lifecycle transitions seem to be acting up. Also, sending navgoals fail.

An example output for the lifecycle thing is:

[controller_server-1] [WARN] [1702648966.041332898] [rcl_lifecycle]: No transition matching 1 found for current state inactive
[controller_server-1] [ERROR] [1702648966.041406110] [controller_server]: Unable to start transition 1 from current state inactive: Transition is not registered., at ./src/rcl_lifecycle.c:355

As far as I can tell, the nodes are activated despite the error.

However, when the bridge is running in one of my gazebo simulations, bt_navigator dies after I send a navgoal. Sending navgoals works fine when I don't run the bridge.

[rviz2-16] [INFO] [1702651216.046634453] [rviz2]: Setting goal pose: Frame:robot2/map, Position(-0.481345, 2.39804, 0), Orientation(0, 0, 0.865052, 0.501682) = Angle: 2.09051
[bt_navigator-12] terminate called after throwing an instance of 'std::runtime_error'
[bt_navigator-12]   what():  Failed to accept new goal
[bt_navigator-12] 
[bt_navigator-12] [INFO] [1702651216.047840482] [robot2.bt_navigator]: Begin navigating from current location (-0.00, 0.00) to (-0.48, 2.40)
[ERROR] [bt_navigator-12]: process has died [pid 11670, exit code -6, cmd '/opt/ros/humble/lib/nav2_bt_navigator/bt_navigator --ros-args -r __node:=bt_navigator -r __ns:=/robot2 --params-file /tmp/tmpsue952wd -r odom:=odometry/global -r /tf:=tf -r /tf_static:=tf_static'].

I tried starting the bridge after I had already started the simulation with nav2 and made sure that sending navgoals worked. Sending another navgoal after I started the bridge resulted in:

[rviz2-16] [INFO] [1702651950.991863971] [rviz2]: Setting goal pose: Frame:robot1/map, Position(-1.25979, 1.01845, 0), Orientation(0, 0, 0.999542, 0.0302465) = Angle: 3.08109
[bt_navigator-12] [INFO] [1702651950.992806330] [robot1.bt_navigator]: Begin navigating from current location (0.00, 0.71) to (-1.26, 1.02)
[bt_navigator-12] terminate called after throwing an instance of 'std::runtime_error'
[bt_navigator-12]   what():  Failed to accept new goal
[bt_navigator-12] 
[planner_server-10] terminate called after throwing an instance of 'std::runtime_error'
[planner_server-10]   what():  Failed to accept new goal
[planner_server-10] 
[ERROR] [bt_navigator-12]: process has died [pid 22391, exit code -6, cmd '/opt/ros/humble/lib/nav2_bt_navigator/bt_navigator --ros-args -r __node:=bt_navigator -r __ns:=/leo1 --params-file /tmp/tmp1k_whwny -r odom:=odometry/global -r /tf:=tf -r /tf_static:=tf_static'].
[ERROR] [planner_server-10]: process has died [pid 22386, exit code -6, cmd '/opt/ros/humble/lib/nav2_planner/planner_server --ros-args -r __node:=planner_server -r __ns:=/leo1 --params-file /tmp/tmp3be7p5hf -r /tf:=tf -r /tf_static:=tf_static'].

To reproduce

To reproduce the lifecycle errors:

  1. Clone https://github.com/ros-planning/navigation2
  2. Open navigation2 as a Dev Container
  3. export RMW_IMPLEMENTATION=rmw_cyclonedds_cpp in the teminals you use in the container
  4. Download the latest zenoh-bridge-ros2dds from https://github.com/eclipse-zenoh/zenoh-plugin-ros2dds/actions
  5. Run ./zenoh-bridge-ros2dds -l tcp/0.0.0.0:7447 in the Dev Container
  6. ros2 launch nav2_bringup navigation_launch.py

I have only seen the crashing nodes when I send a navgoal in my own simulation, but I suspect the issue is general. If you don't have a simulated robot environment to test this in, I can set up a Dev Container with turtlebots or something.

System info

btertoolen commented 10 months ago

I am facing the exact same issue, running the nav2 controller-server with some custom (but simple) controller plugins. It seems like the lifecycle transitions are attempted twice when zenoh is running. I tested running a simple python node with some prints in the callbacks, and there I saw that its service calls weren't being executed twice. I don't know what would make the lifecycle service calls behave differently.

When attempting to send the action goal to the controller server, I get the same runtime exception:

[controller_server-1] [INFO] [1702891959.734452727] [controller_server]: Received a goal, begin computing control effort.
[controller_server-1] terminate called after throwing an instance of 'std::runtime_error'
[controller_server-1]   what():  Failed to accept new goal
[controller_server-1] 
[ERROR] [controller_server-1]: process has died [pid 1760, exit code -6, cmd '/opt/ros/humble/lib/nav2_controller/controller_server --ros-args -r __node:=controller_server -r __ns:=/ --params-file ***.yaml -r /cmd_vel:=/robot/cmd_vel'].

I have been looking into this for some time now, but I still have no idea what could be causing this.

I am also using cyclone-dds, on an Nvida Jetson running Ubuntu 20.04.5 LTS (GNU/Linux 5.10.104-tegra aarch64)

@samiamlabs did you manage to get any new insights?

miltzhaw commented 10 months ago

I am facing the same issue in a slightly different setting. I have a turtlebot2 with nav2 and the Zenoh ro2dds bridge connected over a Zenoh router to another Zenoh ro2dds bridge where I run RVIZ. Both machines use cyclone-dds and DDS traffic remains locally. When I give a goal pose (action) from Rviz the navigation node dies on the turtlebot:

[component_container_isolated-8] [INFO] [1703082979.885569222] [bt_navigator]: Begin navigating from current location (-14.87, -0.51) to (-14.94, -0.22)
[component_container_isolated-8] terminate called after throwing an instance of 'std::runtime_error'
[component_container_isolated-8]   what():  Failed to accept new goal
[component_container_isolated-8] 
[component_container_isolated-8] Magick: abort due to signal 6 (SIGABRT) "Abort"...
[ERROR] [component_container_isolated-8]: process has died [pid 1691, exit code -6, cmd '/opt/ros/humble/lib/rclcpp_components/component_container_isolated --ros-args --log-level info --ros-args -r __node:=nav2_container --params-file /tmp/launch_params_9hiirbx0 --params-file /tmp/launch_params_aox_pcps -r /tf:=tf -r /tf_static:=tf_static'].

The Zenoh bridge gives a warning when this happens which is as follows:

[2023-12-20T14:20:36Z WARN  zenoh_plugin_ros2dds::route_service_srv] Route Service Server (ROS:/compute_path_to_pose/_action/send_goal <-> Zenoh:tb2-1/compute_path_to_pose/_action/send_goal): received response for another client: 70f786a63f39626e (me: a9dc1c8a3b36783)
[2023-12-20T14:20:36Z WARN  zenoh_plugin_ros2dds::route_service_srv] Route Service Server (ROS:/navigate_to_pose/_action/send_goal <-> Zenoh:tb2-1/navigate_to_pose/_action/send_goal): received response for another client: c46c9d06bfe99af1 (me: f9643760349f4104)
[2023-12-20T14:20:46Z WARN  zenoh_plugin_ros2dds::route_service_cli] Route Service Client (ROS:/compute_path_to_pose/_action/get_result <-> Zenoh:tb2-1/compute_path_to_pose/_action/get_result): received error as reply for [9c, 03, 8b, b2, f2, 7e, e5, 28, 27, 00, 00, 00, 00, 00, 00, 00]: Timeout

What I also noticed, is that the Zenoh bridge should be started after the turtlebot bringup, otherwise the nodes will node start up correctly. But I don't know if these two issues are part of the same problem.

Did you find any solution for this?

JEnoch commented 10 months ago

@samiamlabs : I managed to install Navigation2 as a Dev Container and to run it inside, along zenoh-bridge-ros2dds. However it's using rolling and doesn't seems to work properly with my turtlebot3 simulation running on my host with humble. I get some Failed to parse type hash for topic errors from rmw_cyclonedds_cpp that make me guess some types changed fince humble. If you can provide me a Dev Container for some robot simulation, as well as instructions to reproduce the crash, I would be able to reproduce and debug.

I'm not sure how lifecycle nodes are implemented in ROS 2, and especially if they rely on Services or Actions. But the "Timeout" log on call to "/compute_path_to_pose/_action/get_result" in @miltzhaw 's comment makes me think all those issues could be related to the bridge being configured with a default timeout of 5 seconds to all queries (i.e. for any call to Service or Action).

Could you please all try to increase this timeout to 10 minutes (or more) on all your bridges:

Note that this setting was added recently, in commit 6e04f60a.

miltzhaw commented 10 months ago

@JEnoch I just tested what you suggested, changing the timeout value to different values even much higher than 600. While the timeout warning seems to be gone when I use very high values it still doesn't work and I get the following warning on the control bridge before the node dies on the turtlebot:

[2023-12-21T13:53:39Z WARN  zenoh_plugin_ros2dds::route_service_srv] Route Service Server (ROS:/navigate_to_pose/_action/send_goal <-> Zenoh:bot1/navigate_to_pose/_action/send_goal): received response for another client: 7823923a07042a85 (me: 5a16ba2a5fcca52e)
JEnoch commented 10 months ago

Thanks for testing. Could you please send the full logs of the 2 bridges with environment variable: RUST_LOG=zenoh_plugin=trace

miltzhaw commented 9 months ago

I just sent you the full logs per email as they are quite long, thanks

JEnoch commented 9 months ago

Thanks @miltzhaw! I reviewed your logs.

The received response for another client WARN happen when the bridge receives a Service Response message for a a Request initiated by another Service Client than itself. This actually can happen at any time and is not an error, since with Services over DDS the same Reply topic is used for replies to all Clients. This log shouldn't be at WARN level, but rather at DEBUG or TRACE.

On another hand, I saw that each message on /tf topic looks to be routed from the Robot to Zenoh, and then back from Zenoh to the Robot! That shouldn't happen, and lead for a Subscriber on /tf topic in the Robot to receive each message twice... Not sure if that's the cause of troubles with nav2. Anyway, that must be fixed and that's what I did in #41.

I'll now do some tests with Lifecycle Nodes to check if they are correctly supported.

JEnoch commented 9 months ago

There was indeed a bug with Services leading to issue with Lifecycle Nodes: see #43 That's now fixed in main branch.

@samiamlabs , @btertoolen: could you please test with this fix and tell me if this solved your issue with nav2 ?

samiamlabs commented 9 months ago

Hi @JEnoch!

I did a quick test with Release #88 of the bridge, and so far nav2 seems to be working! Will do some more testing this week and get back to you.

Thanks a bunch for fixing this :)

btertoolen commented 9 months ago

Hi @JEnoch, using the latest build indeed seems to have resolved the issue, so thanks! We will do some more testing, so if we notice anything else I will let you know.

samiamlabs commented 9 months ago

Have not had time to do extensive testing but did some more of it. I found no problems that I think are related to the bridge during the testing. This issue looks fixed as far as I can tell :)

JEnoch commented 9 months ago

Thanks for your confirmations @btertoolen and @samiamlabs ! I then close this issue. Feel free to open a new one if you get new problems.

I'll do a patch release (0.10.1-rc2) with those fixes (#41, #43) in the coming days.

miltzhaw commented 9 months ago

Sorry for the late reply @JEnoch but I couldn't test it until today. The good news is that it worked for me as well now for the tests I have done so far. Thanks a lot for your support, will do more testing in the coming days. As a note, to make it work I also had to configure the bridges with timestamping enabled as the Warning messages were telling me:

  timestamping: {
    enabled: true,
    drop_future_timestamp: false,
  },
ciandonovan commented 9 months ago

Unfortunately I'm still able to reproduce on the latest main (2d9f8c999f497c0d713fef5235c9822970747c13) and using the latest commit on the Humble branch of Nav2 (d29de3dbfcd2513d962357b75aa4db9296bd9620).

Including @miltzhaw's config tweak doesn't help either.

Does the merged fix only work with rolling?

JEnoch commented 9 months ago

Hi @ciandonovan, the bridge should work with any ROS 2 version (at least from Foxy).

Could you please create a new issue describing what you're experiencing, adding logs (debug level) of bridges, and ideally with a simple way to reproduce.

ciandonovan commented 9 months ago

@JEnoch this is specifically regarding the Nav2 bringup issue, as described by OP @samiamlabs. Was able to reproduce the original issue with an almost identical setup, will send some reproduceable containers later.

ciandonovan commented 9 months ago

podman run -it --rm --net=host --env RMW_IMPLEMENTATION=rmw_cyclonedds_cpp ghcr.io/ciandonovan/ros2_zenoh_bridge:main ros2 run zenoh_bridge_ros2dds zenoh_bridge_ros2dds -l tcp/0.0.0.0:7447

podman run -it --rm --net=host --env RMW_IMPLEMENTATION=rmw_cyclonedds_cpp ghcr.io/ciandonovan/ros2_navigation:main ros2 launch nav2_bringup bringup_launch.py map:=src/navigation2/nav2_bringup/maps/turtlebot3_world.yaml

When running navigation2 with Zenoh already running, it hangs on: [INFO] [component_container_isolated-1]: process started with pid [57]

When running navigation2 without Zenoh, it works fine, all nodes are brought up by the lifecycle manager.

Links to the sources used to build the containers, with the upstream code repos as submodules, listed below. Zenoh is built from main, navigation2 is built from the humble branch.

https://github.com/ciandonovan/ros2_navigation https://github.com/ciandonovan/ros2_zenoh_bridge

miltzhaw commented 9 months ago

I actually observed something similar as @ciandonovan is mentioning. Namely, I had to start the zenoh bridge after the turtlebot bringup. If the zenoh bridge was already running, the turtlebot bringup would be hanging and not bring all nodes up.

ciandonovan commented 9 months ago

@miltzhaw that's exactly what I'm seeing too, our workaround is as you said, start the bridge after bringup.

Doing it manually at the moment, could automate it with systemd service dependencies and systemd notify which would reduce race conditions somewhat, but hopefully the underlying issue will be resolved.

@JEnoch could you re-open this issue?

JEnoch commented 9 months ago

@ciandonovan Thanks for the podman containers. I managed to install and run those.

I see the same log as you. But I don't know what is stuck in nav2 launch. On bridge side, I see 2 nodes have been discovered (launch_ros1 and nav2_container), but with not so much topics/services except the usual rosout, the parameters topics and some node loading/unloading/list services. What is the launch suppose to do after starting those nodes ?

ciandonovan commented 9 months ago

This is what it's supposed to look like, and what it looks like when the Zenoh bridge is not running.

$ podman run -it --rm --net=host --env RMW_IMPLEMENTATION=rmw_cyclonedds_cpp ghcr.io/ciandonovan/ros2_navigation:main ros2 launch nav2_bringup bringup_launch.py map:=src/navigation2/nav2_bringup/maps/turtlebot3_world.yaml
[INFO] [launch]: All log files can be found below /root/.ros/log/2024-01-18-13-52-28-065297-XXXXXXXXX
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [component_container_isolated-1]: process started with pid [57]
[component_container_isolated-1] [INFO] [1705585949.731211807] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_map_server/lib/libmap_server_core.so
[component_container_isolated-1] [INFO] [1705585949.836903250] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_map_server::CostmapFilterInfoServer>
[component_container_isolated-1] [INFO] [1705585949.836977441] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_map_server::MapSaver>
[component_container_isolated-1] [INFO] [1705585949.836991465] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_map_server::MapServer>
[component_container_isolated-1] [INFO] [1705585949.837003750] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_map_server::MapServer>
[component_container_isolated-1] [INFO] [1705585949.844047585] [map_server]: 
[component_container_isolated-1]    map_server lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585949.844714698] [map_server]: Creating
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/map_server' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585949.846149714] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_controller/lib/libcontroller_server_core.so
[component_container_isolated-1] [INFO] [1705585949.872954283] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_controller::ControllerServer>
[component_container_isolated-1] [INFO] [1705585949.873055008] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_controller::ControllerServer>
[component_container_isolated-1] [INFO] [1705585949.878496003] [controller_server]: 
[component_container_isolated-1]    controller_server lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585949.906274746] [controller_server]: Creating controller server
[component_container_isolated-1] [INFO] [1705585949.912333473] [local_costmap.local_costmap]: 
[component_container_isolated-1]    local_costmap lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585949.916742305] [local_costmap.local_costmap]: Creating Costmap
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/controller_server' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585949.919630998] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_amcl/lib/libamcl_core.so
[component_container_isolated-1] [INFO] [1705585949.934024675] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_amcl::AmclNode>
[component_container_isolated-1] [INFO] [1705585949.934133923] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_amcl::AmclNode>
[component_container_isolated-1] [INFO] [1705585949.939314165] [amcl]: 
[component_container_isolated-1]    amcl lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585949.943059011] [amcl]: Creating
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/amcl' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585949.945399930] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_smoother/lib/libsmoother_server_core.so
[component_container_isolated-1] [INFO] [1705585949.955286781] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_smoother::SmootherServer>
[component_container_isolated-1] [INFO] [1705585949.955350711] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_smoother::SmootherServer>
[component_container_isolated-1] [INFO] [1705585949.960006677] [smoother_server]: 
[component_container_isolated-1]    smoother_server lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585949.966104652] [smoother_server]: Creating smoother server
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/smoother_server' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585949.967586983] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_lifecycle_manager/lib/libnav2_lifecycle_manager_core.so
[component_container_isolated-1] [INFO] [1705585949.973157130] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_lifecycle_manager::LifecycleManager>
[component_container_isolated-1] [INFO] [1705585949.973233420] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_lifecycle_manager::LifecycleManager>
[component_container_isolated-1] [INFO] [1705585949.979817679] [lifecycle_manager_localization]: Creating
[component_container_isolated-1] [INFO] [1705585949.988924911] [lifecycle_manager_localization]: Creating and initializing lifecycle service clients
[component_container_isolated-1] [INFO] [1705585949.989727061] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_planner/lib/libplanner_server_core.so
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/lifecycle_manager_localization' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585949.995307606] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_planner::PlannerServer>
[component_container_isolated-1] [INFO] [1705585949.995522362] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_planner::PlannerServer>
[component_container_isolated-1] [INFO] [1705585949.997366939] [lifecycle_manager_localization]: Starting managed nodes bringup...
[component_container_isolated-1] [INFO] [1705585949.998018742] [lifecycle_manager_localization]: Configuring map_server
[component_container_isolated-1] [INFO] [1705585949.998425734] [map_server]: Configuring
[component_container_isolated-1] [INFO] [map_io]: Loading yaml file: src/navigation2/nav2_bringup/maps/turtlebot3_world.yaml
[component_container_isolated-1] [DEBUG] [map_io]: resolution: 0.05
[component_container_isolated-1] [DEBUG] [map_io]: origin[0]: -10
[component_container_isolated-1] [DEBUG] [map_io]: origin[1]: -10
[component_container_isolated-1] [DEBUG] [map_io]: origin[2]: 0
[component_container_isolated-1] [DEBUG] [map_io]: free_thresh: 0.196
[component_container_isolated-1] [DEBUG] [map_io]: occupied_thresh: 0.65
[component_container_isolated-1] [DEBUG] [map_io]: mode: trinary
[component_container_isolated-1] [DEBUG] [map_io]: negate: 0
[component_container_isolated-1] [INFO] [1705585950.005163271] [planner_server]: 
[component_container_isolated-1]    planner_server lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [map_io]: Loading image_file: src/navigation2/nav2_bringup/maps/turtlebot3_world.pgm
[component_container_isolated-1] [INFO] [1705585950.010928800] [planner_server]: Creating
[component_container_isolated-1] [INFO] [1705585950.018783156] [global_costmap.global_costmap]: 
[component_container_isolated-1]    global_costmap lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585950.020727601] [global_costmap.global_costmap]: Creating Costmap
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/planner_server' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585950.027388203] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_behaviors/lib/libbehavior_server_core.so
[component_container_isolated-1] [DEBUG] [map_io]: Read map src/navigation2/nav2_bringup/maps/turtlebot3_world.pgm: 384 X 384 map @ 0.05 m/cell
[component_container_isolated-1] [INFO] [1705585950.056233022] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<behavior_server::BehaviorServer>
[component_container_isolated-1] [INFO] [1705585950.056335921] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<behavior_server::BehaviorServer>
[component_container_isolated-1] [INFO] [1705585950.058493059] [lifecycle_manager_localization]: Configuring amcl
[component_container_isolated-1] [INFO] [1705585950.058700585] [amcl]: Configuring
[component_container_isolated-1] [INFO] [1705585950.058859598] [amcl]: initTransforms
[component_container_isolated-1] [INFO] [1705585950.066535273] [behavior_server]: 
[component_container_isolated-1]    behavior_server lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585950.072062410] [amcl]: initPubSub
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/behavior_server' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585950.075759166] [amcl]: Subscribed to map topic.
[component_container_isolated-1] [INFO] [1705585950.077148327] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_bt_navigator/lib/libbt_navigator_core.so
[component_container_isolated-1] [INFO] [1705585950.087209679] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_bt_navigator::BtNavigator>
[component_container_isolated-1] [INFO] [1705585950.087287500] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_bt_navigator::BtNavigator>
[component_container_isolated-1] [INFO] [1705585950.088923493] [lifecycle_manager_localization]: Activating map_server
[component_container_isolated-1] [INFO] [1705585950.089459548] [map_server]: Activating
[component_container_isolated-1] [INFO] [1705585950.089878116] [map_server]: Creating bond (map_server) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585950.090513063] [amcl]: Received a 384 X 384 map @ 0.050 m/pix
[component_container_isolated-1] [INFO] [1705585950.098721160] [bt_navigator]: 
[component_container_isolated-1]    bt_navigator lifecycle node launched. 
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/bt_navigator' in container '/nav2_container'
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585950.098798536] [bt_navigator]: Creating
[component_container_isolated-1] [INFO] [1705585950.103230167] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_waypoint_follower/lib/libwaypoint_follower_core.so
[component_container_isolated-1] [INFO] [1705585950.107536239] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_waypoint_follower::WaypointFollower>
[component_container_isolated-1] [INFO] [1705585950.107610681] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_waypoint_follower::WaypointFollower>
[component_container_isolated-1] [INFO] [1705585950.113734334] [waypoint_follower]: 
[component_container_isolated-1]    waypoint_follower lifecycle node launched. 
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585950.116543316] [waypoint_follower]: Creating
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/waypoint_follower' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585950.120816232] [nav2_container]: Load Library: /opt/ros/overlay_ws/install/nav2_velocity_smoother/lib/libvelocity_smoother_core.so
[component_container_isolated-1] [INFO] [1705585950.125509446] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_velocity_smoother::VelocitySmoother>
[component_container_isolated-1] [INFO] [1705585950.125599916] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_velocity_smoother::VelocitySmoother>
[component_container_isolated-1] [INFO] [1705585950.132153139] [velocity_smoother]: 
[component_container_isolated-1]    velocity_smoother lifecycle node launched. 
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/velocity_smoother' in container '/nav2_container'
[component_container_isolated-1]    Waiting on external lifecycle transitions to activate
[component_container_isolated-1]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[component_container_isolated-1] [INFO] [1705585950.136114331] [nav2_container]: Found class: rclcpp_components::NodeFactoryTemplate<nav2_lifecycle_manager::LifecycleManager>
[component_container_isolated-1] [INFO] [1705585950.136168099] [nav2_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<nav2_lifecycle_manager::LifecycleManager>
[component_container_isolated-1] [INFO] [1705585950.140968964] [lifecycle_manager_navigation]: Creating
[component_container_isolated-1] [INFO] [1705585950.142996081] [lifecycle_manager_navigation]: Creating and initializing lifecycle service clients
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/lifecycle_manager_navigation' in container '/nav2_container'
[component_container_isolated-1] [INFO] [1705585950.149695013] [lifecycle_manager_navigation]: Starting managed nodes bringup...
[component_container_isolated-1] [INFO] [1705585950.149774318] [lifecycle_manager_navigation]: Configuring controller_server
[component_container_isolated-1] [INFO] [1705585950.150056212] [controller_server]: Configuring controller interface
[component_container_isolated-1] [INFO] [1705585950.150274841] [controller_server]: getting goal checker plugins..
[component_container_isolated-1] [INFO] [1705585950.150453004] [controller_server]: Controller frequency set to 20.0000Hz
[component_container_isolated-1] [INFO] [1705585950.150550771] [local_costmap.local_costmap]: Configuring
[component_container_isolated-1] [INFO] [1705585950.153589093] [local_costmap.local_costmap]: Using plugin "voxel_layer"
[component_container_isolated-1] [INFO] [1705585950.172172048] [local_costmap.local_costmap]: Subscribed to Topics: scan
[component_container_isolated-1] [INFO] [1705585950.178165830] [local_costmap.local_costmap]: Initialized plugin "voxel_layer"
[component_container_isolated-1] [INFO] [1705585950.178224093] [local_costmap.local_costmap]: Using plugin "inflation_layer"
[component_container_isolated-1] [INFO] [1705585950.179441802] [local_costmap.local_costmap]: Initialized plugin "inflation_layer"
[component_container_isolated-1] [INFO] [1705585950.187226653] [controller_server]: Created progress_checker : progress_checker of type nav2_controller::SimpleProgressChecker
[component_container_isolated-1] [INFO] [1705585950.190051792] [controller_server]: Created goal checker : general_goal_checker of type nav2_controller::SimpleGoalChecker
[component_container_isolated-1] [INFO] [1705585950.190976575] [controller_server]: Controller Server has general_goal_checker  goal checkers available.
[component_container_isolated-1] [INFO] [1705585950.194452198] [lifecycle_manager_localization]: Server map_server connected with bond.
[component_container_isolated-1] [INFO] [1705585950.194532227] [lifecycle_manager_localization]: Activating amcl
[component_container_isolated-1] [INFO] [1705585950.194786337] [amcl]: Activating
[component_container_isolated-1] [INFO] [1705585950.194852017] [amcl]: Creating bond (amcl) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585950.203292427] [controller_server]: Created controller : FollowPath of type dwb_core::DWBLocalPlanner
[component_container_isolated-1] [INFO] [1705585950.205372581] [controller_server]: Setting transform_tolerance to 0.200000
[component_container_isolated-1] [INFO] [1705585950.227288909] [controller_server]: Using critic "RotateToGoal" (dwb_critics::RotateToGoalCritic)
[component_container_isolated-1] [INFO] [1705585950.231807200] [controller_server]: Critic plugin initialized
[component_container_isolated-1] [INFO] [1705585950.232320313] [controller_server]: Using critic "Oscillation" (dwb_critics::OscillationCritic)
[component_container_isolated-1] [INFO] [1705585950.234746901] [controller_server]: Critic plugin initialized
[component_container_isolated-1] [INFO] [1705585950.235379170] [controller_server]: Using critic "BaseObstacle" (dwb_critics::BaseObstacleCritic)
[component_container_isolated-1] [INFO] [1705585950.236805196] [controller_server]: Critic plugin initialized
[component_container_isolated-1] [INFO] [1705585950.237575082] [controller_server]: Using critic "GoalAlign" (dwb_critics::GoalAlignCritic)
[component_container_isolated-1] [INFO] [1705585950.239343312] [controller_server]: Critic plugin initialized
[component_container_isolated-1] [INFO] [1705585950.239841595] [controller_server]: Using critic "PathAlign" (dwb_critics::PathAlignCritic)
[component_container_isolated-1] [INFO] [1705585950.241581353] [controller_server]: Critic plugin initialized
[component_container_isolated-1] [INFO] [1705585950.242687447] [controller_server]: Using critic "PathDist" (dwb_critics::PathDistCritic)
[component_container_isolated-1] [INFO] [1705585950.244169054] [controller_server]: Critic plugin initialized
[component_container_isolated-1] [INFO] [1705585950.244783741] [controller_server]: Using critic "GoalDist" (dwb_critics::GoalDistCritic)
[component_container_isolated-1] [INFO] [1705585950.245916360] [controller_server]: Critic plugin initialized
[component_container_isolated-1] [INFO] [1705585950.246052053] [controller_server]: Controller Server has FollowPath  controllers available.
[component_container_isolated-1] [INFO] [1705585950.253192248] [lifecycle_manager_navigation]: Configuring smoother_server
[component_container_isolated-1] [INFO] [1705585950.253367864] [smoother_server]: Configuring smoother server
[component_container_isolated-1] [INFO] [1705585950.260136864] [smoother_server]: Created smoother : simple_smoother of type nav2_smoother::SimpleSmoother
[component_container_isolated-1] [INFO] [1705585950.261509740] [smoother_server]: Smoother Server has simple_smoother  smoothers available.
[component_container_isolated-1] [INFO] [1705585950.265411254] [lifecycle_manager_navigation]: Configuring planner_server
[component_container_isolated-1] [INFO] [1705585950.265625931] [planner_server]: Configuring
[component_container_isolated-1] [INFO] [1705585950.265701717] [global_costmap.global_costmap]: Configuring
[component_container_isolated-1] [INFO] [1705585950.269485063] [global_costmap.global_costmap]: Using plugin "static_layer"
[component_container_isolated-1] [INFO] [1705585950.271527255] [global_costmap.global_costmap]: Subscribing to the map topic (/map) with transient local durability
[component_container_isolated-1] [INFO] [1705585950.272621007] [global_costmap.global_costmap]: Initialized plugin "static_layer"
[component_container_isolated-1] [INFO] [1705585950.272671312] [global_costmap.global_costmap]: Using plugin "obstacle_layer"
[component_container_isolated-1] [INFO] [1705585950.274911687] [global_costmap.global_costmap]: Subscribed to Topics: scan
[component_container_isolated-1] [INFO] [1705585950.280821719] [global_costmap.global_costmap]: Initialized plugin "obstacle_layer"
[component_container_isolated-1] [INFO] [1705585950.281352874] [global_costmap.global_costmap]: Using plugin "inflation_layer"
[component_container_isolated-1] [INFO] [1705585950.284395385] [global_costmap.global_costmap]: Initialized plugin "inflation_layer"
[component_container_isolated-1] [INFO] [1705585950.289242628] [global_costmap.global_costmap]: StaticLayer: Resizing costmap to 384 X 384 at 0.050000 m/pix
[component_container_isolated-1] [INFO] [1705585950.291849440] [planner_server]: Created global planner plugin GridBased of type nav2_navfn_planner/NavfnPlanner
[component_container_isolated-1] [INFO] [1705585950.291931357] [planner_server]: Configuring plugin GridBased of type NavfnPlanner
[component_container_isolated-1] [INFO] [1705585950.294482785] [planner_server]: Planner Server has GridBased  planners available.
[component_container_isolated-1] [INFO] [1705585950.300250307] [lifecycle_manager_localization]: Server amcl connected with bond.
[component_container_isolated-1] [INFO] [1705585950.300320269] [lifecycle_manager_localization]: Managed nodes are active
[component_container_isolated-1] [INFO] [1705585950.300354464] [lifecycle_manager_localization]: Creating bond timer...
[component_container_isolated-1] [INFO] [1705585950.302040298] [lifecycle_manager_navigation]: Configuring behavior_server
[component_container_isolated-1] [INFO] [1705585950.302268085] [behavior_server]: Configuring
[component_container_isolated-1] [INFO] [1705585950.306673957] [behavior_server]: Creating behavior plugin spin of type nav2_behaviors/Spin
[component_container_isolated-1] [INFO] [1705585950.310216450] [behavior_server]: Configuring spin
[component_container_isolated-1] [INFO] [1705585950.315351776] [behavior_server]: Creating behavior plugin backup of type nav2_behaviors/BackUp
[component_container_isolated-1] [INFO] [1705585950.319159712] [behavior_server]: Configuring backup
[component_container_isolated-1] [INFO] [1705585950.322956937] [behavior_server]: Creating behavior plugin drive_on_heading of type nav2_behaviors/DriveOnHeading
[component_container_isolated-1] [INFO] [1705585950.326567492] [behavior_server]: Configuring drive_on_heading
[component_container_isolated-1] [INFO] [1705585950.330422819] [behavior_server]: Creating behavior plugin assisted_teleop of type nav2_behaviors/AssistedTeleop
[component_container_isolated-1] [INFO] [1705585950.339807387] [behavior_server]: Configuring assisted_teleop
[component_container_isolated-1] [INFO] [1705585950.344108690] [behavior_server]: Creating behavior plugin wait of type nav2_behaviors/Wait
[component_container_isolated-1] [INFO] [1705585950.347445380] [behavior_server]: Configuring wait
[component_container_isolated-1] [INFO] [1705585950.351019941] [lifecycle_manager_navigation]: Configuring bt_navigator
[component_container_isolated-1] [INFO] [1705585950.351260978] [bt_navigator]: Configuring
[component_container_isolated-1] [INFO] [1705585950.523971340] [lifecycle_manager_navigation]: Configuring waypoint_follower
[component_container_isolated-1] [INFO] [1705585950.524185897] [waypoint_follower]: Configuring
[component_container_isolated-1] [INFO] [1705585950.531161852] [waypoint_follower]: Created waypoint_task_executor : wait_at_waypoint of type nav2_waypoint_follower::WaitAtWaypoint
[component_container_isolated-1] [INFO] [1705585950.532665965] [lifecycle_manager_navigation]: Configuring velocity_smoother
[component_container_isolated-1] [INFO] [1705585950.532880244] [velocity_smoother]: Configuring velocity smoother
[component_container_isolated-1] [INFO] [1705585950.537503709] [lifecycle_manager_navigation]: Activating controller_server
[component_container_isolated-1] [INFO] [1705585950.537747335] [controller_server]: Activating
[component_container_isolated-1] [INFO] [1705585950.537818842] [local_costmap.local_costmap]: Activating
[component_container_isolated-1] [INFO] [1705585950.537856457] [local_costmap.local_costmap]: Checking transform
[component_container_isolated-1] [INFO] [1705585950.537905547] [local_costmap.local_costmap]: Timed out waiting for transform from base_link to odom to become available, tf error: Invalid frame ID "odom" passed to canTransform argument target_frame - frame does not exist
[component_container_isolated-1] [INFO] [1705585951.038064295] [local_costmap.local_costmap]: Timed out waiting for transform from base_link to odom to become available, tf error: Invalid frame ID "odom" passed to canTransform argument target_frame - frame does not exist
[component_container_isolated-1] [INFO] [1705585951.537999988] [local_costmap.local_costmap]: Timed out waiting for transform from base_link to odom to become available, tf error: Invalid frame ID "odom" passed to canTransform argument target_frame - frame does not exist
[component_container_isolated-1] [INFO] [1705585952.038063265] [local_costmap.local_costmap]: Timed out waiting for transform from base_link to odom to become available, tf error: Invalid frame ID "odom" passed to canTransform argument target_frame - frame does not exist
^C[WARNING] [launch]: user interrupted with ctrl-c (SIGINT)
[component_container_isolated-1] [INFO] [1705585952.456295875] [rclcpp]: signal_handler(signum=2)
[component_container_isolated-1] [INFO] [1705585952.456493551] [velocity_smoother]: Running Nav2 LifecycleNode rcl preshutdown (velocity_smoother)
[component_container_isolated-1] [INFO] [1705585952.456659188] [velocity_smoother]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.456746630] [velocity_smoother]: Destroying bond (velocity_smoother) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.456781914] [bt_navigator]: Running Nav2 LifecycleNode rcl preshutdown (bt_navigator)
[component_container_isolated-1] [INFO] [1705585952.456839643] [bt_navigator]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.473014302] [bt_navigator]: Completed Cleaning up
[component_container_isolated-1] [INFO] [1705585952.473102712] [bt_navigator]: Destroying bond (bt_navigator) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.473127510] [global_costmap.global_costmap]: Running Nav2 LifecycleNode rcl preshutdown (global_costmap)
[component_container_isolated-1] [INFO] [1705585952.473168374] [global_costmap.global_costmap]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.475398973] [global_costmap.global_costmap]: Destroying bond (global_costmap) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.475458364] [waypoint_follower]: Running Nav2 LifecycleNode rcl preshutdown (waypoint_follower)
[component_container_isolated-1] [INFO] [1705585952.475500677] [waypoint_follower]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.481638594] [waypoint_follower]: Destroying bond (waypoint_follower) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.481714731] [planner_server]: Running Nav2 LifecycleNode rcl preshutdown (planner_server)
[component_container_isolated-1] [INFO] [1705585952.481790240] [planner_server]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.493324717] [planner_server]: Cleaning up plugin GridBased of type NavfnPlanner
[component_container_isolated-1] [INFO] [1705585952.493616478] [planner_server]: Destroying plugin GridBased of type NavfnPlanner
[component_container_isolated-1] [INFO] [1705585952.503476014] [planner_server]: Destroying bond (planner_server) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.503533598] [lifecycle_manager_localization]: Running Nav2 LifecycleManager rcl preshutdown (lifecycle_manager_localization)
[component_container_isolated-1] [INFO] [1705585952.503569822] [lifecycle_manager_localization]: Terminating bond timer...
[component_container_isolated-1] [INFO] [1705585952.529279244] [behavior_server]: Running Nav2 LifecycleNode rcl preshutdown (behavior_server)
[component_container_isolated-1] [INFO] [1705585952.529374783] [behavior_server]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.532865046] [behavior_server]: Destroying bond (behavior_server) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.532917722] [amcl]: Running Nav2 LifecycleNode rcl preshutdown (amcl)
[component_container_isolated-1] [INFO] [1705585952.533005553] [amcl]: Deactivating
[component_container_isolated-1] [INFO] [1705585952.533055314] [amcl]: Destroying bond (amcl) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.533158245] [amcl]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.535855300] [amcl]: Destroying bond (amcl) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.535904409] [smoother_server]: Running Nav2 LifecycleNode rcl preshutdown (smoother_server)
[component_container_isolated-1] [INFO] [1705585952.535945143] [smoother_server]: Cleaning up
[component_container_isolated-1] [INFO] [1705585952.537969089] [local_costmap.local_costmap]: Timed out waiting for transform from base_link to odom to become available, tf error: Invalid frame ID "odom" passed to canTransform argument target_frame - frame does not exist
[component_container_isolated-1] [INFO] [1705585952.544958897] [smoother_server]: Destroying bond (smoother_server) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.545035825] [local_costmap.local_costmap]: Running Nav2 LifecycleNode rcl preshutdown (local_costmap)
[component_container_isolated-1] [INFO] [1705585952.545080102] [local_costmap.local_costmap]: Destroying bond (local_costmap) to lifecycle manager.
[component_container_isolated-1] [INFO] [1705585952.545116358] [lifecycle_manager_navigation]: Running Nav2 LifecycleManager rcl preshutdown (lifecycle_manager_navigation)
JEnoch commented 9 months ago

I think I found the issue: #62 Fix in progress...

JEnoch commented 8 months ago

@ciandonovan the fix has to be reviewed before merging, but you can already test it in the fix_62 branch. I made few tests, including your podman example, and it looks working to me.

ciandonovan commented 8 months ago

I just tested the fix_62 branch and indeed the previous issue no longer seems to occur.

I can now have the bridge running while launching lifecycle nodes from Nav2 and everything seems to work, nodes come online and the robot navigates correctly.

I will let you know if I come across any other issues, but it does look resolved to me, appreciate your work thank you.

JEnoch commented 8 months ago

Thanks for your confirmation. The fix is now merged into main branch. All the fixes discussed in this issue will be included in a 0.10.1-rc.2 patch version I'll release very soon.

JEnoch commented 8 months ago

Version 0.10.1-rc.2 has been released! It's available on our download site, on Docker, on our Debian repo and on our Homebrew tap.