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

[Gary Poster]

[r=jcsackett][bug=838869] Add tests for Launchpad SQL logger; add a more surgical SQL logger for outside of a request than what we had before; and add the ability to conditionally request tracebacks in the SQL logger.

This branch does three things.

- It adds a helper for tracking queries piecemeal in tests and make harness, SQLLogger. This is different than the QueryCollector in lib/lp/testing/_webservice.py because it does not require a browser request to work. I use this in a branch stacked on this one, https://code.launchpad.net/~gary/launchpad/bug811447 , to check queries generated from a piece of model code.

- It adds the ability to conditionally collect stacktraces, and renames the associated function from `start_sql_traceback_logging` to `start_sql_logging`. I use this in a branch stacked on this one, https://code.launchpad.net/~gary/launchpad/bug838878 , to support ++profile++sqltrace conditionally generating stacktraces.

- It adds tests for the logger, which had not existed at all as far as I could find. I include tests for the functionality I added as well as existing functionality. This is bug 838869.

Lint is happy.

Reasonable QA will be to go to https://qastaging.launchpad.net/++profile++sqltrace and make sure it still generates a sql trace analysis; and run `make run LP_DEBUG_SQL=1` on a dev machine to make sure it still produces SQL.

Thank you.

[j.c.sackett (jcsackett)]

Gary, this looks good.

review: Approve

[Robert Collins (lifeless)]

There was/is a non browser query collector in testing/. This may be
duplicative.

On 3/09/2011 4:34 AM, <email address hidden> wrote:

The proposal to merge lp:~gary/launchpad/bug838869 into lp:launchpad has
been updated.

   Status: Approved => Merged

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

--
https://code.launchpad.net/~gary/launchpad/bug838869/+merge/73695
Your team Launchpad code revie...

--
launchpad-reviews mailing list
<email address hidden>
https://lists.ubuntu.com/ma...

=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
--- lib/canonical/launchpad/webapp/adapter.py	2011-08-26 13:13:20 +0000
+++ lib/canonical/launchpad/webapp/adapter.py	2011-09-02 16:31:40 +0000
@@ -6,13 +6,16 @@
 
 __metaclass__ = type
 
+from functools import partial
 import logging
 import os
 import re
+import StringIO
 import sys
 import thread
 import threading
 from time import time
+import traceback
 import warnings
 
 import psycopg2
@@ -79,6 +82,7 @@
     )
 from lp.services.stacktrace import (
     extract_stack,
+    extract_tb,
     print_list,
     )
 
@@ -91,9 +95,11 @@
     'get_request_start_time',
     'get_request_duration',
     'get_store_name',
+    'print_queries',
     'soft_timeout_expired',
-    'start_sql_traceback_logging',
-    'stop_sql_traceback_logging',
+    'SQLLogger',
+    'start_sql_logging',
+    'stop_sql_logging',
     'StoreSelector',
     ]
 
@@ -202,7 +208,9 @@
         warnings.warn('clear_request_started() called outside of a request',
             stacklevel=2)
     _local.request_start_time = None
-    _local.sql_trace = None
+    _local.sql_logging = None
+    _local.sql_logging_start = None
+    _local.sql_logging_tracebacks_if = None
     request = get_current_browser_request()
     set_request_timeline(request, Timeline())
     if getattr(_local, 'commit_logger', None) is not None:
@@ -351,18 +359,75 @@
         return True
 
 
-def start_sql_traceback_logging():
-    """Set the sql traceback data logging for the current request."""
-    _local.sql_trace = []
-
-
-def stop_sql_traceback_logging():
-    """Stop the sql traceback data logging and return the result."""
-    result = getattr(_local, 'sql_trace', None)
-    _local.sql_trace = None
+def start_sql_logging(tracebacks_if=False):
+    """Turn the sql data logging on."""
+    if getattr(_local, 'sql_logging', None) is not None:
+        warnings.warn('SQL logging already started')
+        return
+    _local.sql_logging_tracebacks_if = tracebacks_if
+    _local.sql_logging = []
+    _local.sql_logging_start = int(time() * 1000)
+
+
+def stop_sql_logging():
+    """Turn off the sql data logging and return the result."""
+    result = getattr(_local, 'sql_logging', None)
+    _local.sql_logging_tracebacks_if = None
+    _local.sql_logging = None
+    _local.sql_logging_start = None
+    if result is None:
+        warnings.warn('SQL logging not started')
     return result
 
 
+class SQLLogger:
+
+    def __init__(self, tracebacks_if=False):
+        self.tracebacks_if = tracebacks_if
+
+    queries = None
+
+    def __enter__(self):
+        self.queries = None
+        start_sql_logging(self.tracebacks_if)
+
+    def __exit__(self, exc_type, exc_value, tb):
+        self.queries = stop_sql_logging()
+
+    def __str__(self):
+        if self.queries is None:
+            return '(no queries)'
+        else:
+            out = StringIO.StringIO()
+            print_queries(self.queries, file=out)
+            return out.getvalue()
+
+
+def print_queries(queries, file=None):
+    if file is None:
+        file = sys.stdout
+    for query in queries:
+        stack = query['stack']
+        if stack is not None:
+            exception = query['exception']
+            if exception is not None:
+                file.write(
+                    'Error when determining whether to generate a '
+                    'stacktrace.\n')
+                file.write('Traceback (most recent call last):\n')
+            print_list(stack, file)
+            if exception is not None:
+                lines = traceback.format_exception_only(*exception)
+                file.write(' '.join(lines))
+            file.write("." * 70 + "\n")
+        sql = query['sql']
+        if sql is not None:
+            file.write('%d-%d@%s %s\n' % sql)
+        else:
+            file.write('(no SQL recorded)\n')
+        file.write("-" * 70 + "\n")
+
+
 # ---- Prevent database access in the main thread of the app server
 
 class StormAccessFromMainThread(Exception):
@@ -625,23 +690,14 @@
 class LaunchpadStatementTracer:
     """Storm tracer class to log executed statements."""
 
+    _normalize_whitespace = partial(re.compile('\s+').sub, ' ')
+
     def __init__(self):
         self._debug_sql = bool(os.environ.get('LP_DEBUG_SQL'))
         self._debug_sql_extra = bool(os.environ.get('LP_DEBUG_SQL_EXTRA'))
 
     def connection_raw_execute(self, connection, raw_cursor,
                                statement, params):
-        sql_trace = getattr(_local, 'sql_trace', None)
-        if sql_trace is not None or self._debug_sql_extra:
-            # Gather data for the [start|stop]_sql_traceback_logging
-            # feature, as exposed by ++profile++sqltrace, and/or for stderr,
-            # as exposed by LP_DEBUG_SQL_EXTRA.
-            stack = extract_stack()
-            if sql_trace is not None:
-                sql_trace.append(dict(stack=stack, sql=None))
-            if self._debug_sql_extra:
-                print_list(stack)
-                sys.stderr.write("." * 70 + "\n")
         statement_to_log = statement
         if params:
             # There are some bind parameters so we want to insert them into
@@ -656,18 +712,43 @@
             param_strings = [repr(p) if isinstance(p, basestring) else p
                                  for p in query_params]
             statement_to_log = quoted_statement % tuple(param_strings)
+        # Record traceback to log, if requested.
+        print_traceback = self._debug_sql_extra
+        log_sql = getattr(_local, 'sql_logging', None)
+        log_traceback = False
+        if log_sql is not None:
+            log_sql.append(dict(stack=None, sql=None, exception=None))
+            conditional = getattr(_local, 'sql_logging_tracebacks_if', None)
+            if callable(conditional):
+                try:
+                    log_traceback = conditional(
+                        self._normalize_whitespace(
+                            statement_to_log.strip()).upper())
+                except (MemoryError, SystemExit, KeyboardInterrupt):
+                    raise
+                except:
+                    exc_type, exc_value, tb = sys.exc_info()
+                    log_sql[-1]['exception'] = (exc_type, exc_value)
+                    log_sql[-1]['stack'] = extract_tb(tb)
+            else:
+                log_traceback = bool(conditional)
+        if print_traceback or log_traceback:
+            stack = extract_stack()
+            if log_traceback:
+                log_sql[-1]['stack'] = stack
+            if print_traceback:
+                print_list(stack)
+                sys.stderr.write("." * 70 + "\n")
         # store the last executed statement as an attribute on the current
         # thread
         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):
+            if print_traceback or self._debug_sql or log_sql is not None:
                 # Stash some information for logging at the end of the
-                # request.
+                # SQL execution.
                 connection._lp_statement_info = (
-                    time(),
+                    int(time() * 1000),
                     'SQL-%s' % connection._database.name,
                     statement_to_log)
             return
@@ -682,24 +763,26 @@
             # 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 is not None or self._debug_sql or self._debug_sql_extra:
+        log_sql = getattr(_local, 'sql_logging', None)
+        if log_sql 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:
+                    stop = int(time() * 1000)
                     start, dbname, statement = info
+                    logging_start = (
+                        getattr(_local, 'sql_logging_start', None) or start)
                     # Times are in milliseconds, to mirror actions.
-                    duration = int((time() - start) * 1000)
-                    data = (0, duration, dbname, statement)
+                    start = start - logging_start
+                    stop = stop - logging_start
+                    data = (start, stop, dbname, statement)
+                    connection._lp_statement_info = None
             if data is not None:
-                if sql_trace and sql_trace[-1]['sql'] is None:
-                    sql_trace[-1]['sql'] = data
+                if log_sql and log_sql[-1]['sql'] is None:
+                    log_sql[-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")

=== added file 'lib/canonical/launchpad/webapp/tests/test_statementtracer.py'
--- lib/canonical/launchpad/webapp/tests/test_statementtracer.py	1970-01-01 00:00:00 +0000
+++ lib/canonical/launchpad/webapp/tests/test_statementtracer.py	2011-09-02 16:31:40 +0000
@@ -0,0 +1,316 @@
+# Copyright 2011 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests for the LaunchpadStatementTracer."""
+
+__metaclass__ = type
+
+from contextlib import contextmanager
+import StringIO
+import sys
+
+from lp.testing import (
+    person_logged_in,
+    TestCase,
+    TestCaseWithFactory,
+    )
+from lp.services.osutils import override_environ
+from lp.services.timeline.requesttimeline import get_request_timeline
+from canonical.launchpad.webapp import adapter as da
+from canonical.lazr.utils import get_current_browser_request
+from canonical.testing import DatabaseFunctionalLayer
+
+
+@contextmanager
+def stdout():
+    file = StringIO.StringIO()
+    original = sys.stdout
+    sys.stdout = file
+    try:
+        yield file
+    finally:
+        sys.stdout = original
+
+
+@contextmanager
+def stderr():
+    file = StringIO.StringIO()
+    original = sys.stderr
+    sys.stderr = file
+    try:
+        yield file
+    finally:
+        sys.stderr = original
+
+
+class StubTime:
+
+    time = 1000.0
+
+    def __call__(self):
+        result = self.time
+        self.time += 0.001
+        return result
+
+
+class StubConnection:
+
+    def __init__(self):
+        self._database = type('StubDatabase', (), dict(name='stub-database'))
+
+
+class TestLoggingOutsideOfRequest(TestCase):
+
+    def setUp(self):
+        super(TestLoggingOutsideOfRequest, self).setUp()
+        self.connection = StubConnection()
+        original_time = da.time
+        self.addCleanup(setattr, da, 'time', original_time)
+        da.time = StubTime()
+
+    def execute(self, statement=None, params=None, **environ):
+        with override_environ(**environ):
+            tracer = da.LaunchpadStatementTracer()
+        if statement is None:
+            statement = 'SELECT * FROM bar WHERE bing = 42'
+        tracer.connection_raw_execute(
+            self.connection, None, statement, params)
+        tracer.connection_raw_execute_success(
+            self.connection, None, statement, params)
+
+    def test_no_logging(self):
+        with stderr() as file:
+            self.execute()
+            self.assertEqual('', file.getvalue())
+
+    def test_stderr(self):
+        with stderr() as file:
+            self.execute(LP_DEBUG_SQL='1')
+            self.assertEqual(
+                '0-1@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
+                "-" * 70 + "\n",
+                file.getvalue())
+
+    def test_stderr_with_stacktrace(self):
+        with stderr() as file:
+            self.execute(LP_DEBUG_SQL_EXTRA='1')
+            self.assertStartsWith(
+                file.getvalue(),
+                '  File "')
+            self.assertEndsWith(
+                file.getvalue(),
+                "." * 70 + "\n" +
+                '0-1@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
+                "-" * 70 + "\n")
+
+    def test_data_logging(self):
+        da.start_sql_logging()
+        with stderr() as file:
+            self.execute()
+            self.assertEqual('', file.getvalue())
+        result = da.stop_sql_logging()
+        self.assertEqual(1, len(result))
+        self.assertIs(None, result[0]['stack'])
+        self.assertIs(None, result[0]['exception'])
+        self.assertEqual(
+            (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'),
+            result[0]['sql'])
+
+    def test_data_logging_with_stacktrace(self):
+        da.start_sql_logging(tracebacks_if=True)
+        with stderr() as file:
+            self.execute()
+            self.assertEqual('', file.getvalue())
+        result = da.stop_sql_logging()
+        self.assertEqual(1, len(result))
+        self.assertIsNot(None, result[0]['stack'])
+        self.assertIs(None, result[0]['exception'])
+        self.assertEqual(
+            (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'),
+            result[0]['sql'])
+
+    def test_data_logging_with_conditional_stacktrace(self):
+        # Conditions must be normalized to uppercase.
+        da.start_sql_logging(tracebacks_if=lambda sql: 'KUMQUAT' in sql)
+        with stderr() as file:
+            self.execute()
+            self.execute(statement='SELECT * FROM kumquat WHERE bing = 42')
+            self.assertEqual('', file.getvalue())
+        result = da.stop_sql_logging()
+        self.assertEqual(2, len(result))
+        self.assertIs(None, result[0]['stack'])
+        self.assertIsNot(None, result[1]['stack'])
+
+    def test_data_logging_with_conditional_stacktrace_normalized_whitespace(
+        self):
+        # The whitespace in the SQL is normalized
+        da.start_sql_logging(
+            tracebacks_if=lambda sql: 'FROM KUMQUAT WHERE' in sql)
+        self.execute(
+            statement='SELECT * FROM   kumquat \nWHERE bing = 42')
+        result = da.stop_sql_logging()
+        self.assertEqual(1, len(result))
+        self.assertIsNot(None, result[0]['stack'])
+
+    def test_data_logging_with_broken_conditional_stacktrace(self):
+        error = ValueError('rutebega')
+
+        def ow(sql):
+            raise error
+        da.start_sql_logging(tracebacks_if=ow)
+        with stderr() as file:
+            self.execute()
+            self.assertEqual('', file.getvalue())
+        result = da.stop_sql_logging()
+        self.assertEqual(1, len(result))
+        self.assertIsNot(None, result[0]['stack'])
+        self.assertEqual((ValueError, error), result[0]['exception'])
+        self.assertEqual(
+            (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'),
+            result[0]['sql'])
+
+    def test_print_queries_with_tracebacks(self):
+        da.start_sql_logging(tracebacks_if=True)
+        self.execute()
+        result = da.stop_sql_logging()
+        with stdout() as file:
+            da.print_queries(result)
+            self.assertStartsWith(
+                file.getvalue(),
+                '  File "')
+            self.assertEndsWith(
+                file.getvalue(),
+                "." * 70 + "\n" +
+                '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
+                "-" * 70 + "\n")
+
+    def test_print_queries_without_tracebacks(self):
+        da.start_sql_logging()
+        self.execute()
+        result = da.stop_sql_logging()
+        with stdout() as file:
+            da.print_queries(result)
+            self.assertEqual(
+                '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
+                "-" * 70 + "\n",
+            file.getvalue())
+
+    def test_print_queries_with_exceptions(self):
+        def ow(sql):
+            raise ValueError('rutebega')
+        da.start_sql_logging(tracebacks_if=ow)
+        self.execute()
+        result = da.stop_sql_logging()
+        with stdout() as file:
+            da.print_queries(result)
+            self.assertStartsWith(
+                file.getvalue(),
+                'Error when determining whether to generate a stacktrace.\n' +
+                'Traceback (most recent call last):\n' +
+                '  File "')
+            self.assertEndsWith(
+                file.getvalue(),
+                "ValueError: rutebega\n" +
+                "." * 70 + "\n" +
+                '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
+                "-" * 70 + "\n")
+
+    def test_context_manager(self):
+        logger = da.SQLLogger()
+        with logger:
+            self.execute()
+        self.assertEqual(1, len(logger.queries))
+        self.assertIs(None, logger.queries[0]['stack'])
+        self.assertIs(None, logger.queries[0]['exception'])
+        self.assertEqual(
+            (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'),
+            logger.queries[0]['sql'])
+        with stdout() as file:
+            result = str(logger)
+            self.assertEqual('', file.getvalue())
+        self.assertEqual(
+            '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
+            "-" * 70 + "\n",
+            result)
+
+    def test_context_manager_with_stacktrace(self):
+        logger = da.SQLLogger(tracebacks_if=True)
+        with logger:
+            self.execute()
+        self.assertEqual(1, len(logger.queries))
+        self.assertIsNot(None, logger.queries[0]['stack'])
+
+    def test_sql_parameters(self):
+        logger = da.SQLLogger()
+        with logger:
+            self.execute(statement='SELECT * FROM bar WHERE bing = %s',
+                         params=(142,))
+        self.assertEqual(
+            (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 142'),
+            logger.queries[0]['sql'])
+
+
+class TestLoggingWithinRequest(TestCaseWithFactory):
+    # When called with a request, the code uses the request timeline and
+    # its action objects.
+
+    layer = DatabaseFunctionalLayer
+
+    def setUp(self):
+        super(TestLoggingWithinRequest, self).setUp()
+        self.connection = StubConnection()
+        self.person = self.factory.makePerson()
+        da.set_request_started(1000.0)
+        self.addCleanup(da.clear_request_started)
+
+    def test_logger(self):
+        tracer = da.LaunchpadStatementTracer()
+        logger = da.SQLLogger()
+        with person_logged_in(self.person):
+            with logger:
+                tracer.connection_raw_execute(
+                    self.connection, None,
+                    'SELECT * FROM bar WHERE bing = 42', ())
+                timeline = get_request_timeline(get_current_browser_request())
+                action = timeline.actions[-1]
+                self.assertEqual(
+                    'SELECT * FROM bar WHERE bing = 42',
+                    action.detail)
+                self.assertEqual('SQL-stub-database', action.category)
+                self.assertIs(None, action.duration)
+                # Now we change the detail to verify that the action is the
+                # source of the final log.
+                action.detail = 'SELECT * FROM surprise'
+                tracer.connection_raw_execute_success(
+                    self.connection, None,
+                    'SELECT * FROM bar WHERE bing = 42', ())
+                self.assertIsNot(None, action.duration)
+        self.assertEqual(
+            'SELECT * FROM surprise', logger.queries[0]['sql'][3])
+
+    def test_stderr(self):
+        with override_environ(LP_DEBUG_SQL='1'):
+            tracer = da.LaunchpadStatementTracer()
+        with person_logged_in(self.person):
+            with stderr() as file:
+                tracer.connection_raw_execute(
+                    self.connection, None,
+                    'SELECT * FROM bar WHERE bing = 42', ())
+                timeline = get_request_timeline(get_current_browser_request())
+                action = timeline.actions[-1]
+                self.assertEqual(
+                    'SELECT * FROM bar WHERE bing = 42',
+                    action.detail)
+                self.assertEqual('SQL-stub-database', action.category)
+                self.assertIs(None, action.duration)
+                # Now we change the detail to verify that the action is the
+                # source of the final log.
+                action.detail = 'SELECT * FROM surprise'
+                tracer.connection_raw_execute_success(
+                    self.connection, None,
+                    'SELECT * FROM bar WHERE bing = 42', ())
+                self.assertIsNot(None, action.duration)
+                self.assertEndsWith(
+                    file.getvalue(),
+                    '@SQL-stub-database SELECT * FROM surprise\n' +
+                    "-" * 70 + "\n")

=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py	2011-08-24 17:24:38 +0000
+++ lib/lp/services/profile/profile.py	2011-09-02 16:31:40 +0000
@@ -213,7 +213,7 @@
         actions.add('callgrind')
     if actions:
         if 'sqltrace' in actions:
-            da.start_sql_traceback_logging()
+            da.start_sql_logging(tracebacks_if=True)
         if 'show' in actions or actions.intersection(available_profilers):
             _profilers.profiler = Profiler()
             _profilers.profiler.start()
@@ -346,7 +346,7 @@
         del prof_stats
     trace = None
     if 'sqltrace' in actions:
-        trace = da.stop_sql_traceback_logging() or ()
+        trace = da.stop_sql_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

=== modified file 'lib/lp/services/profile/tests.py'
--- lib/lp/services/profile/tests.py	2011-08-22 19:06:39 +0000
+++ lib/lp/services/profile/tests.py	2011-09-02 16:31:40 +0000
@@ -82,7 +82,6 @@
         profile._profilers.actions = None
         profile._profilers.memory_profile_start = None
         profile._profilers.profiling = False
-        da.stop_sql_traceback_logging()
         super(TestCleanupProfiler, self).tearDown()
 
 
@@ -275,7 +274,7 @@
         profile.start_request(self._get_start_event('/++profile++sqltrace/'))
         self.assertIs(getattr(profile._profilers, 'profiler', None), None)
         self.assertEquals(profile._profilers.actions, set(('sqltrace', )))
-        self.assertEqual([], da.stop_sql_traceback_logging())
+        self.assertEqual([], da.stop_sql_logging())
 
 
 class BaseRequestEndHandlerTest(BaseTest):