From cea97d1fae999001eb991ae1da9db226f2d3b5da Mon Sep 17 00:00:00 2001 From: Mike Bayer Date: Wed, 20 Aug 2014 09:08:59 -0400 Subject: [PATCH 1/2] - pep8 cleanup --- test/engine/test_execute.py | 1 - test/engine/test_logging.py | 37 +++++++++++++------------------------ 2 files changed, 13 insertions(+), 25 deletions(-) diff --git a/test/engine/test_execute.py b/test/engine/test_execute.py index f65168552a..d8e1c655e9 100644 --- a/test/engine/test_execute.py +++ b/test/engine/test_execute.py @@ -21,7 +21,6 @@ from sqlalchemy.testing import fixtures from sqlalchemy.testing.mock import Mock, call, patch from contextlib import contextmanager from sqlalchemy.util import nested -import logging.handlers # needed for logging tests to work correctly users, metadata, users_autoinc = None, None, None diff --git a/test/engine/test_logging.py b/test/engine/test_logging.py index ea2ad3964b..5d792e4701 100644 --- a/test/engine/test_logging.py +++ b/test/engine/test_logging.py @@ -1,30 +1,17 @@ -from sqlalchemy.testing import eq_, assert_raises, assert_raises_message, \ - config, is_ -import re -from sqlalchemy.testing.util import picklers -from sqlalchemy.interfaces import ConnectionProxy -from sqlalchemy import MetaData, Integer, String, INT, VARCHAR, func, \ - bindparam, select, event, TypeDecorator, create_engine, Sequence -from sqlalchemy.sql import column, literal -from sqlalchemy.testing.schema import Table, Column +from sqlalchemy.testing import eq_, assert_raises_message +from sqlalchemy import select import sqlalchemy as tsa -from sqlalchemy import testing from sqlalchemy.testing import engines -from sqlalchemy import util -from sqlalchemy.testing.engines import testing_engine import logging.handlers -from sqlalchemy.dialects.oracle.zxjdbc import ReturningParam -from sqlalchemy.engine import result as _result, default -from sqlalchemy.engine.base import Engine from sqlalchemy.testing import fixtures -from sqlalchemy.testing.mock import Mock, call, patch + class LogParamsTest(fixtures.TestBase): __only_on__ = 'sqlite' __requires__ = 'ad_hoc_engines', def setup(self): - self.eng = engines.testing_engine(options={'echo':True}) + 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 [ @@ -44,7 +31,7 @@ class LogParamsTest(fixtures.TestBase): def test_log_large_dict(self): self.eng.execute( "INSERT INTO foo (data) values (:data)", - [{"data":str(i)} for i in range(100)] + [{"data": str(i)} for i in range(100)] ) eq_( self.buf.buffer[1].message, @@ -76,7 +63,7 @@ class LogParamsTest(fixtures.TestBase): "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 range(100)] + [{"data": str(i)} for i in range(100)] ) ) @@ -94,6 +81,7 @@ class LogParamsTest(fixtures.TestBase): ) ) + class LoggingNameTest(fixtures.TestBase): __requires__ = 'ad_hoc_engines', @@ -104,7 +92,7 @@ class LoggingNameTest(fixtures.TestBase): assert name in ( 'sqlalchemy.engine.base.Engine.%s' % eng_name, 'sqlalchemy.pool.%s.%s' % - (eng.pool.__class__.__name__, pool_name) + (eng.pool.__class__.__name__, pool_name) ) def _assert_no_name_in_execute(self, eng): @@ -118,15 +106,15 @@ class LoggingNameTest(fixtures.TestBase): def _named_engine(self, **kw): options = { - 'logging_name':'myenginename', - 'pool_logging_name':'mypoolname', - 'echo':True + 'logging_name': 'myenginename', + 'pool_logging_name': 'mypoolname', + 'echo': True } options.update(kw) return engines.testing_engine(options=options) def _unnamed_engine(self, **kw): - kw.update({'echo':True}) + kw.update({'echo': True}) return engines.testing_engine(options=kw) def setup(self): @@ -183,6 +171,7 @@ class LoggingNameTest(fixtures.TestBase): eng = self._unnamed_engine(echo='debug', echo_pool='debug') self._assert_no_name_in_execute(eng) + class EchoTest(fixtures.TestBase): __requires__ = 'ad_hoc_engines', From 92b0ad0fef0b9ee3d54767cf17e2baf1fd1546da Mon Sep 17 00:00:00 2001 From: Mike Bayer Date: Wed, 20 Aug 2014 12:01:20 -0400 Subject: [PATCH 2/2] - Fixed bug in connection pool logging where the "connection checked out" debug logging message would not emit if the logging were set up using ``logging.setLevel()``, rather than using the ``echo_pool`` flag. Tests to assert this logging have been added. This is a regression that was introduced in 0.9.0. fixes #3168 --- doc/build/changelog/changelog_09.rst | 11 ++++ lib/sqlalchemy/pool.py | 22 +++---- test/engine/test_logging.py | 85 +++++++++++++++++++++++++++- 3 files changed, 106 insertions(+), 12 deletions(-) diff --git a/doc/build/changelog/changelog_09.rst b/doc/build/changelog/changelog_09.rst index b6eec2e9db..6795a101c5 100644 --- a/doc/build/changelog/changelog_09.rst +++ b/doc/build/changelog/changelog_09.rst @@ -13,6 +13,17 @@ .. changelog:: :version: 0.9.8 + .. change:: + :tags: bug, pool + :versions: 1.0.0 + :tickets: 3168 + + Fixed bug in connection pool logging where the "connection checked out" + debug logging message would not emit if the logging were set up using + ``logging.setLevel()``, rather than using the ``echo_pool`` flag. + Tests to assert this logging have been added. This is a + regression that was introduced in 0.9.0. + .. change:: :tags: feature, postgresql, pg8000 :versions: 1.0.0 diff --git a/lib/sqlalchemy/pool.py b/lib/sqlalchemy/pool.py index d26bbf32c1..89cddfc312 100644 --- a/lib/sqlalchemy/pool.py +++ b/lib/sqlalchemy/pool.py @@ -443,16 +443,17 @@ class _ConnectionRecord(object): except: rec.checkin() raise - fairy = _ConnectionFairy(dbapi_connection, rec) + echo = pool._should_log_debug() + fairy = _ConnectionFairy(dbapi_connection, rec, echo) rec.fairy_ref = weakref.ref( fairy, lambda ref: _finalize_fairy and _finalize_fairy( dbapi_connection, - rec, pool, ref, pool._echo) + rec, pool, ref, echo) ) _refs.add(rec) - if pool._echo: + if echo: pool.logger.debug("Connection %r checked out from pool", dbapi_connection) return fairy @@ -560,9 +561,10 @@ def _finalize_fairy(connection, connection_record, connection) try: - fairy = fairy or _ConnectionFairy(connection, connection_record) + fairy = fairy or _ConnectionFairy( + connection, connection_record, echo) assert fairy.connection is connection - fairy._reset(pool, echo) + fairy._reset(pool) # Immediately close detached instances if not connection_record: @@ -603,9 +605,10 @@ class _ConnectionFairy(object): """ - def __init__(self, dbapi_connection, connection_record): + def __init__(self, dbapi_connection, connection_record, echo): self.connection = dbapi_connection self._connection_record = connection_record + self._echo = echo connection = None """A reference to the actual DBAPI connection being tracked.""" @@ -642,7 +645,6 @@ class _ConnectionFairy(object): fairy._pool = pool fairy._counter = 0 - fairy._echo = pool._should_log_debug() if threadconns is not None: threadconns.current = weakref.ref(fairy) @@ -684,11 +686,11 @@ class _ConnectionFairy(object): _close = _checkin - def _reset(self, pool, echo): + def _reset(self, pool): if pool.dispatch.reset: pool.dispatch.reset(self, self._connection_record) if pool._reset_on_return is reset_rollback: - if echo: + if self._echo: pool.logger.debug("Connection %s rollback-on-return%s", self.connection, ", via agent" @@ -698,7 +700,7 @@ class _ConnectionFairy(object): else: pool._dialect.do_rollback(self) elif pool._reset_on_return is reset_commit: - if echo: + if self._echo: pool.logger.debug("Connection %s commit-on-return%s", self.connection, ", via agent" diff --git a/test/engine/test_logging.py b/test/engine/test_logging.py index 5d792e4701..1432a0f7bf 100644 --- a/test/engine/test_logging.py +++ b/test/engine/test_logging.py @@ -4,6 +4,8 @@ import sqlalchemy as tsa from sqlalchemy.testing import engines import logging.handlers from sqlalchemy.testing import fixtures +from sqlalchemy.testing import mock +from sqlalchemy.testing.util import lazy_gc class LogParamsTest(fixtures.TestBase): @@ -16,7 +18,6 @@ class LogParamsTest(fixtures.TestBase): self.buf = logging.handlers.BufferingHandler(100) for log in [ logging.getLogger('sqlalchemy.engine'), - logging.getLogger('sqlalchemy.pool') ]: log.addHandler(self.buf) @@ -24,7 +25,6 @@ class LogParamsTest(fixtures.TestBase): self.eng.execute("drop table foo") for log in [ logging.getLogger('sqlalchemy.engine'), - logging.getLogger('sqlalchemy.pool') ]: log.removeHandler(self.buf) @@ -82,6 +82,87 @@ class LogParamsTest(fixtures.TestBase): ) +class PoolLoggingTest(fixtures.TestBase): + def setup(self): + self.existing_level = logging.getLogger("sqlalchemy.pool").level + + self.buf = logging.handlers.BufferingHandler(100) + for log in [ + logging.getLogger('sqlalchemy.pool') + ]: + log.addHandler(self.buf) + + def teardown(self): + for log in [ + logging.getLogger('sqlalchemy.pool') + ]: + log.removeHandler(self.buf) + logging.getLogger("sqlalchemy.pool").setLevel(self.existing_level) + + def _queuepool_echo_fixture(self): + return tsa.pool.QueuePool(creator=mock.Mock(), echo='debug') + + def _queuepool_logging_fixture(self): + logging.getLogger("sqlalchemy.pool").setLevel(logging.DEBUG) + return tsa.pool.QueuePool(creator=mock.Mock()) + + def _stpool_echo_fixture(self): + return tsa.pool.SingletonThreadPool(creator=mock.Mock(), echo='debug') + + def _stpool_logging_fixture(self): + logging.getLogger("sqlalchemy.pool").setLevel(logging.DEBUG) + return tsa.pool.SingletonThreadPool(creator=mock.Mock()) + + def _test_queuepool(self, q, dispose=True): + conn = q.connect() + conn.close() + conn = None + + conn = q.connect() + conn.close() + conn = None + + conn = q.connect() + conn = None + del conn + lazy_gc() + q.dispose() + + eq_( + [buf.msg for buf in self.buf.buffer], + [ + 'Created new connection %r', + 'Connection %r checked out from pool', + 'Connection %r being returned to pool', + 'Connection %s rollback-on-return%s', + 'Connection %r checked out from pool', + 'Connection %r being returned to pool', + 'Connection %s rollback-on-return%s', + 'Connection %r checked out from pool', + 'Connection %r being returned to pool', + 'Connection %s rollback-on-return%s', + 'Closing connection %r', + + ] + (['Pool disposed. %s'] if dispose else []) + ) + + def test_stpool_echo(self): + q = self._stpool_echo_fixture() + self._test_queuepool(q, False) + + def test_stpool_logging(self): + q = self._stpool_logging_fixture() + self._test_queuepool(q, False) + + def test_queuepool_echo(self): + q = self._queuepool_echo_fixture() + self._test_queuepool(q) + + def test_queuepool_logging(self): + q = self._queuepool_logging_fixture() + self._test_queuepool(q) + + class LoggingNameTest(fixtures.TestBase): __requires__ = 'ad_hoc_engines',