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

[Gary Poster]

[bug=833972,834466] [r=benji][bug=833972] Fix ++profile++sqltrace for homepage, others

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

[Benji York (benji)]

This branch looks good. Here are a couple of little things:

I would add MemoryError to the (SystemExit, KeyboardInterrupt)
exceptions. Since that tuple is repeated several times you might want
to define a "constant" for it as well.

I don't understand the comment near the end of the diff: "This should
never happen."

review: Approve (code)

[Gary Poster (gary)]

Change made, thanks.

comment: because non-iterating warnings are caught earlier in the pipeline of functions now, the rendering code should not actually encounter this.

=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
--- lib/canonical/launchpad/webapp/adapter.py	2011-08-22 19:06:39 +0000
+++ lib/canonical/launchpad/webapp/adapter.py	2011-08-26 13:16:48 +0000
@@ -661,6 +661,15 @@
         threading.currentThread().lp_last_sql_statement = statement
         request_starttime = getattr(_local, 'request_start_time', None)
         if request_starttime is None:
+            if (sql_trace is not None or
+                self._debug_sql or
+                self._debug_sql_extra):
+                # Stash some information for logging at the end of the
+                # request.
+                connection._lp_statement_info = (
+                    time(),
+                    'SQL-%s' % connection._database.name,
+                    statement_to_log)
             return
         action = get_request_timeline(get_current_browser_request()).start(
             'SQL-%s' % connection._database.name, statement_to_log)
@@ -673,15 +682,27 @@
             # action may be None if the tracer was installed after the
             # statement was submitted.
             action.finish()
-            # Do data reporting for the [start|stop]_sql_traceback_logging
-            # feature, as exposed by ++profile++sqltrace, and/or for stderr,
-            # as exposed by LP_DEBUG_SQL_EXTRA and LP_DEBUG_SQL.
-            sql_trace = getattr(_local, 'sql_trace', None)
-            if sql_trace and sql_trace[-1]['sql'] is None:
-                sql_trace[-1]['sql'] = action.logTuple()
-            if self._debug_sql or self._debug_sql_extra:
-                sys.stderr.write('%d-%d@%s %s\n' % action.logTuple())
-                sys.stderr.write("-" * 70 + "\n")
+        # Do data reporting for the [start|stop]_sql_traceback_logging
+        # feature, as exposed by ++profile++sqltrace, and/or for stderr,
+        # as exposed by LP_DEBUG_SQL_EXTRA and LP_DEBUG_SQL.
+        sql_trace = getattr(_local, 'sql_trace', None)
+        if sql_trace is not None or self._debug_sql or self._debug_sql_extra:
+            data = None
+            if action is not None:
+                data = action.logTuple()
+            else:
+                info = getattr(connection, '_lp_statement_info', None)
+                if info is not None:
+                    start, dbname, statement = info
+                    # Times are in milliseconds, to mirror actions.
+                    duration = int((time() - start) * 1000)
+                    data = (0, duration, dbname, statement)
+            if data is not None:
+                if sql_trace and sql_trace[-1]['sql'] is None:
+                    sql_trace[-1]['sql'] = data
+                if self._debug_sql or self._debug_sql_extra:
+                    sys.stderr.write('%d-%d@%s %s\n' % data)
+                    sys.stderr.write("-" * 70 + "\n")
 
     def connection_raw_execute_error(self, connection, raw_cursor,
                                      statement, params, error):

=== 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-26 13:16:48 +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-26 13:16:48 +0000
@@ -20,6 +20,18 @@
 import traceback
 
 DEBUG_EXCEPTION_FORMATTER = False
+EXPLOSIVE_ERRORS = (SystemExit, MemoryError, KeyboardInterrupt)
+
+
+def _try_except(callable, *args, **kwargs):
+    try:
+        return callable(*args, **kwargs)
+    except EXPLOSIVE_ERRORS:
+        raise
+    except:
+        if DEBUG_EXCEPTION_FORMATTER:
+            traceback.print_exc()
+    # return None
 
 
 def _get_frame(f):
@@ -85,7 +97,7 @@
                     item.append(supp['extra'])  # We do not include a prefix.
             if info:
                 item.append(_fmt(info))
-        except (SystemExit, KeyboardInterrupt):
+        except EXPLOSIVE_ERRORS:
             raise
         except:
             # The values above may not stringify properly, or who knows what
@@ -119,19 +131,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 +147,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 EXPLOSIVE_ERRORS:
+                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 +206,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 +233,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-26 13:16:48 +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