proposal for how to unify logging and make it configurable with a file

[wjwwood]

To start, after speaking with @clalancette, here's a bullet list of the current state of affairs:

• console messages (tuple of logger name, log level, log message, etc...) are sent to rcutils via logging macros
• rcutils determines if the logger is enabled for the console message's level
  • it checks this here: https://github.com/ros2/rcutils/blob/c49b41c9b19ae9e76e746db662285fc6c7d3b1af/src/logging.c#L911-L913
  • severity is considered here: https://github.com/ros2/rcutils/blob/c49b41c9b19ae9e76e746db662285fc6c7d3b1af/src/logging.c#L875-L889
• rcutils calls the output handler (it only supports one at a time)
  • it calls the global output handler here: https://github.com/ros2/rcutils/blob/c49b41c9b19ae9e76e746db662285fc6c7d3b1af/src/logging.c#L901-L904
• by default rcl registers a handler (so the default rcutils one is not used directly)
  • actually by default the client libraries (e.g. rclcpp and rclpy) register a single handler, but in those cases they just make it thread-safe and then forward it to the rcl handler
  • the rcl handler iterates over its internal list of output handlers and calls each one in turn with the console message
    • https://github.com/ros2/rcl/blob/191b13bc2eb8578e40799eb6b50c74b885e7066e/rcl/src/rcl/logging.c#L157-L161
  • by default it has one for the console, which just send the console message back to rcutils and it is printed there
    • https://github.com/ros2/rcl/blob/191b13bc2eb8578e40799eb6b50c74b885e7066e/rcl/src/rcl/logging.c#L91-L93
  • it also has one for rosout:
    • https://github.com/ros2/rcl/blob/191b13bc2eb8578e40799eb6b50c74b885e7066e/rcl/src/rcl/logging.c#L95-L101
  • and finally it has one for the "external logging library" which is the spdlog backend:
    • https://github.com/ros2/rcl/blob/191b13bc2eb8578e40799eb6b50c74b885e7066e/rcl/src/rcl/logging.c#L102-L113
• each logging handler does what it wants with the console message
• the spdlog backend will write it to file only

There a few problems with this:

• rcutils printing to the console means that:
  • we have to configure it separately from the logging backend (including disabling it or changing its default log level)
  • we don't take advantage of implicit features of the logging backend (like the console printing performance of spdlog)
• filter console messages in rcutils instead of in each output handler means:
  • you cannot have different log levels set for each output handler (or sink), e.g. you cannot have debug go to file and info to console
  • also, you limit what goes over /rosout based on what you output to the console, limiting the remote debugger's ability to see more details than what is printed to the screen (I haven't confirmed this, but it seems to be the case based on the code)

Additionally, the default logging backend that uses spdlog does not have any way to configure it using a file or the command line. There is a command line option to disable it entirely (see: #88 (comment))

---

The current state makes it impossible to configure the system in a few ways, the most important of which is a use case that came up from one of our clients where they would like to:

• have a single config file they pass to all nodes (via launch or env var or command line)
• control the default log level of the file and console separately, e.g. debug to file and info to console
• control the log level of specific named loggers based on the sink, e.g. logger 'my_node' puts debug to file and info to console

There are other use cases which might be considered, but this one I think is going to be pretty common and is not possible in the current situation.

---

For these reasons, I propose we make these changes:

• use spdlog (and generally the logging back ends) for console printing (rather than the implementation in rcutils)
• delegate the filtering of console messages by log level to each output handler so they can have different levels
• define a ROS specific console logging config file format that can be parsed and used to configure rcl_logging_spdlog (since spdlog does not have its own config file format)
• (optional) elevate the concept of "sinks" to the ROS level, so users can configure different log levels per sink for each named logger (at least in the config file if not also from the command line)
  • e.g. something like --log-level my_node:=file:debug,console:info instead of --log-level my_node:=debug

[jrutgeer]

If work on this gets started, consider also to allow the use of ROS time instead of system time, so log output is in sync with other time stamps in case of use_sim_time:=true. See ros2/rcutils#432

[firesurfer]

Hi @cfveeded pointed me to this discussion coming from #105

@wjwwood Are there any decisions made yet regarding the configuration file for the spdlog backend?

As stated in #105:

At the moment there is only support for passing in the path to a configuration file. There is no definition in which format the configuration file should be.

The documentation actually says:

Note that the format of this file is backend-specific (and is currently unimplemented for the default backend logger of spdlog) -

What kind of format would you prefer ? I would suggest using yaml file as they are widely used all over the ROS2 ecosystem. On the other hand this would mean to introduce a new dependency to yaml-cpp.

How should existing parameters be handled ?

My guess would be that only adding new parameters to the config file makes sense in order to not break compatibility. As an alternative we could define for currently implemented parameters that the environment variables will always overwrite their counter pendants in the config file.

[wjwwood]

The short answer is no, we haven't had time to invest into this. And I know you guys want to add features, new loggers, and address some of the pain points, but I am wary of adding small patches and fixes that we'll have to tick-tock out later in place for a more complete configuration solution. The problem is, I don't know if/when we'll get to it. @clalancette might have a better outlook for that.

If we can't do it, others like yourselves certainly can, but I'd really want to see a more complete solution, maybe involving a REP since it will impact other client libraries as well (even ones that don't use rcl).

To your specific questions...

At the moment there is only support for passing in the path to a configuration file. There is no definition in which format the configuration file should be.
...
What kind of format would you prefer ? I would suggest using yaml file as they are widely used all over the ROS2 ecosystem. On the other hand this would mean to introduce a new dependency to yaml-cpp.

I think we would really like to change this, so there is a standard for the config file that is not dependent on the backend, but would let you pass through information to the specific backend as needed. Unfortunately, this requires a good deal of design work to consider what is reasonable and not for this file. In terms of what format and dependencies we want, I think YAML is an obvious choice, but not necessarily the only one. We already have a dependency on libyaml which a C library in parts of rcl, so that would be preferable to using yaml-cpp even though it is a bit harder to work with.

How should existing parameters be handled ?

My guess would be that only adding new parameters to the config file makes sense in order to not break compatibility. As an alternative we could define for currently implemented parameters that the environment variables will always overwrite their counter pendants in the config file.

They should continue to work more or less as-is, but we can deprecate them as needed. I think they should work in concert with the config file, probably overriding the config file. The classic pattern we use is something like API arguments override env vars which override the config file which overrides the hard coded defaults. But that can sometimes be complicated by circumstances of the particular setting, e.g. some times you want to override the default with an API call or env var, but not block more specific values from other env vars, etc.

[firesurfer]

Hi @wjwwood I completely understand the need for a thought through solution. Just adding more and more environment variables can not be the longterm solution.
The only thing that bothers me a bit as I already mentioned in #105 this kinda stops all possible development and contributions from the community for the logging system for an undetermined amount of time.

Perhaps we could come up with a solution for how we can still progress with feature development until a solution for the configuration file has been found?
A possible solution could be to enable/disable features at compile time. This way we do not need to add additional environment variables and users who need a certain additional feature can just compile the package themselves (But it is still more convenient than having to maintain your own fork).
In the future we then change the conditional compilation to reading an entry from the config file.

[lowellm91]

I also was wondering what time base the logging message was using, I would like the option to include sim time or add both times to the log output.

[ros-discourse]

This issue has been mentioned on ROS Discourse. There might be relevant details there:

https://discourse.ros.org/t/improving-ros2-logging-with-spdlog-and-fmt/38817/3

[jncfa]

I also was wondering what time base the logging message was using, I would like the option to include sim time or add both times to the log output.

The time data is fetched here: https://github.com/ros2/rcutils/blob/rolling/src/logging.c#L1204-L1205
So it's just using system time

[rr-tom-noble]

Just come across this thread after raising an issue with rcutils and doing some digging (our specific use-case is structured JSON logging with additional fields than those provided by default).

ros2/rcutils#475

The usage of log4cxx in ROS1 seemed very flexible in this regard. At the least, it would be nice to have the option to implement custom spdlog formatters and use a file (akin to the rosconsole config file in ROS1) to specify which formatters to use

[rr-tom-noble]

So, I think we can achieve what we want by using a custom spdlog::formatter to output as JSON, and by adding additional pattern_flags for the fields we want, as these will be known at compile time.

The difficulty, I think, will be getting ROS2 to use the custom logger. From what I can tell, the default logger is pretty much hard-coded in terms of formatters and sinks, so I think the only options I can come up with involve writing a wrapper around rclcpp::Node which either:

• Directly creates an additional spdlog::Logger on instantiation OR
• Sets global spdlog defaults, or fetches the default logger by name and makes those modifications

Neither of these seem ideal since the first is essentially bypassing ROS's logging framework, and the latter is breaking the layer of abstraction that it provides.

I slightly prefer option 2, as it'll avoid us having to also wrap the logging macros to output to additional loggers.

Out of curiosity, what is the issue with allowing support for backend-specific configuration files? The rclcpp::Logger interface could provide an e.g. configure(const std::filesystem::path&) method which simply passes the file along to the backend.

Understandably, this doesn't help much in the way of unification, but presumably end users / developers will be aware of the implementation chosen for their system and can supply the relevant config?

It feels like it's hard to argue for or against what should / shouldn't be added to a unified logging config, and which fields may be too backend-specific, when there's currently only one implementation as far as I'm aware i.e. rcl_logging_spdlog.

[jrutgeer]

@rr-tom-noble I haven't looked at it in detail, but I think the following might be relevant: ros2/rcl#1178 and https://discourse.ros.org/t/ros-2-log-system-meets-rsyslog-and-fluentbit/39280