add trace decorator for logging function execution (silbe) #1089

1 files changed, 82 insertions, 6 deletions

diff --git a/src/sugar/logger.py b/src/sugar/logger.py
index feef692..8280f8b 100644
--- a/src/sugar/logger.py
+++ b/src/sugar/logger.py
@@ -20,14 +20,22 @@
 STABLE.
 """
 
+import array
+import collections
 import errno
+import logging
 import sys
 import os
-import logging
+import repr as repr_
+import decorator
 
-# Let's keep this self contained so that it can be easily
+# Let's keep this module self contained so that it can be easily
 # pasted in external sugar service like the datastore.
 
+# traces function calls, use SUGAR_LOGGER_LEVEL=trace to enable
+TRACE = 5
+logging.addLevelName(TRACE, 'TRACE')
+
 def get_logs_dir():
     profile = os.environ.get('SUGAR_PROFILE', 'default')
     logs_dir = os.environ.get('SUGAR_LOGS_DIR',
@@ -38,7 +46,10 @@ def get_logs_dir():
 _LEVELS = { 'error'   : logging.ERROR,
             'warning' : logging.WARNING,
             'debug'   : logging.DEBUG,
-            'info'    : logging.INFO }
+            'info'    : logging.INFO,
+            'trace'   : TRACE,
+            'all'     : 0,
+}
 def set_level(level):
     if level in _LEVELS:
         logging.getLogger('').setLevel(_LEVELS[level])
@@ -48,7 +59,6 @@ def set_level(level):
         logging.getLogger('').setLevel(int(level))
     except ValueError:
         logging.warning('Invalid log level: %r' % level)
-        pass
 
 
 # pylint: disable-msg=E1101,F0401
@@ -62,13 +72,13 @@ def _except_hook(exctype, value, traceback):
         sys.excepthook = sys.__excepthook__
 
     sys.excepthook(exctype, value, traceback)
-        
+
 def start(log_filename=None):
     # remove existing handlers, or logging.basicConfig() won't have no effect.
     root_logger = logging.getLogger('')
     for handler in root_logger.handlers:
         root_logger.removeHandler(handler)
-    
+
     class SafeLogWrapper(object):
         """Small file-like wrapper to gracefully handle ENOSPC errors when
         logging."""
@@ -117,3 +127,69 @@ def start(log_filename=None):
 
     sys.excepthook = _except_hook
 
+
+class TraceRepr(repr_.Repr):
+
+    # better handling of subclasses of basic types, e.g. for DBus
+    _TYPES = [int, long, bool, tuple, list, array.array, set, frozenset,
+        collections.deque, dict, str]
+    def repr1(self, x, level):
+        for t in self._TYPES:
+            if isinstance(x, t):
+                return getattr(self, 'repr_'+t.__name__)(x, level)
+
+        return repr_.Repr.repr1(self, x, level)
+
+    def repr_int(self, x, level):
+        return repr(x)
+
+    def repr_bool(self, x, level):
+        return repr(x)
+
+
+def trace(logger=None, logger_name=None, skip_args=None, skip_kwargs=None,
+    maxsize_list=30, maxsize_dict=30, maxsize_string=300):
+
+    if skip_args is None:
+        skip_args = []
+
+    if skip_kwargs is None:
+        skip_kwargs = []
+
+    # size-limit repr()
+    trace_repr = TraceRepr()
+    trace_repr.maxlist = maxsize_list
+    trace_repr.maxdict = maxsize_dict
+    trace_repr.maxstring = maxsize_string
+    trace_repr.maxother = maxsize_string
+    trace_logger = logger or logging.getLogger(logger_name)
+
+    def _trace(f, *args, **kwargs):
+        # don't do expensive formatting if loglevel TRACE is not enabled
+        enabled = trace_logger.isEnabledFor(TRACE)
+        logging.debug('logger.trace: mec %r' % enabled)
+        if enabled:
+            params_formatted = ", ".join(
+                [trace_repr.repr(a)
+                    for (idx, a) in enumerate(args) if idx not in skip_args] + \
+                ['%s=%s' % (k,trace_repr.repr(v))
+                    for (k,v) in kwargs.items() if k not in skip_kwargs])
+
+            trace_logger.log(TRACE, "%s(%s) invoked", f.__name__,
+                params_formatted)
+
+        try:
+            res = f(*args, **kwargs)
+        except:
+            trace_logger.exception("Exception occured in %s", f.__name__)
+            raise
+
+        if enabled:
+            trace_logger.log(TRACE, "%s(%s) returned %s", f.__name__,
+                params_formatted, trace_repr.repr(res))
+
+        return res
+
+    return decorator.decorator(_trace)
+
+