Skip to content

Prototype use of rclpy logging for callback_group#186

Closed
dhood wants to merge 2 commits intomasterfrom
use_logging
Closed

Prototype use of rclpy logging for callback_group#186
dhood wants to merge 2 commits intomasterfrom
use_logging

Conversation

@dhood
Copy link
Copy Markdown
Member

@dhood dhood commented Oct 20, 2017

Is this what we expect this example to look like using rclpy logging?
The script passes its logger (ros.callback_group_example) through to the nodes so that the node loggers get attached to the parent logger.

The logger name of the nodes gets the parent logger prepended:

[INFO] [ros.callback_group_example.double_talker]: Publishing: "Hello World: 0"
[INFO] [ros.callback_group_example.listener]: I heard: [Hello World: 0]
[INFO] [ros.callback_group_example.double_talker]: Publishing: "Hello World: 1"
[INFO] [ros.callback_group_example.double_talker]: Publishing: "Hello World: 2"
[INFO] [ros.callback_group_example.listener]: I heard: [Hello World: 1]

And if you enable debug on the parent logger (by uncommenting master...use_logging#diff-41999062ba992334cbe0288b618f2a2dR23), the node loggers get debug enabled too:

[DEBUG] [ros.callback_group_example.double_talker]: Initialization complete
[DEBUG] [ros.callback_group_example]: Nodes added to executor
[INFO] [ros.callback_group_example.double_talker]: Publishing: "Hello World: 0"
[INFO] [ros.callback_group_example.listener]: I heard: [Hello World: 0]

If you don't pass through the script's logger, the nodes will just use independent loggers (still configurable, but not attached to the parent, and the logger name will collide with any other nodes with the same node name).

@dhood dhood added the in progress Actively being worked on (Kanban column) label Oct 20, 2017
@dhood
Copy link
Copy Markdown
Member Author

dhood commented Oct 20, 2017

update: disregard the ros. prefix on the logger, that's a separate question.

This is "in review" for discussion but not being proposed for merge (implementation pending decision)

@dhood dhood added in review Waiting for review (Kanban column) and removed in progress Actively being worked on (Kanban column) labels Oct 20, 2017
@dirk-thomas
Copy link
Copy Markdown
Member

I think it is good that the user can choose to do what is proposed in this patch.

In general I would rather recommend to not embed information about where a node is being run into its logger name. E.g. the node might later be stopped dynamically and being restarted in a separate process. From a user point of view I wouldn't expect the logger name of the node to change.

@dhood
Copy link
Copy Markdown
Member Author

dhood commented Oct 23, 2017

If we want to update it to show best practices to users (taking into account what you pointed out about the logger changing if the node is loaded in a different way), what would we recommend? Not passing through the logger for e.g. the listener to attach to, but instead setting a more specific logger name for the node to use? (that specific name would be re-used if we decide to restart it in a separate process)

import rclpy
from rclpy.callback_groups import MutuallyExclusiveCallbackGroup
from rclpy.executors import MultiThreadedExecutor
import rclpy.logging
Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Does it make sense to require users to import the logging module to use it, or should we always import it in rclpy's init instead?

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 user still needs to call a function from it to create a logger instance. So what gain would we get from an implicit import during init?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

that the diff for this PR would not include this line.

Without the implicit import, even users that just want to use the root logger have to import rclpy.logging to call rclpy.logging.loginfo() (unlike in rospy). It seems convenient to always have it imported but I am asking because it might not be good from a design perspective

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.

My personal opinion is "import what you use" but that is certainly different from what is done in rospy. I will leave it up to others to give feedback on this.

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.

I don't care one way or the other. I wouldn't be surprised/shocked to see that import rclpy allows me to do rclpy.logging.*, which is how import os; os.path.join(...) works. On the other hand, it would be fine to have to explicitly import logging too.

On balance, I'd slightly prefer not needing this import so the user's code is slightly shorter and I figure it will be a common enough thing to save a non-trivial amount of typing on user's part.

@dirk-thomas
Copy link
Copy Markdown
Member

I would expect a node to log its messages on a logger which uses the node name as the logger name.

Optionally with the package name in the front, but even that could be argued against with the same reasoning: if a user forks pkg A to pkg B it couldn't simply run the node from pkg B because all the logger names would be different again.

@wjwwood
Copy link
Copy Markdown
Member

wjwwood commented Oct 23, 2017

It would be cool if the package name (possibly other things) would be part of the logger "instance" but not part of the logger name, i.e. something like a set of key-value pairs. These could be used in our logging output format, e.g. [{package_name}/{logger_name}]: {msg}. But that's not necessary. Users could include the package name in their own messages for now with ros2/ament_cmake_ros#2.

If we assume that node names will be unique at some point, the name should be sufficient to ensure no cross talk in logging and therefore the package name isn't necessary.

@mikaelarguedas mikaelarguedas added in progress Actively being worked on (Kanban column) and removed in review Waiting for review (Kanban column) labels Oct 26, 2017
@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 branch November 3, 2017 22:21
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.

4 participants