test_publisher/run_event_handlers is broken

[eboasson]

Bug report

Required Info:

• Operating System:
  • macOS Big Sur, Linux
• Installation type:
  • from source
• Version or commit hash:
  • 504b082
• DDS implementation:
  • Cyclone DDS
• Client library (if applicable):
  • rclcpp

Steps to reproduce issue

Run the test ...

e.g. cd build/rclcpp/test && RMW_IMPLEMENTATION=rmw_cyclonedds_cpp ./test_publisher

Expected behavior

Test passes

Actual behavior

Test outputs:

[ RUN      ] TestPublisher.run_event_handlers
[WARN] [1607608600.996356466] [ns.my_node]: New subscription discovered on topic '/ns/topic', requesting incompatible QoS. No messages will be sent to it. Last incompatible policy: INVALID_QOS_POLICY
/tmp/ws/src/ros2/rclcpp/rclcpp/test/rclcpp/test_publisher.cpp:509: Failure
Expected: handler->execute(data) throws an exception of type std::runtime_error.
  Actual: it throws nothing.
[  FAILED  ] TestPublisher.run_event_handlers (8 ms)

(this one is from https://build.ros2.org/view/Rci/job/Rci__nightly-cyclonedds_ubuntu_focal_amd64/168/testReport/junit/projectroot.test/rclcpp/test_publisher/)

Additional information

The failing test is the following:

TEST_F(TestPublisher, run_event_handlers) {
  initialize();
  auto publisher = node->create_publisher<test_msgs::msg::Empty>("topic", 10);

  for (const auto & handler : publisher->get_event_handlers()) {
    std::shared_ptr<void> data = handler->take_data();
    EXPECT_THROW(handler->execute(data), std::runtime_error);
  }
}

For RMW implementations that do not support incompatible QoS notifications (e.g., FastRTPS) there will be no event handlers and the loop is a no-op. For ones that do support them (like Cyclone DDS), there will be an event handler installed by default (in the Publisher constructor in rclcpp/include/rclcpp/publisher.hpp):

    if (options_.event_callbacks.incompatible_qos_callback) {
      this->add_event_handler(
        options_.event_callbacks.incompatible_qos_callback,
        RCL_PUBLISHER_OFFERED_INCOMPATIBLE_QOS);
    } else if (options_.use_default_callbacks) {
      // Register default callback when not specified
      try {
        this->add_event_handler(
          [this](QOSOfferedIncompatibleQoSInfo & info) {
            this->default_incompatible_qos_callback(info);
          },
          RCL_PUBLISHER_OFFERED_INCOMPATIBLE_QOS);
      } catch (UnsupportedEventTypeException & /*exc*/) {
        // pass
      }
    }

Taking an event is an operation that the RMW layer defines as setting a taken flag (like the regular take), but rcl converts a successful call to rmw_take_event that returns with taken = false into an error:

  rmw_ret_t ret = rmw_take_event(&event->impl->rmw_handle, event_info, &taken);
  if (RMW_RET_OK != ret) {
    RCL_SET_ERROR_MSG(rmw_get_error_string().str);
    return rcl_convert_rmw_ret_to_rcl_ret(ret);
  }
  if (!taken) {
    RCUTILS_LOG_DEBUG_NAMED(
      ROS_PACKAGE_NAME, "take_event request complete, unable to take event");
    return RCL_RET_EVENT_TAKE_FAILED;
  }

Therefore, the RMW implementations return ok/taken, regardless of whether an event occurred since the last reset.

This means one necessarily ends up in the default handler defined in publisher_base.cpp:

void
PublisherBase::default_incompatible_qos_callback(
  rclcpp::QOSOfferedIncompatibleQoSInfo & event) const
{
  std::string policy_name = qos_policy_name_from_kind(event.last_policy_kind);
  RCLCPP_WARN(
    rclcpp::get_logger(rcl_node_get_logger_name(rcl_node_handle_.get())),
    "New subscription discovered on topic '%s', requesting incompatible QoS. "
    "No messages will be sent to it. "
    "Last incompatible policy: %s",
    get_topic_name(),
    policy_name.c_str());
}

which prints the surprising message while not throwing any exception.

I'd say the libraries are correct, the test code is broken.

[clalancette]

@eboasson Do you think #1497 fixes this?

[eboasson]

@clalancette It definitely should, the surprising message will still be there, but otherwise it should be fine.

[clalancette]

All right, I'm going to go ahead and close this with #1497 fixing it. If you think we need to change anything else, feel free to reopen.