Promise already satisfied

[hsd-dev]

Bug report

Required Info:

• Operating System:
  • Ubuntu 18.04.2 LTS
• Installation type:
  • binaries
• Version or commit hash:
  • 0.7.6
• DDS implementation:
  • Fast-RTPS
• Client library (if applicable):
  • rclcpp

Steps to reproduce issue

      auto send_goal_ops = typename rclcpp_action::Client<ROS2_T>::SendGoalOptions;
      send_goal_ops.result_callback =
        [this](auto res2) mutable
      {

      };
      .
      .
      .
      // send goal and wait for result
      auto gh2_future = client_->async_send_goal(goal2, send_goal_ops);
      auto result = client_->async_get_result(gh2_future.get()).get();

This seems to be similar to the test case

rclcpp/rclcpp_action/test/test_client.cpp

Lines 395 to 413 in bfee90a

	send_goal_ops.result_callback =
	[&result_callback_received](
	const typename ActionGoalHandle::WrappedResult & result) mutable
	{
	if (rclcpp_action::ResultCode::SUCCEEDED == result.code &&
	result.result->sequence.size() == 5u)
	{
	result_callback_received = true;
	}
	};
	auto future_goal_handle = action_client->async_send_goal(goal, send_goal_ops);
	dual_spin_until_future_complete(future_goal_handle);
	auto goal_handle = future_goal_handle.get();
	EXPECT_EQ(rclcpp_action::GoalStatus::STATUS_ACCEPTED, goal_handle->get_status());
	EXPECT_FALSE(goal_handle->is_feedback_aware());
	EXPECT_TRUE(goal_handle->is_result_aware());
	auto future_result = action_client->async_get_result(goal_handle);
	dual_spin_until_future_complete(future_result);
	auto wrapped_result = future_result.get();

Expected behavior

I get the result without any errors

Actual behavior

terminate called after throwing an instance of 'std::future_error'
  what():  std::future_error: Promise already satisfied

Additional information

__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff5698801 in __GI_abort () at abort.c:79
#2  0x00007ffff5ced957 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x00007ffff5cf3ab6 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00007ffff5cf3af1 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#5  0x00007ffff5cf3d24 in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#6  0x00007ffff5cef929 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x0000555555570ef6 in std::__future_base::_State_baseV2::_M_set_result(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>, bool) (
    this=0x7fffcc001090, __res=..., __ignore_failure=false) at /usr/include/c++/7/future:408
#8  0x0000555555597dc7 in std::promise<rclcpp_action::ClientGoalHandle<example_interfaces::action::Fibonacci>::WrappedResult>::set_value (this=0x555556217fe8, __r=...) at /usr/include/c++/7/future:1110
#9  0x000055555559348f in rclcpp_action::ClientGoalHandle<example_interfaces::action::Fibonacci>::set_result (this=0x555556217fc0, wrapped_result=...)
    at /opt/ros/dashing/include/rclcpp_action/client_goal_handle_impl.hpp:75
#10 0x000055555558d41c in rclcpp_action::Client<example_interfaces::action::Fibonacci>::make_result_aware(std::shared_ptr<rclcpp_action::ClientGoalHandle<example_interfaces::action::Fibonacci> >)::{lambda(std::shared_ptr<void>)#1}::operator()(std::shared_ptr<void>) (__closure=0x555556218210, 
    response=std::shared_ptr<void> (use count 4, weak count 0) = {...})
    at /opt/ros/dashing/include/rclcpp_action/client.hpp:613
#11 0x000055555559803c in std::_Function_handler<void (std::shared_ptr<void>), rclcpp_action::Client<example_interfaces::action::Fibonacci>::make_result_aware(std::shared_ptr<rclcpp_action::ClientGoalHandle<example_interfaces::action::Fibonacci> >)::{lambda(std::shared_ptr<void>)#1}>::_M_invoke(std::_Any_data const&, std::shared_ptr<void>&&) (__functor=..., __args#0=...)
    at /usr/include/c++/7/bits/std_function.h:316
#12 0x00007ffff69659ee in rclcpp_action::ClientBase::handle_result_response(rmw_request_id_t const&, std::shared_ptr<void>) () from /opt/ros/dashing/lib/librclcpp_action.so
#13 0x00007ffff69640c5 in rclcpp_action::ClientBase::execute() ()
   from /opt/ros/dashing/lib/librclcpp_action.so
---Type <return> to continue, or q <return> to quit---
#14 0x00007ffff669cc7f in rclcpp::executor::Executor::execute_any_executable(rclcpp::executor::AnyExecutable&) () from /opt/ros/dashing/lib/librclcpp.so
#15 0x00007ffff66a2f2f in rclcpp::executors::SingleThreadedExecutor::spin() () from /opt/ros/dashing/lib/librclcpp.so
#16 0x00007ffff669fc32 in rclcpp::spin(std::shared_ptr<rclcpp::node_interfaces::NodeBaseInterface>) () from /opt/ros/dashing/lib/librclcpp.so
#17 0x00007ffff669feeb in rclcpp::spin(std::shared_ptr<rclcpp::Node>) () from /opt/ros/dashing/lib/librclcpp.so
#18 0x00005555555747ce in ActionBridge<actionlib_tutorials::FibonacciAction_<std::allocator<void> >, example_interfaces::action::Fibonacci>::main (action_name="fibonacci", argc=1, argv=0x7fffffffd9d8)
    at /home/hsd/dev/bridge_ws/src/action_bridge/include/action_bridge/action_bridge.hpp:108
#19 0x000055555556d093 in main (argc=1, argv=0x7fffffffd9d8) at /home/hsd/dev/bridge_ws/src/action_bridge/src/action_bridge_fibonacci.cpp:56

[mathias-luedtke]

My analysis so far:

If async_send_goal is called with result_callback and async_get_result gets called immediately afterwards, make_result_aware might get called twice.

The problem occurs in case of this excution order:

1. rclcpp/rclcpp_action/include/rclcpp_action/client.hpp

   Line 415 in 131a11b

   this->make_result_aware(goal_handle);

2. rclcpp/rclcpp_action/include/rclcpp_action/client.hpp

   Line 382 in 131a11b

   this->make_result_aware(goal_handle);

Which results in calling send_result_request, goal_handle->set_result(wrapped_result) and result_promise_.set_value(wrapped_result) twice.

The implemented "result awareness" mechanism seems to be very fragile and error-prone.

[jacobperron]

@ipa-hsd @ipa-mdl Thanks for the report and investigation!

Looks like a race condition. I can reproduce the issue if I spin in a separate thread. Here is my code:

#include <thread>

#include "example_interfaces/action/fibonacci.hpp"
#include "rclcpp/rclcpp.hpp"
#include "rclcpp_action/rclcpp_action.hpp"

using ActionType = example_interfaces::action::Fibonacci;

void spin(rclcpp::Node::SharedPtr node_ptr)
{
  rclcpp::spin(node_ptr);
}

int main(void)
{
  rclcpp::init(0, nullptr);
  auto node = rclcpp::Node::make_shared("my_action_client");

  std::thread{std::bind(spin, node)}.detach();

  auto client = rclcpp_action::create_client<ActionType>(node, "fibonacci");
  if (!client->wait_for_action_server(std::chrono::seconds(10))) {
    return 1;
  }

  auto send_goal_ops = typename rclcpp_action::Client<ActionType>::SendGoalOptions();
  send_goal_ops.result_callback =
    [](auto res2) mutable
    {
      (void)res2;
    };

  auto goal = ActionType::Goal();
  auto gh_future = client->async_send_goal(goal, send_goal_ops);
  auto result_future = client->async_get_result(gh_future.get());
  auto result = result_future.get();

  rclcpp::shutdown();
  return 0;
}

If I don't spin in a separate thread and use "spin_until_future_complete" after async_get_send_goal and async_get_result, then I am unable to reproduce the issue. I believe this is why the tests do not catch this bug.

With #806, I am unable to reproduce the issue.