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

rclpy/rclpy/rclpy/impl/rcutils_logger.py

Line 313 in 9536f8e

raise ValueError('Logger severity cannot be changed between calls.')

. I'm guessing we do some kind of caching, and thus we would have to invalidate the cache, but I really don't know.

[iamvigneshthangavel]

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):
  ....

[iamvigneshthangavel]

@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.

[iamvigneshthangavel]

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

[JNevrly]

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.

I don't think I can suggest a solution without deeper knowledge, but the problem seems to be in the

rclpy/rclpy/rclpy/impl/rcutils_logger.py

Line 301 in 9536f8e

caller_id = CallerId()

as the contexts are cached by the callerId, and many non-CPython environments (cython included) would always return the same calledID (probably None-based) (see https://docs.python.org/3/library/inspect.html#inspect.currentframe).

So I think this concept of caching context would cause problems not only for Cython, but I don't know how to solve this bug without removing the caching, which probably has been introduced for some reason (that I don't know).