[sqlalchemy] Delayed QueuePool purge causes logger error

[Shige Takeda]

Hi, I'm trying to figure out how to purge connections in the SQLAlchemy's 
connection pool (QueuePool) synchronously. SQLAlchemy version is 1.1.14.

The test case was given from one of the customers. It uses Snowflake DB 
connector that 
leverage the standard Python logging library for logging.

import logging
for logger_name in ['snowflake.connector','botocore']:
logger = logging.getLogger(logger_name)
logger.setLevel(logging.DEBUG)
ch = logging.FileHandler('log')
ch.setLevel(logging.DEBUG)
ch.setFormatter(logging.Formatter('%(asctime)s - %(threadName)s 
%(filename)s:%(lineno)d - %(funcName)s() - %(levelname)s - %(message)s'))
logger.addHandler(ch)

import snowflake.connector

from snowflake.sqlalchemy import URL
from sqlalchemy import *
from sqlalchemy.pool import QueuePool
from sqlalchemy.pool import NullPool
from sqlalchemy.pool import SingletonThreadPool

engine = create_engine(URL(
account='testaccount',
user='user',
password='XXX',
database='testdb',
schema='testschema',
warehouse='X'),
poolclass=QueuePool)

#poolclass=SingletonThreadPool, pool_size=5)
#poolclass=NullPool)
#poolclass=NewQueuePool)
try:
engine.echo = False  # Try changing this to True and see what happens

metadata = MetaData(bind=engine)

users_table = Table('users', metadata,
Column('id', Integer, primary_key=True),
Column('name', String(40)),
Column('age', Integer),
Column('password', String),
)

addresses_table = Table('addresses', metadata,
Column('id', Integer, primary_key=True),
Column('user_id', None, ForeignKey('users.id')),
Column('email_address', String, nullable=False)
)

# create tables in database
metadata.create_all()

conn = engine.connect()

conn.execute(users_table.insert(), [
{"name": "Ted", "age": 10, "password": "dink"},
{"name": "Asahina", "age": 25, "password": "nippon"},
{"name": "Evan", "age": 40, "password": "macaca"}
])
# conn.close()

s = select([users_table])
result = s.execute()

for row in result:
print(row)
finally:
print('dispose started')
engine.dispose()
print('dispose ended')

But when I run it, I often hit the following error.

> python ~/test_python/sqlalchemy_test.py
(1, 'Ted', 10, 'dink')
(2, 'Asahina', 25, 'nippon')
(3, 'Evan', 40, 'macaca')
dispose started
dispose ended
Exception during reset or similar
Traceback (most recent call last):
  File "/tmp/35/lib/python3.5/site-packages/sqlalchemy/pool.py", line 687, 
in _finalize_fairy
fairy._reset(pool)
  File "/tmp/35/lib/python3.5/site-packages/sqlalchemy/pool.py", line 829, 
in _reset
pool._dialect.do_rollback(self)
  File "/tmp/35/lib/python3.5/site-packages/sqlalchemy/engine/default.py", 
line 440, in do_rollback
dbapi_connection.rollback()
  File 
"/tmp/35/lib/python3.5/site-packages/snowflake/connector/connection.py", 
line 358, in rollback
self.cursor().execute("ROLLBACK", timeout=5)
  File 
"/tmp/35/lib/python3.5/site-packages/snowflake/connector/connection.py", 
line 364, in cursor
logger.debug(u'cursor')
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/logging/__init__.py",
 
line 1268, in debug
self._log(DEBUG, msg, args, **kwargs)
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/logging/__init__.py",
 
line 1416, in _log
self.handle(record)
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/logging/__init__.py",
 
line 1426, in handle
self.callHandlers(record)
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/logging/__init__.py",
 
line 1488, in callHandlers
hdlr.handle(record)
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/logging/__init__.py",
 
line 856, in handle
self.emit(record)
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/logging/__init__.py",
 
line 1048, in emit
self.stream = self._open()
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/logging/__init__.py",
 
line 1038, in _open
return open(self.baseFilename, self.mode, encoding=self.encoding)
  File 
"/home/stakeda/python/python-dist-gcc-g++-3.5.3/lib/python3.5/encodings/__init__.py",
 
line 98, in search_function
level=0)
  File "", line 969, in _find_and_load
  File "", line 954, in _find_and_load_unlocked
  File "", line 887, in _find_spec
TypeError: 'NoneType' object is not iterable


It seems that the cause is logging instances already removed when the 
connection is purged. As you see in the output, "dispose ended" shows up 
before the error stack, so I suspect this is happening in the very end of 
Python process.

Is 

[sqlalchemy] Re: Pool connections high-water, session query counter?

[YKdvd]

In a separate thread, Mike had a demo 

 
which kept a query count in a Session instance by stamping a reference to 
the Session in its connections.  It got removed on session commit/rollback:
# can also pop it on commit/rollback, but this won't 
# catch if the Session is just closed() without a commit/rollback. 
# if your app always commits/rollbacks, then this is fine. 
@event.listens_for(Session, "after_commit") 
@event.listens_for(Session, "after_rollback") 
def _c(session, transaction, connection): 
 connection.info.pop('log_session', None) 

The function claims to take three parms including "connection", but the 
docs say 

 
the Session.after_commit/after_rollback events only pass a single parm, 
"session", and I do seem to get a "takes exactly 3 arguments (1 given)" 
error when using this signature.  Am I missing something?  Without the 
connection being passed, popping it's link to a session ("log_session") 
can't occur.

The same example also pops it on the Engine "checkin" event - is there any 
significant case where "checkin" wouldn't be called and the connection 
would be reused in a subsequent session with that "log_session" still in 
its info dict?  And it probably wouldn't matter because the Session 
"after_begin" handler would re-stamp a new reference on a connection being 
reused - the commit/rollback pops should be superfluous?

-- 
SQLAlchemy - 
The Python SQL Toolkit and Object Relational Mapper

http://www.sqlalchemy.org/

To post example code, please provide an MCVE: Minimal, Complete, and Verifiable 
Example.  See  http://stackoverflow.com/help/mcve for a full description.
--- 
You received this message because you are subscribed to the Google Groups 
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.