Merge lp:~lifeless/python-oops-tools/polish into lp:python-oops-tools

[Robert Collins]

Show backtraces in OOPS report timelines.

Update the oops-tools model to show the new backtrace column in OOPS report timelines.

This is a bit crude - I'm making a somewhat horrid table more horrid (by making it wider). It also makes simple queries have a big gap between them.

OTOH there is a bit of a steep curve to get a js library in here due to our preferred tech not being the default in Django. I think we'll have a net benefit from this change without nice JS hiding, and I'm going to investigate JS hiding separately - e.g. Talk to francis about ROI, preferred choice etc etc.

This change can be easily backed out (its about 5 minutes to go from intent to deployed on our oops-tools instance a the moment) if we decide its a problem, so I'd like to get it up there and see.

Most of the changes have test coverage (in that tests broke when the change was made) except the actual template change itself. I've added a smoke test there (that the heading exists, which implies something about the body of the table), but its not truely satisfactory. OTOH I don't know what would be really satisfactory, given we're dealing with a pagetest here.

Thanks for your consideration :)

[Jeroen T. Vermeulen (jtv)]

Is there no HTML test that would covers this at all? I do have a few concerns:

 * Out of interest, any idea how costly it is to record, and later, render tracebacks for every event?

 * What about HTML-escaping? What if the traceback contained a line like:

        123, "</pre>", (a < b))

—wouldn't that upset the rendered HTML? Not likely to be a big problem for us, I suppose, but if we want this code to be reusable…

review: Needs Information

[Jeroen T. Vermeulen (jtv)]

I keep forgetting that <pre> doesn't change tag parsing. Which means that the traceback and all other text items going out are almost certainly escaped just fine.

review: Approve

[Robert Collins (lifeless)]

Thanks for the review. I started a thread about the overheads on launchpad-dev - I measured 0.2seconds for recording, stringifying, and shoving in a list, 1000 tracebacks in a 60 deep stack frame.For a well behaved page with < 100 callouts (SQL, memcache etc) thats an overhead of 20ms, which isn't free, but isn't huge either. For a great page doing 20-30 callouts, thats 4-7ms, totally tolerable. So bad pages may be noticable, on good pages will be fine. This app doesn't do the recording of course; thats done by the oops producer, which doesn't do template rendering - it just puts the capture strings into a bson document if an OOPS is recorded.

On the html/pre side, I'm not a django expert. I'll do a quick manual test to make sure that the django template engine does handle a malicious backtrace.

[Robert Collins (lifeless)]

Django escapes the content in the {{}} so </pre> in a traceback becomes &lt;/pre&gt; etc. All is good.

=== modified file 'src/oopstools/NEWS.txt'
--- src/oopstools/NEWS.txt	2011-11-16 02:22:14 +0000
+++ src/oopstools/NEWS.txt	2011-11-16 08:16:24 +0000
@@ -22,6 +22,11 @@
   a bit better.
   (Robert Collins, William Grant, Roman Yepishev, #885416, #884265)
 
+* Report timelines now include a backtrace for each event, making it easier to
+  determine the origin of the event (e.g. why something is looked up).
+  Timelines without this information will show 'unknown' in the relevant
+  column on the OOPS page. (Robert Collins, #890976)
+
 * The req_vars variable in OOPS reports may now be a dict.
   (Robert Collins, #888866)
 

=== modified file 'src/oopstools/oops/models.py'
--- src/oopstools/oops/models.py	2011-11-16 07:25:56 +0000
+++ src/oopstools/oops/models.py	2011-11-16 08:16:24 +0000
@@ -350,11 +350,11 @@
     # Sanity check/coerce the statements into what we expect.
     # Must be a list:
     if not isinstance(statements, list):
-        statements = [(0, 0, 'badtimeline', str(statements))]
+        statements = [(0, 0, 'badtimeline', str(statements), 'unknown')]
     else:
-        filler = (0, 0, 'unknown', 'unknown')
+        filler = (0, 0, 'unknown', 'unknown', 'unknown')
         for row, action in enumerate(statements):
-            statements[row] = tuple(action[:4]) + filler[len(action):]
+            statements[row] = tuple(action[:5]) + filler[len(action):]
     duration = oops.get('duration')
     if duration is not None:
         total_time = int(duration * 1000)
@@ -388,7 +388,7 @@
         most_expensive_statement = None
     else:
         costs = {}
-        for (start, end, db_id, statement) in statements:
+        for (start, end, db_id, statement, tb) in statements:
             statement = replace_variables(statement)
             cost = end - start
             if statement in costs:
@@ -566,8 +566,8 @@
         #XXX need docstring and test
         if not self.statements:
             return []
-        return [(count+1, start, stop, db_id, stop - start, stmt) for
-                (count, (start, stop, db_id, stmt)) in
+        return [(count+1, start, stop, db_id, stop - start, stmt, tb) for
+                (count, (start, stop, db_id, stmt, tb)) in
                 enumerate(self.statements)]
 
     def repeated_statements(self):
@@ -623,7 +623,7 @@
         if not self.statements:
             return 0
         accumulated_time = 0
-        for (start, stop, db_id, stmt) in self.statements:
+        for (start, stop, db_id, stmt, trace) in self.statements:
             length = stop - start
             accumulated_time += length
         return accumulated_time
@@ -636,13 +636,13 @@
     def _group_queries(self, unsorted_statements):
         """Group SQL log queries.
 
-        unsorted_statements is a list of (start, stop, db_id, statement).
+        unsorted_statements is a list of (start, stop, db_id, statement, tb).
         Return a list of (total_time_ms, count, mean_length, saving, db_id,
         statement).
         """
         sorted_statements = sorted(
             unsorted_statements,
-            key=lambda (start, stop, db_id, statement): statement
+            key=lambda row: row[3]
             )
         groups = []
         def append_to_group(gtime, gcount, db_id, statement):
@@ -653,7 +653,7 @@
 
         group_statement = None
         for row in sorted_statements:
-            start, stop, db_id, statement = row
+            start, stop, db_id, statement, tb = row
             statement = replace_variables(statement)
             length = stop - start
             if statement != group_statement:

=== modified file 'src/oopstools/oops/templates/oops.html'
--- src/oopstools/oops/templates/oops.html	2011-10-13 20:18:51 +0000
+++ src/oopstools/oops/templates/oops.html	2011-11-16 08:16:24 +0000
@@ -168,16 +168,18 @@
          <th>Length</th>
          <th>Database id</th>
          <th>Statement</th>
+         <th>Traceback</th>
        </tr>
      </thead>
      <tbody>
-       {% for num, start, stop, db_id, length, statement in oops.formatted_statements %}
+       {% for num, start, stop, db_id, length, statement, tb in oops.formatted_statements %}
          <tr>
            <td>{{num}}.</td>
            <td>{{start}}</td>
            <td>{{length}}ms</td>
            <td>{{db_id}}</td>
            <td><pre>{{statement|format_sql}}</pre></td>
+           <td><pre>{{tb}}</pre></td>
          </tr>
       {% endfor %}
      </tbody>

=== modified file 'src/oopstools/oops/test/oops.txt'
--- src/oopstools/oops/test/oops.txt	2011-11-02 21:29:36 +0000
+++ src/oopstools/oops/test/oops.txt	2011-11-16 08:16:24 +0000
@@ -263,7 +263,7 @@
 recorded together with the SQL statement.
 
     >>> oops_with_db_id = Oops.objects.get(oopsid__exact="OOPS-1308x1")
-    >>> for start, stop, db_id, statement in oops_with_db_id.statements:
+    >>> for start, stop, db_id, statement, tb in oops_with_db_id.statements:
     ...     print start, stop, db_id, statement
     4 5 session UPDATE SessionData SET last_accessed ...
     6 7 session SELECT key, pickle FROM SessionPkgData WHERE ...

=== modified file 'src/oopstools/oops/test/pagetest.txt'
--- src/oopstools/oops/test/pagetest.txt	2011-11-02 23:26:40 +0000
+++ src/oopstools/oops/test/pagetest.txt	2011-11-16 08:16:24 +0000
@@ -38,7 +38,8 @@
     ...<div id="request_variables">...
     ...
     ...<li>CHANNEL_CREATION_TIME: 1...</li>...
-    ...
+    ...SQL Statement Log...
+    ...Start...Length...Database id...Statement...Traceback...
 
 It also accepts the OOPS id without the "OOPS-" part.
 

=== modified file 'src/oopstools/oops/test/test_dboopsloader.py'
--- src/oopstools/oops/test/test_dboopsloader.py	2011-11-16 02:22:14 +0000
+++ src/oopstools/oops/test/test_dboopsloader.py	2011-11-16 08:16:24 +0000
@@ -196,7 +196,8 @@
             'timeline': 'a'
         }
         oops = parsed_oops_to_model_oops(report, 'bug-890001-1')
-        self.assertEqual([(0, 0, 'badtimeline', 'a')], oops.statements)
+        self.assertEqual(
+            [(0, 0, 'badtimeline', 'a', 'unknown')], oops.statements)
         
     def test_short_timeline_row(self):
         # A timeline row that is short is padded with 'unknown' or 0's.
@@ -211,10 +212,10 @@
         }
         oops = parsed_oops_to_model_oops(report, 'bug-890001-2')
         self.assertEqual([
-            (0, 0, 'unknown', 'unknown'),
-            (1, 0, 'unknown', 'unknown'),
-            (1, 2, 'unknown', 'unknown'),
-            (1, 2, 'foo', 'unknown'),
+            (0, 0, 'unknown', 'unknown', 'unknown'),
+            (1, 0, 'unknown', 'unknown', 'unknown'),
+            (1, 2, 'unknown', 'unknown', 'unknown'),
+            (1, 2, 'foo', 'unknown', 'unknown'),
             ], oops.statements)
 
     def test_long_timeline_row(self):
@@ -222,12 +223,12 @@
         report = {
             'id': 'bug-890001-3',
             'timeline': [
-                (1, 2, 'foo', 'bar', 'baz'),
+                (1, 2, 'foo', 'bar', 'baz', 'quux'),
                 ],
         }
         oops = parsed_oops_to_model_oops(report, 'bug-890001-3')
         self.assertEqual([
-            (1, 2, 'foo', 'bar'),
+            (1, 2, 'foo', 'bar', 'baz'),
             ], oops.statements)
 
     def test_empty_report_long_id_uses_unknown_bug_889982(self):