Merge lp:~gary/launchpad/bug838869 into lp:launchpad
- bug838869
- Merge into devel
Status: | Merged |
---|---|
Approved by: | Gary Poster |
Approved revision: | no longer in the source branch. |
Merged at revision: | 13857 |
Proposed branch: | lp:~gary/launchpad/bug838869 |
Merge into: | lp:launchpad |
Diff against target: |
613 lines (+439/-41) 4 files modified
lib/canonical/launchpad/webapp/adapter.py (+120/-37) lib/canonical/launchpad/webapp/tests/test_statementtracer.py (+316/-0) lib/lp/services/profile/profile.py (+2/-2) lib/lp/services/profile/tests.py (+1/-2) |
To merge this branch: | bzr merge lp:~gary/launchpad/bug838869 |
Related bugs: |
Reviewer | Review Type | Date Requested | Status |
---|---|---|---|
j.c.sackett (community) | Approve | ||
Review via email: mp+73695@code.launchpad.net |
Commit message
[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.
Description of the change
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/
- It adds the ability to conditionally collect stacktraces, and renames the associated function from `start_
- 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:/
Thank you.
Robert Collins (lifeless) wrote : | # |
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:/
--
https:/
Your team Launchpad code revie...
--
launchpad-reviews mailing list
<email address hidden>
https:/
Preview Diff
1 | === modified file 'lib/canonical/launchpad/webapp/adapter.py' | |||
2 | --- lib/canonical/launchpad/webapp/adapter.py 2011-08-26 13:13:20 +0000 | |||
3 | +++ lib/canonical/launchpad/webapp/adapter.py 2011-09-02 16:31:40 +0000 | |||
4 | @@ -6,13 +6,16 @@ | |||
5 | 6 | 6 | ||
6 | 7 | __metaclass__ = type | 7 | __metaclass__ = type |
7 | 8 | 8 | ||
8 | 9 | from functools import partial | ||
9 | 9 | import logging | 10 | import logging |
10 | 10 | import os | 11 | import os |
11 | 11 | import re | 12 | import re |
12 | 13 | import StringIO | ||
13 | 12 | import sys | 14 | import sys |
14 | 13 | import thread | 15 | import thread |
15 | 14 | import threading | 16 | import threading |
16 | 15 | from time import time | 17 | from time import time |
17 | 18 | import traceback | ||
18 | 16 | import warnings | 19 | import warnings |
19 | 17 | 20 | ||
20 | 18 | import psycopg2 | 21 | import psycopg2 |
21 | @@ -79,6 +82,7 @@ | |||
22 | 79 | ) | 82 | ) |
23 | 80 | from lp.services.stacktrace import ( | 83 | from lp.services.stacktrace import ( |
24 | 81 | extract_stack, | 84 | extract_stack, |
25 | 85 | extract_tb, | ||
26 | 82 | print_list, | 86 | print_list, |
27 | 83 | ) | 87 | ) |
28 | 84 | 88 | ||
29 | @@ -91,9 +95,11 @@ | |||
30 | 91 | 'get_request_start_time', | 95 | 'get_request_start_time', |
31 | 92 | 'get_request_duration', | 96 | 'get_request_duration', |
32 | 93 | 'get_store_name', | 97 | 'get_store_name', |
33 | 98 | 'print_queries', | ||
34 | 94 | 'soft_timeout_expired', | 99 | 'soft_timeout_expired', |
37 | 95 | 'start_sql_traceback_logging', | 100 | 'SQLLogger', |
38 | 96 | 'stop_sql_traceback_logging', | 101 | 'start_sql_logging', |
39 | 102 | 'stop_sql_logging', | ||
40 | 97 | 'StoreSelector', | 103 | 'StoreSelector', |
41 | 98 | ] | 104 | ] |
42 | 99 | 105 | ||
43 | @@ -202,7 +208,9 @@ | |||
44 | 202 | warnings.warn('clear_request_started() called outside of a request', | 208 | warnings.warn('clear_request_started() called outside of a request', |
45 | 203 | stacklevel=2) | 209 | stacklevel=2) |
46 | 204 | _local.request_start_time = None | 210 | _local.request_start_time = None |
48 | 205 | _local.sql_trace = None | 211 | _local.sql_logging = None |
49 | 212 | _local.sql_logging_start = None | ||
50 | 213 | _local.sql_logging_tracebacks_if = None | ||
51 | 206 | request = get_current_browser_request() | 214 | request = get_current_browser_request() |
52 | 207 | set_request_timeline(request, Timeline()) | 215 | set_request_timeline(request, Timeline()) |
53 | 208 | if getattr(_local, 'commit_logger', None) is not None: | 216 | if getattr(_local, 'commit_logger', None) is not None: |
54 | @@ -351,18 +359,75 @@ | |||
55 | 351 | return True | 359 | return True |
56 | 352 | 360 | ||
57 | 353 | 361 | ||
67 | 354 | def start_sql_traceback_logging(): | 362 | def start_sql_logging(tracebacks_if=False): |
68 | 355 | """Set the sql traceback data logging for the current request.""" | 363 | """Turn the sql data logging on.""" |
69 | 356 | _local.sql_trace = [] | 364 | if getattr(_local, 'sql_logging', None) is not None: |
70 | 357 | 365 | warnings.warn('SQL logging already started') | |
71 | 358 | 366 | return | |
72 | 359 | def stop_sql_traceback_logging(): | 367 | _local.sql_logging_tracebacks_if = tracebacks_if |
73 | 360 | """Stop the sql traceback data logging and return the result.""" | 368 | _local.sql_logging = [] |
74 | 361 | result = getattr(_local, 'sql_trace', None) | 369 | _local.sql_logging_start = int(time() * 1000) |
75 | 362 | _local.sql_trace = None | 370 | |
76 | 371 | |||
77 | 372 | def stop_sql_logging(): | ||
78 | 373 | """Turn off the sql data logging and return the result.""" | ||
79 | 374 | result = getattr(_local, 'sql_logging', None) | ||
80 | 375 | _local.sql_logging_tracebacks_if = None | ||
81 | 376 | _local.sql_logging = None | ||
82 | 377 | _local.sql_logging_start = None | ||
83 | 378 | if result is None: | ||
84 | 379 | warnings.warn('SQL logging not started') | ||
85 | 363 | return result | 380 | return result |
86 | 364 | 381 | ||
87 | 365 | 382 | ||
88 | 383 | class SQLLogger: | ||
89 | 384 | |||
90 | 385 | def __init__(self, tracebacks_if=False): | ||
91 | 386 | self.tracebacks_if = tracebacks_if | ||
92 | 387 | |||
93 | 388 | queries = None | ||
94 | 389 | |||
95 | 390 | def __enter__(self): | ||
96 | 391 | self.queries = None | ||
97 | 392 | start_sql_logging(self.tracebacks_if) | ||
98 | 393 | |||
99 | 394 | def __exit__(self, exc_type, exc_value, tb): | ||
100 | 395 | self.queries = stop_sql_logging() | ||
101 | 396 | |||
102 | 397 | def __str__(self): | ||
103 | 398 | if self.queries is None: | ||
104 | 399 | return '(no queries)' | ||
105 | 400 | else: | ||
106 | 401 | out = StringIO.StringIO() | ||
107 | 402 | print_queries(self.queries, file=out) | ||
108 | 403 | return out.getvalue() | ||
109 | 404 | |||
110 | 405 | |||
111 | 406 | def print_queries(queries, file=None): | ||
112 | 407 | if file is None: | ||
113 | 408 | file = sys.stdout | ||
114 | 409 | for query in queries: | ||
115 | 410 | stack = query['stack'] | ||
116 | 411 | if stack is not None: | ||
117 | 412 | exception = query['exception'] | ||
118 | 413 | if exception is not None: | ||
119 | 414 | file.write( | ||
120 | 415 | 'Error when determining whether to generate a ' | ||
121 | 416 | 'stacktrace.\n') | ||
122 | 417 | file.write('Traceback (most recent call last):\n') | ||
123 | 418 | print_list(stack, file) | ||
124 | 419 | if exception is not None: | ||
125 | 420 | lines = traceback.format_exception_only(*exception) | ||
126 | 421 | file.write(' '.join(lines)) | ||
127 | 422 | file.write("." * 70 + "\n") | ||
128 | 423 | sql = query['sql'] | ||
129 | 424 | if sql is not None: | ||
130 | 425 | file.write('%d-%d@%s %s\n' % sql) | ||
131 | 426 | else: | ||
132 | 427 | file.write('(no SQL recorded)\n') | ||
133 | 428 | file.write("-" * 70 + "\n") | ||
134 | 429 | |||
135 | 430 | |||
136 | 366 | # ---- Prevent database access in the main thread of the app server | 431 | # ---- Prevent database access in the main thread of the app server |
137 | 367 | 432 | ||
138 | 368 | class StormAccessFromMainThread(Exception): | 433 | class StormAccessFromMainThread(Exception): |
139 | @@ -625,23 +690,14 @@ | |||
140 | 625 | class LaunchpadStatementTracer: | 690 | class LaunchpadStatementTracer: |
141 | 626 | """Storm tracer class to log executed statements.""" | 691 | """Storm tracer class to log executed statements.""" |
142 | 627 | 692 | ||
143 | 693 | _normalize_whitespace = partial(re.compile('\s+').sub, ' ') | ||
144 | 694 | |||
145 | 628 | def __init__(self): | 695 | def __init__(self): |
146 | 629 | self._debug_sql = bool(os.environ.get('LP_DEBUG_SQL')) | 696 | self._debug_sql = bool(os.environ.get('LP_DEBUG_SQL')) |
147 | 630 | self._debug_sql_extra = bool(os.environ.get('LP_DEBUG_SQL_EXTRA')) | 697 | self._debug_sql_extra = bool(os.environ.get('LP_DEBUG_SQL_EXTRA')) |
148 | 631 | 698 | ||
149 | 632 | def connection_raw_execute(self, connection, raw_cursor, | 699 | def connection_raw_execute(self, connection, raw_cursor, |
150 | 633 | statement, params): | 700 | statement, params): |
151 | 634 | sql_trace = getattr(_local, 'sql_trace', None) | ||
152 | 635 | if sql_trace is not None or self._debug_sql_extra: | ||
153 | 636 | # Gather data for the [start|stop]_sql_traceback_logging | ||
154 | 637 | # feature, as exposed by ++profile++sqltrace, and/or for stderr, | ||
155 | 638 | # as exposed by LP_DEBUG_SQL_EXTRA. | ||
156 | 639 | stack = extract_stack() | ||
157 | 640 | if sql_trace is not None: | ||
158 | 641 | sql_trace.append(dict(stack=stack, sql=None)) | ||
159 | 642 | if self._debug_sql_extra: | ||
160 | 643 | print_list(stack) | ||
161 | 644 | sys.stderr.write("." * 70 + "\n") | ||
162 | 645 | statement_to_log = statement | 701 | statement_to_log = statement |
163 | 646 | if params: | 702 | if params: |
164 | 647 | # There are some bind parameters so we want to insert them into | 703 | # There are some bind parameters so we want to insert them into |
165 | @@ -656,18 +712,43 @@ | |||
166 | 656 | param_strings = [repr(p) if isinstance(p, basestring) else p | 712 | param_strings = [repr(p) if isinstance(p, basestring) else p |
167 | 657 | for p in query_params] | 713 | for p in query_params] |
168 | 658 | statement_to_log = quoted_statement % tuple(param_strings) | 714 | statement_to_log = quoted_statement % tuple(param_strings) |
169 | 715 | # Record traceback to log, if requested. | ||
170 | 716 | print_traceback = self._debug_sql_extra | ||
171 | 717 | log_sql = getattr(_local, 'sql_logging', None) | ||
172 | 718 | log_traceback = False | ||
173 | 719 | if log_sql is not None: | ||
174 | 720 | log_sql.append(dict(stack=None, sql=None, exception=None)) | ||
175 | 721 | conditional = getattr(_local, 'sql_logging_tracebacks_if', None) | ||
176 | 722 | if callable(conditional): | ||
177 | 723 | try: | ||
178 | 724 | log_traceback = conditional( | ||
179 | 725 | self._normalize_whitespace( | ||
180 | 726 | statement_to_log.strip()).upper()) | ||
181 | 727 | except (MemoryError, SystemExit, KeyboardInterrupt): | ||
182 | 728 | raise | ||
183 | 729 | except: | ||
184 | 730 | exc_type, exc_value, tb = sys.exc_info() | ||
185 | 731 | log_sql[-1]['exception'] = (exc_type, exc_value) | ||
186 | 732 | log_sql[-1]['stack'] = extract_tb(tb) | ||
187 | 733 | else: | ||
188 | 734 | log_traceback = bool(conditional) | ||
189 | 735 | if print_traceback or log_traceback: | ||
190 | 736 | stack = extract_stack() | ||
191 | 737 | if log_traceback: | ||
192 | 738 | log_sql[-1]['stack'] = stack | ||
193 | 739 | if print_traceback: | ||
194 | 740 | print_list(stack) | ||
195 | 741 | sys.stderr.write("." * 70 + "\n") | ||
196 | 659 | # store the last executed statement as an attribute on the current | 742 | # store the last executed statement as an attribute on the current |
197 | 660 | # thread | 743 | # thread |
198 | 661 | threading.currentThread().lp_last_sql_statement = statement | 744 | threading.currentThread().lp_last_sql_statement = statement |
199 | 662 | request_starttime = getattr(_local, 'request_start_time', None) | 745 | request_starttime = getattr(_local, 'request_start_time', None) |
200 | 663 | if request_starttime is None: | 746 | if request_starttime is None: |
204 | 664 | if (sql_trace is not None or | 747 | if print_traceback or self._debug_sql or log_sql is not None: |
202 | 665 | self._debug_sql or | ||
203 | 666 | self._debug_sql_extra): | ||
205 | 667 | # Stash some information for logging at the end of the | 748 | # Stash some information for logging at the end of the |
207 | 668 | # request. | 749 | # SQL execution. |
208 | 669 | connection._lp_statement_info = ( | 750 | connection._lp_statement_info = ( |
210 | 670 | time(), | 751 | int(time() * 1000), |
211 | 671 | 'SQL-%s' % connection._database.name, | 752 | 'SQL-%s' % connection._database.name, |
212 | 672 | statement_to_log) | 753 | statement_to_log) |
213 | 673 | return | 754 | return |
214 | @@ -682,24 +763,26 @@ | |||
215 | 682 | # action may be None if the tracer was installed after the | 763 | # action may be None if the tracer was installed after the |
216 | 683 | # statement was submitted. | 764 | # statement was submitted. |
217 | 684 | action.finish() | 765 | action.finish() |
223 | 685 | # Do data reporting for the [start|stop]_sql_traceback_logging | 766 | log_sql = getattr(_local, 'sql_logging', None) |
224 | 686 | # feature, as exposed by ++profile++sqltrace, and/or for stderr, | 767 | if log_sql is not None or self._debug_sql or self._debug_sql_extra: |
220 | 687 | # as exposed by LP_DEBUG_SQL_EXTRA and LP_DEBUG_SQL. | ||
221 | 688 | sql_trace = getattr(_local, 'sql_trace', None) | ||
222 | 689 | if sql_trace is not None or self._debug_sql or self._debug_sql_extra: | ||
225 | 690 | data = None | 768 | data = None |
226 | 691 | if action is not None: | 769 | if action is not None: |
227 | 692 | data = action.logTuple() | 770 | data = action.logTuple() |
228 | 693 | else: | 771 | else: |
229 | 694 | info = getattr(connection, '_lp_statement_info', None) | 772 | info = getattr(connection, '_lp_statement_info', None) |
230 | 695 | if info is not None: | 773 | if info is not None: |
231 | 774 | stop = int(time() * 1000) | ||
232 | 696 | start, dbname, statement = info | 775 | start, dbname, statement = info |
233 | 776 | logging_start = ( | ||
234 | 777 | getattr(_local, 'sql_logging_start', None) or start) | ||
235 | 697 | # Times are in milliseconds, to mirror actions. | 778 | # Times are in milliseconds, to mirror actions. |
238 | 698 | duration = int((time() - start) * 1000) | 779 | start = start - logging_start |
239 | 699 | data = (0, duration, dbname, statement) | 780 | stop = stop - logging_start |
240 | 781 | data = (start, stop, dbname, statement) | ||
241 | 782 | connection._lp_statement_info = None | ||
242 | 700 | if data is not None: | 783 | if data is not None: |
245 | 701 | if sql_trace and sql_trace[-1]['sql'] is None: | 784 | if log_sql and log_sql[-1]['sql'] is None: |
246 | 702 | sql_trace[-1]['sql'] = data | 785 | log_sql[-1]['sql'] = data |
247 | 703 | if self._debug_sql or self._debug_sql_extra: | 786 | if self._debug_sql or self._debug_sql_extra: |
248 | 704 | sys.stderr.write('%d-%d@%s %s\n' % data) | 787 | sys.stderr.write('%d-%d@%s %s\n' % data) |
249 | 705 | sys.stderr.write("-" * 70 + "\n") | 788 | sys.stderr.write("-" * 70 + "\n") |
250 | 706 | 789 | ||
251 | === added file 'lib/canonical/launchpad/webapp/tests/test_statementtracer.py' | |||
252 | --- lib/canonical/launchpad/webapp/tests/test_statementtracer.py 1970-01-01 00:00:00 +0000 | |||
253 | +++ lib/canonical/launchpad/webapp/tests/test_statementtracer.py 2011-09-02 16:31:40 +0000 | |||
254 | @@ -0,0 +1,316 @@ | |||
255 | 1 | # Copyright 2011 Canonical Ltd. This software is licensed under the | ||
256 | 2 | # GNU Affero General Public License version 3 (see the file LICENSE). | ||
257 | 3 | |||
258 | 4 | """Tests for the LaunchpadStatementTracer.""" | ||
259 | 5 | |||
260 | 6 | __metaclass__ = type | ||
261 | 7 | |||
262 | 8 | from contextlib import contextmanager | ||
263 | 9 | import StringIO | ||
264 | 10 | import sys | ||
265 | 11 | |||
266 | 12 | from lp.testing import ( | ||
267 | 13 | person_logged_in, | ||
268 | 14 | TestCase, | ||
269 | 15 | TestCaseWithFactory, | ||
270 | 16 | ) | ||
271 | 17 | from lp.services.osutils import override_environ | ||
272 | 18 | from lp.services.timeline.requesttimeline import get_request_timeline | ||
273 | 19 | from canonical.launchpad.webapp import adapter as da | ||
274 | 20 | from canonical.lazr.utils import get_current_browser_request | ||
275 | 21 | from canonical.testing import DatabaseFunctionalLayer | ||
276 | 22 | |||
277 | 23 | |||
278 | 24 | @contextmanager | ||
279 | 25 | def stdout(): | ||
280 | 26 | file = StringIO.StringIO() | ||
281 | 27 | original = sys.stdout | ||
282 | 28 | sys.stdout = file | ||
283 | 29 | try: | ||
284 | 30 | yield file | ||
285 | 31 | finally: | ||
286 | 32 | sys.stdout = original | ||
287 | 33 | |||
288 | 34 | |||
289 | 35 | @contextmanager | ||
290 | 36 | def stderr(): | ||
291 | 37 | file = StringIO.StringIO() | ||
292 | 38 | original = sys.stderr | ||
293 | 39 | sys.stderr = file | ||
294 | 40 | try: | ||
295 | 41 | yield file | ||
296 | 42 | finally: | ||
297 | 43 | sys.stderr = original | ||
298 | 44 | |||
299 | 45 | |||
300 | 46 | class StubTime: | ||
301 | 47 | |||
302 | 48 | time = 1000.0 | ||
303 | 49 | |||
304 | 50 | def __call__(self): | ||
305 | 51 | result = self.time | ||
306 | 52 | self.time += 0.001 | ||
307 | 53 | return result | ||
308 | 54 | |||
309 | 55 | |||
310 | 56 | class StubConnection: | ||
311 | 57 | |||
312 | 58 | def __init__(self): | ||
313 | 59 | self._database = type('StubDatabase', (), dict(name='stub-database')) | ||
314 | 60 | |||
315 | 61 | |||
316 | 62 | class TestLoggingOutsideOfRequest(TestCase): | ||
317 | 63 | |||
318 | 64 | def setUp(self): | ||
319 | 65 | super(TestLoggingOutsideOfRequest, self).setUp() | ||
320 | 66 | self.connection = StubConnection() | ||
321 | 67 | original_time = da.time | ||
322 | 68 | self.addCleanup(setattr, da, 'time', original_time) | ||
323 | 69 | da.time = StubTime() | ||
324 | 70 | |||
325 | 71 | def execute(self, statement=None, params=None, **environ): | ||
326 | 72 | with override_environ(**environ): | ||
327 | 73 | tracer = da.LaunchpadStatementTracer() | ||
328 | 74 | if statement is None: | ||
329 | 75 | statement = 'SELECT * FROM bar WHERE bing = 42' | ||
330 | 76 | tracer.connection_raw_execute( | ||
331 | 77 | self.connection, None, statement, params) | ||
332 | 78 | tracer.connection_raw_execute_success( | ||
333 | 79 | self.connection, None, statement, params) | ||
334 | 80 | |||
335 | 81 | def test_no_logging(self): | ||
336 | 82 | with stderr() as file: | ||
337 | 83 | self.execute() | ||
338 | 84 | self.assertEqual('', file.getvalue()) | ||
339 | 85 | |||
340 | 86 | def test_stderr(self): | ||
341 | 87 | with stderr() as file: | ||
342 | 88 | self.execute(LP_DEBUG_SQL='1') | ||
343 | 89 | self.assertEqual( | ||
344 | 90 | '0-1@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' + | ||
345 | 91 | "-" * 70 + "\n", | ||
346 | 92 | file.getvalue()) | ||
347 | 93 | |||
348 | 94 | def test_stderr_with_stacktrace(self): | ||
349 | 95 | with stderr() as file: | ||
350 | 96 | self.execute(LP_DEBUG_SQL_EXTRA='1') | ||
351 | 97 | self.assertStartsWith( | ||
352 | 98 | file.getvalue(), | ||
353 | 99 | ' File "') | ||
354 | 100 | self.assertEndsWith( | ||
355 | 101 | file.getvalue(), | ||
356 | 102 | "." * 70 + "\n" + | ||
357 | 103 | '0-1@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' + | ||
358 | 104 | "-" * 70 + "\n") | ||
359 | 105 | |||
360 | 106 | def test_data_logging(self): | ||
361 | 107 | da.start_sql_logging() | ||
362 | 108 | with stderr() as file: | ||
363 | 109 | self.execute() | ||
364 | 110 | self.assertEqual('', file.getvalue()) | ||
365 | 111 | result = da.stop_sql_logging() | ||
366 | 112 | self.assertEqual(1, len(result)) | ||
367 | 113 | self.assertIs(None, result[0]['stack']) | ||
368 | 114 | self.assertIs(None, result[0]['exception']) | ||
369 | 115 | self.assertEqual( | ||
370 | 116 | (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'), | ||
371 | 117 | result[0]['sql']) | ||
372 | 118 | |||
373 | 119 | def test_data_logging_with_stacktrace(self): | ||
374 | 120 | da.start_sql_logging(tracebacks_if=True) | ||
375 | 121 | with stderr() as file: | ||
376 | 122 | self.execute() | ||
377 | 123 | self.assertEqual('', file.getvalue()) | ||
378 | 124 | result = da.stop_sql_logging() | ||
379 | 125 | self.assertEqual(1, len(result)) | ||
380 | 126 | self.assertIsNot(None, result[0]['stack']) | ||
381 | 127 | self.assertIs(None, result[0]['exception']) | ||
382 | 128 | self.assertEqual( | ||
383 | 129 | (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'), | ||
384 | 130 | result[0]['sql']) | ||
385 | 131 | |||
386 | 132 | def test_data_logging_with_conditional_stacktrace(self): | ||
387 | 133 | # Conditions must be normalized to uppercase. | ||
388 | 134 | da.start_sql_logging(tracebacks_if=lambda sql: 'KUMQUAT' in sql) | ||
389 | 135 | with stderr() as file: | ||
390 | 136 | self.execute() | ||
391 | 137 | self.execute(statement='SELECT * FROM kumquat WHERE bing = 42') | ||
392 | 138 | self.assertEqual('', file.getvalue()) | ||
393 | 139 | result = da.stop_sql_logging() | ||
394 | 140 | self.assertEqual(2, len(result)) | ||
395 | 141 | self.assertIs(None, result[0]['stack']) | ||
396 | 142 | self.assertIsNot(None, result[1]['stack']) | ||
397 | 143 | |||
398 | 144 | def test_data_logging_with_conditional_stacktrace_normalized_whitespace( | ||
399 | 145 | self): | ||
400 | 146 | # The whitespace in the SQL is normalized | ||
401 | 147 | da.start_sql_logging( | ||
402 | 148 | tracebacks_if=lambda sql: 'FROM KUMQUAT WHERE' in sql) | ||
403 | 149 | self.execute( | ||
404 | 150 | statement='SELECT * FROM kumquat \nWHERE bing = 42') | ||
405 | 151 | result = da.stop_sql_logging() | ||
406 | 152 | self.assertEqual(1, len(result)) | ||
407 | 153 | self.assertIsNot(None, result[0]['stack']) | ||
408 | 154 | |||
409 | 155 | def test_data_logging_with_broken_conditional_stacktrace(self): | ||
410 | 156 | error = ValueError('rutebega') | ||
411 | 157 | |||
412 | 158 | def ow(sql): | ||
413 | 159 | raise error | ||
414 | 160 | da.start_sql_logging(tracebacks_if=ow) | ||
415 | 161 | with stderr() as file: | ||
416 | 162 | self.execute() | ||
417 | 163 | self.assertEqual('', file.getvalue()) | ||
418 | 164 | result = da.stop_sql_logging() | ||
419 | 165 | self.assertEqual(1, len(result)) | ||
420 | 166 | self.assertIsNot(None, result[0]['stack']) | ||
421 | 167 | self.assertEqual((ValueError, error), result[0]['exception']) | ||
422 | 168 | self.assertEqual( | ||
423 | 169 | (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'), | ||
424 | 170 | result[0]['sql']) | ||
425 | 171 | |||
426 | 172 | def test_print_queries_with_tracebacks(self): | ||
427 | 173 | da.start_sql_logging(tracebacks_if=True) | ||
428 | 174 | self.execute() | ||
429 | 175 | result = da.stop_sql_logging() | ||
430 | 176 | with stdout() as file: | ||
431 | 177 | da.print_queries(result) | ||
432 | 178 | self.assertStartsWith( | ||
433 | 179 | file.getvalue(), | ||
434 | 180 | ' File "') | ||
435 | 181 | self.assertEndsWith( | ||
436 | 182 | file.getvalue(), | ||
437 | 183 | "." * 70 + "\n" + | ||
438 | 184 | '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' + | ||
439 | 185 | "-" * 70 + "\n") | ||
440 | 186 | |||
441 | 187 | def test_print_queries_without_tracebacks(self): | ||
442 | 188 | da.start_sql_logging() | ||
443 | 189 | self.execute() | ||
444 | 190 | result = da.stop_sql_logging() | ||
445 | 191 | with stdout() as file: | ||
446 | 192 | da.print_queries(result) | ||
447 | 193 | self.assertEqual( | ||
448 | 194 | '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' + | ||
449 | 195 | "-" * 70 + "\n", | ||
450 | 196 | file.getvalue()) | ||
451 | 197 | |||
452 | 198 | def test_print_queries_with_exceptions(self): | ||
453 | 199 | def ow(sql): | ||
454 | 200 | raise ValueError('rutebega') | ||
455 | 201 | da.start_sql_logging(tracebacks_if=ow) | ||
456 | 202 | self.execute() | ||
457 | 203 | result = da.stop_sql_logging() | ||
458 | 204 | with stdout() as file: | ||
459 | 205 | da.print_queries(result) | ||
460 | 206 | self.assertStartsWith( | ||
461 | 207 | file.getvalue(), | ||
462 | 208 | 'Error when determining whether to generate a stacktrace.\n' + | ||
463 | 209 | 'Traceback (most recent call last):\n' + | ||
464 | 210 | ' File "') | ||
465 | 211 | self.assertEndsWith( | ||
466 | 212 | file.getvalue(), | ||
467 | 213 | "ValueError: rutebega\n" + | ||
468 | 214 | "." * 70 + "\n" + | ||
469 | 215 | '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' + | ||
470 | 216 | "-" * 70 + "\n") | ||
471 | 217 | |||
472 | 218 | def test_context_manager(self): | ||
473 | 219 | logger = da.SQLLogger() | ||
474 | 220 | with logger: | ||
475 | 221 | self.execute() | ||
476 | 222 | self.assertEqual(1, len(logger.queries)) | ||
477 | 223 | self.assertIs(None, logger.queries[0]['stack']) | ||
478 | 224 | self.assertIs(None, logger.queries[0]['exception']) | ||
479 | 225 | self.assertEqual( | ||
480 | 226 | (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 42'), | ||
481 | 227 | logger.queries[0]['sql']) | ||
482 | 228 | with stdout() as file: | ||
483 | 229 | result = str(logger) | ||
484 | 230 | self.assertEqual('', file.getvalue()) | ||
485 | 231 | self.assertEqual( | ||
486 | 232 | '1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' + | ||
487 | 233 | "-" * 70 + "\n", | ||
488 | 234 | result) | ||
489 | 235 | |||
490 | 236 | def test_context_manager_with_stacktrace(self): | ||
491 | 237 | logger = da.SQLLogger(tracebacks_if=True) | ||
492 | 238 | with logger: | ||
493 | 239 | self.execute() | ||
494 | 240 | self.assertEqual(1, len(logger.queries)) | ||
495 | 241 | self.assertIsNot(None, logger.queries[0]['stack']) | ||
496 | 242 | |||
497 | 243 | def test_sql_parameters(self): | ||
498 | 244 | logger = da.SQLLogger() | ||
499 | 245 | with logger: | ||
500 | 246 | self.execute(statement='SELECT * FROM bar WHERE bing = %s', | ||
501 | 247 | params=(142,)) | ||
502 | 248 | self.assertEqual( | ||
503 | 249 | (1, 2, 'SQL-stub-database', 'SELECT * FROM bar WHERE bing = 142'), | ||
504 | 250 | logger.queries[0]['sql']) | ||
505 | 251 | |||
506 | 252 | |||
507 | 253 | class TestLoggingWithinRequest(TestCaseWithFactory): | ||
508 | 254 | # When called with a request, the code uses the request timeline and | ||
509 | 255 | # its action objects. | ||
510 | 256 | |||
511 | 257 | layer = DatabaseFunctionalLayer | ||
512 | 258 | |||
513 | 259 | def setUp(self): | ||
514 | 260 | super(TestLoggingWithinRequest, self).setUp() | ||
515 | 261 | self.connection = StubConnection() | ||
516 | 262 | self.person = self.factory.makePerson() | ||
517 | 263 | da.set_request_started(1000.0) | ||
518 | 264 | self.addCleanup(da.clear_request_started) | ||
519 | 265 | |||
520 | 266 | def test_logger(self): | ||
521 | 267 | tracer = da.LaunchpadStatementTracer() | ||
522 | 268 | logger = da.SQLLogger() | ||
523 | 269 | with person_logged_in(self.person): | ||
524 | 270 | with logger: | ||
525 | 271 | tracer.connection_raw_execute( | ||
526 | 272 | self.connection, None, | ||
527 | 273 | 'SELECT * FROM bar WHERE bing = 42', ()) | ||
528 | 274 | timeline = get_request_timeline(get_current_browser_request()) | ||
529 | 275 | action = timeline.actions[-1] | ||
530 | 276 | self.assertEqual( | ||
531 | 277 | 'SELECT * FROM bar WHERE bing = 42', | ||
532 | 278 | action.detail) | ||
533 | 279 | self.assertEqual('SQL-stub-database', action.category) | ||
534 | 280 | self.assertIs(None, action.duration) | ||
535 | 281 | # Now we change the detail to verify that the action is the | ||
536 | 282 | # source of the final log. | ||
537 | 283 | action.detail = 'SELECT * FROM surprise' | ||
538 | 284 | tracer.connection_raw_execute_success( | ||
539 | 285 | self.connection, None, | ||
540 | 286 | 'SELECT * FROM bar WHERE bing = 42', ()) | ||
541 | 287 | self.assertIsNot(None, action.duration) | ||
542 | 288 | self.assertEqual( | ||
543 | 289 | 'SELECT * FROM surprise', logger.queries[0]['sql'][3]) | ||
544 | 290 | |||
545 | 291 | def test_stderr(self): | ||
546 | 292 | with override_environ(LP_DEBUG_SQL='1'): | ||
547 | 293 | tracer = da.LaunchpadStatementTracer() | ||
548 | 294 | with person_logged_in(self.person): | ||
549 | 295 | with stderr() as file: | ||
550 | 296 | tracer.connection_raw_execute( | ||
551 | 297 | self.connection, None, | ||
552 | 298 | 'SELECT * FROM bar WHERE bing = 42', ()) | ||
553 | 299 | timeline = get_request_timeline(get_current_browser_request()) | ||
554 | 300 | action = timeline.actions[-1] | ||
555 | 301 | self.assertEqual( | ||
556 | 302 | 'SELECT * FROM bar WHERE bing = 42', | ||
557 | 303 | action.detail) | ||
558 | 304 | self.assertEqual('SQL-stub-database', action.category) | ||
559 | 305 | self.assertIs(None, action.duration) | ||
560 | 306 | # Now we change the detail to verify that the action is the | ||
561 | 307 | # source of the final log. | ||
562 | 308 | action.detail = 'SELECT * FROM surprise' | ||
563 | 309 | tracer.connection_raw_execute_success( | ||
564 | 310 | self.connection, None, | ||
565 | 311 | 'SELECT * FROM bar WHERE bing = 42', ()) | ||
566 | 312 | self.assertIsNot(None, action.duration) | ||
567 | 313 | self.assertEndsWith( | ||
568 | 314 | file.getvalue(), | ||
569 | 315 | '@SQL-stub-database SELECT * FROM surprise\n' + | ||
570 | 316 | "-" * 70 + "\n") | ||
571 | 0 | 317 | ||
572 | === modified file 'lib/lp/services/profile/profile.py' | |||
573 | --- lib/lp/services/profile/profile.py 2011-08-24 17:24:38 +0000 | |||
574 | +++ lib/lp/services/profile/profile.py 2011-09-02 16:31:40 +0000 | |||
575 | @@ -213,7 +213,7 @@ | |||
576 | 213 | actions.add('callgrind') | 213 | actions.add('callgrind') |
577 | 214 | if actions: | 214 | if actions: |
578 | 215 | if 'sqltrace' in actions: | 215 | if 'sqltrace' in actions: |
580 | 216 | da.start_sql_traceback_logging() | 216 | da.start_sql_logging(tracebacks_if=True) |
581 | 217 | if 'show' in actions or actions.intersection(available_profilers): | 217 | if 'show' in actions or actions.intersection(available_profilers): |
582 | 218 | _profilers.profiler = Profiler() | 218 | _profilers.profiler = Profiler() |
583 | 219 | _profilers.profiler.start() | 219 | _profilers.profiler.start() |
584 | @@ -346,7 +346,7 @@ | |||
585 | 346 | del prof_stats | 346 | del prof_stats |
586 | 347 | trace = None | 347 | trace = None |
587 | 348 | if 'sqltrace' in actions: | 348 | if 'sqltrace' in actions: |
589 | 349 | trace = da.stop_sql_traceback_logging() or () | 349 | trace = da.stop_sql_logging() or () |
590 | 350 | # The trace is a list of dicts, each with the keys "sql" and | 350 | # The trace is a list of dicts, each with the keys "sql" and |
591 | 351 | # "stack". "sql" is a tuple of start time, stop time, database | 351 | # "stack". "sql" is a tuple of start time, stop time, database |
592 | 352 | # name (with a "SQL-" prefix), and sql statement. "stack" is a | 352 | # name (with a "SQL-" prefix), and sql statement. "stack" is a |
593 | 353 | 353 | ||
594 | === modified file 'lib/lp/services/profile/tests.py' | |||
595 | --- lib/lp/services/profile/tests.py 2011-08-22 19:06:39 +0000 | |||
596 | +++ lib/lp/services/profile/tests.py 2011-09-02 16:31:40 +0000 | |||
597 | @@ -82,7 +82,6 @@ | |||
598 | 82 | profile._profilers.actions = None | 82 | profile._profilers.actions = None |
599 | 83 | profile._profilers.memory_profile_start = None | 83 | profile._profilers.memory_profile_start = None |
600 | 84 | profile._profilers.profiling = False | 84 | profile._profilers.profiling = False |
601 | 85 | da.stop_sql_traceback_logging() | ||
602 | 86 | super(TestCleanupProfiler, self).tearDown() | 85 | super(TestCleanupProfiler, self).tearDown() |
603 | 87 | 86 | ||
604 | 88 | 87 | ||
605 | @@ -275,7 +274,7 @@ | |||
606 | 275 | profile.start_request(self._get_start_event('/++profile++sqltrace/')) | 274 | profile.start_request(self._get_start_event('/++profile++sqltrace/')) |
607 | 276 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) | 275 | self.assertIs(getattr(profile._profilers, 'profiler', None), None) |
608 | 277 | self.assertEquals(profile._profilers.actions, set(('sqltrace', ))) | 276 | self.assertEquals(profile._profilers.actions, set(('sqltrace', ))) |
610 | 278 | self.assertEqual([], da.stop_sql_traceback_logging()) | 277 | self.assertEqual([], da.stop_sql_logging()) |
611 | 279 | 278 | ||
612 | 280 | 279 | ||
613 | 281 | class BaseRequestEndHandlerTest(BaseTest): | 280 | class BaseRequestEndHandlerTest(BaseTest): |
Gary, this looks good.