search

turtlebot / turtlebot4

Turtlebot4 common packages.
Apache License 2.0
105 stars 47 forks source link

Navigation stack having problem starting up (Smoother server and localization server sometimes giving trouble when trying to launch navigation) #466

Open xylhal opened 2 months ago

xylhal commented 2 months ago

Robot Model

Turtlebot4 Standard

ROS distro

Humble

Networking Configuration

Discovery Server

OS

Ubuntu 22.04

Built from source or installed?

Installed

Package version

Unsure

Type of issue

Navigation (SLAM, Nav2 etc.)

Expected behaviour

I expect the nav2 navigation stack to start up without error so that it could be used for navigation.

Actual behaviour

Often times, when I start up the navigation node after running localization, I get the error that the smoother server has failed and will not not respond.

Error messages

[smoother_server.rclcpp]: failed to send response to /smoother_server/change_state (timeout): client will not receive response, at ./src/rmw_response.cpp:154, at ./src/rcl/service.c:314

To Reproduce

  1. Run localization to load map: ros2 launch turtlebot4_navigation localization.launch.py map:=office.yaml
  2. Run navigation node: ros2 launch turtlebot4_navigation nav2.launch.py # navigation

Other notes

I have tried re-flashing the image, setting up the turtlebot from scratch following the instructions, factory resetting the create3 base and the error still occurs. Most of them time, I have to restart the turtlebot multiple times before it can be loaded successfully.

I'm currently using the turtlebot4_standard_humble_1.0.0 image, and running it in the discovery server mode.

I'm also running this with an actual robot and not in simulation.

RustyCPR commented 2 months ago

Hi @xylhal Sorry to see you're encountering issues. Can you please recreate the issue and provide full terminal output from localization and navigation? Thank you, Rusty

xylhal commented 2 months ago 
os2 launch turtlebot4_navigation localization.launch.py map:=maps/demo_map_0822.yaml 
[INFO] [launch]: All log files can be found below /home/user/.ros/log/2024-09-13-13-52-34-263614-iMac-228661
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [map_server-1]: process started with pid [228662]
[INFO] [amcl-2]: process started with pid [228664]
[INFO] [lifecycle_manager-3]: process started with pid [228666]
[lifecycle_manager-3] [INFO] [1726260754.518674706] [lifecycle_manager_localization]: Creating
[amcl-2] [INFO] [1726260754.519741823] [amcl]: 
[amcl-2]    amcl lifecycle node launched. 
[amcl-2]    Waiting on external lifecycle transitions to activate
[amcl-2]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[amcl-2] [INFO] [1726260754.521076312] [amcl]: Creating
[lifecycle_manager-3] [INFO] [1726260754.521607375] [lifecycle_manager_localization]: Creating and initializing lifecycle service clients
[map_server-1] [INFO] [1726260754.534376180] [map_server]: 
[map_server-1]  map_server lifecycle node launched. 
[map_server-1]  Waiting on external lifecycle transitions to activate
[map_server-1]  See https://design.ros2.org/articles/node_lifecycle.html for more information.
[map_server-1] [INFO] [1726260754.534482151] [map_server]: Creating
[lifecycle_manager-3] [INFO] [1726260756.523261554] [lifecycle_manager_localization]: Waiting for service map_server/get_state...
[lifecycle_manager-3] [INFO] [1726260757.548768447] [lifecycle_manager_localization]: Starting managed nodes bringup...
[lifecycle_manager-3] [INFO] [1726260757.549185823] [lifecycle_manager_localization]: Configuring map_server
[map_server-1] [INFO] [1726260757.551469384] [map_server]: Configuring
[map_server-1] [INFO] [map_io]: Loading yaml file: maps/demo_map_0822.yaml
[map_server-1] [DEBUG] [map_io]: resolution: 0.05
[map_server-1] [DEBUG] [map_io]: origin[0]: -17.7
[map_server-1] [DEBUG] [map_io]: origin[1]: -47.6
[map_server-1] [DEBUG] [map_io]: origin[2]: 0
[map_server-1] [DEBUG] [map_io]: free_thresh: 0.25
[map_server-1] [DEBUG] [map_io]: occupied_thresh: 0.65
[map_server-1] [DEBUG] [map_io]: mode: trinary
[map_server-1] [DEBUG] [map_io]: negate: 0
[map_server-1] [INFO] [map_io]: Loading image_file: maps/demo_map_0822.pgm
[map_server-1] [DEBUG] [map_io]: Read map maps/demo_map_0822.pgm: 615 X 866 map @ 0.05 m/cell
[lifecycle_manager-3] [INFO] [1726260757.694424180] [lifecycle_manager_localization]: Configuring amcl
[amcl-2] [INFO] [1726260757.694603223] [amcl]: Configuring
[amcl-2] [INFO] [1726260757.694668777] [amcl]: initTransforms
[amcl-2] [INFO] [1726260757.703748645] [amcl]: initPubSub
[amcl-2] [INFO] [1726260757.710451547] [amcl]: Subscribed to map topic.
[lifecycle_manager-3] [INFO] [1726260757.715998960] [lifecycle_manager_localization]: Activating map_server
[map_server-1] [INFO] [1726260757.716179254] [map_server]: Activating
[map_server-1] [INFO] [1726260757.716727144] [map_server]: Creating bond (map_server) to lifecycle manager.
[lifecycle_manager-3] [INFO] [1726260757.921461425] [lifecycle_manager_localization]: Server map_server connected with bond.
[lifecycle_manager-3] [INFO] [1726260757.921690619] [lifecycle_manager_localization]: Activating amcl
[amcl-2] [INFO] [1726260757.923081035] [amcl]: Activating
[amcl-2] [INFO] [1726260757.923336884] [amcl]: Creating bond (amcl) to lifecycle manager.
[amcl-2] [INFO] [1726260758.090311893] [amcl]: Received a 615 X 866 map @ 0.050 m/pix
[amcl-2] [INFO] [1726260758.171956936] [amcl]: createLaserObject
[lifecycle_manager-3] [ERROR] [1726260758.835965461] [lifecycle_manager_localization]: Failed to change state for node: amcl. Exception: transition invoked while in transition.
[lifecycle_manager-3] [ERROR] [1726260758.836363692] [lifecycle_manager_localization]: Failed to bring up all requested nodes. Aborting bringup.

This above is the output from running ros2 launch turtlebot4_navigation nav2.launch.py

The localization usually runs fine without throwing any errors. 

[INFO] [launch]: All log files can be found below /home/user/.ros/log/2024-09-13-13-52-34-263614-iMac-228661
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [map_server-1]: process started with pid [228662]
[INFO] [amcl-2]: process started with pid [228664]
[INFO] [lifecycle_manager-3]: process started with pid [228666]
[lifecycle_manager-3] [INFO] [1726260754.518674706] [lifecycle_manager_localization]: Creating
[amcl-2] [INFO] [1726260754.519741823] [amcl]: 
[amcl-2]    amcl lifecycle node launched. 
[amcl-2]    Waiting on external lifecycle transitions to activate
[amcl-2]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[amcl-2] [INFO] [1726260754.521076312] [amcl]: Creating
[lifecycle_manager-3] [INFO] [1726260754.521607375] [lifecycle_manager_localization]: Creating and initializing lifecycle service clients
[map_server-1] [INFO] [1726260754.534376180] [map_server]: 
[map_server-1]  map_server lifecycle node launched. 
[map_server-1]  Waiting on external lifecycle transitions to activate
[map_server-1]  See https://design.ros2.org/articles/node_lifecycle.html for more information.
[map_server-1] [INFO] [1726260754.534482151] [map_server]: Creating
[lifecycle_manager-3] [INFO] [1726260756.523261554] [lifecycle_manager_localization]: Waiting for service map_server/get_state...
[lifecycle_manager-3] [INFO] [1726260757.548768447] [lifecycle_manager_localization]: Starting managed nodes bringup...
[lifecycle_manager-3] [INFO] [1726260757.549185823] [lifecycle_manager_localization]: Configuring map_server
[map_server-1] [INFO] [1726260757.551469384] [map_server]: Configuring
[map_server-1] [INFO] [map_io]: Loading yaml file: maps/demo_map_0822.yaml
[map_server-1] [DEBUG] [map_io]: resolution: 0.05
[map_server-1] [DEBUG] [map_io]: origin[0]: -17.7
[map_server-1] [DEBUG] [map_io]: origin[1]: -47.6
[map_server-1] [DEBUG] [map_io]: origin[2]: 0
[map_server-1] [DEBUG] [map_io]: free_thresh: 0.25
[map_server-1] [DEBUG] [map_io]: occupied_thresh: 0.65
[map_server-1] [DEBUG] [map_io]: mode: trinary
[map_server-1] [DEBUG] [map_io]: negate: 0
[map_server-1] [INFO] [map_io]: Loading image_file: maps/demo_map_0822.pgm
[map_server-1] [DEBUG] [map_io]: Read map maps/demo_map_0822.pgm: 615 X 866 map @ 0.05 m/cell
[lifecycle_manager-3] [INFO] [1726260757.694424180] [lifecycle_manager_localization]: Configuring amcl
[amcl-2] [INFO] [1726260757.694603223] [amcl]: Configuring
[amcl-2] [INFO] [1726260757.694668777] [amcl]: initTransforms
[amcl-2] [INFO] [1726260757.703748645] [amcl]: initPubSub
[amcl-2] [INFO] [1726260757.710451547] [amcl]: Subscribed to map topic.
[lifecycle_manager-3] [INFO] [1726260757.715998960] [lifecycle_manager_localization]: Activating map_server
[map_server-1] [INFO] [1726260757.716179254] [map_server]: Activating
[map_server-1] [INFO] [1726260757.716727144] [map_server]: Creating bond (map_server) to lifecycle manager.
[lifecycle_manager-3] [INFO] [1726260757.921461425] [lifecycle_manager_localization]: Server map_server connected with bond.
[lifecycle_manager-3] [INFO] [1726260757.921690619] [lifecycle_manager_localization]: Activating amcl
[amcl-2] [INFO] [1726260757.923081035] [amcl]: Activating
[amcl-2] [INFO] [1726260757.923336884] [amcl]: Creating bond (amcl) to lifecycle manager.
[amcl-2] [INFO] [1726260758.090311893] [amcl]: Received a 615 X 866 map @ 0.050 m/pix
[amcl-2] [INFO] [1726260758.171956936] [amcl]: createLaserObject
[lifecycle_manager-3] [ERROR] [1726260758.835965461] [lifecycle_manager_localization]: Failed to change state for node: amcl. Exception: transition invoked while in transition.
[lifecycle_manager-3] [ERROR] [1726260758.836363692] [lifecycle_manager_localization]: Failed to bring up all requested nodes. Aborting bringup.
[amcl-2] [WARN] [1726260759.780823698] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260761.834404668] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260763.845259570] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260765.898655532] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260767.936217984] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260770.098911117] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260772.231447543] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260774.392645915] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260776.481303374] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260778.493120189] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260780.499769705] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260782.529359600] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260784.533451565] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260786.593174609] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260788.635358370] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260790.790227505] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260792.800804637] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260794.837358941] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260796.892083680] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260798.931796197] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260801.089906116] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260803.095597429] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260805.131669252] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260807.192199788] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260809.204753951] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260811.235314311] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260813.294502179] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260815.321780079] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260817.337651636] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260819.490639884] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260821.534726564] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260823.599306048] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260825.732267361] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260827.734740721] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260829.788403208] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260831.930044269] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260833.989823434] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260836.129902773] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260838.134984520] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [WARN] [1726260840.184767441] [amcl]: AMCL cannot publish a pose or update the transform. Please set the initial pose...
[amcl-2] [INFO] [1726260841.539704294] [amcl]: initialPoseReceived
[amcl-2] [WARN] [1726260841.540136813] [amcl]: Failed to transform initial pose in time (Lookup would require extrapolation into the future.  Requested time 1726260841.539869 but the latest data is at time 1726260841.477453, when looking up transform from frame [base_link] to frame [odom])
[amcl-2] [INFO] [1726260841.540248136] [amcl]: Setting pose (1726260841.540247): 0.451 -24.106 -3.071
[amcl-2] [INFO] [1726260849.029340696] [amcl]: initialPoseReceived
[amcl-2] [WARN] [1726260849.029695591] [amcl]: Failed to transform initial pose in time (Lookup would require extrapolation into the future.  Requested time 1726260849.029562 but the latest data is at time 1726260848.980560, when looking up transform from frame [base_link] to frame [odom])
[amcl-2] [INFO] [1726260849.029862728] [amcl]: Setting pose (1726260849.029862): 0.522 -24.138 -3.123
[amcl-2] [INFO] [1726260857.127122247] [amcl]: initialPoseReceived
[amcl-2] [WARN] [1726260857.127212914] [amcl]: Failed to transform initial pose in time (Lookup would require extrapolation into the future.  Requested time 1726260857.127164 but the latest data is at time 1726260857.029737, when looking up transform from frame [base_link] to frame [odom])
[amcl-2] [INFO] [1726260857.127238600] [amcl]: Setting pose (1726260857.127239): 0.502 -24.269 3.116
[amcl-2] [INFO] [1726260865.302901101] [amcl]: initialPoseReceived
[amcl-2] [WARN] [1726260865.303006160] [amcl]: Failed to transform initial pose in time (Lookup would require extrapolation into the future.  Requested time 1726260865.302943 but the latest data is at time 1726260865.222835, when looking up transform from frame [base_link] to frame [odom])
[amcl-2] [INFO] [1726260865.303034315] [amcl]: Setting pose (1726260865.303034): 0.527 -24.358 -3.134
[amcl-2] [INFO] [1726260872.092745123] [amcl]: initialPoseReceived
[amcl-2] [WARN] [1726260872.092867290] [amcl]: Failed to transform initial pose in time (Lookup would require extrapolation into the future.  Requested time 1726260872.092801 but the latest data is at time 1726260872.021836, when looking up transform from frame [base_link] to frame [odom])
[amcl-2] [INFO] [1726260872.092906877] [amcl]: Setting pose (1726260872.092907): 0.597 -24.449 3.057
[amcl-2] [INFO] [1726260977.232779189] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260975.654 for reason 'discarding message because the queue is full'
[amcl-2] [INFO] [1726260977.367344168] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260975.777 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[amcl-2] [INFO] [1726260977.395209172] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260975.912 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[amcl-2] [INFO] [1726260977.493471133] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260976.035 for reason 'discarding message because the queue is full'
[amcl-2] [INFO] [1726260977.528298893] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260976.170 for reason 'discarding message because the queue is full'
[amcl-2] [INFO] [1726260977.682360804] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260976.293 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[amcl-2] [INFO] [1726260977.851396699] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260976.416 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[amcl-2] [INFO] [1726260978.234537421] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260976.932 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[amcl-2] [INFO] [1726260978.373043295] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260977.055 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[amcl-2] [INFO] [1726260978.528863363] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260977.436 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[amcl-2] [INFO] [1726260978.718702148] [amcl]: Message Filter dropping message: frame 'rplidar_link' at time 1726260977.558 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
xylhal commented 1 month ago

Hi @RustyCPR, @smatarCPR

Any feedback on this? I realized that this is a common issue but this issue always gets closed. I would like to dive deeper into the cause of this.

Thanks

smatarCPR commented 1 month ago

Hello @xylhal Apologies for the delay on this we are still processing the data from the logs, but we will provide an update soon. Best Regards, Saif

daisukes commented 1 month ago

Hi @xylhal, @RustyCPR, and @smatarCPR

I recently got into the same issue with my robot.

[lifecycle_manager-3] [ERROR] [1726260758.835965461] [lifecycle_manager_localization]: Failed to change state for node: amcl. Exception: transition invoked while in transition.

I found that this error is raised at this line, and it may be a timing-related issue while creating a bond between a lifecycle manager and a node, in this case, amcl.

https://github.com/ros/bond_core/blob/52e181c717186185cb25fed62ed95a16804b5a17/smclib/include/smclib/statemap.hpp#L168

I plan to look into it, but I just wanted to tell you what I found. Best regards,

daisukes commented 1 month ago

https://github.com/ros/bond_core/pull/97

I made a PR to bond_core, which may fix this issue. Best,

xylhal commented 1 month ago

@daisukes Thank you, please let us know if you have any update on whether your PR fixed the issue.

@RustyCPR, @smatarCPR Please also let me know what your findings are

hilary-luo commented 3 weeks ago

@xylhal the logs that you provided are all from the localization launch, can you please share the log from the nav2 launch command that you are using? Additionally, can you clarify where you are running the localization / nav nodes? We recommend running them offboard, on a separate machine that runs Ubuntu natively (not on the turtlebot itself).

@daisukes I took a quick look at your PR and although your comment says that you want the change included on Humble, the PR is for Galactic. Galactic is end of life and is no longer supported, if you want them to look at your PR I would suggest creating a new one for Humble.

daisukes commented 3 weeks ago

@daisukes I took a quick look at your PR and although your comment says that you want the change included on Humble, the PR is for Galactic. Galactic is end of life and is no longer supported, if you want them to look at your PR I would suggest creating a new one for Humble.

Thanks for the check! There is no humble branch in bond_core, and humble use 3.0.2, equivalent to the galactic branch. I've tried the ros2 branch, but it might have an API change and won't work with humble nav2. Do you have any suggestions?

https://github.com/ros2-gbp/bond_core-release/tree/master?tab=readme-ov-file#bond_core-humble---302-3

xylhal commented 3 weeks ago

@hilary-luo Apologies, here is the screenshot of the error we faced when running nav2 launch command. Although the error above from running the localization sometimes occurs as well, but most of the them, the error comes from launching nav2. And I am currently running them offboard on a dedicated Ubuntu machine following the discovery server architecture

~/turtlebot4_ws$ ros2 launch turtlebot4_navigation nav2.launch.py
[INFO] [launch]: All log files can be found below /home/.ros/log/2024-11-01-12-53-01-563861-iMac-797603
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [controller_server-1]: process started with pid [797604]
[INFO] [smoother_server-2]: process started with pid [797606]
[INFO] [planner_server-3]: process started with pid [797608]
[INFO] [behavior_server-4]: process started with pid [797610]
[INFO] [bt_navigator-5]: process started with pid [797612]
[INFO] [waypoint_follower-6]: process started with pid [797614]
[INFO] [velocity_smoother-7]: process started with pid [797616]
[INFO] [lifecycle_manager-8]: process started with pid [797618]
[planner_server-3] [INFO] [1730490781.976843993] [planner_server]: 
[planner_server-3]  planner_server lifecycle node launched. 
[planner_server-3]  Waiting on external lifecycle transitions to activate
[planner_server-3]  See https://design.ros2.org/articles/node_lifecycle.html for more information.
[smoother_server-2] [INFO] [1730490781.979593777] [smoother_server]: 
[smoother_server-2]     smoother_server lifecycle node launched. 
[smoother_server-2]     Waiting on external lifecycle transitions to activate
[smoother_server-2]     See https://design.ros2.org/articles/node_lifecycle.html for more information.
[bt_navigator-5] [INFO] [1730490781.993174885] [bt_navigator]: 
[bt_navigator-5]    bt_navigator lifecycle node launched. 
[bt_navigator-5]    Waiting on external lifecycle transitions to activate
[bt_navigator-5]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[bt_navigator-5] [INFO] [1730490781.993324240] [bt_navigator]: Creating
[smoother_server-2] [INFO] [1730490781.998475878] [smoother_server]: Creating smoother server
[planner_server-3] [INFO] [1730490782.000698533] [planner_server]: Creating
[waypoint_follower-6] [INFO] [1730490782.002810615] [waypoint_follower]: 
[waypoint_follower-6]   waypoint_follower lifecycle node launched. 
[waypoint_follower-6]   Waiting on external lifecycle transitions to activate
[waypoint_follower-6]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[velocity_smoother-7] [INFO] [1730490782.007289702] [velocity_smoother]: 
[velocity_smoother-7]   velocity_smoother lifecycle node launched. 
[velocity_smoother-7]   Waiting on external lifecycle transitions to activate
[velocity_smoother-7]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[waypoint_follower-6] [INFO] [1730490782.010565170] [waypoint_follower]: Creating
[controller_server-1] [INFO] [1730490782.012620460] [controller_server]: 
[controller_server-1]   controller_server lifecycle node launched. 
[controller_server-1]   Waiting on external lifecycle transitions to activate
[controller_server-1]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[planner_server-3] [INFO] [1730490782.015495857] [global_costmap.global_costmap]: 
[planner_server-3]  global_costmap lifecycle node launched. 
[planner_server-3]  Waiting on external lifecycle transitions to activate
[planner_server-3]  See https://design.ros2.org/articles/node_lifecycle.html for more information.
[behavior_server-4] [INFO] [1730490782.016740095] [behavior_server]: 
[behavior_server-4]     behavior_server lifecycle node launched. 
[behavior_server-4]     Waiting on external lifecycle transitions to activate
[behavior_server-4]     See https://design.ros2.org/articles/node_lifecycle.html for more information.
[controller_server-1] [INFO] [1730490782.021188771] [controller_server]: Creating controller server
[planner_server-3] [INFO] [1730490782.022262209] [global_costmap.global_costmap]: Creating Costmap
[lifecycle_manager-8] [INFO] [1730490782.022583267] [lifecycle_manager_navigation]: Creating
[lifecycle_manager-8] [INFO] [1730490782.024381683] [lifecycle_manager_navigation]: Creating and initializing lifecycle service clients
[controller_server-1] [INFO] [1730490782.027705975] [local_costmap.local_costmap]: 
[controller_server-1]   local_costmap lifecycle node launched. 
[controller_server-1]   Waiting on external lifecycle transitions to activate
[controller_server-1]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[controller_server-1] [INFO] [1730490782.028262660] [local_costmap.local_costmap]: Creating Costmap
[lifecycle_manager-8] [INFO] [1730490784.025644963] [lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1730490786.026172570] [lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1730490786.149798928] [lifecycle_manager_navigation]: Starting managed nodes bringup...
[lifecycle_manager-8] [INFO] [1730490786.149847865] [lifecycle_manager_navigation]: Configuring controller_server
[controller_server-1] [INFO] [1730490786.150178719] [controller_server]: Configuring controller interface
[controller_server-1] [INFO] [1730490786.150822070] [controller_server]: getting goal checker plugins..
[controller_server-1] [INFO] [1730490786.151235480] [controller_server]: Controller frequency set to 20.0000Hz
[controller_server-1] [INFO] [1730490786.151287888] [local_costmap.local_costmap]: Configuring
[controller_server-1] [INFO] [1730490786.159505710] [local_costmap.local_costmap]: Using plugin "static_layer"
[controller_server-1] [INFO] [1730490786.164340312] [local_costmap.local_costmap]: Subscribing to the map topic (/map) with transient local durability
[controller_server-1] [INFO] [1730490786.165983064] [local_costmap.local_costmap]: Initialized plugin "static_layer"
[controller_server-1] [INFO] [1730490786.166019785] [local_costmap.local_costmap]: Using plugin "voxel_layer"
[controller_server-1] [INFO] [1730490786.167386301] [local_costmap.local_costmap]: Subscribed to Topics: scan
[controller_server-1] [INFO] [1730490786.178629082] [local_costmap.local_costmap]: Initialized plugin "voxel_layer"
[controller_server-1] [INFO] [1730490786.178669909] [local_costmap.local_costmap]: Using plugin "inflation_layer"
[controller_server-1] [INFO] [1730490786.181501226] [local_costmap.local_costmap]: Initialized plugin "inflation_layer"
[controller_server-1] [INFO] [1730490786.193335752] [controller_server]: Created progress_checker : progress_checker of type nav2_controller::SimpleProgressChecker
[controller_server-1] [INFO] [1730490786.194380194] [controller_server]: Created goal checker : general_goal_checker of type nav2_controller::SimpleGoalChecker
[controller_server-1] [INFO] [1730490786.195646203] [controller_server]: Controller Server has general_goal_checker  goal checkers available.
[controller_server-1] [INFO] [1730490786.197504904] [controller_server]: Created controller : FollowPath of type dwb_core::DWBLocalPlanner
[controller_server-1] [INFO] [1730490786.199812368] [controller_server]: Setting transform_tolerance to 0.200000
[controller_server-1] [INFO] [1730490786.220061555] [controller_server]: Using critic "RotateToGoal" (dwb_critics::RotateToGoalCritic)
[controller_server-1] [INFO] [1730490786.221268136] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730490786.221527939] [controller_server]: Using critic "Oscillation" (dwb_critics::OscillationCritic)
[controller_server-1] [INFO] [1730490786.222430116] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730490786.222655996] [controller_server]: Using critic "BaseObstacle" (dwb_critics::BaseObstacleCritic)
[controller_server-1] [INFO] [1730490786.223017277] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730490786.223214010] [controller_server]: Using critic "GoalAlign" (dwb_critics::GoalAlignCritic)
[controller_server-1] [INFO] [1730490786.228808436] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730490786.229140930] [controller_server]: Using critic "PathAlign" (dwb_critics::PathAlignCritic)
[controller_server-1] [INFO] [1730490786.229743418] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730490786.229968462] [controller_server]: Using critic "PathDist" (dwb_critics::PathDistCritic)
[controller_server-1] [INFO] [1730490786.230387334] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730490786.230615356] [controller_server]: Using critic "GoalDist" (dwb_critics::GoalDistCritic)
[controller_server-1] [INFO] [1730490786.231594454] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730490786.231634354] [controller_server]: Controller Server has FollowPath  controllers available.
[lifecycle_manager-8] [INFO] [1730490786.243495502] [lifecycle_manager_navigation]: Configuring smoother_server
[smoother_server-2] [INFO] [1730490791.386230954] [smoother_server]: Configuring smoother server
[smoother_server-2] [INFO] [1730490791.470714579] [smoother_server]: Created smoother : simple_smoother of type nav2_smoother::SimpleSmoother
[smoother_server-2] [INFO] [1730490791.474019006] [smoother_server]: Smoother Server has simple_smoother  smoothers available.
[smoother_server-2] [WARN] [1730490791.588452217] [smoother_server.rclcpp]: failed to send response to /smoother_server/change_state (timeout): client will not receive response, at ./src/rmw_response.cpp:154, at ./src/rcl/service.c:314
[controller_server-1] [INFO] [1730490798.341902004] [local_costmap.local_costmap]: StaticLayer: Resizing static layer to 615 X 866 at 0.050000 m/pix
xylhal commented 3 weeks ago

@hilary-luo This is from a different session of re-running the nav2 launch file

`~/turtlebot4_ws$ ros2 launch turtlebot4_navigation nav2.launch.py
[INFO] [launch]: All log files can be found below /home/.ros/log/2024-11-01-13-03-28-962151-iMac-798691
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [controller_server-1]: process started with pid [798692]
[INFO] [smoother_server-2]: process started with pid [798694]
[INFO] [planner_server-3]: process started with pid [798696]
[INFO] [behavior_server-4]: process started with pid [798698]
[INFO] [bt_navigator-5]: process started with pid [798700]
[INFO] [waypoint_follower-6]: process started with pid [798702]
[INFO] [velocity_smoother-7]: process started with pid [798704]
[INFO] [lifecycle_manager-8]: process started with pid [798706]
[behavior_server-4] [INFO] [1730491409.382424999] [behavior_server]: 
[behavior_server-4]     behavior_server lifecycle node launched. 
[behavior_server-4]     Waiting on external lifecycle transitions to activate
[behavior_server-4]     See https://design.ros2.org/articles/node_lifecycle.html for more information.
[planner_server-3] [INFO] [1730491409.387354568] [planner_server]: 
[planner_server-3]  planner_server lifecycle node launched. 
[planner_server-3]  Waiting on external lifecycle transitions to activate
[planner_server-3]  See https://design.ros2.org/articles/node_lifecycle.html for more information.
[velocity_smoother-7] [INFO] [1730491409.389075560] [velocity_smoother]: 
[velocity_smoother-7]   velocity_smoother lifecycle node launched. 
[velocity_smoother-7]   Waiting on external lifecycle transitions to activate
[velocity_smoother-7]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[controller_server-1] [INFO] [1730491409.390346802] [controller_server]: 
[controller_server-1]   controller_server lifecycle node launched. 
[controller_server-1]   Waiting on external lifecycle transitions to activate
[controller_server-1]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[planner_server-3] [INFO] [1730491409.394796486] [planner_server]: Creating
[controller_server-1] [INFO] [1730491409.396629725] [controller_server]: Creating controller server
[smoother_server-2] [INFO] [1730491409.398142869] [smoother_server]: 
[smoother_server-2]     smoother_server lifecycle node launched. 
[smoother_server-2]     Waiting on external lifecycle transitions to activate
[smoother_server-2]     See https://design.ros2.org/articles/node_lifecycle.html for more information.
[smoother_server-2] [INFO] [1730491409.402195659] [smoother_server]: Creating smoother server
[controller_server-1] [INFO] [1730491409.404122805] [local_costmap.local_costmap]: 
[controller_server-1]   local_costmap lifecycle node launched. 
[controller_server-1]   Waiting on external lifecycle transitions to activate
[controller_server-1]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[controller_server-1] [INFO] [1730491409.405062683] [local_costmap.local_costmap]: Creating Costmap
[planner_server-3] [INFO] [1730491409.409072905] [global_costmap.global_costmap]: 
[planner_server-3]  global_costmap lifecycle node launched. 
[planner_server-3]  Waiting on external lifecycle transitions to activate
[planner_server-3]  See https://design.ros2.org/articles/node_lifecycle.html for more information.
[planner_server-3] [INFO] [1730491409.409607709] [global_costmap.global_costmap]: Creating Costmap
[lifecycle_manager-8] [INFO] [1730491409.415954329] [lifecycle_manager_navigation]: Creating
[waypoint_follower-6] [INFO] [1730491409.416887030] [waypoint_follower]: 
[waypoint_follower-6]   waypoint_follower lifecycle node launched. 
[waypoint_follower-6]   Waiting on external lifecycle transitions to activate
[waypoint_follower-6]   See https://design.ros2.org/articles/node_lifecycle.html for more information.
[waypoint_follower-6] [INFO] [1730491409.417477151] [waypoint_follower]: Creating
[lifecycle_manager-8] [INFO] [1730491409.418233154] [lifecycle_manager_navigation]: Creating and initializing lifecycle service clients
[bt_navigator-5] [INFO] [1730491409.419928671] [bt_navigator]: 
[bt_navigator-5]    bt_navigator lifecycle node launched. 
[bt_navigator-5]    Waiting on external lifecycle transitions to activate
[bt_navigator-5]    See https://design.ros2.org/articles/node_lifecycle.html for more information.
[bt_navigator-5] [INFO] [1730491409.420038891] [bt_navigator]: Creating
[lifecycle_manager-8] [INFO] [1730491411.419620761] [lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1730491413.431492682] [lifecycle_manager_navigation]: Starting managed nodes bringup...
[lifecycle_manager-8] [INFO] [1730491413.431895578] [lifecycle_manager_navigation]: Configuring controller_server
[controller_server-1] [INFO] [1730491413.435375529] [controller_server]: Configuring controller interface
[controller_server-1] [INFO] [1730491413.439997063] [controller_server]: getting goal checker plugins..
[controller_server-1] [INFO] [1730491413.451373748] [controller_server]: Controller frequency set to 20.0000Hz
[controller_server-1] [INFO] [1730491413.455163536] [local_costmap.local_costmap]: Configuring
[controller_server-1] [INFO] [1730491413.494030208] [local_costmap.local_costmap]: Using plugin "static_layer"
[controller_server-1] [INFO] [1730491413.503518598] [local_costmap.local_costmap]: Subscribing to the map topic (/map) with transient local durability
[controller_server-1] [INFO] [1730491413.508482258] [local_costmap.local_costmap]: Initialized plugin "static_layer"
[controller_server-1] [INFO] [1730491413.508537738] [local_costmap.local_costmap]: Using plugin "voxel_layer"
[controller_server-1] [INFO] [1730491413.512292888] [local_costmap.local_costmap]: Subscribed to Topics: scan
[controller_server-1] [INFO] [1730491413.527473349] [local_costmap.local_costmap]: Initialized plugin "voxel_layer"
[controller_server-1] [INFO] [1730491413.527527954] [local_costmap.local_costmap]: Using plugin "inflation_layer"
[controller_server-1] [INFO] [1730491413.528800583] [local_costmap.local_costmap]: Initialized plugin "inflation_layer"
[controller_server-1] [INFO] [1730491413.542775882] [controller_server]: Created progress_checker : progress_checker of type nav2_controller::SimpleProgressChecker
[controller_server-1] [INFO] [1730491413.544356124] [controller_server]: Created goal checker : general_goal_checker of type nav2_controller::SimpleGoalChecker
[controller_server-1] [INFO] [1730491413.545015609] [controller_server]: Controller Server has general_goal_checker  goal checkers available.
[controller_server-1] [INFO] [1730491413.546834473] [controller_server]: Created controller : FollowPath of type dwb_core::DWBLocalPlanner
[controller_server-1] [INFO] [1730491413.548840902] [controller_server]: Setting transform_tolerance to 0.200000
[controller_server-1] [INFO] [1730491413.573882422] [controller_server]: Using critic "RotateToGoal" (dwb_critics::RotateToGoalCritic)
[controller_server-1] [INFO] [1730491413.575788658] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730491413.576044222] [controller_server]: Using critic "Oscillation" (dwb_critics::OscillationCritic)
[controller_server-1] [INFO] [1730491413.577728601] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730491413.578130458] [controller_server]: Using critic "BaseObstacle" (dwb_critics::BaseObstacleCritic)
[controller_server-1] [INFO] [1730491413.578953310] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730491413.579362270] [controller_server]: Using critic "GoalAlign" (dwb_critics::GoalAlignCritic)
[controller_server-1] [INFO] [1730491413.580370966] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730491413.580593899] [controller_server]: Using critic "PathAlign" (dwb_critics::PathAlignCritic)
[controller_server-1] [INFO] [1730491413.582345469] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730491413.582750961] [controller_server]: Using critic "PathDist" (dwb_critics::PathDistCritic)
[controller_server-1] [INFO] [1730491413.583623415] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730491413.584113059] [controller_server]: Using critic "GoalDist" (dwb_critics::GoalDistCritic)
[controller_server-1] [INFO] [1730491413.585511370] [controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1730491413.585562340] [controller_server]: Controller Server has FollowPath  controllers available.
[lifecycle_manager-8] [INFO] [1730491413.597895524] [lifecycle_manager_navigation]: Configuring smoother_server
[smoother_server-2] [INFO] [1730491416.438685242] [smoother_server]: Configuring smoother server
[smoother_server-2] [INFO] [1730491416.519824384] [smoother_server]: Created smoother : simple_smoother of type nav2_smoother::SimpleSmoother
[smoother_server-2] [INFO] [1730491416.523847128] [smoother_server]: Smoother Server has simple_smoother  smoothers available.
[lifecycle_manager-8] [INFO] [1730491416.534255447] [lifecycle_manager_navigation]: Configuring planner_server
[planner_server-3] [INFO] [1730491416.534577649] [planner_server]: Configuring
[planner_server-3] [INFO] [1730491416.534613701] [global_costmap.global_costmap]: Configuring
[planner_server-3] [INFO] [1730491416.545457307] [global_costmap.global_costmap]: Using plugin "static_layer"
[planner_server-3] [INFO] [1730491416.552214808] [global_costmap.global_costmap]: Subscribing to the map topic (/map) with transient local durability
[planner_server-3] [INFO] [1730491416.554768000] [global_costmap.global_costmap]: Initialized plugin "static_layer"
[planner_server-3] [INFO] [1730491416.554814527] [global_costmap.global_costmap]: Using plugin "obstacle_layer"
[planner_server-3] [INFO] [1730491416.558558481] [global_costmap.global_costmap]: Subscribed to Topics: scan
[planner_server-3] [INFO] [1730491416.568221045] [global_costmap.global_costmap]: Initialized plugin "obstacle_layer"
[planner_server-3] [INFO] [1730491416.568255001] [global_costmap.global_costmap]: Using plugin "inflation_layer"
[planner_server-3] [INFO] [1730491416.569872568] [global_costmap.global_costmap]: Initialized plugin "inflation_layer"
[planner_server-3] [INFO] [1730491416.594632852] [planner_server]: Created global planner plugin GridBased of type nav2_navfn_planner/NavfnPlanner
[planner_server-3] [INFO] [1730491416.594672842] [planner_server]: Configuring plugin GridBased of type NavfnPlanner
[planner_server-3] [INFO] [1730491416.596340908] [planner_server]: Planner Server has GridBased  planners available.
[lifecycle_manager-8] [INFO] [1730491416.615512703] [lifecycle_manager_navigation]: Configuring behavior_server
[behavior_server-4] [INFO] [1730491416.615773326] [behavior_server]: Configuring
[behavior_server-4] [INFO] [1730491416.631017344] [behavior_server]: Creating behavior plugin spin of type nav2_behaviors/Spin
[behavior_server-4] [INFO] [1730491416.631896338] [behavior_server]: Configuring spin
[behavior_server-4] [INFO] [1730491416.641514662] [behavior_server]: Creating behavior plugin backup of type nav2_behaviors/BackUp
[behavior_server-4] [INFO] [1730491416.642597692] [behavior_server]: Configuring backup
[behavior_server-4] [INFO] [1730491416.653477271] [behavior_server]: Creating behavior plugin drive_on_heading of type nav2_behaviors/DriveOnHeading
[behavior_server-4] [INFO] [1730491416.654388926] [behavior_server]: Configuring drive_on_heading
[behavior_server-4] [INFO] [1730491416.661897725] [behavior_server]: Creating behavior plugin assisted_teleop of type nav2_behaviors/AssistedTeleop
[behavior_server-4] [INFO] [1730491416.663421982] [behavior_server]: Configuring assisted_teleop
[controller_server-1] [INFO] [1730491416.670739072] [local_costmap.local_costmap]: StaticLayer: Resizing static layer to 615 X 866 at 0.050000 m/pix
[behavior_server-4] [INFO] [1730491416.681505849] [behavior_server]: Creating behavior plugin wait of type nav2_behaviors/Wait
[behavior_server-4] [INFO] [1730491416.682343399] [behavior_server]: Configuring wait
[lifecycle_manager-8] [INFO] [1730491416.701783946] [lifecycle_manager_navigation]: Configuring bt_navigator
[bt_navigator-5] [INFO] [1730491416.702026112] [bt_navigator]: Configuring
[lifecycle_manager-8] [INFO] [1730491416.813230314] [lifecycle_manager_navigation]: Configuring waypoint_follower
[waypoint_follower-6] [INFO] [1730491416.813516454] [waypoint_follower]: Configuring
[waypoint_follower-6] [INFO] [1730491416.824753593] [waypoint_follower]: Created waypoint_task_executor : wait_at_waypoint of type nav2_waypoint_follower::WaitAtWaypoint
[lifecycle_manager-8] [INFO] [1730491416.826780829] [lifecycle_manager_navigation]: Configuring velocity_smoother
[velocity_smoother-7] [INFO] [1730491416.827079895] [velocity_smoother]: Configuring velocity smoother
[lifecycle_manager-8] [INFO] [1730491416.845764759] [lifecycle_manager_navigation]: Activating controller_server
[controller_server-1] [INFO] [1730491416.846143424] [controller_server]: Activating
[controller_server-1] [INFO] [1730491416.846176797] [local_costmap.local_costmap]: Activating
[controller_server-1] [INFO] [1730491416.846190198] [local_costmap.local_costmap]: Checking transform
[controller_server-1] [INFO] [1730491416.846340609] [local_costmap.local_costmap]: start
[controller_server-1] [INFO] [1730491417.097963466] [controller_server]: Creating bond (controller_server) to lifecycle manager.
[lifecycle_manager-8] [INFO] [1730491417.224351664] [lifecycle_manager_navigation]: Server controller_server connected with bond.
[lifecycle_manager-8] [INFO] [1730491417.224665986] [lifecycle_manager_navigation]: Activating smoother_server
[smoother_server-2] [INFO] [1730491417.226187102] [smoother_server]: Activating
[smoother_server-2] [INFO] [1730491417.226408413] [smoother_server]: Creating bond (smoother_server) to lifecycle manager.
[lifecycle_manager-8] [INFO] [1730491417.357861674] [lifecycle_manager_navigation]: Server smoother_server connected with bond.
[lifecycle_manager-8] [INFO] [1730491417.358081977] [lifecycle_manager_navigation]: Activating planner_server
[planner_server-3] [INFO] [1730491417.359853146] [planner_server]: Activating
[planner_server-3] [INFO] [1730491417.360054954] [global_costmap.global_costmap]: Activating
[planner_server-3] [INFO] [1730491417.360143500] [global_costmap.global_costmap]: Checking transform
[planner_server-3] [INFO] [1730491417.360267863] [global_costmap.global_costmap]: Timed out waiting for transform from base_link to map to become available, tf error: Invalid frame ID "map" passed to canTransform argument target_frame - frame does not exist
[planner_server-3] [INFO] [1730491417.701870291] [global_costmap.global_costmap]: StaticLayer: Resizing costmap to 615 X 866 at 0.050000 m/pix
[planner_server-3] [INFO] [1730491417.860485983] [global_costmap.global_costmap]: Timed out waiting for transform from base_link to map to become available, tf error: Lookup would require extrapolation into the past.  Requested time 1730491417.793022 but the earliest data is at time 1730491418.618683, when looking up transform from frame [base_link] to frame [map]
[controller_server-1] [INFO] [1730491418.337218527] [local_costmap.local_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1730491417.999 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[planner_server-3] [INFO] [1730491418.360320052] [global_costmap.global_costmap]: Timed out waiting for transform from base_link to map to become available, tf error: Lookup would require extrapolation into the past.  Requested time 1730491418.049098 but the earliest data is at time 1730491418.618683, when looking up transform from frame [base_link] to frame [map]
[controller_server-1] [INFO] [1730491418.565687528] [local_costmap.local_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1730491418.257 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[planner_server-3] [INFO] [1730491418.860521567] [global_costmap.global_costmap]: start
[planner_server-3] [INFO] [1730491419.963419420] [planner_server]: Activating plugin GridBased of type NavfnPlanner
[planner_server-3] [INFO] [1730491419.968374457] [planner_server]: Creating bond (planner_server) to lifecycle manager.
[lifecycle_manager-8] [INFO] [1730491420.217792727] [lifecycle_manager_navigation]: Server planner_server connected with bond.
[lifecycle_manager-8] [INFO] [1730491420.217901349] [lifecycle_manager_navigation]: Activating behavior_server
[behavior_server-4] [INFO] [1730491420.222494287] [behavior_server]: Activating
[behavior_server-4] [INFO] [1730491420.222772490] [behavior_server]: Activating spin
[behavior_server-4] [INFO] [1730491420.222810281] [behavior_server]: Activating backup
[behavior_server-4] [INFO] [1730491420.222838308] [behavior_server]: Activating drive_on_heading
[behavior_server-4] [INFO] [1730491420.222871998] [behavior_server]: Activating assisted_teleop
[behavior_server-4] [INFO] [1730491420.222898948] [behavior_server]: Activating wait
[behavior_server-4] [INFO] [1730491420.222932248] [behavior_server]: Creating bond (behavior_server) to lifecycle manager.
[planner_server-3] [INFO] [1730491420.404478646] [global_costmap.global_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1730491420.063 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[planner_server-3] [INFO] [1730491420.665134867] [global_costmap.global_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1730491420.321 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[planner_server-3] [INFO] [1730491420.883672490] [global_costmap.global_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1730491420.578 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[lifecycle_manager-8] [INFO] [1730491421.345664862] [lifecycle_manager_navigation]: Server behavior_server connected with bond.
[lifecycle_manager-8] [INFO] [1730491421.345938720] [lifecycle_manager_navigation]: Activating bt_navigator
[bt_navigator-5] [INFO] [1730491421.350806691] [bt_navigator]: Activating
[bt_navigator-5] [INFO] [1730491421.597924374] [bt_navigator]: Creating bond (bt_navigator) to lifecycle manager.
[lifecycle_manager-8] [ERROR] [1730491422.521021728] [lifecycle_manager_navigation]: Failed to change state for node: bt_navigator. Exception: transition invoked while in transition.
[lifecycle_manager-8] [ERROR] [1730491422.521119908] [lifecycle_manager_navigation]: Failed to bring up all requested nodes. Aborting bringup.
^C[WARNING] [launch]: user interrupted with ctrl-c (SIGINT)
[velocity_smoother-7] [INFO] [1730491424.770654215] [rclcpp]: signal_handler(signum=2)
[velocity_smoother-7] [INFO] [1730491424.771421494] [velocity_smoother]: Running Nav2 LifecycleNode rcl preshutdown (velocity_smoother)
[lifecycle_manager-8] [INFO] [1730491424.770654233] [rclcpp]: signal_handler(signum=2)
[waypoint_follower-6] [INFO] [1730491424.770803187] [rclcpp]: signal_handler(signum=2)
[planner_server-3] [INFO] [1730491424.771104690] [rclcpp]: signal_handler(signum=2)
`
xylhal commented 2 weeks ago

Hi @RustyCPR @smatarCPR @hilary-luo Do you have updates on your findings? We got a second turtlebot that is setup in a totally independent network and this is still happening.

daisukes commented 2 weeks ago

Hi @xylhal

Could you try to clone my bond_cpp fix into your workspace and build it with your packages to see if it can fix the issue?

If it works, please leave a comment for support at the PR!

Thanks

xylhal commented 2 weeks ago

@daisukes Sure, I will try it out and get back to you

hilary-luo commented 2 days ago

@daisukes you could try bringing it up on ROS discourse or discord to try and get some attention to your PR.

@xylhal was @daisukes solution able to address the issue? If not I would suggest bringing this forward to the Nav2 team to see if they can provide additional insight.

xylhal commented 2 days ago

@hilary-luo I haven't had time to try @daisukes solution yet, I will update if it works or not. In the meantime, did your team find anything?