Merge lp:~lifeless/storm/timelinetracer into lp:storm

[Robert Collins]

Follow on from https://code.launchpad.net/~lifeless/storm/timelinetracer/+merge/74947 addressing JamesH's concerns.

[James Henstridge (jamesh)]

Looks good. I noticed a few small issues, but it looks pretty much ready to merge:

[1]
+ # be preserved as that is where we are substiting values in.

Should be "substituting"

[2]
+ #param timeline_factory: A factory function to produce the timeline to

Should be "@param"

[3]
It looks like all the tests are running with conn.param_mark == '?'. It'd be good to have at least one that runs with a StubConnection with param_mark set to '%s' to test the other branch in connection_raw_execute.

review: Approve

[Robert Collins (lifeless)]

all actioned, pushing it up now. Thanks!

=== modified file 'storm/tracer.py'
--- storm/tracer.py	2011-09-12 06:43:04 +0000
+++ storm/tracer.py	2011-09-13 04:08:34 +0000
@@ -118,12 +118,20 @@
             # 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(
+            if connection.param_mark == '%s':
+                # Double the %'s in the string so that python string formatting
+                # can restore them to the correct number. Note that %s needs to
+                # be preserved as that is where we are substiting values in.
+                quoted_statement = re.sub(
                     "%%%", "%%%%", re.sub("%([^s])", r"%%\1", statement))
-            quoted_statement = convert_param_marks(
-                quoted_statement, connection.param_mark, "%s")
+            else:
+                # Double all the %'s in the statement so that python string
+                # formatting can restore them to the correct number. Any %s in
+                # the string should be preserved because the param_mark is not
+                # %s.
+                quoted_statement = re.sub("%", "%%", statement)
+                quoted_statement = convert_param_marks(
+                    quoted_statement, connection.param_mark, "%s")
             # We need to massage the query parameters a little to deal with
             # string parameters which represent encoded binary data.
             render_params = []
@@ -132,7 +140,12 @@
                     render_params.append(repr(param.encode('utf8')))
                 else:
                     render_params.append(repr(param))
-            statement_to_log = quoted_statement % tuple(render_params)
+            try:
+                statement_to_log = quoted_statement % tuple(render_params)
+            except TypeError:
+                statement_to_log = \
+                    "Unformattable query: %r with params %r." % (
+                    statement, query_params)
         self._expanded_raw_execute(connection, raw_cursor, statement_to_log)
 
     def _expanded_raw_execute(self, connection, raw_cursor, statement):
@@ -146,26 +159,29 @@
     For more information on timelines see the module at
     http://pypi.python.org/pypi/timeline.
     
-    The timeline to use is obtained via a threading.local lookup -
-    self.threadinfo.timeline. If TimelineTracer is being used in a thread
-    pooling environment, you should set this to the timeline you wish to
-    accumulate actions against before making queries.
+    The timeline to use is obtained by calling the timeline_factory supplied to
+    the constructor. This simple function takes no parameters and returns a
+    timeline to use. If it returns None, the tracer is bypassed.
     """
 
-    def __init__(self, prefix='SQL-'):
+    def __init__(self, timeline_factory, prefix='SQL-'):
         """Create a TimelineTracer.
 
+        #param timeline_factory: A factory function to produce the timeline to
+            record a query against.
         @param prefix: A prefix to give the connection name when starting an
             action. Connection names are found by trying a getattr for 'name'
             on the connection object. If no name has been assigned, '<unknown>'
             is used instead.
         """
         super(TimelineTracer, self).__init__()
+        self.timeline_factory = timeline_factory
+        self.prefix = prefix
+        # Stores the action in progress in a given thread.
         self.threadinfo = threading.local()
-        self.prefix = prefix
 
     def _expanded_raw_execute(self, connection, raw_cursor, statement):
-        timeline = getattr(self.threadinfo, 'timeline', None)
+        timeline = self.timeline_factory()
         if timeline is None:
             return
         connection_name = getattr(connection, 'name', '<unknown>')

=== modified file 'tests/tracer.py'
--- tests/tracer.py	2011-09-12 10:24:04 +0000
+++ tests/tracer.py	2011-09-13 04:08:34 +0000
@@ -361,6 +361,19 @@
             [(conn, 'cursor', "SELECT * FROM person where name = 'VAR1'")],
             tracer.calls)
 
+    def test_qmark_percent_s_literal_preserved(self):
+        """With ? parameters %s in the statement can be kept intact."""
+        tracer = self.LoggingBaseStatementTracer()
+        conn = self.StubConnection()
+        var1 = MockVariable(1)
+        tracer.connection_raw_execute(
+            conn, 'cursor',
+            "SELECT * FROM person where id > ? AND name LIKE '%s'", [var1])
+        self.assertEqual(
+            [(conn, 'cursor',
+              "SELECT * FROM person where id > 1 AND name LIKE '%s'")],
+            tracer.calls)
+
     def test_int_variable_as_int(self):
         """Int parameters are formatted as an int literal."""
         tracer = self.LoggingBaseStatementTracer()
@@ -386,21 +399,37 @@
                               "LIKE '%%' || 'substring' || '-suffix%%'")],
             tracer.calls)
 
+    def test_unformattable_statements_are_handled(self):
+        tracer = self.LoggingBaseStatementTracer()
+        conn = self.StubConnection()
+        var1 = MockVariable(u'substring')
+        tracer.connection_raw_execute(
+            conn, 'cursor', "%s %s",
+            [var1])
+        self.assertEqual(
+            [(conn, 'cursor',
+              "Unformattable query: '%s %s' with params [u'substring'].")],
+            tracer.calls)
+
 
 class TimelineTracerTest(TestHelper):
 
     def is_supported(self):
         return timeline is not None
 
+    def factory(self):
+        self.timeline = timeline.Timeline()
+        return self.timeline
+
     def test_separate_tracers_own_state(self):
         """"Check that multiple TimelineTracer's could be used at once."""
-        tracer1 = TimelineTracer()
-        tracer2 = TimelineTracer()
-        tracer1.threadinfo.timeline = 'foo'
-        self.assertEqual(None, getattr(tracer2.threadinfo, 'timeline', None))
+        tracer1 = TimelineTracer(self.factory)
+        tracer2 = TimelineTracer(self.factory)
+        tracer1.threadinfo.action = 'foo'
+        self.assertEqual(None, getattr(tracer2.threadinfo, 'action', None))
 
     def test_error_finishes_action(self):
-        tracer = TimelineTracer()
+        tracer = TimelineTracer(self.factory)
         action = timeline.Timeline().start('foo', 'bar')
         tracer.threadinfo.action = action
         tracer.connection_raw_execute_error(
@@ -408,27 +437,25 @@
         self.assertNotEqual(None, action.duration)
 
     def test_success_finishes_action(self):
-        tracer = TimelineTracer()
+        tracer = TimelineTracer(self.factory)
         action = timeline.Timeline().start('foo', 'bar')
         tracer.threadinfo.action = action
         tracer.connection_raw_execute_success(
             'conn', 'cursor', 'statement', 'params')
         self.assertNotEqual(None, action.duration)
 
-    def test_finds_timeline_from_threadinfo(self):
-        """tracer.threadinfo.timeline is writable as part of the API."""
-        tracer = TimelineTracer()
-        tracer.threadinfo.timeline = timeline.Timeline()
+    def test_finds_timeline_from_factory(self):
+        factory_result = timeline.Timeline()
+        factory = lambda:factory_result
+        tracer = TimelineTracer(lambda:factory_result)
         tracer._expanded_raw_execute('conn', 'cursor', 'statement')
-        self.assertEqual(1, len(tracer.threadinfo.timeline.actions))
+        self.assertEqual(1, len(factory_result.actions))
 
     def test_action_details_are_statement(self):
         """The detail in the timeline action is the formatted SQL statement."""
-        tracer = TimelineTracer()
-        tracer.threadinfo.timeline = timeline.Timeline()
+        tracer = TimelineTracer(self.factory)
         tracer._expanded_raw_execute('conn', 'cursor', 'statement')
-        self.assertEqual(
-            'statement', tracer.threadinfo.timeline.actions[-1].detail)
+        self.assertEqual('statement', self.timeline.actions[-1].detail)
 
     def test_category_from_prefix_and_connection_name(self):
         class StubConnection(Connection):
@@ -438,24 +465,18 @@
                 self._event = None
                 self._raw_connection = None
                 self.name = 'Foo'
-        tracer = TimelineTracer(prefix='bar-')
-        tracer.threadinfo.timeline = timeline.Timeline()
+        tracer = TimelineTracer(self.factory, prefix='bar-')
         tracer._expanded_raw_execute(StubConnection(), 'cursor', 'statement')
-        self.assertEqual(
-            'bar-Foo', tracer.threadinfo.timeline.actions[-1].category)
+        self.assertEqual('bar-Foo', self.timeline.actions[-1].category)
 
     def test_unnamed_connection(self):
         """A connection with no name has <unknown> put in as a placeholder."""
-        tracer = TimelineTracer(prefix='bar-')
-        tracer.threadinfo.timeline = timeline.Timeline()
+        tracer = TimelineTracer(self.factory, prefix='bar-')
         tracer._expanded_raw_execute('conn', 'cursor', 'statement')
-        self.assertEqual(
-            'bar-<unknown>', tracer.threadinfo.timeline.actions[-1].category)
+        self.assertEqual('bar-<unknown>', self.timeline.actions[-1].category)
 
     def test_default_prefix(self):
         """By default the prefix "SQL-" is added to the action's category."""
-        tracer = TimelineTracer()
-        tracer.threadinfo.timeline = timeline.Timeline()
+        tracer = TimelineTracer(self.factory)
         tracer._expanded_raw_execute('conn', 'cursor', 'statement')
-        self.assertEqual(
-            'SQL-<unknown>', tracer.threadinfo.timeline.actions[-1].category)
+        self.assertEqual('SQL-<unknown>', self.timeline.actions[-1].category)