From ef1d7941a84f9d5d7604ac98a9b85e65a6707843 Mon Sep 17 00:00:00 2001 From: Mike Purvis Date: Tue, 7 Feb 2017 11:09:36 -0500 Subject: [PATCH] Add named loggers to rospy (#948) --- clients/rospy/src/rospy/core.py | 181 +++++++++++++++++++------------- 1 file changed, 110 insertions(+), 71 deletions(-) diff --git a/clients/rospy/src/rospy/core.py b/clients/rospy/src/rospy/core.py index 39689ea5ee..ae47f637c3 100644 --- a/clients/rospy/src/rospy/core.py +++ b/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 @@ -68,6 +69,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") @@ -139,78 +142,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