Add source code context information to debug logs

The log.debug() function helpfully adds the name of the function
invoking it but in a complicated software package there are many
functions/methods which share the same name. Thus a debug message
like this:

DEBUG(__init__): xxx

does not give you much context, there are probably hundreds of
__init__ methods. It would help to qualify the method name which it's
class name, that gives a lot more context when reading the
log. Sometimes it's also helpful to know the file and line number.

This patch adds the class name to the function and included the
filename and line number as well. The file path is trimmed to the last
3 components, sufficient to give context but not too verbose. Now the
debug message might look like this instead:

DEBUG(ipsilon/providers/common.py:129 LoadProviders.__init__()): xxx

Also included is a config option 'stacktrace_on_error' which will
include a stacktrace when the log.error function is called. It can be
very useful to see a stacktrace when logging an error, it defaults to
off.

Signed-off-by: John Dennis <jdennis@redhat.com>
Reviewed-by: Simo Sorce <simo@redhat.com>

1 files changed, 64 insertions, 3 deletions

diff --git a/ipsilon/util/log.py b/ipsilon/util/log.py
index a010b16..857a5ba 100644
--- a/ipsilon/util/log.py
+++ b/ipsilon/util/log.py
@@ -3,8 +3,10 @@
 # See the file named COPYING for the project license
 
 import cherrypy
-import inspect
 import cStringIO
+import inspect
+import os
+import traceback
 
 def log_request_response():
     '''Log the contents of the request and subsequent response.
@@ -246,10 +248,67 @@ cherrypy.tools.log_request_response = cherrypy.Tool('on_end_resource', log_reque
 
 class Log(object):
 
+    @staticmethod
+    def stacktrace():
+        buf = cStringIO.StringIO()
+
+        stack = traceback.extract_stack()
+        traceback.print_list(stack[:-2], file=buf)
+
+        stacktrace_string = buf.getvalue()
+        buf.close()
+        return stacktrace_string
+
+    @staticmethod
+    def get_class_from_frame(frame_obj):
+        '''
+        Taken from:
+        http://stackoverflow.com/questions/2203424/
+        python-how-to-retrieve-class-information-from-a-frame-object
+
+        At the frame object level, there does not seem to be any way
+        to find the actual python function object that has been
+        called.
+
+        However, if your code relies on the common convention of naming
+        the instance parameter of a method self, then you could do this.
+        '''
+
+        args, _, _, value_dict = inspect.getargvalues(frame_obj)
+        # Is the functions first parameter named 'self'?
+        if len(args) and args[0] == 'self':
+        # in that case, 'self' will be referenced in value_dict
+            instance = value_dict.get('self', None)
+            if instance:
+                # return its class
+                return getattr(instance, '__class__', None)
+        # return None otherwise
+        return None
+
+    @staticmethod
+    def call_location():
+        frame = inspect.stack()[2]
+        frame_obj = frame[0]
+        filename = frame[1]
+        line_number = frame[2]
+        func = frame[3]
+
+        # Only report the last 3 components of the path
+        filename = os.sep.join(filename.split(os.sep)[-3:])
+
+        cls = Log.get_class_from_frame(frame_obj)
+        if cls:
+            location = '%s:%s %s.%s()' %  \
+                       (filename, line_number, cls.__name__, func)
+        else:
+            location = '%s:%s %s()' % (filename, line_number, func)
+        return location
+
+
     def debug(self, fact):
         if cherrypy.config.get('debug', False):
-            s = inspect.stack()
-            cherrypy.log('DEBUG(%s): %s' % (s[1][3], fact))
+            location = Log.call_location()
+            cherrypy.log('DEBUG(%s): %s' % (location, fact))
 
     # for compatibility with existing code
     _debug = debug
@@ -259,3 +318,5 @@ class Log(object):
 
     def error(self, fact):
         cherrypy.log.error('ERROR: %s' % fact)
+        if cherrypy.config.get('stacktrace_on_error', False):
+            cherrypy.log.error(Log.stacktrace())