launchpad-reviewers team mailing list archive

[William Grant <me@xxxxxxxxxxxxxxxxxx>]

William Grant has proposed merging lp:~wgrant/launchpad/improve-sql-logging into lp:launchpad.

Commit message:
LaunchpadStatementTracer now logs genuine SQL rather than a cheap imitation with broken parameters.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)

For more details, see:
https://code.launchpad.net/~wgrant/launchpad/improve-sql-logging/+merge/134268

The database statements logged in OOPSes and with LP_DEBUG_SQL have forever taunted us with their strange almost-but-not-quite-SQL. This ends today.

I've switched our statement tracer to use psycopg2's mogrify method, which is what it uses internally in execute().
-- 
https://code.launchpad.net/~wgrant/launchpad/improve-sql-logging/+merge/134268
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~wgrant/launchpad/improve-sql-logging into lp:launchpad.

=== modified file 'lib/lp/services/webapp/adapter.py'
--- lib/lp/services/webapp/adapter.py	2012-10-17 12:51:44 +0000
+++ lib/lp/services/webapp/adapter.py	2012-11-14 09:37:21 +0000
@@ -30,10 +30,7 @@
     QueryCanceledError,
     )
 import pytz
-from storm.database import (
-    Connection,
-    register_scheme,
-    )
+from storm.database import register_scheme
 from storm.databases.postgres import (
     Postgres,
     PostgresTimeoutTracer,
@@ -661,18 +658,8 @@
                                statement, params):
         statement_to_log = statement
         if 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))
-            # We need to ensure % symbols used for LIKE statements etc are
-            # properly quoted or else the string format operation will fail.
-            quoted_statement = re.sub(
-                    "%%%", "%%%%", re.sub("%([^s])", r"%%\1", statement))
-            # We need to massage the query parameters a little to deal with
-            # string parameters which represent encoded binary data.
-            param_strings = [repr(p) if isinstance(p, basestring) else p
-                                 for p in query_params]
-            statement_to_log = quoted_statement % tuple(param_strings)
+            statement_to_log = raw_cursor.mogrify(
+                statement, tuple(connection.to_database(params)))
         # Record traceback to log, if requested.
         print_traceback = self._debug_sql_extra
         log_sql = getattr(_local, 'sql_logging', None)

=== modified file 'lib/lp/services/webapp/doc/test_adapter.txt'
--- lib/lp/services/webapp/doc/test_adapter.txt	2012-10-17 12:51:44 +0000
+++ lib/lp/services/webapp/doc/test_adapter.txt	2012-11-14 09:37:21 +0000
@@ -66,10 +66,10 @@
     ...     print statement
     SELECT 1
     SELECT 2
-    SELECT * FROM person where name = u'fred'
+    SELECT * FROM person where name = E'fred'
     SELECT * FROM person where name = '%s foo'
     SELECT * FROM person where id = 2
-    SELECT * FROM person where name like '%%' || u'fred'
+    SELECT * FROM person where name like '%' || E'fred'
     SELECT * FROM person where name like '%d foo'||'%%'
 
 A timeline is created too:
@@ -81,10 +81,10 @@
     ...    print action.detail
     SELECT 1
     SELECT 2
-    SELECT * FROM person where name = u'fred'
+    SELECT * FROM person where name = E'fred'
     SELECT * FROM person where name = '%s foo'
     SELECT * FROM person where id = 2
-    SELECT * FROM person where name like '%%' || u'fred'
+    SELECT * FROM person where name like '%' || E'fred'
     SELECT * FROM person where name like '%d foo'||'%%'
 
 After we complete the request, the statement log is cleared:

=== modified file 'lib/lp/services/webapp/tests/test_statementtracer.py'
--- lib/lp/services/webapp/tests/test_statementtracer.py	2012-01-01 02:58:52 +0000
+++ lib/lp/services/webapp/tests/test_statementtracer.py	2012-11-14 09:37:21 +0000
@@ -60,12 +60,28 @@
     def __init__(self):
         self._database = type('StubDatabase', (), dict(name='stub-database'))
 
+    def to_database(self, params):
+        for param in params:
+            yield param
+
+
+class StubCursor:
+
+    def mogrify(self, statement, params):
+        # This will behave rather differently than the real thing for
+        # most types, but we can't use psycopg2's mogrify without a real
+        # connection.
+        mangled_params = tuple(
+            repr(p) if isinstance(p, basestring) else p for p in params)
+        return statement % tuple(mangled_params)
+
 
 class TestLoggingOutsideOfRequest(TestCase):
 
     def setUp(self):
         super(TestLoggingOutsideOfRequest, self).setUp()
         self.connection = StubConnection()
+        self.cursor = StubCursor()
         original_time = da.time
         self.addCleanup(setattr, da, 'time', original_time)
         da.time = StubTime()
@@ -76,9 +92,9 @@
         if statement is None:
             statement = 'SELECT * FROM bar WHERE bing = 42'
         tracer.connection_raw_execute(
-            self.connection, None, statement, params)
+            self.connection, self.cursor, statement, params)
         tracer.connection_raw_execute_success(
-            self.connection, None, statement, params)
+            self.connection, self.cursor, statement, params)
 
     def test_no_logging(self):
         with stderr() as file: