Problem not to run halt correctly in bt_action_node #3848
Description
Bug report
Required Info:
- Operating System: Ubuntu 22.04.3 LTS (Jammy Jellyfish)
- ROS2 Version: Rolling
- Version or commit hash: 42670c0
- Package: nav2_behavior_tree
Description of the debug
When bt_action_node is halted before goal is completed, it is wait that the goal cancels but not wait that corresponding result_callback finish its job. This brings about not to run return_callback on time.
Expected behavior
When bt_action_node is halted, if corresponding goal is not completed, it should be cancelled goal and triggered on_cancelled callback as soon as result_callback of corresponding goal.
Example:
tested on fixed version with new test case
[==========] Running 3 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 3 tests from BTActionNodeTestFixture
[ RUN ] BTActionNodeTestFixture.test_server_timeout_success
[INFO] [1696115562.369772159] [fibonacci_node]: Goal is received..
[INFO] [1696115562.372381439] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.372449402] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.372459457] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.372467514] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.399797082] [bt_action_node_test_fixture]: Tree is halting.
[INFO] [1696115562.400117689] [fibonacci_node]: Goal is received..
[WARN] [1696115562.420314587] [bt_action_node_test_fixture]: Timed out while waiting for action server to acknowledge goal request for fibonacci
[INFO] [1696115562.500597589] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.500720054] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.500750949] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.500777890] [fibonacci_node]: Goal is feedbacking.
[ OK ] BTActionNodeTestFixture.test_server_timeout_success (146 ms)
[ RUN ] BTActionNodeTestFixture.test_server_timeout_failure
[INFO] [1696115562.517242055] [fibonacci_node]: Goal is received..
[WARN] [1696115562.607679797] [bt_action_node_test_fixture]: Timed out while waiting for action server to acknowledge goal request for fibonacci
[INFO] [1696115562.607779583] [bt_action_node_test_fixture]: Tree is halting.
[INFO] [1696115562.617928910] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.618053432] [fibonacci_node]: Goal is received..
[INFO] [1696115562.643561865] [fibonacci_node]: Goal is feedbacking.
[ OK ] BTActionNodeTestFixture.test_server_timeout_failure (177 ms)
[ RUN ] BTActionNodeTestFixture.test_server_cancel
[INFO] [1696115562.691858205] [fibonacci_node]: Goal is received..
[INFO] [1696115562.694168168] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.744286127] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.794286136] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.844289791] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.894289973] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.944271683] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115562.994283654] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.044274036] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.094300868] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.144290212] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.191882925] [bt_action_node_test_fixture]: Tree is halting.
[INFO] [1696115563.194281769] [fibonacci_node]: Goal is canceling.
[INFO] [1696115563.194488821] [fibonacci_node]: Goal is received..
[INFO] [1696115563.196825651] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.246898272] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.296907588] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.346878787] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.396942015] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.446884970] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.496937918] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.546887427] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.596942564] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.646888989] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.696866105] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.746948518] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.796937509] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.846880042] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696115563.891885037] [bt_action_node_test_fixture]: Tree is halting.
[INFO] [1696115563.896869056] [fibonacci_node]: Goal is canceling.
[ OK ] BTActionNodeTestFixture.test_server_cancel (1223 ms)
[----------] 3 tests from BTActionNodeTestFixture (1547 ms total)
[----------] Global test environment tear-down
[==========] 3 tests from 1 test suite ran. (1565 ms total)
[ PASSED ] 3 tests.
Actual behavior
When bt_action_node is halted, if corresponding goal is not completed, it's cancelled goal but not triggered on_cancelled callback as soon as result_callback of corresponding goal.
Example:
tested on current version with new test case
[==========] Running 3 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 3 tests from BTActionNodeTestFixture
[ RUN ] BTActionNodeTestFixture.test_server_timeout_success
[INFO] [1696108379.002220192] [fibonacci_node]: Goal is received..
[INFO] [1696108379.004713719] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.004780406] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.004795524] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.004809114] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.032193949] [bt_action_node_test_fixture]: Tree is halting.
[INFO] [1696108379.032453403] [fibonacci_node]: Goal is received..
[WARN] [1696108379.052975003] [bt_action_node_test_fixture]: Timed out while waiting for action server to acknowledge goal request for fibonacci
[INFO] [1696108379.133070636] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.133182788] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.133211336] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.133233461] [fibonacci_node]: Goal is feedbacking.
[ OK ] BTActionNodeTestFixture.test_server_timeout_success (152 ms)
[ RUN ] BTActionNodeTestFixture.test_server_timeout_failure
[INFO] [1696108379.151498461] [fibonacci_node]: Goal is received..
[WARN] [1696108379.241635426] [bt_action_node_test_fixture]: Timed out while waiting for action server to acknowledge goal request for fibonacci
[INFO] [1696108379.241739630] [bt_action_node_test_fixture]: Tree is halting.
[INFO] [1696108379.252277279] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.252380287] [fibonacci_node]: Goal is received..
[INFO] [1696108379.277881534] [fibonacci_node]: Goal is feedbacking.
[ OK ] BTActionNodeTestFixture.test_server_timeout_failure (177 ms)
[ RUN ] BTActionNodeTestFixture.test_server_cancel
[INFO] [1696108379.328595353] [fibonacci_node]: Goal is received..
[INFO] [1696108379.330908688] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.380994297] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.431020035] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.481026478] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.530985800] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.581019693] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.631024159] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.681022296] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.731017380] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.781026289] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.828634063] [bt_action_node_test_fixture]: Tree is halting.
/home/nav_ws/src/navigation2/nav2_behavior_tree/test/plugins/action/test_bt_action_node.cpp:443: Failure
Expected equality of these values:
on_cancelled_triggered
Which is: false
true
[INFO] [1696108379.829193971] [fibonacci_node]: Goal is received..
[INFO] [1696108379.830984797] [fibonacci_node]: Goal is canceling.
[INFO] [1696108379.831522230] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.881610684] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.931639105] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108379.981594191] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.031633841] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.081623700] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.131602613] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.181603073] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.231639431] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.281636402] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.331600897] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.381621817] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.431643660] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.481588516] [fibonacci_node]: Goal is feedbacking.
[INFO] [1696108380.528579163] [bt_action_node_test_fixture]: Tree is halting.
/home/nav_ws/src/navigation2/nav2_behavior_tree/test/plugins/action/test_bt_action_node.cpp:475: Failure
Expected equality of these values:
on_cancelled_triggered
Which is: false
true
[INFO] [1696108380.531588490] [fibonacci_node]: Goal is canceling.
[ FAILED ] BTActionNodeTestFixture.test_server_cancel (1215 ms)
[----------] 3 tests from BTActionNodeTestFixture (1545 ms total)
[----------] Global test environment tear-down
[==========] 3 tests from 1 test suite ran. (1561 ms total)
[ PASSED ] 2 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] BTActionNodeTestFixture.test_server_cancel
1 FAILED TEST
Additional information
For more information about this bug, please look at this discussion
I think it should be added new test case for the scenairo to halt bt_action_node before goal execution is completed.
I tested on ros::rolling docker image.
My question on this bug
Is this part still necessary after this bug is solved? I think about it but i haven't found it.