Set child logger's log level separately

[tonynajjar]

trafficstars

Bug report

Required Info:

• Operating System:
  • Ubuntu 22
• Installation type:
  • binaries
• Version or commit hash:
  • rolling
• DDS implementation:
  • CycloneDDs
• Client library (if applicable):
  • both

Steps to reproduce issue

terminal 1:

ros2 run examples_rclpy_minimal_action_server server --ros-args --log-level minimal_action_server:=debug

terminal 2:

ros2 run examples_rclpy_minimal_action_server server --ros-args --log-level minimal_action_server:=debug

Expected behavior

I expect only the logger with name "minimal_action_server" to have the debug log level. This node doesn't happen to have debug logs but if there were, and were logged using the node's logger, I'd expect to see them as well --> this part works though

root@logi-XMG-CORE-REN-M20:/code# ros2 run examples_rclpy_minimal_action_server server --ros-args --log-level minimal_action_server:=debug
[INFO] [1676554619.084247330] [minimal_action_server]: Received goal request
[INFO] [1676554619.087030475] [minimal_action_server]: Executing goal...
[INFO] [1676554619.087344829] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1])
[INFO] [1676554620.088874606] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2])

Actual behavior

It seems like its child logger also gets the debug log level

root@logi-XMG-CORE-REN-M20:/code# ros2 run examples_rclpy_minimal_action_server server --ros-args --log-level minimal_action_server:=debug
[DEBUG] [1676554619.083808500] [minimal_action_server.action_server]: New goal request with ID: [231 144 204  21  63  93  68  31 175 171  84 233 207 225 181 169]
[INFO] [1676554619.084247330] [minimal_action_server]: Received goal request
[DEBUG] [1676554619.084897432] [minimal_action_server.action_server]: New goal accepted: [231 144 204  21  63  93  68  31 175 171  84 233 207 225 181 169]
[DEBUG] [1676554619.086532640] [minimal_action_server.action_server]: Result request received for goal with ID: [231 144 204  21  63  93  68  31 175 171  84 233 207 225 181 169]
[DEBUG] [1676554619.086612299] [minimal_action_server.action_server]: Executing goal with ID [231 144 204  21  63  93  68  31 175 171  84 233 207 225 181 169]
[INFO] [1676554619.087030475] [minimal_action_server]: Executing goal...
[INFO] [1676554619.087344829] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1])
[INFO] [1676554620.088874606] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2])

[fujitatomoya]

@tonynajjar thanks for creating issue.

so are you suggesting using --ros-args --log-level minimal_action_server:=debug only sets the logging debug level to minimal_action_server? not all subordinate child loggers, right?

[tonynajjar]

Exactly. Makes sense don't you think? I'd like to see the debug info of my nodes without getting the "ROS internal logs"

[fujitatomoya]

How about the following? does that work for you?

root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 run examples_rclpy_minimal_action_server server --ros-args --log-level minimal_action_server:=debug --log-level minimal_action_server.action_server:=WARN
[INFO] [1676571229.724406498] [minimal_action_server]: Received goal request
[INFO] [1676571229.725345312] [minimal_action_server]: Executing goal...
[INFO] [1676571229.726392145] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1])
[INFO] [1676571230.729463624] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2])
[INFO] [1676571231.732984657] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2, 3])
[INFO] [1676571232.735480752] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2, 3, 5])
[INFO] [1676571233.737449582] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2, 3, 5, 8])
[INFO] [1676571234.739130885] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2, 3, 5, 8, 13])
[INFO] [1676571235.742725082] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2, 3, 5, 8, 13, 21])
[INFO] [1676571236.746402343] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2, 3, 5, 8, 13, 21, 34])
[INFO] [1676571237.750148785] [minimal_action_server]: Publishing feedback: array('i', [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55])
[INFO] [1676571238.755345757] [minimal_action_server]: Returning result: array('i', [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55])

[tonynajjar]

Thanks for this proposition. While this does work, it's not very practical I feel; If new children loggers are added internally, we would need to set their log level as well.

[clalancette]

In short, this is not how it is currently designed. When a logger (or sublogger) is created, it essentially has an "unset" level. When the code sees an unset level, it then walks up the logger hierarchy, looking for a user-set level. If it finds one, it then uses that level. If it it doesn't find one, it uses the default level (which I think is INFO, but I don't remember right now).

So in this example, what is happening is that minimal_action_server.action_server has an unset level, so when we go to determine the level, we walk up to minimal_action_server, and find the DEBUG level there. So we then use that.

With all of that said, we could reconsider the current design, but I think we'd need to find out a) what use cases currently work that would be broken by this, and b) what the advantage of this is. Then we'd have to write up some design docs for it.

[fujitatomoya]

IMO,

• i think current logger hierarchy is not bad design, if the logger level is unset, walks up to hierarchy to find and set the logger level. (this is useful for user, unless user does not set the logger levels in subordinate loggers.)
• what bothers here is that includes system library loggers such as action_server in this particular case. (@tonynajjar correct me if i got this wrong, but this is the problem you are saying?)
• if user application creates or adds child loggers, that is user responsibility to set the logger level for those loggers. user can take advantage of logger hierarchy, or can set each logging level for logger.

so, maybe we can set default logging level for system loggers? i am not really inclined to take this approach, since if logger levels are set in system libraries, it cannot be changed during runtime, unless we have feature https://github.com/ros2/ros2/issues/1355?

any thoughts?

[tonynajjar]

what bothers here is that includes system library loggers such as action_server in this particular case. (@tonynajjar correct me if i got this wrong, but this is the problem you are saying?)

This is the issue I'm raising yes -> I can't get my user application debug logs without them being "polluted" with, as you call them, "system library loggers'" debug logs. I feel like there should be a "logical" separation between user application loggers and system library loggers.

[clalancette]

We had a short discussion about this today. Some notes from that discussion:

• As I mentioned above, the existing design is meant to be hierarchical, so this is currently operating as intended.
• If we changed this, we risk breaking some use cases that work today.
• We could separate "system" loggers from others, but that introduces an artificial distinction between the ROS 2 core and other packages, which we don't particular like. It is also totally unclear where we would draw that line.
• One thing that would be very nice here is to have a rqt tool that allowed you to introspect the entire logging hierarchy, and then selectively enable/disable the loggers that you want.
• Another change that we could make is to the client libraries so that get_logger("foo") returned a special string (like foo.user) so that the user could enable just their part of the hierarchy.

[fujitatomoya]

One thing that would be very nice here is to have a rqt tool that allowed you to introspect the entire logging hierarchy, and then selectively enable/disable the loggers that you want.

👍