Bug Not To Handle ResultCallback While Canceling Goal

[CihatAltiparmak]

Hello @facontidavide ,
Firstly, i want to thank for your great work. I have found a bug in cancelGoal function in bt_action_node.hpp . When it's canceled goal, it's not waited that the goal gets result after finishing. This bug gives rise to exist the possibility of sending new goal without handling result_callback of corresponding goal. If you debug by putting following lines to according places, you understand the bug.

RCLCPP_INFO(node_->get_logger(), "RESULT_GOAL ID : %s", rclcpp_action::to_string(result.goal_id).c_str()); to line 332

RCLCPP_INFO(node_->get_logger(), "CANCEL_GOAL ID : %s", rclcpp_action::to_string(goal_handle_->get_goal_id()).c_str()); to line 431

I tried with your btcpp_ros2_samples. I run ros2 run btcpp_ros2_samples sleep_client for my fixed version and your current version of this repo.

Your output:

PrintValue: start
[INFO] [1695293776.715275411] [sleep_client]: RESULT_GOAL ID : ef75e3cbdd7c226bb1c6e2cd36a0c236
[INFO] [1695293776.715445058] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695293778.268966187] [sleep_client]: CANCEL_GOAL ID : dd28f1f6ab96854d84f85a2fdde2a2
[INFO] [1695293778.269641275] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695293780.270740751] [sleep_client]: RESULT_GOAL ID : 1dcb1f40d8421bd4f824346bfb878b
[INFO] [1695293780.270829274] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695293780.271580174] [sleep_client]: RESULT_GOAL ID : dd28f1f6ab96854d84f85a2fdde2a2
[INFO] [1695293781.773432366] [sleep_client]: CANCEL_GOAL ID : 2160659ffbfa6596de53aabe02fa9e5
[INFO] [1695293781.774070320] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695293783.775155203] [sleep_client]: RESULT_GOAL ID : 956327c886842cca4da9a83ba9a375df
[INFO] [1695293783.775239360] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695293783.775899932] [sleep_client]: RESULT_GOAL ID : 2160659ffbfa6596de53aabe02fa9e5
[INFO] [1695293785.275925308] [sleep_client]: CANCEL_GOAL ID : 45126ab2219b8e3861537d843c991
[INFO] [1695293785.276538092] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695293787.277526354] [sleep_client]: RESULT_GOAL ID : dd451ef6592bf2b73c6935dc4cf70d6
[INFO] [1695293787.277612585] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695293787.278468184] [sleep_client]: RESULT_GOAL ID : 45126ab2219b8e3861537d843c991
[INFO] [1695293788.783090360] [sleep_client]: CANCEL_GOAL ID : acbe325acc152b348c40c6a96178fd8c
[INFO] [1695293788.783685525] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695293790.784665696] [sleep_client]: RESULT_GOAL ID : 3a38ae54fb365a81490d7737b49a8
[INFO] [1695293790.784733127] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695293790.785492102] [sleep_client]: RESULT_GOAL ID : acbe325acc152b348c40c6a96178fd8c
[INFO] [1695293792.286093402] [sleep_client]: CANCEL_GOAL ID : 8688086cee0346310fbdc595213e
[INFO] [1695293792.286707982] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted

My Output:

PrintValue: start
[INFO] [1695295344.142244774] [sleep_client]: RESULT_GOAL ID : f9f6d789aa5114b51857d44126bc662
[INFO] [1695295344.142411571] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695295345.643276985] [sleep_client]: CANCEL_GOAL ID : e5261931333755dc253252dfb2e861d9
[INFO] [1695295345.743568867] [sleep_client]: RESULT_GOAL ID : e5261931333755dc253252dfb2e861d9
[INFO] [1695295345.743714297] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695295347.744981916] [sleep_client]: RESULT_GOAL ID : c2baf96cb5b79a7674a94352a087383f
[INFO] [1695295347.745074847] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695295349.264379159] [sleep_client]: CANCEL_GOAL ID : 5454cc3c188455c138a998b5d9280
[INFO] [1695295349.346670567] [sleep_client]: RESULT_GOAL ID : 5454cc3c188455c138a998b5d9280
[INFO] [1695295349.346815698] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695295351.348284469] [sleep_client]: RESULT_GOAL ID : 1ab7cf57e54120eaf0fceeddd65562c4
[INFO] [1695295351.348366768] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695295352.868317555] [sleep_client]: CANCEL_GOAL ID : f276a469da4f1365db2cd3bc79961469
[INFO] [1695295352.949544723] [sleep_client]: RESULT_GOAL ID : f276a469da4f1365db2cd3bc79961469
[INFO] [1695295352.949629849] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695295354.950950643] [sleep_client]: RESULT_GOAL ID : e99b9b5b9c75a854f22234197362ff9
[INFO] [1695295354.951044802] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695295356.471232107] [sleep_client]: CANCEL_GOAL ID : 69b57badefdb26a65bafeaca7b2a4537
[INFO] [1695295356.552313938] [sleep_client]: RESULT_GOAL ID : 69b57badefdb26a65bafeaca7b2a4537
[INFO] [1695295356.552409254] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted
PrintValue: start
[INFO] [1695295358.553869406] [sleep_client]: RESULT_GOAL ID : eee66aede6adfc71a2326b49d98fd677
[INFO] [1695295358.553942439] [sleep_client]: sleepA: onResultReceived. Done = true
PrintValue: sleep completed
[INFO] [1695295360.058143973] [sleep_client]: CANCEL_GOAL ID : 6cafc4d991f0ff796b338252e123618
[INFO] [1695295360.155102960] [sleep_client]: RESULT_GOAL ID : 6cafc4d991f0ff796b338252e123618
[INFO] [1695295360.155213032] [sleep_client]: sleepB: onHalt
PrintValue: sleep aborted

Shortly, Without waiting result, it cancels goal with new id, but runs result_callback with previous id.

In addition, i have several questions for you:

• Why do you use emitWakeUpSignal in result_callback and feedback? I think you use for preventing race condition etc. But i would love to hear from you as well.
• Do you think it is necessary to remove controlling if goal_handle_.goal_id == result.goal_id after this fix. I haven't been sure. Could you inform me about it? Because it looks like navigation2 stack is little bit sufferer by this issue.

If all of it is problem or bug, i will pull request to ros-planning/navigation2 stack too.

Thank you in advance.

[facontidavide]

Why do you use emitWakeUpSignal in result_callback and feedback? I think you use for preventing race condition etc. But i would love to hear from you as well.

No, it is used to wake up a sleeping executor.

Thanks for the PR!

[CihatAltiparmak]

Hello @facontidavide again, It seems like more correctly that add timeout while asynchronously getting result. I have pr for it. #38