Add named loggers to rospy (ros#948)

clients/rospy/src/rospy/core.py

@@ -37,11 +37,12 @@
 
 
 import atexit
-try:
-    import cPickle as pickle
-except ImportError:
-    import pickle
-import inspect
+try:
+    import cPickle as pickle
+except ImportError:
+    import pickle
+import inspect
+import hashlib
 import logging
 import os
 import signal
@@ -72,6 +73,8 @@
 from rospy.impl.validators import ParameterInvalid
 
 from rosgraph_msgs.msg import Log
+from functools import partial
+from collections import namedtuple
 
 _logger = logging.getLogger("rospy.core")
 
@@ -143,78 +146,114 @@ def rospywarn(msg, *args):
     """Internal rospy client library warn logging"""
     _rospy_logger.warn(msg, *args)
 
-logdebug = logging.getLogger('rosout').debug
 
-logwarn = logging.getLogger('rosout').warning
+def _base_logger(msg, *args, **kwargs):
+
+    try:
+        name = kwargs.pop('logger_name')
+    except KeyError:
+        name = None
+
+    try:
+        throttle = kwargs.pop('logger_throttle')
+    except KeyError:
+        throttle = None
+
+    try:
+        level = kwargs.pop('logger_level')
+    except KeyError:
+        level = None
+
+    rospy_logger = logging.getLogger('rosout')
+    if name:
+        rospy_logger = rospy_logger.getChild(name)
+    logfunc = getattr(rospy_logger, level)
+
+    if throttle:
+        caller_id = _frame_record_to_caller_id(inspect.stack()[1])
+        _logging_throttle(caller_id, logfunc, throttle, msg, *args)
+    else:
+        logfunc(msg, *args)
+
+
+loginfo = partial(_base_logger, logger_level='info')
 
-loginfo = logging.getLogger('rosout').info
 logout = loginfo # alias deprecated name
 
-logerr = logging.getLogger('rosout').error
+logdebug = partial(_base_logger, logger_level='debug')
+
+logwarn = partial(_base_logger, logger_level='warn')
+
+logerr = partial(_base_logger, logger_level='error')
+
 logerror = logerr # alias logerr
 
-logfatal = logging.getLogger('rosout').critical
-
-
-class LoggingThrottle(object):
-
-    last_logging_time_table = {}
-
-    def __call__(self, caller_id, logging_func, period, msg):
-        """Do logging specified message periodically.
-
-        - caller_id (str): Id to identify the caller
-        - logging_func (function): Function to do logging.
-        - period (float): Period to do logging in second unit.
-        - msg (object): Message to do logging.
-        """
-        now = rospy.Time.now()
-
-        last_logging_time = self.last_logging_time_table.get(caller_id)
-
-        if (last_logging_time is None or
-              (now - last_logging_time) > rospy.Duration(period)):
-            logging_func(msg)
-            self.last_logging_time_table[caller_id] = now
-
-
-_logging_throttle = LoggingThrottle()
-
-
-def _frame_record_to_caller_id(frame_record):
-    frame, _, lineno, _, code, _ = frame_record
-    caller_id = (
-        inspect.getabsfile(frame),
-        lineno,
-        frame.f_lasti,
-    )
-    return pickle.dumps(caller_id)
-
-
-def logdebug_throttle(period, msg):
-    caller_id = _frame_record_to_caller_id(inspect.stack()[1])
-    _logging_throttle(caller_id, logdebug, period, msg)
-
-
-def loginfo_throttle(period, msg):
-    caller_id = _frame_record_to_caller_id(inspect.stack()[1])
-    _logging_throttle(caller_id, loginfo, period, msg)
-
-
-def logwarn_throttle(period, msg):
-    caller_id = _frame_record_to_caller_id(inspect.stack()[1])
-    _logging_throttle(caller_id, logwarn, period, msg)
-
-
-def logerr_throttle(period, msg):
-    caller_id = _frame_record_to_caller_id(inspect.stack()[1])
-    _logging_throttle(caller_id, logerr, period, msg)
-
-
-def logfatal_throttle(period, msg):
-    caller_id = _frame_record_to_caller_id(inspect.stack()[1])
-    _logging_throttle(caller_id, logfatal, period, msg)
-
+logfatal = partial(_base_logger, logger_level='critical')
+
+
+class LoggingThrottle(object):
+
+    LogEntry = namedtuple("LogEntry", "time digest")
+
+    last_log_entry = {}
+
+    def __call__(self, caller_id, logging_func, period, msg, *args):
+        """Do logging specified message periodically. Messages with different contents will bypass throttling
+
+        - caller_id (str): Id to identify the caller
+        - logging_func (function): Function to do logging.
+        - period (float): Period to do logging in seconds.
+        - msg (object): Message to do logging.
+        """
+        now = rospy.Time.now()
+
+        last = self.last_log_entry.get(caller_id, self.LogEntry(time=None, digest=None))
+        digest = _get_digest(msg, *args)
+
+        if (last.time is None or (now - last.time) > rospy.Duration(period) or digest != last.digest):
+            logging_func(msg, *args)
+            self.last_log_entry[caller_id] = self.LogEntry(time=now, digest=digest)
+
+
+def _get_digest(*args):
+    m = hashlib.md5()
+    for arg in args:
+        m.update(str(args))
+    return m.hexdigest()
+
+
+_logging_throttle = LoggingThrottle()
+
+
+def _frame_record_to_caller_id(frame_record):
+    frame, _, lineno, _, code, _ = frame_record
+    caller_id = (
+        inspect.getabsfile(frame),
+        lineno,
+        frame.f_lasti,
+    )
+    return pickle.dumps(caller_id)
+
+
+def logdebug_throttle(period, msg):
+    logdebug(msg, logger_name=None, logger_throttle=period)
+
+
+def loginfo_throttle(period, msg):
+    loginfo(msg, logger_name=None, logger_throttle=period)
+
+
+def logwarn_throttle(period, msg):
+    logwarn(msg, logger_name=None, logger_throttle=period)
+
+
+def logerr_throttle(period, msg):
+    logerr(msg, logger_name=None, logger_throttle=period)
+
+
+def logfatal_throttle(period, msg):
+    logfatal(msg, logger_name=None, logger_throttle=period)
+
 
 #########################################################
 # CONSTANTS