[tf2_ros] Fix waitForTransform race condition

[alireza-moayyedi]

Description

Hi,

I was facing a race condition as following:

• use waitForTransform to lookup a tf
• parallely create and publish that tf from a different node exactly at the same time
• sometimes, even though the transform becomes available, waitForTransform would eventually timeout.

After taking a deeper look at it I noticed that the problem is that there is a slight delay between addTransformableRequest and ceating the timer. If the transform becomes available in between, then cb would get triggered, finds an empty map (since timer is not yet added to timer_to_request_map_) so it incorrectly assumes timeout is occured and returns silently. Which means waitForTransform never resolves and it eventually timeouts.

Now my proposal is to basically use timer_to_request_map_mutex_ for both adding the cb as well as adding the timer. This way, cb would not be triggered in between.

Recreating this issue only via testing is a bit difficult, because as you can immagine, the race condition happens only in the time between those few lines. That's why I have made a test to repeat the process 100 times. But again, not really a test if sometimes it may or may not happen. To guarantee reproducing it, then you can edit buffer.cpp by adding a small sleep before creating timer's lock such that the callback is added, requested transform is set and only then timer is added. Then you can see the issue without my fixes.

[mergify]

Tick the box to add this pull request to the merge queue (same as @mergifyio queue).

• Queue this pull request

[tfoote]

That's quite a narrow window to hit the race condition. Covering both of these with the existing mutex makes sense with the deferred callback invocation.

[asymingt]

I triggered a run in CI using this repos file:

• Linux
• Linux-aarch64
• Linux-rhel
• Windows

[asymingt]

Thank you for finding and fixing this. I spent a few moments seeing if I could create a more deterministic version of the test, which I couldn't. So, I triggered CI and we'll merge if everything goes green.

[alireza-moayyedi]

That's quite a narrow window to hit the race condition.

@tfoote In theory yes. In the test that I have added I had to set the nr of regressions to tens of thousends for it to eventually happen naturally. Time window is just a few lines of cpp. But for some reason on my robot this happens way more frequently. Something like 3 out 10 times. The exact work flow there is:

• An orchestrator node sends an asynchronous service request to a perception node to create a specific tf and in its request callback (which is there only to confirm request was received) uses waitForTransform.
• the perception node while subscribed to a 10hz lidar stream, receives the request, calculates and publishes the tf

Somehow, this recreates the perfect scenario for this specific race condition to happen. I wonder if rmw or executor here is playing a role in prolonging that time window such that the race condition occurs more often.

@asymingt I agree, unfortunately the only way to guarantee the race condition would be to put a sleep in buffer.cpp itself to winden the race window. Which is also why I was a bit doubting if this test is actually useful here. I mean sure, it needs to work, but it's not really that effective in hitting the right spot.