launchpad-reviewers team mailing list archive
-
launchpad-reviewers team
-
Mailing list archive
-
Message #04846
[Merge] lp:~gary/launchpad/bug838869 into lp:launchpad
Gary Poster has proposed merging lp:~gary/launchpad/bug838869 into lp:launchpad.
Requested reviews:
Launchpad code reviewers (launchpad-reviewers)
Related bugs:
Bug #838869 in Launchpad itself: "Launchpad's custom database log machinery has no tests"
https://bugs.launchpad.net/launchpad/+bug/838869
For more details, see:
https://code.launchpad.net/~gary/launchpad/bug838869/+merge/73695
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.
--
https://code.launchpad.net/~gary/launchpad/bug838869/+merge/73695
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~gary/launchpad/bug838869 into lp:launchpad.
=== 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-01 16:41:36 +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,25 +690,19 @@
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:
+ print_traceback = self._debug_sql_extra
+ log_sql = getattr(_local, 'sql_logging', None)
+ render_sql = print_traceback or self._debug_sql or log_sql is not None
+ if render_sql and params:
# There are some bind parameters so we want to insert them into
# the sql statement so we can log the statement.
query_params = list(Connection.to_database(params))
@@ -656,18 +715,41 @@
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.
+ 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 render_sql:
# 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 +764,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-01 16:41:36 +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-01 16:41:36 +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-01 16:41:36 +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):
