- Improvement to multi-param statement logging,

long lists of bound parameter sets will be
compressed with an informative indicator
of the compression taking place.  Exception
messages use the same improved formatting.
[ticket:2243]

5 files changed, 115 insertions, 11 deletions

diff --git a/CHANGES b/CHANGES
index 54e0a27fd..563e36df8 100644
--- a/CHANGES
+++ b/CHANGES
@@ -49,6 +49,13 @@ CHANGES
     there's no usual need to subclass pools.
     [ticket:2254]
 
+  - Improvement to multi-param statement logging,
+    long lists of bound parameter sets will be 
+    compressed with an informative indicator
+    of the compression taking place.  Exception
+    messages use the same improved formatting.  
+    [ticket:2243]
+
 - types
   - Extra keyword arguments to the base Float 
     type beyond "precision" and "asdecimal" are ignored;
diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py
index 3139904d2..e350b5bed 100644
--- a/lib/sqlalchemy/engine/base.py
+++ b/lib/sqlalchemy/engine/base.py
@@ -24,7 +24,7 @@ import inspect, StringIO, sys, operator
 from itertools import izip
 from sqlalchemy import exc, schema, util, types, log, interfaces, \
     event, events
-from sqlalchemy.sql import expression
+from sqlalchemy.sql import expression, util as sql_util
 from sqlalchemy import processors
 import collections
 
@@ -1617,7 +1617,7 @@ class Connection(Connectable):
 
         if self._echo:
             self.engine.logger.info(statement)
-            self.engine.logger.info("%r", parameters)
+            self.engine.logger.info("%r", sql_util._repr_params(parameters, batches=10))
         try:
             if context.executemany:
                 self.dialect.do_executemany(
diff --git a/lib/sqlalchemy/exc.py b/lib/sqlalchemy/exc.py
index 951e44d61..0cc52fd25 100644
--- a/lib/sqlalchemy/exc.py
+++ b/lib/sqlalchemy/exc.py
@@ -146,15 +146,11 @@ class StatementError(SQLAlchemyError):
         self.orig = orig
 
     def __str__(self):
-        if isinstance(self.params, (list, tuple)) and \
-            len(self.params) > 10 and \
-            isinstance(self.params[0], (list, dict, tuple)):
-            return ' '.join((SQLAlchemyError.__str__(self),
-                             repr(self.statement),
-                             repr(self.params[:2]),
-                             '... and a total of %i bound parameter sets' % len(self.params)))
+        from sqlalchemy.sql import util
+        params_repr = util._repr_params(self.params, 10)
         return ' '.join((SQLAlchemyError.__str__(self),
-                         repr(self.statement), repr(self.params)))
+                         repr(self.statement), repr(params_repr)))
+
 
 class DBAPIError(StatementError):
     """Raised when the execution of a database operation fails.
diff --git a/lib/sqlalchemy/sql/util.py b/lib/sqlalchemy/sql/util.py
index fa65070aa..61a95d764 100644
--- a/lib/sqlalchemy/sql/util.py
+++ b/lib/sqlalchemy/sql/util.py
@@ -170,6 +170,28 @@ def _quote_ddl_expr(element):
     else:
         return repr(element)
 
+class _repr_params(object):
+    """A string view of bound parameters, truncating
+    display to the given number of 'multi' parameter sets.
+    
+    """
+    def __init__(self, params, batches):
+        self.params = params
+        self.batches = batches
+
+    def __repr__(self):
+        if isinstance(self.params, (list, tuple)) and \
+            len(self.params) > self.batches and \
+            isinstance(self.params[0], (list, dict, tuple)):
+            return ' '.join((
+                        repr(self.params[:self.batches - 2])[0:-1],
+                        " ... displaying %i of %i total bound parameter sets ... " % (self.batches, len(self.params)),
+                        repr(self.params[-2:])[1:]
+                    ))
+        else:
+            return repr(self.params)
+
+
 def expression_as_ddl(clause):
     """Given a SQL expression, convert for usage in DDL, such as 
      CREATE INDEX and CHECK CONSTRAINT.
diff --git a/test/engine/test_execute.py b/test/engine/test_execute.py
index 5f11684ba..25108d7da 100644
--- a/test/engine/test_execute.py
+++ b/test/engine/test_execute.py
@@ -272,11 +272,87 @@ class CompiledCacheTest(fixtures.TestBase):
         assert len(cache) == 1
         eq_(conn.execute("select count(*) from users").scalar(), 3)
 
+class LogParamsTest(fixtures.TestBase):
+    __only_on__ = 'sqlite'
+    __requires__ = 'ad_hoc_engines',
+
+    def setup(self):
+        self.eng = engines.testing_engine(options={'echo':True})
+        self.eng.execute("create table foo (data string)")
+        self.buf = logging.handlers.BufferingHandler(100)
+        for log in [
+            logging.getLogger('sqlalchemy.engine'),
+            logging.getLogger('sqlalchemy.pool')
+        ]:
+            log.addHandler(self.buf)
+
+    def teardown(self):
+        self.eng.execute("drop table foo")
+        for log in [
+            logging.getLogger('sqlalchemy.engine'),
+            logging.getLogger('sqlalchemy.pool')
+        ]:
+            log.removeHandler(self.buf)
+
+    def test_log_large_dict(self):
+        self.eng.execute(
+            "INSERT INTO foo (data) values (:data)", 
+            [{"data":str(i)} for i in xrange(100)]
+        )
+        eq_(
+            self.buf.buffer[1].message,
+            "[{'data': '0'}, {'data': '1'}, {'data': '2'}, {'data': '3'}, "
+            "{'data': '4'}, {'data': '5'}, {'data': '6'}, {'data': '7'}"
+            "  ... displaying 10 of 100 total bound "
+            "parameter sets ...  {'data': '98'}, {'data': '99'}]"
+        )
+
+    def test_log_large_list(self):
+        self.eng.execute(
+            "INSERT INTO foo (data) values (?)", 
+            [(str(i), ) for i in xrange(100)]
+        )
+        eq_(
+            self.buf.buffer[1].message,
+            "[('0',), ('1',), ('2',), ('3',), ('4',), ('5',), "
+            "('6',), ('7',)  ... displaying 10 of 100 total "
+            "bound parameter sets ...  ('98',), ('99',)]"
+        )
+
+    def test_error_large_dict(self):
+        assert_raises_message(
+            tsa.exc.DBAPIError,
+            r".*'INSERT INTO nonexistent \(data\) values \(:data\)' "
+            "\[{'data': '0'}, {'data': '1'}, {'data': '2'}, "
+            "{'data': '3'}, {'data': '4'}, {'data': '5'}, "
+            "{'data': '6'}, {'data': '7'}  ... displaying 10 of "
+            "100 total bound parameter sets ...  {'data': '98'}, {'data': '99'}\]",
+            lambda: self.eng.execute(
+                "INSERT INTO nonexistent (data) values (:data)", 
+                [{"data":str(i)} for i in xrange(100)]
+            )
+        )
+
+    def test_error_large_list(self):
+        assert_raises_message(
+            tsa.exc.DBAPIError,
+            r".*INSERT INTO nonexistent \(data\) values "
+            "\(\?\)' \[\('0',\), \('1',\), \('2',\), \('3',\), "
+            "\('4',\), \('5',\), \('6',\), \('7',\)  ... displaying "
+            "10 of 100 total bound parameter sets ...  "
+            "\('98',\), \('99',\)\]",
+            lambda: self.eng.execute(
+                "INSERT INTO nonexistent (data) values (?)", 
+                [(str(i), ) for i in xrange(100)]
+            )
+        )
+
 class LoggingNameTest(fixtures.TestBase):
     __requires__ = 'ad_hoc_engines',
 
     def _assert_names_in_execute(self, eng, eng_name, pool_name):
         eng.execute(select([1]))
+        assert self.buf.buffer
         for name in [b.name for b in self.buf.buffer]:
             assert name in (
                 'sqlalchemy.engine.base.Engine.%s' % eng_name,
@@ -286,6 +362,7 @@ class LoggingNameTest(fixtures.TestBase):
 
     def _assert_no_name_in_execute(self, eng):
         eng.execute(select([1]))
+        assert self.buf.buffer
         for name in [b.name for b in self.buf.buffer]:
             assert name in (
                 'sqlalchemy.engine.base.Engine',
@@ -295,12 +372,14 @@ class LoggingNameTest(fixtures.TestBase):
     def _named_engine(self, **kw):
         options = {
             'logging_name':'myenginename',
-            'pool_logging_name':'mypoolname'
+            'pool_logging_name':'mypoolname',
+            'echo':True
         }
         options.update(kw)
         return engines.testing_engine(options=options)
 
     def _unnamed_engine(self, **kw):
+        kw.update({'echo':True})
         return engines.testing_engine(options=kw)
 
     def setup(self):