Move_base posting incorrect goal_ID timestamp
I'm attempting to create a program that can send a series of waypoints to a turtlebot3 performing 2D slam with AMCL and using move_base as the controller. Doing all this as a simulation.
I'm trying to get this all running in gazebo. I have followed the turtlebot3 navigation and simulation tutorials, I can get gazebo running, see the robot, launch Rviz, reset the pose, and even send a command via the Rviz 2N nav goal GUI, and it all works.
First I run:
roslaunch turtlebot3_gazebo turtlebot3_world.launch
Then:
roslaunch turtlebot3_navigation turtlebot3_navigation.launch map_file:=$HOME/map.yaml
However, when I go to give it a second goal (either from terminal, or the rviz GUI), nothing happens. No new global or local plan is generated, it just sits there.
Ive tried running rostopic echo move_base/status:
for the first goal, everything works fine and when it reaches goal I get this:
header:
seq: 1104
stamp:
secs: 285
nsecs: 411000000
frame_id: ''
status_list:
-
goal_id:
stamp:
secs: 2690710792
nsecs: 32577
id: "/move_base-1-2690710792.32577"
status: 3
text: "Goal reached."
When I set a new 2nd goal, it seems to be immediately rejected because another goal?
header:
seq: 1308
stamp:
secs: 326
nsecs: 8000000
frame_id: ''
status_list:
goal_id:
stamp:
secs: 2690710792
nsecs: 32577
id: "/move_base-1-2690710792.32577"
status: 3
text: "Goal reached."
goal_id:
stamp:
secs: 321
nsecs: 25000000
id: "/move_base-2-321.25000000"
status: 8
text: "This goal was canceled because another goal was recieved by the simple action server"
Ive dug through as many of these rostopic lists as I could looking for more clues, but have come up empty handed. Please hlep me shed light on this one!!
A few notes on system: ROS Kinetic running on Ubuntu 16.04, all on a virtual machine running in windows.
------ UPDATE-----
Interesting! I suspected time had something to do with this, but missed that clue.
More clues: I generated these messages from echo move_base/goal. The first is the very first message (successful), the second was rejected.
header:
seq: 0
stamp:
secs: 44
nsecs: 156000000
frame_id: ''
goal_id:
stamp:
secs: 0
nsecs: 0
id: ''
goal:
target_pose:
header:
seq: 0
stamp:
secs: 44
nsecs: 156000000
frame_id: "map"
pose:
position:
x: -0.520000100136
y: -1.67999970913
z: 0.0
orientation:
x: 0.0
y: 0.0
z: 0.010867499424
w: 0.999940946985
---
header:
seq: 1
stamp:
secs: 65
nsecs: 551000000
frame_id: ''
goal_id:
stamp:
secs: 0
nsecs: 0
id: ''
goal:
target_pose:
header:
seq: 1
stamp:
secs: 65
nsecs: 552000000
frame_id: "map"
pose:
position:
x: -0.58999979496
y: 0.510000050068
z: 0.0
orientation:
x: 0.0
y: 0.0
z: 0.702834457478
w: 0.711353446173
This is from move_base/status:
---
header:
seq: 277
stamp:
secs: 65
nsecs: 552000000
frame_id: ''
status_list:
-
goal_id:
stamp:
secs: 4294967295
nsecs: 0
id: "/move_base-1-4294967295.0"
status: 3
text: "Goal reached."
-
goal_id:
stamp:
secs: 1397513456
nsecs: 32765
id: "/move_base-2-1397513456.32765"
status: 8
text: "This goal was canceled because another goal was recieved by the simple action server"
From this it looks indeed like the goal ID handoff is getting botched or not set somewhere, since from the goal topic, the goal_id time is 0 0, and under status, its effectively garbage.
Any idea how to make rviz attach a better goal_id time than this garbage?
------NEW UPDATE--------
It seems that something within move_base is getting a bad timestamp. And Rviz has nothing to do with the problem.
I am posting a movebase/goal message with an appropriate goalid timestamp, but as soon as move_base picks this up, the timestamp seems to be generated internally based on incorrect data, and gives some crazy result.
What could possibly be causing this?
Ive checked it against both the simtime and the walltime values, and neither match, so it isnt coming from any direct ros::time source.
where else could this be coming from??
Asked by agillin on 2019-03-10 21:03:26 UTC
Answers
Careful with the stamps of your goals.
The first goal has a stamp
stamp:
secs: 2690710792
nsecs: 32577
Which is "GMT: Wednesday, 7 April 2055 11:39:52".
And the second goal has a stamp
stamp:
secs: 321
nsecs: 25000000
If you send a goal with a stamp in the future all goals received with a previous stamps will be ignored. Most likely you are not filling out the timestamp of your goal and move_base is just receiving garbage there.
Asked by Martin Peris on 2019-03-11 00:24:53 UTC
Comments
Interesting! I edited my initial question above with more info
Asked by agillin on 2019-03-11 01:48:06 UTC
So I updated my question - but it seems the timestamp is coming internally from move_base. I have no idea where its getting this incorrect information though. Its beyond frustrating...
Asked by agillin on 2019-03-11 23:04:00 UTC
Well, not exactly a root-cause solution: I ended up creating a new Ubuntu VM, installed kinetic from scratch and now it all works fine. Im getting goal_id timestamps that match with clock.
So, Id be very interested in knowing where the other install went sideways, but not a fight I want to fight solo.
Asked by agillin on 2019-03-13 00:57:20 UTC
Comments
nitpick, but: the timestamp is not "garbage". It's unexpected, but it's a valid timestamp (it just happens to be in the future).
RViz is being used by many people, and has been for a long time, also in navigation contexts, so my first guess would be that something is either not right with the clock it's using/gets on your machine, or there is some weirdness going on with
use_sim_time
.Asked by gvdhoorn on 2019-03-11 02:57:09 UTC
Good point, I take back my garbage comment. Was late and I was frustrated...
Any tips on how I can troubleshoot those clock issues? How can I tell where move_base is pulling that data?
Asked by agillin on 2019-03-11 15:48:59 UTC