Revision history [back]

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.

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

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)

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
```

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.

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

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

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)

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