Merge lp:~pconnell/entrails/sextant into lp:entrails

[Phil Connell]

Various changes made while getting entrails working with sextant.

Main externally-visible change is that entrails makes a slightly better effort to find the names of classes corresponding to method calls (i.e. get qualnames rather than just function names).

Some bits of internal cleanup too: have a properly structured 'Event' object rather than the weird sort-of-an-obj-sort-of-a-dumb-container Frame (that wasn't a frame).

Various changes made while getting entrails working with sextant.

Main externally-visible change is that entrails makes a slightly better effort to find the names of classes corresponding to method calls (i.e. get qualnames rather than just function names).

Some bits of internal cleanup too: have a properly structured 'Event' object rather than the weird sort-of-an-obj-sort-of-a-dumb-container Frame (that wasn't a frame).

[Martin Morrison (isoschiz)]

EnTrails could really do with some UT to make me more confident that you hadn't missed any of the name changes... There are at least a couple inline that look wrong, but I've not read every line carefully to be sure there aren't others.

review: Needs Fixing

[Phil Connell (pconnell)]

> EnTrails could really do with some UT to make me more confident that you
> hadn't missed any of the name changes... There are at least a couple inline
> that look wrong, but I've not read every line carefully to be sure there
> aren't others.

Completely agree on the UT front, but I'm not especially concerned about this right now:
 - I'm pretty sure nobody uses any of this stuff.
 - Outputting to sextant is likely to supercede the existing output formats for all practical purposes, and I think the most risk is to the outputs.

As it happens, after taking another look I'm pretty convinced that the HTMLOutput stuff was already not working...

[ChrisD (gingerchris)]

Ideal

[ChrisD (gingerchris)]

review: Approve

=== modified file 'src/entrails/_filter.py'
--- src/entrails/_filter.py	2014-07-10 18:08:27 +0000
+++ src/entrails/_filter.py	2014-09-03 20:05:48 +0000
@@ -36,9 +36,9 @@
     """
     matches = ("/usr/lib", "/usr/local/lib", "/usr/lib64", "/twisted", "/zope")
 
-    def filter(self, frameobject):
+    def filter(self, event):
         for m in self.matches:
-            if m in frameobject['co_filename']:
+            if m in event.code.co_filename:
                 return False
         return True
 
@@ -54,8 +54,7 @@
             "_utils",
         ))
 
-    def filter(self, frameobject):
-        filename = frameobject["co_filename"]
-        return not any(filename.endswith(module)
-                       for module in self.modules)
+    def filter(self, event):
+        filename = event.code.co_filename
+        return not any(filename.endswith(module) for module in self.modules)
 

=== modified file 'src/entrails/_output.py'
--- src/entrails/_output.py	2014-07-07 12:48:49 +0000
+++ src/entrails/_output.py	2014-09-03 20:05:48 +0000
@@ -36,14 +36,25 @@
     def __init__(self):
         pass
     def close(self):
-        pass
-    def enter(self, o):
-        pass
-    def exit(self, o):
-        pass
-    def exception(self, o):
+        """Invoked when no further tracing data is to be output."""
+        pass
+    def enter(self, event):
+        """Invoked with an entrails event, when a function is called."""
+        pass
+    def exit(self, event):
+        """Invoked with an entrails event, when a function returns."""
+        pass
+    def exception(self, event):
+        """
+        Invoked with an entrails event, when an exception is raised.
+
+        As an exception propagates up the call stack, this method is called for
+        every frame in which the exception is raised.
+
+        """
         pass
     def logging(self, o, event_type_string):
+        #@@@ not used?
         pass
 
 
@@ -76,15 +87,15 @@
         return "Call " + o.short_call_string()
 
     def _default_exit_func(self, o):
-        return "Return from {0} with value {1}".format(o["co_name"],
+        return "Return from {0} with value {1}".format(o.code.co_name,
                                                        o.short_return_value())
 
     def _default_exception_func(self, o):
         return "Encountered exception" #@@@ more info TODO
 
     def _default_prefix_func(self, o):
-        return ("[%s][%03d:%s]" + "  "*self.depth) % (o["label"],
-                                                      o["f_lineno"],
+        return ("[%s][%03d:%s]" + "  "*self.depth) % (o.label,
+                                                      o.frame.f_lineno,
                                                       _utils.pretty_resize_string(o.nice_filename(), 15, exact=True))
 
     def enter(self, o):
@@ -103,7 +114,7 @@
 
     def logging(self, o, event_type_string):
         self.safe_write("ERROR TRACING with event: %s on line %d in %s\n" % (
-                event_type_string, o["f_lineno"], o["co_filename"]))
+                event_type_string, o.frame.f_lineno, o.code.co_filename))
         return None
 
 
@@ -160,17 +171,17 @@
         return None
 
     def exception(self, o):
-        print("EXCEPTION on line {0} in {1}".format(o["f_lineno"],
-                                                    o["co_filename"]))
+        print("EXCEPTION on line {0} in {1}".format(o.frame.f_lineno,
+                                                    o.code.co_filename))
         for k, v in o.items():
           print(k + ": " + str(v))
         return None
 
     def logging(self, o, event_type_string):
-        print("ERROR TRACING with event: {0} on line {1} in {2}".format(event_type_string,
-                                                                        o["f_lineno"],
-                                                                        o["co_filename"]))
-        return None
+        print("ERROR TRACING with event: {0} on line {1} in {2}".format(
+                event_type_string,
+                o.frame.f_lineno,
+                o.code.co_filename))
 
 
 class HTMLOutput(EntrailsOutput):
@@ -186,14 +197,18 @@
         self.f.write("\n</body></html>\n")
         self.f.close()
 
-    def enter(self, codeframe):
+    def enter(self, event):
         self.depth += 1
-        self.f.write(" > "*self.depth + "<b>Now entering:</b> " + codeframe["name"] + "<br />\n")
+        self.f.write(" > " * self.depth +
+                     "<b>Now entering:</b> " +
+                     event.code.co_name + "<br />\n")
         return None
 
-    def exit(self, codeframe):
+    def exit(self, event):
         self.depth -= 1
-        self.f.write(" > "*(self.depth+1) + "<b>and exiting:</b> " + codeframe["name"] + " with return value " + str(codeframe["return_value"]) + "<br />\n")
+        self.f.write(" > " * (self.depth + 1) + "<b>and exiting:</b> " +
+                     event.code.co_name + " with return value " +
+                     str(event.return_value) + "<br />\n")
         return None
 
     def exception(self, o):
@@ -216,10 +231,22 @@
 
     def write_out(self, codeframe, event_type):
         event = ET.SubElement(self.root, "event")
-        event.attrib = {"timestamp" : "{0:f}".format(codeframe["timestamp"])}
-        for k, v in codeframe.items():
-            if k != "timestamp":
-                ET.SubElement(event, k).text = str(v)
+        event.attrib = {"timestamp" : "{0:f}".format(codeframe.timestamp)}
+        info = {
+            "label": codeframe.label,
+            "f_lineno": codeframe.frame.f_lineno,
+            "f_back": codeframe.frame.f_back,
+            "f_locals": codeframe.frame.f_locals,
+            "co_name": codeframe.code.co_name,
+            "co_argcount": codeframe.code.co_argcount,
+            "co_filename": codeframe.code.co_filename,
+            "co_names": codeframe.code.co_names,
+            "co_varnames": codeframe.code.co_varnames,
+        }
+        if codeframe.return_value is not None:
+            info["return_value"] = codeframe.return_value
+        for k, v in info.items():
+            ET.SubElement(event, k).text = str(v)
         ET.SubElement(event, "type").text = event_type
         ET.SubElement(event, "call_string").text = codeframe.call_string()
         ET.SubElement(event, "short_call_string").text = codeframe.short_call_string()

=== modified file 'src/entrails/_trace.py'
--- src/entrails/_trace.py	2014-07-07 12:48:49 +0000
+++ src/entrails/_trace.py	2014-09-03 20:05:48 +0000
@@ -12,6 +12,7 @@
 
 __all__ = (
     "Entrails",
+    "Event",
 )
 
 
@@ -19,29 +20,85 @@
 import os.path
 import sys
 import time
+import types
 
 from . import _filter
 from . import _utils
 
 
-class _Frame(dict):
-    """
-    Holds information about a frame.
-
-    Use as a dict to access the important bits of the frame and arg
-    parameters, along with timestamp and label.  Also has convienience
-    methods to generate function call string and class info.  This is
-    supplied to an output adapter's call(), return() and exception()
-    methods.
-    """
+class Event(object):
+    """
+    Holds information about a traced event.
+
+    Attributes:
+        arg: Additional argument passed to the sys.settrace-installed function.
+        code: Code object being executed.
+        frame: Frame object for the executing code.
+        label: String passed when event was created.
+        return_value: For function exit events the value returned, otherwise
+        None.
+        timestamp: Time, in seconds relative to initialisation, at which the
+        event occurred.
+
+    Instances are supplied to an output adapter's call(), return() and
+    exception() methods.
+
+    """
+
+    def __init__(self, frame, event, arg,
+                 label, timestamp):
+        """
+        Initialise this event.
+
+        frame:
+            Frame object passed to trace function.
+        event:
+            Event string passed to trace function.
+        arg:
+            Final argument passed to trace function.
+        label:
+            String identifying the context for the event.
+        timestamp:
+            Time, in seconds relative to initialisation, at which the event
+            occurred.
+
+        """
+        self.arg = arg
+        self.code = frame.f_code
+        self.frame = frame
+        self.label = label
+        self.timestamp = timestamp
+
+        self.return_value = (arg if event == "return" else None)
+
+    def basename(self):
+        """Returns the name of the function for this event's frame."""
+        cls, method = self._retrieve_cls_method()
+        if method is not None:
+            try:
+                name = method.__qualname__
+            except AttributeError:
+                # Old version, < 3.3.
+                name = "{}.{}".format(cls.__name__, method.__name__)
+        else:
+            name = self.frame.f_code.co_name
+
+        return name
+
+    def qualname(self):
+        """Returns the fully-qualified function name for this event's frame."""
+        return "{}.{}".format(self.frame.f_globals["__name__"],
+                              self.basename())
+
     def parameters(self):
         """
         Returns dict of form {parameter_name: argument_value}.
         """
         # We rely on CPython putting arguments at start of f_locals (in reverse
         #   order for some reason...).  This is undocumented, but consistent.
-        parameters = [(k, v) for k, v in self["f_locals"].items()
-                    if k in self["co_varnames"][0:self["co_argcount"]]]
+        parameters = [(k, v)
+                      for k, v in self.frame.f_locals.items()
+                      if k in self.code.co_varnames[0:self.code.co_argcount]]
         parameters.reverse()
         return collections.OrderedDict(parameters)
 
@@ -79,14 +136,13 @@
 
         Only designed for 'call' event (i.e. function entry)
         """
+        output = '{}({})'.format(self.qualname(),
+                                 ', '.join(self.string_arguments()))
         if self.is_method():
-            return '{0}.{1}({2})'.format(self.instance_name(), self['co_name'],
-                                         ', '.join(self.string_arguments()))
-        else:
-            return '{0}({1})'.format(self['co_name'],
-                                     ', '.join(self.string_arguments()))
+            output += ' on instance {}'.format(self.instance_name())
+        return output
 
-    def short_call_string(self, length=40):
+    def short_call_string(self, length=80):
         """
         Returns a pretty string of the function call, shortened to at
           most length characters.
@@ -95,7 +151,7 @@
         """
         return _utils.pretty_resize_string(self.call_string(), length)
 
-    def short_return_value(self, length=40):
+    def short_return_value(self, length=80):
         """
         Returns a pretty string representation of the return value,
           shortened to at most length characters.
@@ -103,7 +159,7 @@
         Only designed for 'call' event (i.e. function entry)
         """
         try:
-            return _utils.pretty_resize_string(repr(self['return_value']), length)
+            return _utils.pretty_resize_string(repr(self.return_value), length)
         except:
             return _utils.pretty_resize_string('<repr error>', length)
 
@@ -120,7 +176,7 @@
         """
         Nice filename, without directory segment.
         """
-        return os.path.basename(self["co_filename"])
+        return os.path.basename(self.code.co_filename)
 
     def is_method(self):
         """
@@ -131,7 +187,7 @@
 
         TODO: What happens for class methods/other decorated methods?
         """
-        if self['co_varnames'] and self['co_varnames'][0] == 'self':
+        if self.code.co_varnames and self.code.co_varnames[0] == 'self':
             return True
         return False
 
@@ -141,9 +197,12 @@
         Only designed for 'call' event (i.e. function entry)
         We cache value after first proper lookup.
         """
-        if 'instance_name' not in self:
-            self['instance_name'] = self._retrieve_instance_name()
-        return self['instance_name']
+        try:
+            name = self._instance_name
+        except AttributeError:
+            name = self._retrieve_instance_name()
+            self._instance_name = name
+        return name
 
     def _retrieve_instance_name(self):
         """
@@ -153,22 +212,59 @@
         try:
             # This is confusing.  We go into the previous (parent) frame and
             #   find the local variable name in that pointing to a our class.
-            for k, v in list(self['f_back'].f_locals.items()):
-                if v == self['f_locals']['self']:
+            for k, v in list(self.frame.f_back.f_locals.items()):
+                if v == self.frame.f_locals['self']:
                     return k
         except:
             return '<lookup error>'
 
-    def class_name(self):
-        """
-        Class name of method, or empty string if not method.
-        Only designed for 'call' event (i.e. function entry)
-        Should only be called on methods.
-        """
-        try:
-            return self["f_locals"]["self"].__class__.__name__
-        except:
-            return '<lookup error>'
+    def method(self):
+        """
+        Attempt to find the method corresponding to this event, if any.
+
+        On success, returns the function found. If the frame doesn't look like
+        it corresponds to a method, `None` is returned.
+
+        """
+        return self._retrieve_cls_method()[1]
+
+    def _retrieve_cls_method(self):
+        """
+        Attempt to find the method and class corresponding to this event.
+
+        On success returns a class, method tuple, where the method is an
+        attribute on the class returned (helpful for <3.3 where __qualname__
+        isn't available).
+
+        If the event doesn't look like it corresponds to a method, returns
+        None, None.
+
+        """
+        if not self.code.co_varnames or self.code.co_varnames[0] != "self":
+            return None, None
+
+        meth_self = self.frame.f_locals["self"]
+        meth_name = self.code.co_name
+        is_unbound_method = False
+
+        # Alternative approaches:
+        #   - Source code parsing via inspect.
+        #   - gc.get_referrers
+        #   - ?
+        #
+        # GC is plausible (but won't scale very well with number of objects).
+
+        for cls in type(meth_self).mro():
+            try:
+                candidate = getattr(cls, meth_name)
+            except AttributeError:
+                continue
+
+            if callable(candidate):
+                return cls, candidate
+
+        else:
+            return None, None
 
 
 class Entrails(object):
@@ -184,7 +280,9 @@
 
     def __init__(self,
                  label='<untitled>',
-                 filters=(_filter.LibraryFilter(), _filter.SelfFilter())):
+                 filters=None):
+        if filters is None:
+            filters = (_filter.LibraryFilter(), _filter.SelfFilter())
         self._outputs = []
         self._init_time = time.time()
         self._label = label
@@ -198,19 +296,10 @@
             return True
         return False
 
-    def _trace_function(self, trace, event, arg):
-        # Build Frame
-        obj = _Frame()
-        obj["label"] = self._label
-        obj["timestamp"] = time.time() - self._init_time
-        obj["f_lineno"] = trace.f_lineno
-        obj["f_back"] = trace.f_back
-        obj["f_locals"] = trace.f_locals
-        obj["co_name"] = trace.f_code.co_name
-        obj["co_argcount"] = trace.f_code.co_argcount
-        obj["co_filename"] = trace.f_code.co_filename
-        obj["co_names"] = trace.f_code.co_names
-        obj["co_varnames"] = trace.f_code.co_varnames
+    def _trace_function(self, frame, event, arg):
+        obj = Event(frame, event, arg,
+                    self._label,
+                    time.time() - self._init_time)
 
         # Filter
         # If this object is to be discarded, return trace_function to
@@ -218,11 +307,6 @@
         if not self.filter(obj):
             return self._trace_function
 
-        # Possibly add return_value.  If event is non-return, arg isn't really
-        #   that useful.
-        if event is 'return':
-            obj["return_value"] = arg
-
         if event in self.event_names:
             for output in self._outputs:
                 #try:

=== modified file 'src/trace.py'
--- src/trace.py	2014-07-07 12:48:49 +0000
+++ src/trace.py	2014-09-03 20:05:48 +0000
@@ -47,7 +47,7 @@
     first=True
     for line in fileinput.input(filename, inplace=1, backup=".backup"):
         if first and line.startswith("#!/"):
-            print(line, end=' ')
+            print(line, end='')
             continue
         if first:
             print(MARKER)
@@ -61,7 +61,7 @@
             print("_entrails_t.start_trace()")
             print(ENDMARKER)
             first = False
-        print(line, end=' ')
+        print(line, end='')
     fileinput.close()
 
 
@@ -131,7 +131,7 @@
             if line.startswith(MARKER):
                 extra = True
             if not extra:
-                print(line, end=' ')
+                print(line, end='')
             if line.startswith(ENDMARKER):
                 extra = False
         fileinput.close()