Skip to content

Prototype for using logging macros#184

Closed
dhood wants to merge 1 commit intomasterfrom
use_logging_prototype
Closed

Prototype for using logging macros#184
dhood wants to merge 1 commit intomasterfrom
use_logging_prototype

Conversation

@dhood
Copy link
Copy Markdown
Member

@dhood dhood commented Oct 21, 2017

Proposed usage for logging macro wrappers provided by rclcpp (not considering logger objects at the moment)

The purpose for wrapping the rcutils macros in the first place is to inject default names and/or name suffixes to log calls.

For comparison, ROS 1's rosconsole does the following:

  1. uses "ros.<package_name>" as the name for unnamed log calls (a default name of sorts, to allow for some automatic grouping of logging messages even if users just call ROS_INFO)
  2. prepends "ros.<package_name>" to all named log calls e.g. ROS_INFO_NAMED, presumably to distinguish them from other non-ros loggers, e.g. rqt_gui_py_node exposes loggers like PyQt5.uic.properties
  3. doesn't provide a way to avoid the suffix when using the macros from what I can tell (you don't have to use the macros though)

The proposal for ROS 2 is to do something similar by setting a default name/prefix, but also provide ROS_INFO_FULLNAMED that allows users to provide the full logger name if they want to.

Concrete proposals:

  1. Default name of just "<package_name>" for nameless log calls (when using ROS_INFO)
  2. Default name is prepended as a prefix for named calls (when using ROS_INFO_NAMED)
  3. No prefix added for fully-named calls (when using ROS_INFO_FULLNAMED)

Reasoning:
Speaking with a couple of people it seems that we don't feel that having the "ros" prefix for the default name/prefix is that necessary, but that a default of some sort is still needed, so we can just go with "<package_name>". IMO if a user calls ROS_INFO_NAMED in the same file as ROS_INFO they should go to the same parent logger (different child for the named one), suggesting that whatever the default name is it should continue to be prepended even in the case of ROS_INFO_NAMED.

However, most people I spoke to were surprised that the package name was always being prepended without a way to override it, so we can also add ROS_INFO_FULLNAMED, which doesn't do any name modification, it just passes it through to rcutils.
Examples when you might want to use ROS_INFO_FULLNAMED:

  1. someone wants to group all of their packages relating to robotX under a common root logger
  2. someone has 2 instances of robotX and wants them to publish under separate root loggers based on their robot name.

This PR has some usage examples.

@dhood dhood self-assigned this Oct 21, 2017
@dhood dhood added the in progress Actively being worked on (Kanban column) label Oct 21, 2017
Copy link
Copy Markdown
Member

@dirk-thomas dirk-thomas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good to me.

printf("add_two_ints_client was interrupted while waiting for the service. Exiting.\n");
// This will have <package_name>.<node_name> as the logger name.
ROS_INFO_NAMED(node->get_name(),
"add_two_ints_client was interrupted while waiting for the service. Exiting.\n");
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The trailing \n should be obsolete.

Same below.

ss << "Incoming request" << std::endl;
ss << "a: " << request->a << " b: " << request->b << std::endl;
// No stream log macro yet. This will get <package_name> as the logger name.
ROS_INFO("%s", ss.str().c_str())
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This could be reduced to just: ROS_INFO(ss.str().c_str())

@dhood
Copy link
Copy Markdown
Member Author

dhood commented Oct 23, 2017

I've realised that the reason for the "ros" prefix for roscpp could be from the log4cxx backend requiring the notion of a root logger. Since rcutils doesn't impose that in ros2/rcutils#57, that doesn't apply to ros2, so we can remove it.

@wjwwood
Copy link
Copy Markdown
Member

wjwwood commented Oct 24, 2017

I have a few questions about the approach:

  • Why ROS_ and not RCLCPP_?
  • Wouldn't it be useful to have a default prefix for nodes (overridable with the _FULLNAME)?
    • That would let people do things like "set all loggers for ROS nodes to info".
    • Without a common prefix that becomes impossible I think.
    • I don't know if it should be ros.<node_name> or something like ros.nodes.<node_name>.
  • Is there any plan to support "turn the discovery logger for Node X to debug"?
    • Rather than turn the discovery logger for everyone to debug?
    • This would require the code under a node to "get the node's logger name" and extend it, so that there is a clear hierarchy.
    • Wasn't needed in ROS 1 because the node was a singleton.

@dhood
Copy link
Copy Markdown
Member Author

dhood commented Nov 3, 2017

closing in favour of design discussions elsewhere

@dhood dhood closed this Nov 3, 2017
@dhood dhood removed the in progress Actively being worked on (Kanban column) label Nov 3, 2017
@dhood dhood deleted the use_logging_prototype branch November 15, 2017 22:18
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants