Putting log messages from non-ROS code into ROS logging system

edit

I'll propose a more pythonic way to merge a separate logging into roslogging. Feedback welcome!

1. Pros
2. Cons/Todos
3. How To

1. Pros

• Just use the standard python logging module, featuring formatting, namespacing hierarchy, log levels etc. pp.
• If the library is used without modifying its logging like above, the logs are written to console in the given formatting
• If only the forwarding code above is executed, the logs are written to console using ROS (so the formatting matches the rest of the program)
• If additionally the wrapping/user code calls rospy.init_node(..), the logs are automatically published on /rosout
• The logging namespace hierarchy is viewable in the logger level GUIs and for each namespace a level can be set, affecting console and rosout output as usual.

2. Cons/Todos

• Logs issued right after init_node without any delay might not be published. I don't know where that buffer is missing, but have never experienced that with the default rospy logging (rospy.log*) so it could be fixable.

3. How To

In the ROS-agnostic library add: (named rgoap in this case, the file being rgoap/__init__.py):

## logging

import logging
_logger = logging.getLogger('rgoap')
"""The logger used in this library"""
_logger.setLevel(logging.INFO)

# add default console output
_loghandler = logging.StreamHandler()
_loghandler.setLevel(logging.INFO)
_loghandler.setFormatter(logging.Formatter('[%(levelname)s] %(message)s'))
_logger.addHandler(_loghandler)

def remove_default_loghandler():
    """Call this to mute this library or to prevent duplicate messages
    when adding another log handler to the logger named 'rgoap'."""
    _logger.removeHandler(_loghandler)

In the library's code files just log via:

import logging
_logger = logging.getLogger('rgoap') # you can also use dotted namespaces like 'rgoap.planner'!

def my_func():
    _logger.info("Hello %s", "World")

In the ROS-wrapper for that library add: (for example in rgoap_ros/__init__.py)

import rgoap
import rospy

### set up rgoap-ros interface

## forward rgoap's logging to ROS
import logging

# ..for console output
import rosgraph.roslogging as _rl
logging.getLogger('rgoap').addHandler(_rl.RosStreamHandler())

# ..for network output (/rosout)
import rospy.impl.rosout as _ro
logging.getLogger('rgoap').addHandler(_ro.RosOutHandler())

# remove the default console output
rgoap.remove_default_loghandler()

As a simple form I use this header: ros_printouts.h

#ifndef ROS_PRINTOUTS_H
#define ROS_PRINTOUTS_H

/// Compatibility header for non-ros build

#if ROS_BUILD
    // Nothing to do, use the ROS functionality
#else

    #define ROS_DEBUG_STREAM(args) \
    cout << args << endl;

    #define ROS_INFO_STREAM(args) \
    cout << args << endl;


    #define ROS_DEBUG \
        printf 

    #define ROS_INFO \
        printf 

    #define ROS_WARN \
        printf 

    #define ROS_ERROR \
        printf 

    #define ROS_FATAL \
        printf

    #define ROS_ASSERT assert

#endif

#endif

I ran into similar issues. The ROS logging macros are numerous and defined 5 or more levels deep, so whenever you pass the wrong one of the plethora of stringy types in C++, you get several screenfulls of preprocessor error.

If you're developing in C++11, you can use closures to bring back a measure of explicitly typed sanity:

    auto log_info =  [] (const std::string & str) {ROS_INFO_STREAM(str);};
    auto log_warning =  [] (const std::string & str) {ROS_WARNING_STREAM(str);};
    auto log_error =  [] (const std::string & str) {ROS_ERROR_STREAM(str);};

There are probably many ways of defining the above closures; there may be a better one for your code. Doing it this way decomposes the task of fixing the types in the call sites in your code from the much harder problem of figuring out which types will actually work in ROS's macros.

I'm sure there are reasonable historical reasons for why ROS is code generating header files full of macros nested 5 levels deep, but IMHO it has resulted in an unreasonable level of complexity for something as simple as logging a string. Perhaps someone can post an example of what all the macros actually boil down to in the end.