- 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

3 files changed, 106 insertions, 12 deletions

diff --git a/doc/build/changelog/changelog_09.rst b/doc/build/changelog/changelog_09.rst
index b6eec2e9d..6795a101c 100644
--- a/doc/build/changelog/changelog_09.rst
+++ b/doc/build/changelog/changelog_09.rst
@@ -14,6 +14,17 @@
     :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
         :pullreq: github:125
diff --git a/lib/sqlalchemy/pool.py b/lib/sqlalchemy/pool.py
index d26bbf32c..89cddfc31 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 5d792e470..1432a0f7b 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',