Inconsistent Navigation on Existing Maps

[EdBrayUTS]

Robot Model

Turtlebot4 Standard

ROS distro

Humble

Networking Configuration

Discovery Server

OS

Ubuntu 22.04

Built from source or installed?

Installed

Package version

turtlebot4_navigation version 1.0.5-1jammy.20250114.201201

All packages on both remote PC and Raspberry Pi fully-updated at time of opening this issue.

Type of issue

Navigation (SLAM, Nav2 etc.)

Expected behaviour

The robot to be able to autonomously navigate to goals provied in RViz using a pre-existing map of the environment.

Actual behaviour

This behaviour is very inconsistent. Very rarely, the everything works as expected. However typically something crashes when launching nav2.launch.py. An example error log is shown below.

The error is not always the same, but it is typically lifecycle_manager being unable to reach either controller_server or smoother_server after 4 seconds by bond. In the below instance, it was controller_server that cannot be reached.

Error messages

[INFO] [launch]: All log files can be found below /home/ed/.ros/log/2025-02-10-11-33-39-912698-Unhygienix-24041
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [controller_server-1]: process started with pid [24042]
[INFO] [smoother_server-2]: process started with pid [24044]
[INFO] [planner_server-3]: process started with pid [24046]
[INFO] [behavior_server-4]: process started with pid [24048]
[INFO] [bt_navigator-5]: process started with pid [24050]
[INFO] [waypoint_follower-6]: process started with pid [24052]
[INFO] [velocity_smoother-7]: process started with pid [24054]
[INFO] [lifecycle_manager-8]: process started with pid [24056]
[velocity_smoother-7] [INFO] [1739147620.022728425] [tb4.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] [1739147620.026065141] [tb4.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] [1739147620.026408458] [tb4.waypoint_follower]: Creating
[lifecycle_manager-8] [INFO] [1739147620.026702640] [tb4.lifecycle_manager_navigation]: Creating
[bt_navigator-5] [INFO] [1739147620.027269513] [tb4.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] [1739147620.027338303] [tb4.bt_navigator]: Creating
[lifecycle_manager-8] [INFO] [1739147620.027507127] [tb4.lifecycle_manager_navigation]: Creating and initializing lifecycle service clients
[controller_server-1] [INFO] [1739147620.029482791] [tb4.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.
[behavior_server-4] [INFO] [1739147620.029882550] [tb4.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] [1739147620.031244657] [tb4.controller_server]: Creating controller server
[controller_server-1] [INFO] [1739147620.033090280] [tb4.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.
[smoother_server-2] [INFO] [1739147620.033249216] [tb4.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.
[controller_server-1] [INFO] [1739147620.033317454] [tb4.local_costmap.local_costmap]: Creating Costmap
[smoother_server-2] [INFO] [1739147620.033950263] [tb4.smoother_server]: Creating smoother server
[planner_server-3] [INFO] [1739147620.036680856] [tb4.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.
[planner_server-3] [INFO] [1739147620.037522448] [tb4.planner_server]: Creating
[planner_server-3] [INFO] [1739147620.039236625] [tb4.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] [1739147620.039439076] [tb4.global_costmap.global_costmap]: Creating Costmap
[lifecycle_manager-8] [INFO] [1739147622.027983201] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147624.028178826] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147626.028357785] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147628.028672616] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147630.028848347] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147632.029022374] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147634.029209576] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147636.029453824] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147638.029705882] [tb4.lifecycle_manager_navigation]: Waiting for service controller_server/get_state...
[lifecycle_manager-8] [INFO] [1739147640.718887739] [tb4.lifecycle_manager_navigation]: Waiting for service smoother_server/get_state...
[lifecycle_manager-8] [INFO] [1739147642.719141579] [tb4.lifecycle_manager_navigation]: Waiting for service smoother_server/get_state...
[lifecycle_manager-8] [INFO] [1739147644.719448955] [tb4.lifecycle_manager_navigation]: Waiting for service smoother_server/get_state...
[lifecycle_manager-8] [INFO] [1739147646.719667778] [tb4.lifecycle_manager_navigation]: Waiting for service smoother_server/get_state...
[lifecycle_manager-8] [INFO] [1739147648.719862938] [tb4.lifecycle_manager_navigation]: Waiting for service smoother_server/get_state...
[lifecycle_manager-8] [INFO] [1739147650.720143566] [tb4.lifecycle_manager_navigation]: Waiting for service smoother_server/get_state...
[lifecycle_manager-8] [INFO] [1739147652.720410725] [tb4.lifecycle_manager_navigation]: Waiting for service smoother_server/get_state...
[lifecycle_manager-8] [INFO] [1739147657.841892730] [tb4.lifecycle_manager_navigation]: Waiting for service bt_navigator/get_state...
[lifecycle_manager-8] [INFO] [1739147658.891662652] [tb4.lifecycle_manager_navigation]: Starting managed nodes bringup...
[lifecycle_manager-8] [INFO] [1739147658.891753408] [tb4.lifecycle_manager_navigation]: Configuring controller_server
[controller_server-1] [INFO] [1739147658.892280146] [tb4.controller_server]: Configuring controller interface
[controller_server-1] [INFO] [1739147658.892660785] [tb4.controller_server]: getting goal checker plugins..
[controller_server-1] [INFO] [1739147658.892881374] [tb4.controller_server]: Controller frequency set to 20.0000Hz
[controller_server-1] [INFO] [1739147658.892927591] [tb4.local_costmap.local_costmap]: Configuring
[controller_server-1] [INFO] [1739147658.966383194] [tb4.local_costmap.local_costmap]: Using plugin "static_layer"
[controller_server-1] [INFO] [1739147658.993837239] [tb4.local_costmap.local_costmap]: Subscribing to the map topic (/tb4/map) with transient local durability
[controller_server-1] [INFO] [1739147658.997600881] [tb4.local_costmap.local_costmap]: Initialized plugin "static_layer"
[controller_server-1] [INFO] [1739147658.997698649] [tb4.local_costmap.local_costmap]: Using plugin "voxel_layer"
[controller_server-1] [INFO] [1739147659.046349681] [tb4.local_costmap.local_costmap]: Subscribed to Topics: scan
[controller_server-1] [INFO] [1739147659.539914932] [tb4.local_costmap.local_costmap]: Initialized plugin "voxel_layer"
[controller_server-1] [INFO] [1739147659.540056514] [tb4.local_costmap.local_costmap]: Using plugin "inflation_layer"
[controller_server-1] [INFO] [1739147659.587299825] [tb4.local_costmap.local_costmap]: Initialized plugin "inflation_layer"
[controller_server-1] [INFO] [1739147659.697181794] [tb4.controller_server]: Created progress_checker : progress_checker of type nav2_controller::SimpleProgressChecker
[controller_server-1] [INFO] [1739147659.700322598] [tb4.controller_server]: Created goal checker : general_goal_checker of type nav2_controller::SimpleGoalChecker
[controller_server-1] [INFO] [1739147659.719785391] [tb4.controller_server]: Controller Server has general_goal_checker  goal checkers available.
[controller_server-1] [INFO] [1739147659.723887149] [tb4.controller_server]: Created controller : FollowPath of type dwb_core::DWBLocalPlanner
[controller_server-1] [INFO] [1739147659.824447919] [tb4.controller_server]: Setting transform_tolerance to 0.200000
[controller_server-1] [INFO] [1739147659.939537472] [tb4.local_costmap.local_costmap]: StaticLayer: Resizing static layer to 172 X 402 at 0.050000 m/pix
[controller_server-1] [INFO] [1739147660.030484326] [tb4.controller_server]: Using critic "RotateToGoal" (dwb_critics::RotateToGoalCritic)
[controller_server-1] [INFO] [1739147660.045523167] [tb4.controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1739147660.045910631] [tb4.controller_server]: Using critic "Oscillation" (dwb_critics::OscillationCritic)
[controller_server-1] [INFO] [1739147660.055796507] [tb4.controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1739147660.056134382] [tb4.controller_server]: Using critic "BaseObstacle" (dwb_critics::BaseObstacleCritic)
[controller_server-1] [INFO] [1739147660.056645938] [tb4.controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1739147660.056912225] [tb4.controller_server]: Using critic "GoalAlign" (dwb_critics::GoalAlignCritic)
[controller_server-1] [INFO] [1739147660.090788793] [tb4.controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1739147660.091454840] [tb4.controller_server]: Using critic "PathAlign" (dwb_critics::PathAlignCritic)
[controller_server-1] [INFO] [1739147660.093106174] [tb4.controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1739147660.093714075] [tb4.controller_server]: Using critic "PathDist" (dwb_critics::PathDistCritic)
[controller_server-1] [INFO] [1739147660.094728391] [tb4.controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1739147660.095309701] [tb4.controller_server]: Using critic "GoalDist" (dwb_critics::GoalDistCritic)
[controller_server-1] [INFO] [1739147660.096217918] [tb4.controller_server]: Critic plugin initialized
[controller_server-1] [INFO] [1739147660.096259174] [tb4.controller_server]: Controller Server has FollowPath  controllers available.
[lifecycle_manager-8] [INFO] [1739147660.193751024] [tb4.lifecycle_manager_navigation]: Configuring smoother_server
[smoother_server-2] [INFO] [1739147660.194473525] [tb4.smoother_server]: Configuring smoother server
[smoother_server-2] [INFO] [1739147660.240800951] [tb4.smoother_server]: Created smoother : simple_smoother of type nav2_smoother::SimpleSmoother
[smoother_server-2] [INFO] [1739147660.245882476] [tb4.smoother_server]: Smoother Server has simple_smoother  smoothers available.
[lifecycle_manager-8] [INFO] [1739147660.294532184] [tb4.lifecycle_manager_navigation]: Configuring planner_server
[planner_server-3] [INFO] [1739147660.294986182] [tb4.planner_server]: Configuring
[planner_server-3] [INFO] [1739147660.295066481] [tb4.global_costmap.global_costmap]: Configuring
[planner_server-3] [INFO] [1739147660.355722352] [tb4.global_costmap.global_costmap]: Using plugin "static_layer"
[planner_server-3] [INFO] [1739147660.362795783] [tb4.global_costmap.global_costmap]: Subscribing to the map topic (/tb4/map) with transient local durability
[planner_server-3] [INFO] [1739147660.375231543] [tb4.global_costmap.global_costmap]: Initialized plugin "static_layer"
[planner_server-3] [INFO] [1739147660.375448822] [tb4.global_costmap.global_costmap]: Using plugin "obstacle_layer"
[planner_server-3] [INFO] [1739147660.392342689] [tb4.global_costmap.global_costmap]: Subscribed to Topics: scan
[planner_server-3] [INFO] [1739147660.438141231] [tb4.global_costmap.global_costmap]: Initialized plugin "obstacle_layer"
[planner_server-3] [INFO] [1739147660.438265243] [tb4.global_costmap.global_costmap]: Using plugin "inflation_layer"
[planner_server-3] [INFO] [1739147660.441842522] [tb4.global_costmap.global_costmap]: Initialized plugin "inflation_layer"
[planner_server-3] [INFO] [1739147660.496202058] [tb4.planner_server]: Created global planner plugin GridBased of type nav2_navfn_planner/NavfnPlanner
[planner_server-3] [INFO] [1739147660.496302180] [tb4.planner_server]: Configuring plugin GridBased of type NavfnPlanner
[planner_server-3] [INFO] [1739147660.506536817] [tb4.planner_server]: Planner Server has GridBased  planners available.
[lifecycle_manager-8] [INFO] [1739147660.675196184] [tb4.lifecycle_manager_navigation]: Configuring behavior_server
[behavior_server-4] [INFO] [1739147660.675945848] [tb4.behavior_server]: Configuring
[behavior_server-4] [INFO] [1739147660.723754918] [tb4.behavior_server]: Creating behavior plugin spin of type nav2_behaviors/Spin
[behavior_server-4] [INFO] [1739147660.724904956] [tb4.behavior_server]: Configuring spin
[behavior_server-4] [INFO] [1739147660.824232999] [tb4.behavior_server]: Creating behavior plugin backup of type nav2_behaviors/BackUp
[behavior_server-4] [INFO] [1739147660.825919481] [tb4.behavior_server]: Configuring backup
[behavior_server-4] [INFO] [1739147660.877482940] [tb4.behavior_server]: Creating behavior plugin drive_on_heading of type nav2_behaviors/DriveOnHeading
[behavior_server-4] [INFO] [1739147660.878910310] [tb4.behavior_server]: Configuring drive_on_heading
[behavior_server-4] [INFO] [1739147660.975635213] [tb4.behavior_server]: Creating behavior plugin assisted_teleop of type nav2_behaviors/AssistedTeleop
[behavior_server-4] [INFO] [1739147660.979125526] [tb4.behavior_server]: Configuring assisted_teleop
[behavior_server-4] [INFO] [1739147661.172087832] [tb4.behavior_server]: Creating behavior plugin wait of type nav2_behaviors/Wait
[behavior_server-4] [INFO] [1739147661.173516293] [tb4.behavior_server]: Configuring wait
[lifecycle_manager-8] [INFO] [1739147661.237295687] [tb4.lifecycle_manager_navigation]: Configuring bt_navigator
[bt_navigator-5] [INFO] [1739147661.237813645] [tb4.bt_navigator]: Configuring
[lifecycle_manager-8] [INFO] [1739147662.861497223] [tb4.lifecycle_manager_navigation]: Configuring waypoint_follower
[waypoint_follower-6] [INFO] [1739147662.861955057] [tb4.waypoint_follower]: Configuring
[waypoint_follower-6] [INFO] [1739147662.954726925] [tb4.waypoint_follower]: Created waypoint_task_executor : wait_at_waypoint of type nav2_waypoint_follower::WaitAtWaypoint
[lifecycle_manager-8] [INFO] [1739147662.957751612] [tb4.lifecycle_manager_navigation]: Configuring velocity_smoother
[velocity_smoother-7] [INFO] [1739147662.958550155] [tb4.velocity_smoother]: Configuring velocity smoother
[lifecycle_manager-8] [INFO] [1739147663.069175109] [tb4.lifecycle_manager_navigation]: Activating controller_server
[controller_server-1] [INFO] [1739147663.069904953] [tb4.controller_server]: Activating
[controller_server-1] [INFO] [1739147663.070005957] [tb4.local_costmap.local_costmap]: Activating
[controller_server-1] [INFO] [1739147663.070123811] [tb4.local_costmap.local_costmap]: Checking transform
[controller_server-1] [INFO] [1739147663.070347706] [tb4.local_costmap.local_costmap]: start
[controller_server-1] [INFO] [1739147663.272693534] [tb4.controller_server]: Creating bond (controller_server) to lifecycle manager.
[lifecycle_manager-8] [ERROR] [1739147665.292793558] [tb4.lifecycle_manager_navigation]: Server controller_server was unable to be reached after 4.00s by bond. This server may be misconfigured.
[lifecycle_manager-8] [ERROR] [1739147665.292893387] [tb4.lifecycle_manager_navigation]: Failed to bring up all requested nodes. Aborting bringup.
[planner_server-3] [INFO] [1739147665.787061830] [tb4.global_costmap.global_costmap]: StaticLayer: Resizing costmap to 172 X 402 at 0.050000 m/pix
[controller_server-1] [INFO] [1739147668.063874559] [tb4.local_costmap.local_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1739147667.334 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[controller_server-1] [INFO] [1739147672.577698654] [tb4.local_costmap.local_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1739147671.438 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[controller_server-1] [INFO] [1739147672.621853636] [tb4.local_costmap.local_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1739147671.446 for reason 'the timestamp on the message is earlier than all the data in the transform cache'
[controller_server-1] [INFO] [1739147675.335092485] [tb4.local_costmap.local_costmap]: Message Filter dropping message: frame 'rplidar_link' at time 1739147674.459 for reason 'the timestamp on the message is earlier than all the data in the transform cache'

To Reproduce

On the remote PC, open three terminals:

1. Terminal 1: ros2 launch turtlebot4_viz view_robot.launch.py namespace:=/tb4
2. Terminal 2: ros2 launch turtlebot4_navigation localization.launch.py namespace:=/tb4 map:=map_name.yaml
3. Terminal 3: ros2 launch turtlebot4_navigation nav2.launch.py namespace:=/tb4

Other notes

I am running the robot in discovery_server mode with a namespace /tb4 as suggested in #468 .

I get a lot of warnings about dropped messages as the timestamp on the message is earlier than all the data in the transform cache. Following advice in #530 I have set up time sync between the Create3, Raspberry Pi, and remote PC. Sync between the Create3 and Raspberry Pi was enabled by default. I made changes to /etc/chrony/chrony.conf on the Pi and remote PC as follows:

• Pi: added server <remote_pc_ip> iburst prefer
• Remote PC: added allow <raspberry_pi_ip>

Running sudo chronyc sources on the Pi now shows:

MS Name/IP address         Stratum Poll Reach LastRx Last sample               
===============================================================================
^- alphyn.canonical.com          2   6   377    55  -2317us[-2317us] +/-  326ms
^- prod-ntp-4.ntp1.ps5.cano>     2   6   375   252  +3336us[+3336us] +/-  130ms
^- prod-ntp-5.ntp4.ps5.cano>     2   6   377   252  +2938us[+2938us] +/-  130ms
^- prod-ntp-3.ntp1.ps5.cano>     2   6   377   253  +1372us[+1372us] +/-  131ms
^- smtp.juneks.com.au            1   6   377   320   -189us[  +50us] +/- 3602us
^- auvps1.sameteem.com           5   6   376   253   -228us[ -228us] +/- 5530us
^- syd.clearnet.pw               2   6   377   252   -321us[ -321us] +/-   27ms
^- time.cloudflare.com           3   6   377   254   -589us[ -589us] +/- 4914us
^* <remote_pc_ip>                2   6   377   255   +453us[ +918us] +/- 6733us

And running sudo chronyc clients on the remote PC gives:

Hostname                      NTP   Drop Int IntL Last     Cmd   Drop Int  Last
===============================================================================
<raspberry_pi_ip>                 31      0   6   -    20       0      0   -     -

This indicates to me that the remote PC is the preferred source, but sync doesn't seem perfect. Could this be the root of the issue?

I've also observed the nodes started by localization.launch.py and nav2.launch.py take a long time to find services eg. controller_server/get_state (as in this example) or the map_server services. Sometimes they don't find them after 30 seconds, and I restart the command. Is this possibly related?