mod_wsgi, SQLite3 and a threading anomaly because connection is not returned to pool by session.remove()

[Vinay Sajip]

I'm getting the "SQLite objects created in a thread can only be used
in that same thread." error when using a web application with mod_wsgi
configured in daemon mode with processes=1, threads=15 on Ubuntu
Karmic, using Python2.6.

I saw another thread [1] which mentioned a similar issue, and I
believe I am using the approach recommended by Mike Bayer in that
thread.

I have a multi-db setup - 2 of the databases are SQLite and one is
PostgreSQL. There are three sessions, set up using

session_var = scoped_session(sessionmaker(extension=extn))

where the extension just allows listeners to be registered which are
called at before_flush and before_commit - I don't believe that's part
of the problem.

When a GET request is received, a user is retrieved from an ID stored
in the HTTP session - this uses a query attribute on the mapped class
which is obtained using session_var.query_property(). All conventional
stuff.

At the end of the request, I call

session_var.remove()

for each of the three sessions. This is what I understand to be the
correct practice - no instantiation of session_var is required.

I enabled debug logging for sqlalchemy.pool and find that under the
failing scenariio, the session_var.remove() sometimes fails to remove
the session. This leads to the SQLite error on a subsequent request.

The failing scenario: Invoke the same URL multiple times from Firefox,
setting a new locale preference (Accept-Language) between requests.
Pretty soon you get the error, full log file is here [2]. I modified
the pool.py code to display a stack trace in the log, so that I could
see what led to a connection being created. From what I can see, it's
the same code path each time.

It's a 219-line trace, but I'll reproduce the relevant lines here: The
PID and thread ID are in braces in each log message.

[ersatz.core:705]{5648/-1385407632} DEBUG dispatching request GET
http://localhost/admin/book/add/
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:275]{5648/-1385407632}
DEBUG Created new connection <sqlite3.Connection object at 0x21d61ca0>
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:282]{5648/-1385407632}
DEBUG Stack at this point <snipped>
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:337]{5648/-1385407632}
DEBUG Connection <sqlite3.Connection object at 0x21d61ca0> checked out
from pool
[ersatz.core:746]{5648/-1385407632} DEBUG 0.420: time for
http://localhost/admin/book/add/ (end of request processing)
[ersatz.db:328]{5648/-1385407632} DEBUG session cleanup starting
[ersatz.db:336]{5648/-1385407632} DEBUG Calling session.remove() for
db1 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b6190c>)
[ersatz.db:336]{5648/-1385407632} DEBUG Calling session.remove() for
db3 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b61aec>)
[ersatz.db:336]{5648/-1385407632} DEBUG Calling session.remove() for
db2 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b61ccc>)
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:310]{5648/-1385407632}
DEBUG Connection <sqlite3.Connection object at 0x21d61ca0> being
returned to pool
[ersatz.db:338]{5648/-1385407632} DEBUG session cleanup done

As can be seen, the session.remove() for the session variable for db2
returns the connection to the pool, as expected. Next request:

[ersatz.core:705]{5648/-1238549648} DEBUG dispatching request GET
http://localhost/admin/book/add/
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:275]{5648/-1238549648}
DEBUG Created new connection <sqlite3.Connection object at 0x2202f5a0>
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:282]{5648/-1238549648}
DEBUG Stack at this point: <snipped>

The call to create this connection was made with the same code path as
for the previous request.

[sqlalchemy.pool.SingletonThreadPool.0x...c44c:337]{5648/-1238549648}
DEBUG Connection <sqlite3.Connection object at 0x2202f5a0> checked out
from pool
[ersatz.core:746]{5648/-1238549648} DEBUG 0.085: time for
http://localhost/admin/book/add/ (end of request processing)
[ersatz.db:328]{5648/-1238549648} DEBUG session cleanup starting
[ersatz.db:336]{5648/-1238549648} DEBUG Calling session.remove() for
db1 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b6190c>)
[ersatz.db:336]{5648/-1238549648} DEBUG Calling session.remove() for
db3 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b61aec>)
[ersatz.db:336]{5648/-1238549648} DEBUG Calling session.remove() for
db2 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b61ccc>)
[ersatz.db:338]{5648/-1238549648} DEBUG session cleanup done

No connection was returned to the pool! Next request:

[ersatz.core:705]{5648/-1249039504} DEBUG dispatching request GET
http://localhost/admin/book/add/
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:275]{5648/-1249039504}
DEBUG Created new connection <sqlite3.Connection object at 0x2202f4a0>
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:282]{5648/-1249039504}
DEBUG Stack at this point: <snipped>

Called from the same place as the previous two requests.

[sqlalchemy.pool.SingletonThreadPool.0x...c44c:337]{5648/-1249039504}
DEBUG Connection <sqlite3.Connection object at 0x2202f4a0> checked out
from pool
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:236]{5648/-1249039504}
INFO Invalidate connection <sqlite3.Connection object at 0x2202f5a0>
(reason: ProgrammingError:SQLite objects created in a thread can only
be used in that same thread.The object was created in thread id
-1238549648 and this is thread id -1249039504)
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:263]{5648/-1249039504}
DEBUG Closing connection <sqlite3.Connection object at 0x2202f5a0>
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:269]{5648/-1249039504}
DEBUG Connection <sqlite3.Connection object at 0x2202f5a0> threw an
error on close: SQLite objects created in a thread can only be used in
that same thread.The object was created in thread id -1238549648 and
this is thread id -1249039504

And here we have the error.

[sqlalchemy.pool.SingletonThreadPool.0x...c44c:310]{5648/-1249039504}
DEBUG Connection None being returned to pool
[ersatz.core:738]{5648/-1249039504} ERROR Error while handling
request /admin/book/add/: (ProgrammingError) SQLite objects created in
a thread can only be used in that same thread.The object was created
in thread id -1238549648 and this is thread id -1249039504
Traceback (most recent call last): <part snipped>
File "/usr/lib/python2.6/dist-packages/ersatz/db.py", line 902, in
get_choices
for o in sorted(self.query.all(), key=get_label):
File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/query.py",
line 1422, in all
return list(self)
File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/query.py",
line 1534, in __iter__
return self._execute_and_instances(context)
File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/query.py",
line 1539, in _execute_and_instances
mapper=self._mapper_zero_or_none())
File "/usr/lib/python2.6/dist-packages/sqlalchemy/orm/session.py",
line 735, in execute
clause, params or {})
File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py",
line 1157, in execute
params)
File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py",
line 1235, in _execute_clauseelement
parameters=params
File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py",
line 1348, in __create_execution_context
None, None)
File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/base.py",
line 1343, in __create_execution_context
connection=self, **kwargs)
File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/
default.py", line 370, in __init__
self.cursor = self.create_cursor()
File "/usr/lib/python2.6/dist-packages/sqlalchemy/engine/
default.py", line 511, in create_cursor
return self._connection.connection.cursor()
File "/usr/lib/python2.6/dist-packages/sqlalchemy/pool.py", line
378, in cursor
c = self.connection.cursor(*args, **kwargs)
ProgrammingError: (ProgrammingError) SQLite objects created in a
thread can only be used in that same thread.The object was created in
thread id -1238549648 and this is thread id -1249039504 None [{}]
[ersatz.core:746]{5648/-1249039504} DEBUG 0.121: time for
http://localhost/admin/book/add/
[ersatz.db:328]{5648/-1249039504} DEBUG session cleanup starting
[ersatz.db:336]{5648/-1249039504} DEBUG Calling session.remove() for
db1 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b6190c>)
[ersatz.db:336]{5648/-1249039504} DEBUG Calling session.remove() for
db3 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b61aec>)
[ersatz.db:336]{5648/-1249039504} DEBUG Calling session.remove() for
db2 (<sqlalchemy.orm.scoping.ScopedSession object at 0x21b61ccc>)
[sqlalchemy.pool.SingletonThreadPool.0x...c44c:310]{5648/-1249039504}
DEBUG Connection <sqlite3.Connection object at 0x2202f4a0> being
returned to pool
[ersatz.db:338]{5648/-1249039504} DEBUG session cleanup done

Notice that here again, the connection which was checked out of the
pool is returned to it at the end, as expected.

Using Mike Bayer's _threading_local patch in thread [1] made no
difference.

It seems as if under some circumstances the link between the
connection and the session is lost in some way, so that
session.remove() doesn't return the connection to the pool.

Can anyone help? Is there any particular place I could add more
logging or debugging to see what's going on? Have I missed something
really obvious?

Regards,

Vinay Sajip

[1] http://groups.google.com/group/sqlalchemy/browse_thread/thread/fbca1399020f6a2e/
[2] http://paste.pocoo.org/show/223990/

[Michael Bayer]

On Jun 10, 2010, at 2:54 PM, Vinay Sajip wrote:

> I'm getting the "SQLite objects created in a thread can only be used
> in that same thread." error when using a web application with mod_wsgi
> configured in daemon mode with processes=1, threads=15 on Ubuntu
> Karmic, using Python2.6.

>

> When a GET request is received, a user is retrieved from an ID stored
> in the HTTP session - this uses a query attribute on the mapped class
> which is obtained using session_var.query_property(). All conventional
> stuff.

First off, the absolute recommended behavior for SQLite if a file-based database is to not use pooling. I would suggest you use a NullPool to eliminate any connection pooling. Some detail on this at http://www.sqlalchemy.org/docs/reference/dialects/sqlite.html#threading-behavior . Seems like I mention it in the linked thread as well.

You then need to ensure no sqlalchemy-session-bound objects in your web application are shared between threads. When you put things into your HTTP session, assuming its an in-memory HTTP session, make sure objects that go in there arent attached to a SQLAlchemy session. Use expunge() or similar for this. Calling remove() at the end of the request will work, except for the fact that a concurrent thread might be accessing the HTTP session before you get that far. I would recommend using cookie based HTTP sessions in any case (see Beaker for this functionality).

> Using Mike Bayer's _threading_local patch in thread [1] made no
> difference.

That thread regarded someone using an extremely rare tool called PyISAPIe, which had threading bugs in it. That doesn't apply to a basic mod_wsgi configuration.

[Vinay Sajip]

On Jun 10, 10:08 pm, Michael Bayer <mike...@zzzcomputing.com> wrote:
> First off, the absolute recommended behavior for SQLite if a file-based database is to not use pooling.  I would suggest you use a NullPool to eliminate any connection pooling.  Some detail on this athttp://www.sqlalchemy.org/docs/reference/dialects/sqlite.html#threadi....   Seems like I mention it in the linked thread as well.
>

Indeed. I understand about NullPool, and the setup I'm using is a test
setup for multi-db operation. I would expect the session.remove() to
clean up any SQLA connections used during the request, but it's not
happening some of the time - I was hoping to find the cause; of course
if I switched to NullPool the problem would go away.

> You then need to ensure no sqlalchemy-session-bound objects in your web application are shared between threads.  When you put things into your HTTP session, assuming its an in-memory HTTP session, make sure objects that go in there arent attached to a SQLAlchemy session.  Use expunge() or similar for this.  Calling remove() at the end of the request will work, except for the fact that a concurrent thread might be accessing the HTTP session before you get that far.

In the failing case, requests are not actually happening concurrently
- mod_wsgi just happens to use different threads for servicing the
sequential requests, which are a second or two apart. The problem is
caused by a connection sometimes not being found when session.remove()
is called. The connection is always created in response to a query to
get a User object from an integer ID stored in the session. While the
User object is a SQLA mapped object, it's not stored in the session,
only the ID is.

Note that the problem occurs during clean up via session.remove()
(connection not found to return to pool) but manifests itself on the
next request (a second or two later). I'm wondering if there's some
reason why an opened connection might sometimes not be registered
properly [ has() returning False ] which is why it's not returned to
the pool.

Concurrent thread access to the session isn't (I believe) happening in
this case as the server is on my local test machine with no other load
than me accessing via Firefox locally. There are concurrent requests
but only for static files.

>   I would recommend using cookie based HTTP sessions in any case (see Beaker for this functionality).

I presume you mean where all session state is stored in the cookie. I
can do this but I'm working on a framework component which also needs
to support server-side sessions.

> That thread regarded someone using an extremely rare tool called PyISAPIe, which had threading bugs in it.  That doesn't apply to a basic mod_wsgi configuration.

I see now. It was a clutching-at-straws kind of thing :-)

Thanks & regards,

Vinay Sajip