From: Mike Bayer Date: Mon, 22 Aug 2011 15:12:36 +0000 (-0400) Subject: - Improvement to multi-param statement logging, X-Git-Tag: rel_0_7_3~66 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d3c1f245efb22b45c77561345346469cf6a82ddd;p=thirdparty%2Fsqlalchemy%2Fsqlalchemy.git - 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] --- diff --git a/CHANGES b/CHANGES index 54e0a27fdd..563e36df8b 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 3139904d24..e350b5bedc 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 951e44d61a..0cc52fd25c 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 fa65070aa8..61a95d764d 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 5f11684ba0..25108d7da6 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):