tf wait for transform failure

edit

I believe this question is related to http://answers.ros.org/question/12358/tfwaitfortransform-does-not-wait-for-transform/, though I am not sure if a bug report was filed with the previous one.

I cannot get TransformListener::waitForTransform to wait for the given duration - Unless I supply an excessive long timeout (10000 seconds), the waitForTransform call returns immediately. It also never seems to succeed.

A bag file to reproduce this error is available here (47 MB). To run the bag file, don't use --clock as /clock was recorded explicitly:

rosparam set /use_sim_time true && rosbag play tf.bag

This bag file was recorded for a multi robot setup in simulation, and a number of different nodes are publishing tf information. The view frames output (is correct), and available here. This output can be reproduced by running:

rosrun tf view_frames

On the other hand, while running tf_echo the waitForTransform call in tf_echo always fails, and the first lookupTransform fails (as waitForTransform does not wait sufficiently long). All subsequent lookupTransform calls produce the correct output:

rosrun tf tf_echo /segbot1/base_footprint /segbot1/ens1/map

Example Output:

Failure at 458.729000000
Exception thrown:Frame id /segbot1/base_footprint does not exist! Frames (1): 
The current list of frames is:

At time 459.605
- Translation: [-5.000, -5.000, 0.001]
- Rotation: in Quaternion [0.000, 0.000, -0.000, 1.000]
            in RPY [0.000, 0.000, -0.000]
At time 460.600
- Translation: [-5.000, -5.000, 0.001]
- Rotation: in Quaternion [0.000, 0.000, -0.000, 1.000]
            in RPY [0.000, 0.000, -0.000]

I made a local copy of tf_echo, and increased the wait duration to about 100 seconds. I have an average gazebo speedup between 2.5 to 3.5 seconds, so I should see the waitForTransform call blocking for about 30 seconds before looking up the transform. This does not happen, and the call returns immediately (unsuccessful).

If anyone has any insights into this, then let me know. Otherwise I'll proceed with filing this as a bug. Currently the waitForTransform call for this transform fails repeatedly in a loop in the navigation stack.

UPDATE #1

I have created a simple downloadable package to test tf_echo here.

Usage:

rosrun tf_test tf_echo /segbot1/base_footprint /segbot1/ens1/map _duration:=1.0
rosrun tf_test tf_echo /segbot1/base_footprint /segbot1/ens1/map _duration:=10.0
rosrun tf_test tf_echo /segbot1/base_footprint /segbot1/ens1/map _duration:=100.0

Output:

using duration: 100
waitForTransform Success: 0
Failure at 458.520000000
Exception thrown:Frame id /segbot1/ens1/map does not exist! Frames (5): Frame /segbot1/base_footprint exists with parent /segbot1/odom.
Frame /segbot1/odom exists with parent NO_PARENT.
Frame /segbot2/base_footprint exists with parent /segbot2/odom.
Frame /segbot2/odom exists with parent NO_PARENT.

The current list of frames is:
Frame /segbot1/base_footprint exists with parent /segbot1/odom.
Frame /segbot1/odom exists with parent NO_PARENT.
Frame /segbot2/base_footprint exists with parent /segbot2/odom.
Frame /segbot2/odom exists with parent NO_PARENT.

At time 459.401
- Translation: [-5.000, -5.000, 0.001 ...