rclpy icon indicating copy to clipboard operation
rclpy copied to clipboard

Adding a service to nodes for adjusting the node's logger level

Open mlautman opened this issue 7 years ago • 7 comments

This adds a service to python nodes for changing the logger level. Depends on: https://github.com/ros2/rcl_interfaces/pull/56

mlautman avatar Dec 18 '18 00:12 mlautman

This makes sense generally as a direct port of the ROS1 functionality. However just looking at the message and the service it seems like it really is just a parameter on the node. And that if we reused the existing parameter infrastructure we would get a lot more tools and introspection available.

Logging level could be set and introspected using standard parameter tools. All that it would take is to pick a convention like using parameters that start with /logging_level / <LOGGERNAME> / level

Then tools like rqt_logger_level could simply be a parameter setting GUI with a filter for parameters that start with the prefix. Listing loggers would simply use the parameter listing capabilities.

When a new logger is created in the node it would create the parameter with it's startup setting. And would register for a parameter changed callback to validate any new logger settings.

In the future potentially other parameters could be added such as changing the logging output, not just the level.

tfoote avatar Dec 19 '18 00:12 tfoote

@tfoote I think that is a great Idea but I'm a little lost as to how I should implement that. Parsing through the code, the Python and C++ node classes call a shared method from logging.c in the rclutils package. (https://github.com/ros2/rcutils/blob/a7f880efc5701386ee8be8069a84a7ae7139cd6b/src/logging.c#L280). This method uses a map to store logger levels which would need to be replaced by setters and getters to the parameter server. I was initially thinking that I could put the parameter logic in the rcutils code but I don't see any examples for setting/getting parameters in C.

My second thought is that it may be better to remove the map logic entirely and implement setter and getter methods for the parameters in the Python and C++ code separately. Does this sound like a reasonable plan of attack?

mlautman avatar Dec 20 '18 20:12 mlautman

I think that for the moment we should probably implement it in c++ and python separately.

At a high level the logging level node component will

  1. register a callback for a new requested parameter change (along the lines of https://github.com/ros2/rclpy/blob/e173ccd693266c0057a322f27dfe7cfefc96db55/rclpy/rclpy/node.py#L216 though this needs to be extended to support multiple callbacks so the user can set one or more as well as other components)
  2. in that callback when the parameter for the logging level is set it will validate the request and if there's a change required call the rcutils set logger level, and then set the parameter and the
  3. The get will just read the parameter. This has the risk that the logging level could be set at the lower level. If that's something we think might be a risk we could setup a callback to be invoked when the rcutils logging level changes and that will update the parameter storage value. (This will also provide a conveniently streamed parameter event for people introspecting the system too)

I'm not as familar with the rclpy code base but for rclcpp I'd suggest creating a node_log_level_interface that can leverage the the parameter interface and the logging interface. It probably makes sense to extend the logging interface to support getting and setting the logging level. Then the log_level_interface can register a param_change_callback to validate the changes and act on them. This also would want to have the notification callback from the rcutils layer to know if the logging level is changed by some other mechanism. And again this will require extending the registration to support multiple callbacks to support potentially multiple user callback as well as our new internal implementation callbacks.

tfoote avatar Dec 21 '18 01:12 tfoote

On further consideration, I don't know if I agree that this is the best way forward. If all loggers were created by nodes storing logger levels as parameters would make a ton of sense. However, maintaining logger_levels for both node loggers and rclutils loggers would require either duplicate or split storage. This would add quite a bit of complexity and likely break API while offering limited new functionality. Splitting storage between parameters and rclutils would be less complex but it would make it unclear to the user where data is being stored.

  1. register a callback for a new requested parameter change ( ... though this needs to be extended to support multiple callbacks so the user can set one or more as well as other components)

Independent of logger_levels I think this would be a great contribution. ROS2 users very likely would appreciate the ability to register different callbacks for different parameters. If we change API from:

NodeParameters::register_param_change_callback(ParametersCallbackFunction callback)

to something like:

NodeParameters::register_param_change_callback(const std::string& parameter_path, ParametersCallbackFunction callback)

We could store these callbacks in a map std::map<std::string, ParametersCallbackFunction callback>. Then for each incoming parameter change we apply all matching callbacks. (eg: if we had a callback for '/logger/logger_level/', and we set /logger/logger_level/my_node/my_logger to 10, then the callback would be called)

mlautman avatar Dec 21 '18 22:12 mlautman

@tfoote Have you had the chance to look at this again?

mlautman avatar Jan 02 '19 19:01 mlautman

Indeed it's slightly more complex to have the duplicate storage, but if the parameter value is treated as a cached version of the underlying logger the status is relatively clear. And as long as we have a reliable method to make sure that the parameter value is updated any time the rcutils value is updated then we can be confident that any query will be valid. And vice versa setting the parameter doesn't actually change the value of the parameter it calls rcutils to change the value which then sets the parameter. The double bookkeeping is a small overhead compared to implementing all the necessary front ends and adds another whole interface surface for developers and users to learn.

For the callbacks I think that we will want to use a handle based approach not a path/filter string. The path/filter is another feature but it's easy to see that there might be multiple components interested in the same set of parameters so the path/filter would not be unique and then only one would get it's callbacks.

Also unless there's a significant optimization for pre-filtering I suspect that it might be simpler to just filter at the top of each callback instead of trying to externalize that filtering. There's potentially a lot of custom logic for filtering that would be hard to capture in a generic API. However a helper function that callbacks could use might be helpful.

tfoote avatar Jan 02 '19 19:01 tfoote

We have a limited budget for this effort and I don't think we have the resources to implement the preferred solution that you outlined. I'm happy to support anyone else who has an interest in picking up where this left off.

mlautman avatar Jan 22 '19 19:01 mlautman

We ended up implementing this in #1102 , so I'm going to close this one out. Feel free to reopen if there is another part of this that is missing.

clalancette avatar Oct 06 '23 12:10 clalancette