pool_recycle parameter doesn't always work properly

[Former user]

I've verified this on multiple Windows XP systems. For this test, I set the MySQL timeout to 60 seconds (pool_recycle is 30).

>>> import sqlalchemy
>>> import sqlalchemy.orm
>>> eng = sqlalchemy.create_engine('mysql://root:rootpw@localhost/testdb', pool_recycle=30)
>>> Session = sqlalchemy.orm.sessionmaker()
>>> Session.configure(bind = eng)
>>> s = Session()
>>> s.execute("SELECT 1")
<sqlalchemy.engine.base.ResultProxy object at 0x014A5130>
>>> del s

(wait for MySQL connection to timeout)

>>> s = Session()
>>> s.execute("SELECT 1")

Traceback (most recent call last):
  File "<pyshell#9>", line 1, in <module>
    s.execute("SELECT 1")
  File "c:\python25\lib\site-packages\SQLAlchemy-0.4.6-py2.5.egg\sqlalchemy\orm\session.py", line 625, in execute
    return self.__connection(engine, close_with_result=True).execute(clause, params or {})
  File "c:\python25\lib\site-packages\SQLAlchemy-0.4.6-py2.5.egg\sqlalchemy\engine\base.py", line 844, in execute
    return Connection.executors[c](c)(self, object, multiparams, params)
  File "c:\python25\lib\site-packages\SQLAlchemy-0.4.6-py2.5.egg\sqlalchemy\engine\base.py", line 854, in _execute_text
    self.__execute_raw(context)
  File "c:\python25\lib\site-packages\SQLAlchemy-0.4.6-py2.5.egg\sqlalchemy\engine\base.py", line 916, in __execute_raw
    self._cursor_execute(context.cursor, context.statement, context.parameters[0](0), context=context)
  File "c:\python25\lib\site-packages\SQLAlchemy-0.4.6-py2.5.egg\sqlalchemy\engine\base.py", line 960, in _cursor_execute
    self._handle_dbapi_exception(e, statement, parameters, cursor)
  File "c:\python25\lib\site-packages\SQLAlchemy-0.4.6-py2.5.egg\sqlalchemy\engine\base.py", line 942, in _handle_dbapi_exception
    raise exceptions.DBAPIError.instance(statement, parameters, e, connection_invalidated=is_disconnect)
OperationalError: (OperationalError) (2006, 'MySQL server has gone away') 'SELECT 1' {}

"MySQL server has gone away" means it attempted to use the first connection, even though it was older than pool_recycle.

This is probably related to #1094, which is a error with NullPool under similar circumstances. The FAQ regarding pool_recycle says that it won't work properly if the connection is held the entire time, but I don't see what could be "holding" the connection here; I explicitly delete the first session object before waiting for the timeout.

[Mike Bayer]

#1094 involves the reconnection mechanisms not being implemented for the NullPool (where its usually not an issue either since NullPool doesn't "pool" any connections). The symptom there is specifically a NotImplementedError and is not related to the behavior you're seeing here.

The issue here is a combination of 1. the connection is not being returned to the pool, since "del s" is not the proper way to close a session; use session.close(). You'll notice that placing an "import gc; gc.collect()" after your "del s" will also work. As it stands, the connection remains checked out. Sessions are all stored in a WeakValueDictionary and likely have circular references so they don't get an immediate "reference count" gc (and this is not something you should ever depend on anyway).

The second part of the particular equation is 2. because the pool in SQLA 0.4 is set to "use_threadlocal" by default, meaning two connection requests in the same thread will share the same connection if they overlap. You can turn this off by sending pool_threadlocal=False to create_engine().

Since you already have a connection opened in the first phase of the operation, the second phase of the test uses the same connection which has now timed out. The connection pool is never consulted for its "recycle" option. This is visible by turning on logging for "sqlalchemy.pool", where you can see the connection not being returned. Adding session.close() or gc.collect() will allow the recycle mechanism to function which you'll also see in the logs.

the use_threadlocal setting in 0.4 was a bad idea, but was officially part of 0.4 from the beginning of that series; so the change to this default began with the 0.5 series.