Logs from child loggers are not sent to /rosout

[rasmusan]

Bug report

Required Info:

• Operating System:
  • Ubuntu 20.04
• Installation type:
  • Binary
• Version or commit hash:
  • galactic
• DDS implementation:
  • Cyclone DDS
• Client library (if applicable):
  • rclcpp

Steps to reproduce issue

Run this code:

#include "rclcpp/rclcpp.hpp"
#include "rcutils/logging_macros.h"

class MyNode : public rclcpp::Node
{
public:
  explicit MyNode(const std::string & node_name) : rclcpp::Node(node_name)
  {
    RCLCPP_INFO(get_logger(), "Node logger");
    RCLCPP_INFO(get_logger().get_child("child"), "Child logger");
  }
};

int main(int argc, char * argv[])
{
  rclcpp::init(argc, argv);
  rclcpp::executors::SingleThreadedExecutor exe;
  std::shared_ptr<MyNode> lc_node = std::make_shared<MyNode>("my_node");
  exe.add_node(lc_node->get_node_base_interface());
  exe.spin();

  rclcpp::shutdown();
  return 0;
}

Expected behavior

Terminal output:

1623765894.901377435 [INFO] [my_node::MyNode]: Node logger
1623765894.901569946 [INFO] [my_node.child::MyNode]: Child logger

File output to /home/user/.ros/log/logging_tester_81312_1623765894893:

1623765894.901377435 [INFO] [my_node::MyNode]: Node logger
1623765894.901569946 [INFO] [my_node.child::MyNode]: Child logger

Output on /rosout:

$ ros2 topic echo /rosout
stamp:
  sec: 1623765894
  nanosec: 901377435
level: 20
name: my_node
msg: Node logger
file: /home/user/ws/src/logging_tester/src/my_node.cpp
function: MyNode
line: 9
---
stamp:
  sec: 1623765894
  nanosec: 901377435
level: 20
name: my_node.child
msg: Child logger
file: /home/user/ws/src/logging_tester/src/my_node.cpp
function: MyNode
line: 10
---

---

Actual behavior

Output to terminal and to file is as expected. Output to /rosout only contains the top-level log, and not the child log:

$ ros2 topic echo /rosout
stamp:
  sec: 1623765894
  nanosec: 901377435
level: 20
name: my_node
msg: Node logger
file: /home/user/ws/src/logging_tester/src/my_node.cpp
function: MyNode
line: 9
---

Additional information

The child logs are omitted no matter if the child logger is stored as a member.

[iuhilnehc-ynos]

@rasmusan

Thank you for reporting this issue, but I am afraid it is not a bug.

If you expect RCLCPP_INFO(get_logger().get_child("child"), "Child logger"); to publish message on topic /rosout, I think you need to create a node named /my_node/child before calling it.

e.g.

MyNode constructor {
	child_ = rclcpp::Node::make_shared("child", "/my_node");
}

private:
	rclcpp::Node::SharedPtr child_;

FYI. If you are interested in how rosout publisher worked, please refer to
1. init each node to create a rosout publisher
2. create a rosout publisher and then put the item into a map
3. rcutils_log to call rcl_logging_rosout_output_handler, it will check the logger name has an entry(mainly for the rosout publisher)
rcl_logging_rosout_output_handler document

I would like to hear others' opinions.

[rasmusan]

@iuhilnehc-ynos, ok, I see. It is not completely logical to me that logging to /rosout should behave differently than logging to terminal and file (when enabled). If others agree, then this could maybe become a feature request instead?

In any case, I appreciate the feedback and explanation!

[wjwwood]

Actually, I'm surprised by this behavior. I would have expected that what @rasmusan described should work. For example, there are places where we use get_child() internally in rclcpp with the expectation (in my opinion) that those messages should be logged as a "sublogger" of the node, e.g.:

• rclcpp/rclcpp/src/rclcpp/client.cpp

  Line 53 in 1037822

  rclcpp::get_node_logger(handle.get()).get_child("rclcpp"),

• rclcpp/rclcpp_action/src/client.cpp

  Line 46 in 1037822

  logger(node_logging->get_logger().get_child("rclcpp_action")),

So it's something maybe we should look into.

[wjwwood]

There was a bit of an issue with node name uniqueness when the rosout feature was originally developed, but I didn't see anything discussing sub loggers. It was likely not considered properly or child loggers came afterward:

ros2/rcl#350

Anyway, I would expect that child loggers that share a root name with a node should be published.

Further more, I expect that all log messages should be logged to rosout by someone. Like I said, I wasn't involved with the implementation or review (for the most part) of the rosout feature pull request, but I am surprised to find that only a select few things make it to rosout, but there might have been good reasons for that.

I can imagine also that we may have desired to publish more log messages, but went for the incremental improvement of publishing some of them until we had time to solve issues related to publishing them all.

@hidmic @jacobperron I think you guys helped review the original rosout pull request, do you remember these decisions being made/discussed?

[fujitatomoya]

Anyway, I would expect that child loggers that share a root name with a node should be published.

+1 on this. i see that currently this cannot be done but it would be nice to have this.

[hidmic]

I think you guys helped review the original rosout pull request, do you remember these decisions being made/discussed?

Memories from 2019? That's in cold storage already :)

So, quick inspection suggests the problem is that there's no concept of a child logger outside rclcpp. That's not a problem for console and file logging, but it is for /rosout logging when it attempts to use the logger name to fetch the publisher. Simplest solution I can think of is to introduce the concept of child loggers in rcl and use the root logger to fetch the publisher.

I wonder if and how this is working in rclpy 🤔

[jacobperron]

Yeah, any discussions are ancient history to me, but I'm pretty sure the subject of sub-loggers never came up when implementing rosout.

[tonynajjar]

I wonder if and how this is working in rclpy thinking

Unfortunately It doesn't as well. I realized it after this PR. Any short term plans for this? I think this is extremely important for people using logging tools that rely on /rosout (e.g foxglove); currently we are missing a considerable amount of information in our "rosout" logs

[fujitatomoya]

There have been open PRs to address this issue in rclcpp.

• use parent logger rcl#921
• to create a sublogger while getting child of Logger #1717

[tonynajjar]

Thank you @fujitatomoya for pushing this effort forward!

[fujitatomoya]

Just FYI, rcply fix is ros2/rclpy#1084

[iuhilnehc-ynos]

As this issue was reported for rclcpp, I think it should be closed after #1717 is merged.

[jrutgeer]

@fujitatomoya @iuhilnehc-ynos
If I correctly understand the code:

• A rosout publisher is only created when instantiating a node
  • This implies that non-node logs (e.g. RCLCPP_INFO(rclcpp::get_logger("some_name"), "Log message")) are not sent to /rosout, and that get_child on a non-node logger will output an error.
  • Is this intentional? I did not find any specifications wrt. /rosout other than above mentioned PR #350 and this discourse thread. In any case it is an inconsistency between node and non-node loggers.
• Since this merge, a sublogger publisher is added upon call of Logger:get_child(child_name), but not on get_logger("parent_name.child_name"). So the latter will only work if the corresponding get_child() was called beforehand. This seems inconsistent with this remark of @clalancette

I don´t have a strong opionion about this (after all, nobody seems to be missing those non-node logs on /rosout), but I think it should be formally decided to leave it as it is, or to reopen this issue (or a new one).

[jrutgeer]

Actually, it's tricky:
Below code will not output "Log 3" to /rosout, as the child logger is deleted when leaving the scope of the 2nd log call.

int main(int argc, char * argv[])
{
  rclcpp::init(argc, argv);
  auto node = std::make_shared<rclcpp::Node>("LoggerNode");
  RCLCPP_INFO(node->get_logger(), "Log 1");
  RCLCPP_INFO(node->get_logger().get_child("child"), "Log 2");
  RCLCPP_INFO(rclcpp::get_logger("LoggerNode.child"), "Log 3");
  rclcpp::shutdown();
  return 0;
}

This works as expected:

int main(int argc, char * argv[])
{
  rclcpp::init(argc, argv);
  auto node = std::make_shared<rclcpp::Node>("LoggerNode");
  auto childnode = node->get_logger().get_child("child");
  RCLCPP_INFO(node->get_logger(), "Log 1");
  RCLCPP_INFO(node->get_logger().get_child("child"), "Log 2");
  RCLCPP_INFO(rclcpp::get_logger("LoggerNode.child"), "Log 3");
  rclcpp::shutdown();
  return 0;
}

[fujitatomoya]

A rosout publisher is only created when instantiating a node

sorry for answering question with question. but how can we publish the log w/o having corresponding node?

[jrutgeer]

how can we publish the log w/o having corresponding node?

This does not seem a blocking issue? E.g. by creating a node on initialization (e.g. in rcl_logging_rosout_init()), which provides the publisher for all non-node loggers?

[fujitatomoya]

@jrutgeer let me clarify this, you are suggesting that logger should be working to send data to rosout w/o node creating, right?

btw, probably we can open another issue for further discussion.