0
$\begingroup$

I believe this is likely a bug. Here is a minimal example and the output with a stack trace (made with backwardcpp):

#include <rclcpp/rclcpp.hpp>

rclcpp::Logger& getLogger() {
  static auto logger = rclcpp::get_logger("moveit");
  return logger;
}

// make the child logger the first time we use it
rclcpp::Logger getStaticChildLogger()
{
  static auto logger = [] {
    auto logger = getLogger().get_child("child");
    RCLCPP_INFO(logger, "making the child logger");
    return logger;
  }();
  return logger;
}

int main(int argc, char** argv)
{
  rclcpp::init(argc, argv);
  rclcpp::Node::SharedPtr node = rclcpp::Node::make_shared("dut_node");

  getLogger() = node->get_logger();
  RCLCPP_INFO(getLogger(), "node logger");

  RCLCPP_INFO(getStaticChildLogger(), "child node logger");
}
[INFO] [1698780244.672370104] [dut_node]: node logger
[INFO] [1698780244.672399117] [dut_node.child]: making the child logger
[INFO] [1698780244.672402452] [dut_node.child]: child node logger
terminate called after throwing an instance of 'rclcpp::exceptions::RCLError'
  what():  failed to call rcl_logging_rosout_remove_sublogger: Sub-logger 'dut_node.child' not exist., at ./src/rcl/logging_rosout.c:530
Stack trace (most recent call last):
#19   Object "", at 0xffffffffffffffff, in 
#18   Object "/home/tyler/code/ws_moveit/install/moveit_core/lib/moveit_core/logger_from_child_dut", at 0x55756bef8624, in _start
#17   Source "../csu/libc-start.c", line 392, in __libc_start_main_impl [0x7fad3c229e3f]
#16   Source "../sysdeps/nptl/libc_start_call_main.h", line 74, in __libc_start_call_main [0x7fad3c229d96]
#15   Source "./stdlib/exit.c", line 143, in exit [0x7fad3c24560f]
#14   Source "./stdlib/exit.c", line 113, in __run_exit_handlers [0x7fad3c245494]
#13   Source "/opt/ros/rolling/include/rclcpp/rclcpp/logger.hpp", line 92, in ~Logger [0x55756bef9467]
         89: rcpputils::fs::path
         90: get_logging_directory();
         91: 
      >  92: class Logger
         93: {
         94: public:
         95:   /// An enum for the type of logger level.
#12   Source "/usr/include/c++/11/bits/shared_ptr.h", line 122, in ~shared_ptr [0x55756bef93bd]
        119:    * pointer see `std::shared_ptr::owner_before` and `std::owner_less`.
        120:   */
        121:   template<typename _Tp>
      > 122:     class shared_ptr : public __shared_ptr<_Tp>
        123:     {
        124:       template<typename... _Args>
        125:    using _Constructible = typename enable_if<
#11   Source "/usr/include/c++/11/bits/shared_ptr_base.h", line 1154, in ~__shared_ptr [0x55756bef939d]
       1152:       __shared_ptr(const __shared_ptr&) noexcept = default;
       1153:       __shared_ptr& operator=(const __shared_ptr&) noexcept = default;
      >1154:       ~__shared_ptr() = default;
       1155: 
       1156:       template<typename _Yp, typename = _Compatible<_Yp>>
       1157:    __shared_ptr(const __shared_ptr<_Yp, _Lp>& __r) noexcept
#10   Source "/usr/include/c++/11/bits/shared_ptr_base.h", line 705, in ~__shared_count [0x55756bef9ee6]
        702:       ~__shared_count() noexcept
        703:       {
        704:    if (_M_pi != nullptr)
      > 705:      _M_pi->_M_release();
        706:       }
        707: 
        708:       __shared_count(const __shared_count& __r) noexcept
#9    Source "/usr/include/c++/11/bits/shared_ptr_base.h", line 168, in _M_release [0x55756befa64c]
        165:    if (__gnu_cxx::__exchange_and_add_dispatch(&_M_use_count, -1) == 1)
        166:      {
        167:             _GLIBCXX_SYNCHRONIZATION_HAPPENS_AFTER(&_M_use_count);
      > 168:        _M_dispose();
        169:        // There must be a memory barrier between dispose() and destroy()
        170:        // to ensure that the effects of dispose() are observed in the
        171:        // thread that runs destroy().
#8    Object "/opt/ros/rolling/lib/librclcpp.so", at 0x7fad3cb27e06, in 
#7    Object "/opt/ros/rolling/lib/librclcpp.so", at 0x7fad3cafe6d8, in rclcpp::exceptions::throw_from_rcl_error(int, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, rcutils_error_state_s const*, void (*)())
#6    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.30", at 0x7fad3c6ae1fd, in std::rethrow_exception(std::__exception_ptr::exception_ptr)
#5    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.30", at 0x7fad3c6ae276, in std::terminate()
#4    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.30", at 0x7fad3c6ae20b, in 
#3    Object "/usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.30", at 0x7fad3c6a2b9d, in 
#2    Source "./stdlib/abort.c", line 79, in abort [0x7fad3c2287f2]
#1    Source "../sysdeps/posix/raise.c", line 26, in raise [0x7fad3c242475]
#0  | Source "./nptl/pthread_kill.c", line 89, in __pthread_kill_internal
    | Source "./nptl/pthread_kill.c", line 78, in __pthread_kill_implementation
      Source "./nptl/pthread_kill.c", line 44, in __pthread_kill [0x7fad3c2969fc]
Aborted (Signal sent by tkill() 1572362 1000)
Aborted (core dumped)
$\endgroup$

1 Answer 1

1
$\begingroup$

I wrote some documentation here: there is a hash table (__logger_map) that links logger and child logger names to the respective publisher.

I think this is the reason:

  • The node goes out of scope,
  • This calls rcl_logging_rosout_fini_publisher_for_node,
  • which calls _rcl_logging_rosout_remove_logger_map,
  • This iterates through __logger_map and 'unsets' all entries associates with that node,
  • Then the child logger destructs and it fails to find its entry in the __logger_map here.

Quick fix that confirms above:

Change

rclcpp::Node::SharedPtr node = rclcpp::Node::make_shared("dut_node");`

into

static rclcpp::Node::SharedPtr node = rclcpp::Node::make_shared("dut_node");`

And there no longer is an exception, since the node outlives the loggers.

An unrelated remark:

Note that calling get_child on a named logger (i.e. a non-node logger such as rclcpp::get_logger("moveit")) throws an exception (as a named logger does not have a publisher).

So in your example code it is mandatory to issue getLogger() = node->get_logger();, before calling getStaticChildLogger().

$\endgroup$
7
  • $\begingroup$ wow, thank you for figuring this out. is this what everyone who wants to use child loggers is doing? $\endgroup$ Commented Nov 1, 2023 at 18:34
  • $\begingroup$ side note, i discovered what you wrote about the exception and was trying to work around that here: github.com/ros-planning/moveit2/blob/… $\endgroup$ Commented Nov 1, 2023 at 18:39
  • $\begingroup$ thank you for your documentation, that was excellent, saved me from trying to go read all that rcl code to answer this question. $\endgroup$ Commented Nov 1, 2023 at 18:49
  • $\begingroup$ I think most people use node loggers and child loggers within a node, so it's impossible that the logger outlives the node. $\endgroup$
    – JRTG
    Commented Nov 1, 2023 at 18:56
  • 1
    $\begingroup$ Glad at least someone read that documentation! ;-) The code is ultimately undocumented unfortunately. $\endgroup$
    – JRTG
    Commented Nov 1, 2023 at 18:57

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.