ROS2 Logging

There was some interesting development in rosconsole from @mgrrx to use pluginlib to support different logging sinks, particuilarly to support journald (https://github.com/ros/rosconsole/issues/16). I wonder if you could consider a similar approach for logging in ROS2, which would provide a familiar mechanism for swapping logging sinks without recompilation.

@Paul_Bovbel is your desire to be able to actually develop custom logging sinks (a reason for using pluginlib), or are you simply suggesting that ROS2 should be able to log to a number of backends which should be configurable at runtime (not necessarily requiring pluginlib)?

I have a pretty limited number of sinks in mind (stdout, /rosout, journald), but given the fluentd suggestion above (and that ROS2 is cross platform), being able to develop a sink plugin outside of the rcl source tree via pluginlib seems valuable.

Of course, you can always just write /rosout to journald via an intermediate node, but this can be expensive when intra-process transport is not available.

it would be very nice if we can choose the backend logging system, cz some vendors have their own specific logging system once it comes to the embedded system.

@nburek are there any tutorials, examples, or demos for making use of the new logging features?

1 Like

@nuclearsandwich This doesn’t exist right now but i have opened https://github.com/ros2/rcl_logging/issues/6 for our team to track.

is there any process / package to store /rosout into the file system?
e.g) ROS rosout node.

and there are directories under ~/.ros/log/, once we run the ros node there will be directory based on PID. so far it is empty, what this is for? expecting we are able to enable/disable logging to file system under ~/.ros/log/ for each node setting.

@tomoyafujita There are a couple of options right now for logging to a file. There were hooks added in crystal to allow a third-party logger to be hooked up that can handle logging to a file. An implementation using log4cxx was created, but was ultimately not enabled in the release due to some memory safety issues in the library that can cause it to segfault during shutdown (https://github.com/ros2/build_cop/issues/189). If you don’t mind that issue you can use the log4cxx logger by compiling rcl_logging_log4cxx and rcl with the set environment variable RCL_LOGGING_IMPLEMENTATION=rcl_logging_log4cxx.

The second option is to configure a log file handler in your launch file. I have not personally looked into it much, so maybe someone else here can provide more detail, but you should now be able to configure your launch files to forward the stdout/stderr from the processes it starts to a log handler class that can be configured to send it to a log file. See the example configuration here: https://github.com/ros2/launch/blob/master/launch/examples/launch_counters.py#L43-L44

@nburek

appreciate for your quick response!

a third-party logger to be hooked up that can handle logging to a file.

actually i already tried to use RCL_LOGGING_IMPLEMENTATION=rcl_logging_sony,
that works just fine, we can use our own implementation.

i was thinking that there is common way(not vendor specific) to log to file? and configurable for each node to do that? of course, we can do that with RCL_LOGGING_IMPLEMENTATION, but i think this is common use-case during debug.

okay i will look into launch_counter

thanks,
Tomoya

okay launch_counters example is logger setting example for launch.
for launch logger can be configurable launch.logging.launch_config.
actually launch.log is configured in default and store launch log into file system.

what i am looking for is node logger for file system…

The intent had been for rcl_logger_log4cxx to be included by default to solve the common use case. However, the memory safety issue in multithreaded programs was discovered in the last few weeks before the release and there wasn’t time to replace it with something else. There is already done discussions on a new logger implementation that could be used as a default.

@nburek

thanks for the information to share, really appreciate that.

i mean that dumping info into file system is really common usage as default during development, so i was thinking that it should be generic and enabled as default(but can be configurable), not as in user extension or anything like that.

do you have any information above that?

thanks,
Tomoya

1 Like

I’ve posted a few PRs that implement a new per-process ROS 2 logger; the main one is at https://github.com/ros2/rcl_logging/pull/17 . Any feedback on the proposed implementation and choice of the backend logger is appreciated.

@clalancette

thanks for the PR! i just left my comment on here.

This behavior really hit me by surprise today. I really don’t think this is a good developer/user experience. What’s the best way to solve this? Have the first node that comes online in a process to create a publisher, which then handles publishing all logs to /rosout?

CC’ing @emersonknapp

You start to run into other problems if you just try to have one node handle all the publishing for the entire system. If you’re trying to really tune the performance of a node then it’s even more odd to say that it could unknowingly get assigned an additional publisher if it’s the first to come up. What about if the first Node to come up goes down before the rest of the system?

What should I do when I want to log to syslog?
Because if I understand logging correctly, rcl is logging to all set g_rcl_logging_out_handlers.
I don’t know if g_rcl_logging_ext_lib_enabled could help me or how it could be used at all.

But in our non ROS libraries we also have spdlog and we just use the spdlog sink like that:
auto syslog_sink = std::make_shared<spdlog::sinks::syslog_sink_mt>(logfileName, LOG_PID, LOG_USER);

That would be pretty easy, but spdlog implementation in rcl is fixed to the basic_file_sink_mt.
Customizing rcl_logging_spdlog package is also not an option, as I would need to build all from source…

Yes, rcl is composing multiple output handlers into a single handler that it registers with rcutils (see: https://github.com/ros2/rcl/blob/master/rcl/src/rcl/logging.c#L127-L139 and https://github.com/ros2/rcl/blob/master/rcl/src/rcl/logging.c#L103). If you just want to disable the spdlog handler then you could use g_rcl_logging_ext_lib_enabled, which gets set based on parameters when you run your ROS application.

If you want to go the route of modifying rcl_logging_spdlog to register a syslog sink instead or in addition to the file sink you could definitely do that. The external logging library is statically linked when rcl is compiled, but I believe that the rcl library is dynamically linked during runtime. That should mean that you only need to recompile rcl_logging_spdlog and rcl and make sure they’re sourced as an overlay to the base ROS install. During development I was recompiling only rcl, rclcpp, and rclpy with the modified loggers and my test application was working correctly. I haven’t tested only recompiling rcl and not the cpp/python client libraries as well, but I think it should work.

Your other option right now if you absolutely don’t want to recompile rcl would be to override the base output handler that rcutils uses for all loggers. All of the individual log out handlers (rosout, stdout, and ext_lib) should all be publicly available in the libraries so you can write your own composition function with your own custom spdlog handler and register it in your application (see how rcl registers it here: https://github.com/ros2/rcl/blob/master/rcl/src/rcl/logging.c#L103). The drawback to this approach is that you’ll have to have every ROS application that runs explicitly do this.

If you want to think beyond the Eloquent release, you could always contribute additional functionality to the ROS codebase to make the rcl_logging_spdlog library configurable at runtime or make the external logging library dynamically loaded during runtime instead of during compile. Both of those features were discussed but ultimate cut from initial implementation due to time constraints.

3 Likes

Thanks for the nice explanation!
Really appreciate that.
I need to think about it and look into the options you gave me.

You are right, that was enough for me.
But the overlaying didn’t work for me reliably. So I just build deb packages and installed them…
As this is not a long time solution, I like the idea of having it configurable.
Maybe I can help you out but would need some more information on hoe this should be done.