Cannot log in ROS2 node after building with cython

Question

I have ROS2 package written in python (with usage of rclpy) with ROS2 node. Inside this node I want to use node logger, lets say in following way:

def __init__(self):
    self.get_logger().info("Starting my node!")
    self.get_logger().warn("My node has already started!")

This works perfectly with standard python build, but when I want to build it using Cython (because code is going to production) I encounter error: Logger severity cannot be changed between calls. This is caused by implementation of CallerId:

class CallerId(
        namedtuple('CallerId', ['function_name', 'file_path', 'line_number', 'last_index'])):

    def __new__(cls, frame=None):
        if not frame:
            frame = _find_caller(inspect.currentframe())
        return super(CallerId, cls).__new__(
            cls,
            function_name=frame.f_code.co_name,
            file_path=os.path.abspath(inspect.getframeinfo(frame).filename),
            line_number=frame.f_lineno,
            last_index=frame.f_lasti,  # To distinguish between two callers on the same line
        )

in file rcutils_logger.py. I understand perfectly that after "cythonization" of file my inspect module won't work anymore (because every call to inspect functions returns same line/file), but I am unable to fix it. Has anyone encountered similar problems before?

Answer 1

I am using a workaround which is far from a perfect solution but it might help you / someone else:

    def _cython_workaround(log_function):
    """Workaround for cython to accept the logger functions."""
      if cython.compiled:
        def wrapper(msg, *args, **kwargs):
            try:
                log_function(msg, *args, **kwargs)
            except Exception:
                # catch without re-raise
                # TODO: 'Logger severity cannot be changed between calls.'
                # https://stackoverflow.com/questions/77287788/cannot-log-in-ros2-node-after-building-with-cython
                msg = log_function.__name__.upper() + ": " + msg
                logger.info(msg, *args, **kwargs)
        return wrapper
    else:
        return log_function

And then you need to duck-type your composite and the logger itself, since the rclpy implementation does log as well. Also, since the problem comes from changing logging severity between calls, you need to make sure the first log is called is of the same severity used above.

    if cython.compiled:
        # make sure that the first log message has the severity level 
        # INFO set, otherwise the logger will (re)raise on exception
        logger.info("Cython compiled")
        composite.info = logger.info
        composite.debug = _cython_workaround(logger.debug)
        # ...

        # prevent rclpy implementation from raising on exception when itself logs something
        logger.debug = composite.info
        logger.warning = composite.warning
        # ...   
    else:
        composite.info = logger.info
        composite.debug = logger.debug
        # ...

This is not yet very well tested. The logger does log sometimes fine in another severity level, so probably there is a better workaround. And any filters set raise as well! so loosing "throtle_duration_sec..." or "once=True" may trouble you as well.

Answer 2

I have check the rclpy library, it is assigning the caller id based on the module and which the logging is called also setting the Severity level for that. Simple Example:

{
   'main_module' : info_severity,
   'funtion1' : warn_severity,
   'function2' : error_severity
}

if your severity changing on the same module it will throw the error.

if you try to create a functions inside your python code for each log and call that wherever that particular logs needed, the problem will be fixed,

def error(message):
   ....

def warn(message):
  ....