Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

Hydro move_base/tf2 extrapolation error into the future errror

Hi All,

We are using Hyrdo's move_base and we continue to get an extrapolation error into the future. I believe this is causing our robot to stop and start during a traverse.

In looking the ROS source code it appears that the lookupTransform in navigation/base_local_planner/src/goal_functions.cpp line 110 in transformGlobalPlan is returning the error. We are using the dwa_local_planner. We are publishing transforms at 20hz from a separate node. The parameters to tf.lookupTransform are global_frame = "local" and the plan_pose.header.frame_id = "global", and the plan_pose.header.stamp comes from the generating the gloabl plan. I think the bug is coming from tf2/src/buffer_core.cpp in WalkToTopParent(). I still need to do more debugging to find the exact problem. I've turned the debug information on for move_base so I'm including a snippet of it, and the console log below. Any help would be appreciated. Thanks.

[ WARN] [1386166204.799236284]: Could not transform the global plan to the frame of the controller [ WARN] [1386166207.099315434]: Could not transform the global plan to the frame of the controller FROM CONSOLE:

Hydro move_base/tf2 extrapolation error into the future errror

Hi All,

We are using Hyrdo's move_base and we continue to get an extrapolation error into the future. I believe this is causing our robot to stop and start during a traverse.

In looking the ROS source code it appears that the lookupTransform in navigation/base_local_planner/src/goal_functions.cpp line 110 in transformGlobalPlan is returning the error. We are using the dwa_local_planner. We are publishing transforms at 20hz from a separate node. The parameters to tf.lookupTransform are global_frame = "local" and the plan_pose.header.frame_id = "global", and the plan_pose.header.stamp comes from the generating the gloabl plan. I think the bug is coming from tf2/src/buffer_core.cpp in WalkToTopParent(). I still need to do more debugging to find the exact problem. I've turned the debug information on for move_base so I'm including a snippet of it, and the console log below. Any help would be appreciated. Thanks.

[ WARN] [1386166204.799236284]: Could not transform the global plan to the frame of the controller [ WARN] [1386166207.099315434]: Could not transform the global plan to the frame of the controller FROM CONSOLE:

Hydro move_base/tf2 extrapolation error into the future errror

Hi All,

We are using Hyrdo's move_base and we continue to get an extrapolation error into the future. I believe this is causing our robot to stop and start during a traverse.

In looking the ROS source code it appears that the lookupTransform in navigation/base_local_planner/src/goal_functions.cpp line 110 in transformGlobalPlan is returning the error. We are using the dwa_local_planner. We are publishing transforms at 20hz from a separate node. The parameters to tf.lookupTransform are global_frame = "local" and the plan_pose.header.frame_id = "global", and the plan_pose.header.stamp comes from the generating the gloabl plan. I think the bug is coming from tf2/src/buffer_core.cpp in WalkToTopParent(). I still need to do more debugging to find the exact problem. I've turned the debug information on for move_base so I'm including a snippet of it, and the console log below. Any help would be appreciated. Thanks.

[DEBUG] [1386166204.375994679]: The action server has received a new goal request
[DEBUG] [1386166204.376260355]: A new goal has been recieved by the single goal action server
[DEBUG] [1386166204.376656845]: Accepting a new goal
[DEBUG] [1386166204.376895493]: Accepting goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.377491239]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.377705512]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.378025665]: Planning...
[DEBUG] [1386166204.378168840]: Waiting for plan, in the planning state.
[DEBUG] [1386166204.378332478]: Full control cycle time: 0.000979315

[DEBUG] [1386166204.455307564]: Got Plan with 49 points!
[DEBUG] [1386166204.457263957]: Generated a plan from the base_global_planner
[DEBUG] [1386166204.458307175]: Planner thread is suspending
[DEBUG] [1386166204.477544259]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.477708316]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.477914069]: Got a new plan...swap pointers
[DEBUG] [1386166204.478065066]: pointers swapped!
[ INFO] [1386166204.478229751]: Got new plan
[DEBUG] [1386166204.478925371]: In controlling state.
[DEBUG] [1386166204.515009849]: Got a valid command from the local planner: 0.500, 0.000, 2.000
[DEBUG] [1386166204.516475469]: Full control cycle time: 0.037907056

[DEBUG] [1386166204.578542367]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.579298889]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.580845315]: In controlling state.
[DEBUG] [1386166204.609181880]: Got a valid command from the local planner: 0.500, 0.000, 2.000
[DEBUG] [1386166204.610400540]: Full control cycle time: 0.031062960

[DEBUG] [1386166204.677557610]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.677725508]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.677947673]: In controlling state.
[DEBUG] [1386166204.704567051]: Got a valid command from the local planner: 0.500, 0.000, 2.000
[DEBUG] [1386166204.705445516]: Full control cycle time: 0.027409982

[DEBUG] [1386166204.777927638]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.779469173]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.790713341]: In controlling state.
[ WARN] [1386166204.799236284]: Could not transform the global plan to the frame of the controller
[DEBUG] [1386166204.802767947]: The local planner could not find a valid plan.
[DEBUG] [1386166204.804277915]: Planning...
[DEBUG] [1386166204.806757562]: Full control cycle time: 0.029080164

[DEBUG] [1386166204.877208489]: Got Plan with 49 points!
[DEBUG] [1386166204.878977430]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.879146725]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.879352897]: Waiting for plan, in the planning state.
[DEBUG] [1386166204.879506199]: Full control cycle time: 0.002110815

[DEBUG] [1386166204.884773975]: Generated a plan from the base_global_planner
[DEBUG] [1386166204.886034821]: Planner thread is suspending
[DEBUG] [1386166204.977587453]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.977886654]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.978173771]: Got a new plan...swap pointers
[DEBUG] [1386166204.978476044]: pointers swapped!
[ INFO] [1386166204.978669994]: Got new plan
[DEBUG] [1386166204.978856819]: In controlling state.
[DEBUG] [1386166205.017628512]: Got a valid command from the local planner: 0.448, 0.000, 1.812
[DEBUG] [1386166205.018593509]: Full control cycle time: 0.040484062

[DEBUG] [1386166205.077536129]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.077705983]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.077902098]: In controlling state.
[DEBUG] [1386166205.117635921]: Got a valid command from the local planner: 0.266, 0.000, 2.063
[DEBUG] [1386166205.118555451]: Full control cycle time: 0.040495094

[DEBUG] [1386166205.177749432]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.179715326]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.185337546]: In controlling state.
[DEBUG] [1386166205.230841448]: Got a valid command from the local planner: 0.397, 0.000, 2.072
[DEBUG] [1386166205.232476503]: Full control cycle time: 0.054954404

[DEBUG] [1386166205.281725014]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.282137427]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.285275257]: In controlling state.
[DEBUG] [1386166205.324930439]: Got a valid command from the local planner: 0.333, 0.000, 1.935
[DEBUG] [1386166205.325334959]: Full control cycle time: 0.043936313

[DEBUG] [1386166205.377754753]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.400018545]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.403311982]: In controlling state.
[DEBUG] [1386166205.434306499]: Got a valid command from the local planner: 0.500, 0.000, 1.819
[DEBUG] [1386166205.434547731]: Full control cycle time: 0.057089105

[DEBUG] [1386166205.478460574]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.480680196]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.487263089]: In controlling state.
[DEBUG] [1386166205.526915895]: Got a valid command from the local planner: 0.500, 0.000, 1.819
[DEBUG] [1386166205.529046611]: Full control cycle time: 0.050830132

[DEBUG] [1386166205.577675708]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.578052571]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.581128380]: In controlling state.
[DEBUG] [1386166205.637572985]: Got a valid command from the local planner: 0.195, 0.000, -2.543
[DEBUG] [1386166205.639640568]: Full control cycle time: 0.062151475

[DEBUG] [1386166205.677513544]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.678263639]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.681451196]: In controlling state.
[DEBUG] [1386166205.727866873]: Got a valid command from the local planner: 0.500, 0.000, -3.059
[DEBUG] [1386166205.730029437]: Full control cycle time: 0.052604942

[DEBUG] [1386166205.780110809]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.794376448]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.796889897]: In controlling state.
[DEBUG] [1386166205.830207541]: Got a valid command from the local planner: 0.152, 0.000, -2.778
[DEBUG] [1386166205.831599686]: Full control cycle time: 0.050707284

[DEBUG] [1386166205.877740193]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.879729759]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.884120613]: In controlling state.
[DEBUG] [1386166205.937035721]: Got a valid command from the local planner: 0.038, 0.000, -2.498
[DEBUG] [1386166205.937388280]: Full control cycle time: 0.059935484

[DEBUG] [1386166205.977746411]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.978260444]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.978659377]: In controlling state.
[DEBUG] [1386166206.023969471]: Got a valid command from the local planner: 0.108, 0.000, -2.564
[DEBUG] [1386166206.025671223]: Full control cycle time: 0.048180431

[DEBUG] [1386166206.077568603]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.079011246]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.090116010]: In controlling state.
[DEBUG] [1386166206.119367495]: Got a valid command from the local planner: -0.130, 0.000, 1.822
[DEBUG] [1386166206.120285489]: Full control cycle time: 0.042222758

[DEBUG] [1386166206.177683082]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.182863279]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.197095536]: In controlling state.
[DEBUG] [1386166206.212940568]: Got a valid command from the local planner: -0.198, 0.000, 1.442
[DEBUG] [1386166206.214603070]: Full control cycle time: 0.035785557

[DEBUG] [1386166206.277678969]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.284374863]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.296676079]: In controlling state.
[DEBUG] [1386166206.319835447]: Got a valid command from the local planner: 0.500, 0.000, -1.653
[DEBUG] [1386166206.321370140]: Full control cycle time: 0.042692021

[DEBUG] [1386166206.377575259]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.377766834]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.378720587]: In controlling state.
[DEBUG] [1386166206.413027463]: Got a valid command from the local planner: 0.500, 0.000, -1.745
[DEBUG] [1386166206.414450061]: Full control cycle time: 0.035884731

[DEBUG] [1386166206.477536506]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.477800296]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.477999414]: In controlling state.
[DEBUG] [1386166206.512341491]: Got a valid command from the local planner: 0.500, 0.000, -1.800
[DEBUG] [1386166206.515639114]: Full control cycle time: 0.037860399

[DEBUG] [1386166206.577530785]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.577707902]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.578704469]: In controlling state.
[DEBUG] [1386166206.619075733]: Got a valid command from the local planner: 0.500, 0.000, -1.625
[DEBUG] [1386166206.619376330]: Full control cycle time: 0.041916294

[DEBUG] [1386166206.678381670]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.678848279]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.679309161]: In controlling state.
[DEBUG] [1386166206.717656704]: Got a valid command from the local planner: 0.500, 0.000, -1.331
[DEBUG] [1386166206.717989707]: Full control cycle time: 0.039929237

[DEBUG] [1386166206.777679981]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.778062151]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.785956171]: In controlling state.
[DEBUG] [1386166206.828150085]: Got a valid command from the local planner: 0.500, 0.000, -1.237
[DEBUG] [1386166206.829181222]: Full control cycle time: 0.050999570

[DEBUG] [1386166206.877526477]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.878493218]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.880053119]: In controlling state.
[DEBUG] [1386166206.915862917]: Got a valid command from the local planner: 0.500, 0.000, -1.524
[DEBUG] [1386166206.916878689]: Full control cycle time: 0.039424008

[DEBUG] [1386166206.978204362]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.979811901]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.992529931]: In controlling state.
[DEBUG] [1386166207.028332035]: Got a valid command from the local planner: 0.500, 0.000, -2.383
[DEBUG] [1386166207.029387966]: Full control cycle time: 0.050805903

[DEBUG] [1386166207.077680283]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166207.078072371]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166207.093392754]: In controlling state.
[ WARN] [1386166207.099315434]: Could not transform the global plan to the frame of the controller
[DEBUG] [1386166207.101504469]: The local planner could not find a valid plan.
[DEBUG] [1386166207.101739345]: Planning...
[DEBUG] [1386166207.107393974]: Full control cycle time: 0.029821387

[DEBUG] [1386166207.167421509]: Got Plan with 54 points!
[DEBUG] [1386166207.167596461]: Generated a plan from the base_global_planner
[DEBUG] [1386166207.167711420]: Planner thread is suspending
[DEBUG] [1386166207.177533339]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166207.177852095]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166207.178045695]: Got a new plan...swap pointers
[DEBUG] [1386166207.178153530]: pointers swapped!
[ INFO] [1386166207.178254660]: Got new plan
[DEBUG] [1386166207.178382330]: In controlling state.
[DEBUG] [1386166207.218677960]: Got a valid command from the local planner: 0.500, 0.000, -2.453
[DEBUG] [1386166207.219088626]: Full control cycle time: 0.041611440

[DEBUG] [1386166207.277684346]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166207.278083839]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166207.278807744]: In controlling state.
[DEBUG] [1386166207.325121383]: Got a valid command from the local planner: 0.500, 0.000, -2.205
[DEBUG] [1386166207.328377944]: Full control cycle time: 0.050748982

FROM CONSOLE:

[ERROR] [1386166204.794600431]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166204.760608679 but the latest data is at time 1386166204.681006934, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166204.798496177]: Global Frame: local Plan Frame size 49: global

[ERROR] [1386166204.801676467]: Could not get local plan
[ERROR] [1386166207.094102621]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166207.060895396 but the latest data is at time 1386166206.992936965, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166207.098096425]: Global Frame: local Plan Frame size 49: global

[ERROR] [1386166207.101307796]: Could not get local plan
[ERROR] [1386166208.600555921]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166208.560276359 but the latest data is at time 1386166208.477921333, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166208.605807498]: Global Frame: local Plan Frame size 54: global

[ERROR] [1386166208.608851947]: Could not get local plan
[ERROR] [1386166210.296415706]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166210.259930623 but the latest data is at time 1386166210.184060640, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166210.299559126]: Global Frame: local Plan Frame size 53: global

[ERROR] [1386166210.305595433]: Could not get local plan
[ERROR] [1386166211.594665718]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166211.560573392 but the latest data is at time 1386166211.480167357, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166211.597373393]: Global Frame: local Plan Frame size 56: global

[ERROR] [1386166211.601120168]: Could not get local plan
click to hide/show revision 4
retagged

Hydro move_base/tf2 extrapolation error into the future errror

Hi All,

We are using Hyrdo's move_base and we continue to get an extrapolation error into the future. I believe this is causing our robot to stop and start during a traverse.

In looking the ROS source code it appears that the lookupTransform in navigation/base_local_planner/src/goal_functions.cpp line 110 in transformGlobalPlan is returning the error. We are using the dwa_local_planner. We are publishing transforms at 20hz from a separate node. The parameters to tf.lookupTransform are global_frame = "local" and the plan_pose.header.frame_id = "global", and the plan_pose.header.stamp comes from the generating the gloabl plan. I think the bug is coming from tf2/src/buffer_core.cpp in WalkToTopParent(). I still need to do more debugging to find the exact problem. I've turned the debug information on for move_base so I'm including a snippet of it, and the console log below. Any help would be appreciated. Thanks.

[DEBUG] [1386166204.375994679]: The action server has received a new goal request
[DEBUG] [1386166204.376260355]: A new goal has been recieved by the single goal action server
[DEBUG] [1386166204.376656845]: Accepting a new goal
[DEBUG] [1386166204.376895493]: Accepting goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.377491239]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.377705512]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.378025665]: Planning...
[DEBUG] [1386166204.378168840]: Waiting for plan, in the planning state.
[DEBUG] [1386166204.378332478]: Full control cycle time: 0.000979315

[DEBUG] [1386166204.455307564]: Got Plan with 49 points!
[DEBUG] [1386166204.457263957]: Generated a plan from the base_global_planner
[DEBUG] [1386166204.458307175]: Planner thread is suspending
[DEBUG] [1386166204.477544259]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.477708316]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.477914069]: Got a new plan...swap pointers
[DEBUG] [1386166204.478065066]: pointers swapped!
[ INFO] [1386166204.478229751]: Got new plan
[DEBUG] [1386166204.478925371]: In controlling state.
[DEBUG] [1386166204.515009849]: Got a valid command from the local planner: 0.500, 0.000, 2.000
[DEBUG] [1386166204.516475469]: Full control cycle time: 0.037907056

[DEBUG] [1386166204.578542367]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.579298889]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.580845315]: In controlling state.
[DEBUG] [1386166204.609181880]: Got a valid command from the local planner: 0.500, 0.000, 2.000
[DEBUG] [1386166204.610400540]: Full control cycle time: 0.031062960

[DEBUG] [1386166204.677557610]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.677725508]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.677947673]: In controlling state.
[DEBUG] [1386166204.704567051]: Got a valid command from the local planner: 0.500, 0.000, 2.000
[DEBUG] [1386166204.705445516]: Full control cycle time: 0.027409982

[DEBUG] [1386166204.777927638]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.779469173]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.790713341]: In controlling state.
[ WARN] [1386166204.799236284]: Could not transform the global plan to the frame of the controller
[DEBUG] [1386166204.802767947]: The local planner could not find a valid plan.
[DEBUG] [1386166204.804277915]: Planning...
[DEBUG] [1386166204.806757562]: Full control cycle time: 0.029080164

[DEBUG] [1386166204.877208489]: Got Plan with 49 points!
[DEBUG] [1386166204.878977430]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.879146725]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.879352897]: Waiting for plan, in the planning state.
[DEBUG] [1386166204.879506199]: Full control cycle time: 0.002110815

[DEBUG] [1386166204.884773975]: Generated a plan from the base_global_planner
[DEBUG] [1386166204.886034821]: Planner thread is suspending
[DEBUG] [1386166204.977587453]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166204.977886654]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166204.978173771]: Got a new plan...swap pointers
[DEBUG] [1386166204.978476044]: pointers swapped!
[ INFO] [1386166204.978669994]: Got new plan
[DEBUG] [1386166204.978856819]: In controlling state.
[DEBUG] [1386166205.017628512]: Got a valid command from the local planner: 0.448, 0.000, 1.812
[DEBUG] [1386166205.018593509]: Full control cycle time: 0.040484062

[DEBUG] [1386166205.077536129]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.077705983]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.077902098]: In controlling state.
[DEBUG] [1386166205.117635921]: Got a valid command from the local planner: 0.266, 0.000, 2.063
[DEBUG] [1386166205.118555451]: Full control cycle time: 0.040495094

[DEBUG] [1386166205.177749432]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.179715326]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.185337546]: In controlling state.
[DEBUG] [1386166205.230841448]: Got a valid command from the local planner: 0.397, 0.000, 2.072
[DEBUG] [1386166205.232476503]: Full control cycle time: 0.054954404

[DEBUG] [1386166205.281725014]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.282137427]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.285275257]: In controlling state.
[DEBUG] [1386166205.324930439]: Got a valid command from the local planner: 0.333, 0.000, 1.935
[DEBUG] [1386166205.325334959]: Full control cycle time: 0.043936313

[DEBUG] [1386166205.377754753]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.400018545]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.403311982]: In controlling state.
[DEBUG] [1386166205.434306499]: Got a valid command from the local planner: 0.500, 0.000, 1.819
[DEBUG] [1386166205.434547731]: Full control cycle time: 0.057089105

[DEBUG] [1386166205.478460574]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.480680196]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.487263089]: In controlling state.
[DEBUG] [1386166205.526915895]: Got a valid command from the local planner: 0.500, 0.000, 1.819
[DEBUG] [1386166205.529046611]: Full control cycle time: 0.050830132

[DEBUG] [1386166205.577675708]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.578052571]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.581128380]: In controlling state.
[DEBUG] [1386166205.637572985]: Got a valid command from the local planner: 0.195, 0.000, -2.543
[DEBUG] [1386166205.639640568]: Full control cycle time: 0.062151475

[DEBUG] [1386166205.677513544]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.678263639]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.681451196]: In controlling state.
[DEBUG] [1386166205.727866873]: Got a valid command from the local planner: 0.500, 0.000, -3.059
[DEBUG] [1386166205.730029437]: Full control cycle time: 0.052604942

[DEBUG] [1386166205.780110809]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.794376448]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.796889897]: In controlling state.
[DEBUG] [1386166205.830207541]: Got a valid command from the local planner: 0.152, 0.000, -2.778
[DEBUG] [1386166205.831599686]: Full control cycle time: 0.050707284

[DEBUG] [1386166205.877740193]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.879729759]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.884120613]: In controlling state.
[DEBUG] [1386166205.937035721]: Got a valid command from the local planner: 0.038, 0.000, -2.498
[DEBUG] [1386166205.937388280]: Full control cycle time: 0.059935484

[DEBUG] [1386166205.977746411]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166205.978260444]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166205.978659377]: In controlling state.
[DEBUG] [1386166206.023969471]: Got a valid command from the local planner: 0.108, 0.000, -2.564
[DEBUG] [1386166206.025671223]: Full control cycle time: 0.048180431

[DEBUG] [1386166206.077568603]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.079011246]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.090116010]: In controlling state.
[DEBUG] [1386166206.119367495]: Got a valid command from the local planner: -0.130, 0.000, 1.822
[DEBUG] [1386166206.120285489]: Full control cycle time: 0.042222758

[DEBUG] [1386166206.177683082]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.182863279]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.197095536]: In controlling state.
[DEBUG] [1386166206.212940568]: Got a valid command from the local planner: -0.198, 0.000, 1.442
[DEBUG] [1386166206.214603070]: Full control cycle time: 0.035785557

[DEBUG] [1386166206.277678969]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.284374863]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.296676079]: In controlling state.
[DEBUG] [1386166206.319835447]: Got a valid command from the local planner: 0.500, 0.000, -1.653
[DEBUG] [1386166206.321370140]: Full control cycle time: 0.042692021

[DEBUG] [1386166206.377575259]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.377766834]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.378720587]: In controlling state.
[DEBUG] [1386166206.413027463]: Got a valid command from the local planner: 0.500, 0.000, -1.745
[DEBUG] [1386166206.414450061]: Full control cycle time: 0.035884731

[DEBUG] [1386166206.477536506]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.477800296]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.477999414]: In controlling state.
[DEBUG] [1386166206.512341491]: Got a valid command from the local planner: 0.500, 0.000, -1.800
[DEBUG] [1386166206.515639114]: Full control cycle time: 0.037860399

[DEBUG] [1386166206.577530785]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.577707902]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.578704469]: In controlling state.
[DEBUG] [1386166206.619075733]: Got a valid command from the local planner: 0.500, 0.000, -1.625
[DEBUG] [1386166206.619376330]: Full control cycle time: 0.041916294

[DEBUG] [1386166206.678381670]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.678848279]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.679309161]: In controlling state.
[DEBUG] [1386166206.717656704]: Got a valid command from the local planner: 0.500, 0.000, -1.331
[DEBUG] [1386166206.717989707]: Full control cycle time: 0.039929237

[DEBUG] [1386166206.777679981]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.778062151]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.785956171]: In controlling state.
[DEBUG] [1386166206.828150085]: Got a valid command from the local planner: 0.500, 0.000, -1.237
[DEBUG] [1386166206.829181222]: Full control cycle time: 0.050999570

[DEBUG] [1386166206.877526477]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.878493218]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.880053119]: In controlling state.
[DEBUG] [1386166206.915862917]: Got a valid command from the local planner: 0.500, 0.000, -1.524
[DEBUG] [1386166206.916878689]: Full control cycle time: 0.039424008

[DEBUG] [1386166206.978204362]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166206.979811901]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166206.992529931]: In controlling state.
[DEBUG] [1386166207.028332035]: Got a valid command from the local planner: 0.500, 0.000, -2.383
[DEBUG] [1386166207.029387966]: Full control cycle time: 0.050805903

[DEBUG] [1386166207.077680283]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166207.078072371]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166207.093392754]: In controlling state.
[ WARN] [1386166207.099315434]: Could not transform the global plan to the frame of the controller
[DEBUG] [1386166207.101504469]: The local planner could not find a valid plan.
[DEBUG] [1386166207.101739345]: Planning...
[DEBUG] [1386166207.107393974]: Full control cycle time: 0.029821387

[DEBUG] [1386166207.167421509]: Got Plan with 54 points!
[DEBUG] [1386166207.167596461]: Generated a plan from the base_global_planner
[DEBUG] [1386166207.167711420]: Planner thread is suspending
[DEBUG] [1386166207.177533339]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166207.177852095]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166207.178045695]: Got a new plan...swap pointers
[DEBUG] [1386166207.178153530]: pointers swapped!
[ INFO] [1386166207.178254660]: Got new plan
[DEBUG] [1386166207.178382330]: In controlling state.
[DEBUG] [1386166207.218677960]: Got a valid command from the local planner: 0.500, 0.000, -2.453
[DEBUG] [1386166207.219088626]: Full control cycle time: 0.041611440

[DEBUG] [1386166207.277684346]: Publishing feedback for goal, id: /waypoint_management_node-1-1386166204.372833387, stamp: 1386166204.37
[DEBUG] [1386166207.278083839]: Publishing feedback for goal with id: /waypoint_management_node-1-1386166204.372833387 and stamp: 1386166204.37
[DEBUG] [1386166207.278807744]: In controlling state.
[DEBUG] [1386166207.325121383]: Got a valid command from the local planner: 0.500, 0.000, -2.205
[DEBUG] [1386166207.328377944]: Full control cycle time: 0.050748982

FROM CONSOLE:

[ERROR] [1386166204.794600431]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166204.760608679 but the latest data is at time 1386166204.681006934, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166204.798496177]: Global Frame: local Plan Frame size 49: global

[ERROR] [1386166204.801676467]: Could not get local plan
[ERROR] [1386166207.094102621]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166207.060895396 but the latest data is at time 1386166206.992936965, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166207.098096425]: Global Frame: local Plan Frame size 49: global

[ERROR] [1386166207.101307796]: Could not get local plan
[ERROR] [1386166208.600555921]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166208.560276359 but the latest data is at time 1386166208.477921333, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166208.605807498]: Global Frame: local Plan Frame size 54: global

[ERROR] [1386166208.608851947]: Could not get local plan
[ERROR] [1386166210.296415706]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166210.259930623 but the latest data is at time 1386166210.184060640, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166210.299559126]: Global Frame: local Plan Frame size 53: global

[ERROR] [1386166210.305595433]: Could not get local plan
[ERROR] [1386166211.594665718]: Extrapolation Error: Lookup would require extrapolation into the future.  Requested time 1386166211.560573392 but the latest data is at time 1386166211.480167357, when looking up transform from frame [local] to frame [global]

[ERROR] [1386166211.597373393]: Global Frame: local Plan Frame size 56: global

[ERROR] [1386166211.601120168]: Could not get local plan