launchpad-reviewers team mailing list archive

[Colin Watson <cjwatson@xxxxxxxxxxxxx>]

Colin Watson has proposed merging ~cjwatson/launchpad:statement-tracer-gap-between-requests into launchpad:master.

Commit message:
Fix LaunchpadStatementTracer to handle gaps between requests

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)

For more details, see:
https://code.launchpad.net/~cjwatson/launchpad/+git/launchpad/+merge/394415

If statement tracing spans multiple requests (particularly due to LP_DEBUG_SQL or LP_DEBUG_SQL_EXTRA), then there may be statements executed between requests.  In such a case, connection._lp_statement_action wasn't cleared, which meant that connection_raw_execute_success incorrectly kept on logging information about the last statement in the previous request.
-- 
Your team Launchpad code reviewers is requested to review the proposed merge of ~cjwatson/launchpad:statement-tracer-gap-between-requests into launchpad:master.

diff --git a/lib/lp/services/webapp/adapter.py b/lib/lp/services/webapp/adapter.py
index 24620b3..cb5ac0a 100644
--- a/lib/lp/services/webapp/adapter.py
+++ b/lib/lp/services/webapp/adapter.py
@@ -719,6 +719,7 @@ class LaunchpadStatementTracer:
                     int(time() * 1000),
                     u'SQL-%s' % connection._database.name,
                     statement_to_log)
+                connection._lp_statement_action = None
             return
         action = get_request_timeline(get_current_browser_request()).start(
             u'SQL-%s' % connection._database.name, statement_to_log)
diff --git a/lib/lp/services/webapp/tests/test_statementtracer.py b/lib/lp/services/webapp/tests/test_statementtracer.py
index 51ae1cf..bc5ddef 100644
--- a/lib/lp/services/webapp/tests/test_statementtracer.py
+++ b/lib/lp/services/webapp/tests/test_statementtracer.py
@@ -342,3 +342,29 @@ class TestLoggingWithinRequest(TestCaseWithFactory):
                     file.getvalue(),
                     '@SQL-stub-database SELECT * FROM surprise\n' +
                     "-" * 70 + "\n")
+
+    def test_gap_between_requests(self):
+        # The tracer doesn't get confused by statements executed between
+        # requests.
+        tracer = da.LaunchpadStatementTracer()
+        with person_logged_in(self.person):
+            with StormStatementRecorder() as logger:
+                tracer.connection_raw_execute(
+                    self.connection, None, 'SELECT * FROM one', ())
+                tracer.connection_raw_execute_success(
+                    self.connection, None, 'SELECT * FROM one', ())
+            self.assertEqual(['SELECT * FROM one'], logger.statements)
+            da.clear_request_started()
+            with StormStatementRecorder() as logger:
+                tracer.connection_raw_execute(
+                    self.connection, None, 'SELECT * FROM two', ())
+                tracer.connection_raw_execute_success(
+                    self.connection, None, 'SELECT * FROM two', ())
+            self.assertEqual(['SELECT * FROM two'], logger.statements)
+            da.set_request_started(2000.0)
+            with StormStatementRecorder() as logger:
+                tracer.connection_raw_execute(
+                    self.connection, None, 'SELECT * FROM three', ())
+                tracer.connection_raw_execute_success(
+                    self.connection, None, 'SELECT * FROM three', ())
+            self.assertEqual(['SELECT * FROM three'], logger.statements)