logging improvements and fix

Reduced length of tracing messages written to log by rendering just the
first item of list, dict or set instead of whole argument. This will
also improve execution time when running in debug mode.

Fixed logging decorator of software job manager which previously
rendered informations from uninteresting frame.

2 files changed, 42 insertions, 17 deletions

diff --git a/src/python/lmi/providers/cmpi_logging.py b/src/python/lmi/providers/cmpi_logging.py
index 1eb9e3a..ca24601 100644
--- a/src/python/lmi/providers/cmpi_logging.py
+++ b/src/python/lmi/providers/cmpi_logging.py
@@ -184,6 +184,41 @@ class CMPILogger(logging.getLoggerClass()):
 
 logging.setLoggerClass(CMPILogger)
 
+def render_value(val):
+    """
+    When logging values, we want to avoid excessively long messages caused
+    by rendering argument values like lists, dictionaries etc.
+    Let's shorten these iterable objects to just one or few items.
+
+    :param val: Any value for rendering.
+    :returns: Representation string of value, possibly shortened.
+    :rtype: string
+    """
+    if isinstance(val, list):
+        if len(val) < 2:
+            return repr(val)
+        else:
+            return "[%s, ... (%d more items)]" % (
+                    render_value(val[0]), len(val) - 1)
+    elif isinstance(val, dict):
+        if len(val) < 2:
+            return repr(val)
+        else:
+            key = next(iter(val))
+            return '{%s: %s, ... (%d more items)}' % (
+                    render_value(key), render_value(val[key]), len(val) - 1)
+    elif isinstance(val, set):
+        if len(val) < 2:
+            return repr(val)
+        else:
+            return '{%s, ... (%d more items)}' % (
+                    render_value(val[0]), len(val) - 1)
+    elif isinstance(val, tuple):
+        return "(%s%s)" % (
+                ", ".join(render_value(i) for i in val),
+                ", " if len(val) < 2 else '')
+    return repr(val)
+
 def trace_function_or_method(is_method=False, frame_level=1):
     """
     Factory for function and method decorators. Generated decorators
@@ -211,18 +246,6 @@ def trace_function_or_method(is_method=False, frame_level=1):
         if not inspect.ismethod(func) and not inspect.isfunction(func):
             raise TypeError("func must be a function")
 
-        def _print_value(val):
-            """
-            Used here for printing function arguments. Shortens the output
-            string, if that would be too long.
-            """
-            if isinstance(val, list):
-                if len(val) < 2:
-                    return str(val)
-                else:
-                    return "[%s, ...]" % _print_value(val[0])
-            return str(val)
-
         module = func.__module__.split('.')[-1]
         frm = inspect.currentframe()
         for _ in range(frame_level):
@@ -250,8 +273,8 @@ def trace_function_or_method(is_method=False, frame_level=1):
                     "lineno" : lineno,
                     "action" : "entering",
                     "args"   : ", ".join(chain(
-                                (_print_value(a) for a in args),
-                                (   "%s=%s"%(k, _print_value(v))
+                                (render_value(a) for a in args),
+                                (   "%s=%s"%(k, render_value(v))
                                 for k, v in kwargs.items())))
                 })
 
diff --git a/src/software/lmi/software/yumdb/jobmanager.py b/src/software/lmi/software/yumdb/jobmanager.py
index 6b0b854..1b986bd 100644
--- a/src/software/lmi/software/yumdb/jobmanager.py
+++ b/src/software/lmi/software/yumdb/jobmanager.py
@@ -69,7 +69,7 @@ def job_handler(job_from_target=True):
         it an instance of YumJob. The method is then called with "job" argument
         instead of "target".
         """
-        logged = cmpi_logging.trace_method(method)
+        logged = cmpi_logging.trace_method(method, frame_level=2)
 
         def _new_func(self, *args, **kwargs):
             """Wrapper around method."""
@@ -294,7 +294,8 @@ class JobManager(threading.Thread):
                 LOG.exception("control job %s failed", job)
             job.finish(result, data)
             LOG.debug("sending reply for %s: (%s, %s)", job,
-                    job.ResultNames[job.result], job.result_data)
+                    job.ResultNames[job.result],
+                    cmpi_logging.render_value(job.result_data))
             self._queue_out.put(job)
         else:
             if job is None:
@@ -508,7 +509,8 @@ class JobManager(threading.Thread):
                 ind.send(True)
             else:
                 LOG.debug("sending reply for %s: (%s, %s)", job,
-                        job.ResultNames[job.result], job.result_data)
+                        job.ResultNames[job.result],
+                        cmpi_logging.render_value(job.result_data))
                 self._queue_out.put(job)
             return job