← Back to team overview

launchpad-reviewers team mailing list archive

[Merge] lp:~gary/launchpad/sqlprofiler into lp:launchpad

 

Gary Poster has proposed merging lp:~gary/launchpad/sqlprofiler into lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #832208 in Launchpad itself: "LP_DEBUG_SQL_EXTRA does not give template information in tracebacks"
  https://bugs.launchpad.net/launchpad/+bug/832208
  Bug #832215 in Launchpad itself: "LP_DEBUG_SQL_EXTRA is inconvenient on qastaging"
  https://bugs.launchpad.net/launchpad/+bug/832215

For more details, see:
https://code.launchpad.net/~gary/launchpad/sqlprofiler/+merge/72765

This branch fixes a problem observed in the QA for bug 832215: ++profile++sqltrace would cause Apache to fall over if used on some pages, such as the Launchpad home page.  The problem was that strings need to be rendered immediately.  This branch does that, as well as adding a quick hack to see a traceback if something like this happens again when trying to see a ++profile++ page.

lint is happy.

Tests are there for all of the core stacktrace changes.  I did not add tests for the emergency hatch in ++profile++ traceback rendering, which I added for diagnosis of this problem and left in because it was convenient.

QA: go to https://qastaging.launchpad.net/++profile++sqltrace and actually see that it works.  If it doesn't, I suggest that we still mark the branch qa-ok even as we mark the failure in the bug: this should not affect production.

Thank you
-- 
https://code.launchpad.net/~gary/launchpad/sqlprofiler/+merge/72765
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~gary/launchpad/sqlprofiler into lp:launchpad.
=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py	2011-08-22 19:06:39 +0000
+++ lib/lp/services/profile/profile.py	2011-08-24 17:41:27 +0000
@@ -16,12 +16,13 @@
 import heapq
 import os
 import pstats
+import StringIO
+import sys
 import threading
-import StringIO
 
 from bzrlib import lsprof
 import oops_datedir_repo.serializer_rfc822
-from zope.pagetemplate.pagetemplatefile import PageTemplateFile
+from z3c.pt.pagetemplate import PageTemplateFile
 from zope.app.publication.interfaces import IEndRequestEvent
 from zope.component import (
     adapter,
@@ -29,6 +30,7 @@
     )
 from zope.contenttype.parse import parse
 from zope.error.interfaces import IErrorReportingUtility
+from zope.exceptions.exceptionformatter import format_exception
 from zope.traversing.namespace import view
 
 from canonical.config import config
@@ -344,7 +346,7 @@
         del prof_stats
     trace = None
     if 'sqltrace' in actions:
-        trace = da.stop_sql_traceback_logging()
+        trace = da.stop_sql_traceback_logging() or ()
         # The trace is a list of dicts, each with the keys "sql" and
         # "stack".  "sql" is a tuple of start time, stop time, database
         # name (with a "SQL-" prefix), and sql statement.  "stack" is a
@@ -451,7 +453,14 @@
     if actions and is_html:
         # Hack the new HTML in at the end of the page.
         encoding = content_type_params.get('charset', 'utf-8')
-        added_html = template(**template_context).encode(encoding)
+        try:
+            added_html = template(**template_context).encode(encoding)
+        except (SystemExit, KeyboardInterrupt):
+            raise
+        except:
+            error = ''.join(format_exception(*sys.exc_info(), as_html=True))
+            added_html = (
+                '<div class="profiling_info">' + error + '</div>')
         existing_html = request.response.consumeBody()
         e_start, e_close_body, e_end = existing_html.rpartition(
             '</body>')

=== modified file 'lib/lp/services/stacktrace.py'
--- lib/lp/services/stacktrace.py	2011-08-22 19:06:39 +0000
+++ lib/lp/services/stacktrace.py	2011-08-24 17:41:27 +0000
@@ -22,6 +22,17 @@
 DEBUG_EXCEPTION_FORMATTER = False
 
 
+def _try_except(callable, *args, **kwargs):
+    try:
+        return callable(*args, **kwargs)
+    except (SystemExit, KeyboardInterrupt):
+        raise
+    except:
+        if DEBUG_EXCEPTION_FORMATTER:
+            traceback.print_exc()
+    # return None
+
+
 def _get_frame(f):
     "if the frame is None, make one."
     if f is None:
@@ -119,19 +130,11 @@
 
 def _get_frame_data(f, lineno):
     "Given a frame and a lineno, return data for each item of extract_*."
-    co = f.f_code
-    filename = co.co_filename
-    name = co.co_name
-    linecache.checkcache(filename)
-    line = linecache.getline(filename, lineno, f.f_globals)
-    if line:
-        line = line.strip()
-    else:
-        line = None
     # Adapted from zope.exceptions.
+    try_except = _try_except  # This is a micro-optimization.
     modname = f.f_globals.get('__name__')
     # Output a traceback supplement, if any.
-    supplement = info = None
+    supplement_dict = info = None
     if '__traceback_supplement__' in f.f_locals:
         # Use the supplement defined in the function.
         tbs = f.f_locals['__traceback_supplement__']
@@ -143,42 +146,50 @@
     if tbs is not None:
         factory = tbs[0]
         args = tbs[1:]
-        try:
-            supplement = factory(*args)
-        except (SystemExit, KeyboardInterrupt):
-            raise
-        except:
-            if DEBUG_EXCEPTION_FORMATTER:
-                traceback.print_exc()
-            # else just swallow the exception.
-        else:
+        supplement = try_except(factory, *args)
+        if supplement is not None:
             # It might be nice if supplements could be dicts, for simplicity.
             # Historically, though, they are objects.
-            # We will turn the supplement into a dict, so that we have
-            # "getInfo" pre-processed and so that we are not holding on to
-            # anything from the frame.
+            # We will turn the supplement into a dict of strings, so that we
+            # have "getInfo" pre-processed and so that we are not holding on
+            # to anything from the frame.
             extra = None
             getInfo = getattr(supplement, 'getInfo', None)
             if getInfo is not None:
-                try:
-                    extra = getInfo()
-                except (SystemExit, KeyboardInterrupt):
-                    raise
-                except:
-                    if DEBUG_EXCEPTION_FORMATTER:
-                        traceback.print_exc()
-                    # else just swallow the exception.
-            supplement = dict(
-                # The "_url" suffix is historical.
-                source_url=getattr(supplement, 'source_url', None),
-                line=getattr(supplement, 'line', None),
-                column=getattr(supplement, 'column', None),
-                expression=getattr(supplement, 'expression', None),
-                warnings=getattr(supplement, 'warnings', ()),
-                extra=extra)
+                extra = try_except(getInfo)
+                extra = try_except(str, extra) if extra is not None else None
+            warnings = []
+            # The outer try-except is for the iteration.
+            try:
+                for warning in getattr(supplement, 'warnings', ()):
+                    if warning is not None:
+                        warning = try_except(str, warning)
+                    if warning is not None:
+                        warnings.append(warning)
+            except (SystemExit, KeyboardInterrupt):
+                raise
+            except:
+                if DEBUG_EXCEPTION_FORMATTER:
+                    traceback.print_exc()
+            supplement_dict = dict(warnings=warnings, extra=extra)
+            for key in ('source_url', 'line', 'column', 'expression'):
+                value = getattr(supplement, key, None)
+                if value is not None:
+                    value = try_except(str, value)
+                supplement_dict[key] = value
     info = f.f_locals.get('__traceback_info__', None)
+    info = try_except(str, info) if info is not None else None
     # End part adapted from zope.exceptions.
-    return (filename, lineno, name, line, modname, supplement, info)
+    co = f.f_code
+    filename = co.co_filename
+    name = co.co_name
+    linecache.checkcache(filename)
+    line = linecache.getline(filename, lineno, f.f_globals)
+    if line:
+        line = line.strip()
+    else:
+        line = None
+    return (filename, lineno, name, line, modname, supplement_dict, info)
 
 
 def extract_stack(f=None, limit=None):
@@ -194,8 +205,9 @@
     limit = _get_limit(limit)
     list = []
     n = 0
+    get_frame_data = _get_frame_data  # This is a micro-optimization.
     while f is not None and (limit is None or n < limit):
-        list.append(_get_frame_data(f, f.f_lineno))
+        list.append(get_frame_data(f, f.f_lineno))
         f = f.f_back
         n = n + 1
     list.reverse()
@@ -220,8 +232,9 @@
     limit = _get_limit(limit)
     list = []
     n = 0
+    get_frame_data = _get_frame_data  # This is a micro-optimization.
     while tb is not None and (limit is None or n < limit):
-        list.append(_get_frame_data(tb.tb_frame, tb.tb_lineno))
+        list.append(get_frame_data(tb.tb_frame, tb.tb_lineno))
         tb = tb.tb_next
         n = n + 1
     return list

=== modified file 'lib/lp/services/tests/test_stacktrace.py'
--- lib/lp/services/tests/test_stacktrace.py	2011-08-22 19:06:39 +0000
+++ lib/lp/services/tests/test_stacktrace.py	2011-08-24 17:41:27 +0000
@@ -16,6 +16,8 @@
 # the tests to pass.
 MY_LINE_NUMBER = 17
 
+MY_FILE_NAME = __file__[:__file__.rindex('.py')] + '.py'
+
 
 class Supplement:
     def __init__(self, kwargs):
@@ -35,6 +37,12 @@
     return sys._getframe()
 
 
+class BadString:
+
+    def __str__(self):
+        raise ValueError()
+
+
 class TestStacktrace(TestCase):
 
     layer = BaseLayer
@@ -71,7 +79,7 @@
     def test_get_frame_data_standard(self):
         filename, lineno, name, line, modname, supplement, info = (
             stacktrace._get_frame_data(get_frame(), MY_LINE_NUMBER))
-        self.assertEqual(__file__, filename)
+        self.assertEqual(MY_FILE_NAME, filename)
         self.assertEqual(MY_LINE_NUMBER, lineno)
         self.assertEqual('get_frame', name)
         self.assertStartsWith(line, 'MY_LINE_NUMBER = ')
@@ -91,7 +99,7 @@
                 get_frame(supplement={}), MY_LINE_NUMBER))
         self.assertEqual(
             dict(source_url=None, line=None, column=None, expression=None,
-                 warnings=(), extra=None),
+                 warnings=[], extra=None),
             supplement)
 
     def test_get_frame_data_supplement_and_info(self):
@@ -101,7 +109,7 @@
                 MY_LINE_NUMBER))
         self.assertEqual(
             dict(source_url=None, line=None, column=None, expression=None,
-                 warnings=(), extra=None),
+                 warnings=[], extra=None),
             supplement)
         self.assertEqual('foo bar', info)
 
@@ -119,9 +127,9 @@
                     )),
                 MY_LINE_NUMBER))
         self.assertEqual(
-            dict(source_url='/foo/bar.pt', line=42, column=84,
+            dict(source_url='/foo/bar.pt', line='42', column='84',
                  expression='tal:define="foo view/foo"',
-                 warnings=('watch out', 'pass auf'),
+                 warnings=['watch out', 'pass auf'],
                  extra='read all about it'),
             supplement)
 
@@ -134,7 +142,7 @@
                 MY_LINE_NUMBER))
         self.assertEqual(
             dict(source_url=None, line=None, column=None, expression=None,
-                 warnings=(), extra=None),
+                 warnings=[], extra=None),
             supplement)
 
     def test_get_frame_data_supplement_bad_getInfo_with_traceback(self):
@@ -153,16 +161,47 @@
             stacktrace.DEBUG_EXCEPTION_FORMATTER = False
         self.assertEqual(
             dict(source_url=None, line=None, column=None, expression=None,
-                 warnings=(), extra=None),
+                 warnings=[], extra=None),
             supplement)
         self.assertIn('boo_hiss', stderr.getvalue())
 
+    def test_get_frame_data_broken_str(self):
+        bad = BadString()
+        filename, lineno, name, line, modname, supplement, info = (
+            stacktrace._get_frame_data(
+                get_frame(
+                    supplement=dict(
+                        source_url=bad,
+                        line=bad,
+                        column=bad,
+                        expression=bad,
+                        warnings=('watch out', bad),
+                        getInfo=lambda: bad
+                    ),
+                    info=bad),
+                MY_LINE_NUMBER))
+        self.assertEqual(
+            dict(source_url=None, line=None, column=None,
+                 expression=None, warnings=['watch out'], extra=None),
+            supplement)
+        self.assertIs(None, info)
+
+    def test_get_frame_data_broken_warnings(self):
+        filename, lineno, name, line, modname, supplement, info = (
+            stacktrace._get_frame_data(
+                get_frame(
+                    supplement=dict(
+                        warnings=object()
+                    )),
+                MY_LINE_NUMBER))
+        self.assertEqual([], supplement['warnings'])
+
     def test_extract_stack(self):
         extracted = stacktrace.extract_stack(get_frame())
         self.assertTrue(len(extracted) > 1)
         filename, lineno, name, line, modname, supplement, info = (
             extracted[-1])
-        self.assertEqual(__file__, filename)
+        self.assertEqual(MY_FILE_NAME, filename)
         self.assertIsInstance(lineno, int)
         self.assertEqual('get_frame', name)
         self.assertEqual('return sys._getframe()', line)
@@ -179,7 +218,7 @@
         self.assertEqual(1, len(extracted))
         filename, lineno, name, line, modname, supplement, info = (
             extracted[0])
-        self.assertEqual(__file__, filename)
+        self.assertEqual(MY_FILE_NAME, filename)
         self.assertIsInstance(lineno, int)
         self.assertEqual('test_extract_tb', name)
         self.assertEqual('raise ValueError()', line)
@@ -195,7 +234,7 @@
             self.assertEndsWith(line, '\n')
         line = formatted[-1].split('\n')
         self.assertStartsWith(
-            line[0], '  File "' + __file__ + '", line ')
+            line[0], '  File "' + MY_FILE_NAME + '", line ')
         self.assertEndsWith(line[0], ', in get_frame')
         self.assertEqual('    return sys._getframe()', line[1])
 
@@ -218,7 +257,7 @@
             self.assertEndsWith(line, '\n')
         line = formatted[-1].split('\n')
         self.assertStartsWith(
-            line[0], '  File "' + __file__ + '", line ')
+            line[0], '  File "' + MY_FILE_NAME + '", line ')
         self.assertEndsWith(line[0], ', in get_frame')
         self.assertEqual('    return sys._getframe()', line[1])
         self.assertEqual('   - /foo/bar.pt', line[2])
@@ -234,13 +273,8 @@
         self.assertEqual('   - I am the Walrus', line[8])
 
     def test_format_list_extra_errors(self):
-        extracted = stacktrace.extract_stack(
-            get_frame(
-                supplement=dict(
-                    # This will cause an error because it is not iterable.
-                    warnings=object()
-                ))
-            )
+        extracted = stacktrace.extract_stack(get_frame(supplement=dict()))
+        extracted[-1][-2]['warnings'] = object()  # This should never happen.
         stderr = sys.stderr = StringIO.StringIO()
         self.assertFalse(stacktrace.DEBUG_EXCEPTION_FORMATTER)
         stacktrace.DEBUG_EXCEPTION_FORMATTER = True