ROS log file change of time-stamping format

edit

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