ROS Resources: Documentation | Support | Discussion Forum | Index | Service Status | ros @ Robotics Stack Exchange
Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

After much digging around, I found this is possible, but the current logging architecture in ROS Kinetic makes it quite clunky. The problem is that even though ROS uses Python's logging module and provides its own user-customizable logging configuration file, the custom log stream handler defined in rosgraph.roslogging.RosStreamHandler completely ignores the formatting options specified in the configuration file, and hard-codes its own format. Although this is not good, it can still be overridden, but it's a bit more work.

Here's what I did to change the log's timestamp to a datetime.

  1. Define your own logging configuration file by copying the default at /opt/ros/kinetic/share/rosgraph/conf/python_logging.conf and pasting it to somewhere in your project folder (preferrably a "conf" directory).
  2. Create a "logging.py" somewhere in your project folder (preferrably a Python package) and subclass RosStreamHandler like:

    from __future__ import absolute_import import os import time import logging import sys import datetime

    from rosgraph.roslogging import RosStreamHandler as _RosStreamHandler, _logging_to_rospy_names, _defaultFormatter

    class RosStreamHandler(_RosStreamHandler):

    def emit(self, record):
        level, color = _logging_to_rospy_names[record.levelname]
        record_message = _defaultFormatter.format(record)
        msg = os.environ.get('ROSCONSOLE_FORMAT', '[${severity}] [${time}]: ${message}')
        msg = msg.replace('${severity}', level)
        msg = msg.replace('${message}', str(record_message))
        msg = msg.replace('${walltime}', '%f' % time.time())
        msg = msg.replace('${thread}', str(record.thread))
        msg = msg.replace('${logger}', str(record.name))
        msg = msg.replace('${file}', str(record.pathname))
        msg = msg.replace('${line}', str(record.lineno))
        msg = msg.replace('${function}', str(record.funcName))
        try:
            from rospy import get_name
            node_name = get_name()
        except ImportError:
            node_name = '<unknown_node_name>'
        msg = msg.replace('${node}', node_name)
        time_str = datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S')
        msg = msg.replace('${time}', time_str)
        msg += '\n'
        if record.levelno < logging.WARNING:
            self._write(sys.stdout, msg, color)
        else:
            self._write(sys.stderr, msg, color)
    
  3. In your custom python_logging.conf find the line that says:

     class=rosgraph.roslogging.RosStreamHandler
    

    and change it to point to your new class. If your project's Python package is called "myrobot", and you created logging.py directly inside that, this would look like:

    class=rosgraph.logging.RosStreamHandler
    
  4. Now apply it. To test this, I created a simple test_node.py that looks like:

    #!/usr/bin/env python
    import time
    import inspect
    import rospy
    rospy.init_node('test_node')
    while 1:
        rospy.loginfo("Waiting for 1 second...")
        time.sleep(1)
    

    and associated launch file. To use your custom logging configuration, export the ROS_PYTHON_LOG_CONFIG_FILE environment variable when running any node like:

    export ROS_PYTHON_LOG_CONFIG_FILE=myrobot/config/logging.conf; roslaunch myrobot test_node.launch
    

The output I get is:

[INFO] [2018-01-15 18:36:55]: Waiting for 1 second...
[INFO] [2018-01-15 18:36:56]: Waiting for 1 second...
[INFO] [2018-01-15 18:36:57]: Waiting for 1 second...
[INFO] [2018-01-15 18:36:58]: Waiting for 1 second...

Now clearly, this is a relatively large amount of work to change something relatively minor. Hopefully this is fixed in the next ROS release so it's a lot easier to customize.

After much digging around, I found this is possible, but the current logging architecture in ROS Kinetic makes it quite clunky. The problem is that even though ROS uses Python's logging module and provides its own user-customizable logging configuration file, the custom log stream handler defined in rosgraph.roslogging.RosStreamHandler completely ignores the formatting options specified in the configuration file, and hard-codes its own format. Although this is not good, it can still be overridden, but it's a bit more work.

Here's what I did to change the log's timestamp to a datetime.

  1. Define your own logging configuration file by copying the default at /opt/ros/kinetic/share/rosgraph/conf/python_logging.conf and pasting it to somewhere in your project folder (preferrably a "conf" directory).

    test

  2. Create a "logging.py" somewhere in your project folder (preferrably a Python package) and subclass RosStreamHandler like:

    from __future__ import absolute_import
    import os
    import time
    import logging
    import sys
    import datetime

    datetime from rosgraph.roslogging import RosStreamHandler as _RosStreamHandler, _logging_to_rospy_names, _defaultFormatter

    _defaultFormatter class RosStreamHandler(_RosStreamHandler):

    RosStreamHandler(_RosStreamHandler):
    
        def emit(self, record):
         level, color = _logging_to_rospy_names[record.levelname]
         record_message = _defaultFormatter.format(record)
         msg = os.environ.get('ROSCONSOLE_FORMAT', '[${severity}] [${time}]: ${message}')
         msg = msg.replace('${severity}', level)
         msg = msg.replace('${message}', str(record_message))
         msg = msg.replace('${walltime}', '%f' % time.time())
         msg = msg.replace('${thread}', str(record.thread))
         msg = msg.replace('${logger}', str(record.name))
         msg = msg.replace('${file}', str(record.pathname))
         msg = msg.replace('${line}', str(record.lineno))
         msg = msg.replace('${function}', str(record.funcName))
         try:
             from rospy import get_name
             node_name = get_name()
         except ImportError:
             node_name = '<unknown_node_name>'
         msg = msg.replace('${node}', node_name)
         time_str = datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S')
         msg = msg.replace('${time}', time_str)
         msg += '\n'
         if record.levelno < logging.WARNING:
             self._write(sys.stdout, msg, color)
         else:
             self._write(sys.stderr, msg, color)
    
  3. In your custom python_logging.conf find the line that says:

     class=rosgraph.roslogging.RosStreamHandler
    

    and change it to point to your new class. If your project's Python package is called "myrobot", and you created logging.py directly inside that, this would look like:

    class=rosgraph.logging.RosStreamHandler
    
  4. Now apply it. To test this, I created a simple test_node.py that looks like:

    #!/usr/bin/env python
    import time
    import inspect
    import rospy
    rospy.init_node('test_node')
    while 1:
        rospy.loginfo("Waiting for 1 second...")
        time.sleep(1)
    

    and associated launch file. To use your custom logging configuration, export the ROS_PYTHON_LOG_CONFIG_FILE environment variable when running any node like:

    export ROS_PYTHON_LOG_CONFIG_FILE=myrobot/config/logging.conf; roslaunch myrobot test_node.launch
    

The output I get is:

[INFO] [2018-01-15 18:36:55]: Waiting for 1 second...
[INFO] [2018-01-15 18:36:56]: Waiting for 1 second...
[INFO] [2018-01-15 18:36:57]: Waiting for 1 second...
[INFO] [2018-01-15 18:36:58]: Waiting for 1 second...

Now clearly, this is a relatively large amount of work to change something relatively minor. Hopefully this is fixed in the next ROS release so it's a lot easier to customize.