Cannot log in ROS2 node after building with cython

[placek-robotec]

Bug report

Required Info:

• Operating System:
  • Ubuntu 22.04
• Installation type:
  • binaries
• Version or commit hash:
  • humble
• DDS implementation:
  • cyclonedds
• Client library (if applicable):
  • rclpy

Steps to reproduce issue

Write simple node with at least two logging statements with different severity

from rclpy.node import Node
class LoggingNode(Node):
    def __init__(self) -> None:
        super().__init__("LoggingNode")
        self.get_logger().info("Info log")
        self.get_logger().warn("Warn log")

Update your setup.py to compile python with following command:

from glob import glob
from Cython.Build import cythonize
setup(
    ext_modules=cythonize(glob('**/*.py', recursive=True),
                          exclude=['test/*.py', 'setup.py'],
                          compiler_directives={'language_level' : '3'}, quiet=True),

Expected behavior

Node prints logs in console.

Actual behavior

Exception with message "Logger severity cannot be changed between calls." is thrown.

Additional information

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)

[clalancette]

We don't explicitly support or test cython with rclpy. However, if you find a solution for your problem, please do feel free to open a pull request and we are happy to review.

[complikator]

We don't explicitly support or test cython with rclpy. However, if you find a solution for your problem, please do feel free to open a pull request and we are happy to review.

Ok, so can you tell me why we cannot change logger severity between calls? It would help me understand the specific requirements behind this code and maybe then I would be able to find a solution

[clalancette]

Ok, so can you tell me why we cannot change logger severity between calls? It would help me understand the specific requirements behind this code and maybe then I would be able to find a solution

I'm honestly not sure. That line comes from https://github.com/ros2/rclpy/blob/9536f8ec66020a552cf9ad421a11629ad8804a16/rclpy/rclpy/impl/rcutils_logger.py#L313 . I'm guessing we do some kind of caching, and thus we would have to invalidate the cache, but I really don't know.

[vigneshmgz]

Hi @placek-robotec, I have check the rclpy library like @clalancette said, 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):
  ....

[vigneshmgz]

@placek-robotec

In normal python file, every line number will be considered and maked as new context, but in cython build or live python interpreter, you may encounter the error of severity level changed.

[vigneshmgz]

I found the problem is in the .so file after built by cython doesn't give the proper line number to create a caller id, so if @clalancette by any changes to make line number things disable or something we can log with cython