On Feb 24, 2011, at 6:50 PM, Will Berry wrote:
> I am using SQLAlchemy 0.5.5 which is the version packaged with Red Hat
> Enterprise 6. I am using the below class to implement transactions
> using closures. (I have excluded methods unrelated to this issue.) I
> am using psycopg2 2.0.13 ('postgres://' URLs) to talk to the database,
> if that matters.
>
> The difference between "working" and "not working" for me is this
> difference in __init__.
>
> Working:
> self._engine = sqlalchemy.create_engine(URL)
> self._session = sqlalchemy.orm.scoped_session(
> sqlalchemy.orm.sessionmaker(self._engine,
> **self._set_compatibility(sqlalchemy.__version__)))
>
> Not working:
> self._session =
> sqlalchemy.orm.sessionmaker(**self._set_compatibility(sqlalchemy.__version__))
> self._engine = sqlalchemy.create_engine(URL)
> self._session.configure(bind=self._engine)
>
> The problem is, if I pass poolclass=AssertionPool to create_engine, I
> get an AssertionError exception after as few as three consecutive
> transactions with the "non-working" code. I have a single-threaded
> process that does not use nested transactions and executes
> transactions sequentially.
>
> Basically my question is, is the observed behavior surprising, and if
> not, what exactly is wrong with my "not working" code? I'm not
> certain that I really understand how sessions work.
>
> "Working" code with portions removed that are not relevant to this
> posting:
>
> import sqlalchemy.orm
>
> class SQLAlchemyDB:
> def _set_compatibility(self, version):
> major, minor = map(int, version.split('.'))[:2]
> if major > 0 or minor > 5:
> raise NotImplementedError, \
> 'this module not tested against SQLAlchemy version %s' %
> (version,)
> smargs = {'autoflush': True}
> if minor > 4:
> smargs['autocommit'] = False
> smargs['expire_on_commit'] = False # no need to merge for
> every transaction
> else: # version 0.4.x
> smargs['transactional'] = True
> return smargs
>
> def __init__(self, URL):
> self._engine = sqlalchemy.create_engine(URL)
> self._session =
> sqlalchemy.orm.scoped_session(sqlalchemy.orm.sessionmaker(
> self._engine,
> **self._set_compatibility(sqlalchemy.__version__)))
> self._metadata = sqlalchemy.MetaData(bind=self._engine)
>
> def named_table(self, tablename):
> return sqlalchemy.Table(tablename, self._metadata,
> autoload=True)
>
> def bind_class(self, freeclass, table):
> sqlalchemy.orm.mapper(freeclass, table)
>
> def new_bound_class(self, table):
> class ORMClassPrototype(object): pass
> self.bind_class(ORMClassPrototype, table)
> return ORMClassPrototype
>
> def named_orm_class(self, name):
> return self.new_bound_class(self.named_table(name))
>
> def transaction(self, callback):
> session = self._session()
> if not hasattr(session, 'add'): # compatibility with
> SQLAlchemy 0.4.x
> session.add = session.save
> try:
> result = callback(session)
> except BaseException:
> session.rollback()
> raise
> else:
> session.commit()
> finally:
> session.close()
> return result
The above code will procure connections from the connection pool inside of
"named_table()", which will be returned immediately upon completion of that
method (but note this connection is independent of one which may already be
held by Session), and within transaction(), which will also be returned when
the try: block reaches rollback() or commit(). There is a difference between
using scoped_session and not, in that the former retrieves the Session from a
thread local registry, which will be re-used within the same thread on the next
call to transaction since remove() is not called. Here, the transaction()
method is handling the Session completely locally to a function so there is no
need to use scoped_session in this case.
> Below is my log file with application-specific information scrubbed
> out (I enabled logging at level logging.INFO for logger
> sqlalchemy.pool). To get this log, I used the "non-working" code and
> interactively triggered the same transaction function three times in a
> row. The transaction function calls the named_orm_class method and
> uses session.query a few times. No objects created by the transaction
> function have living references (in application code) after it
> returns. Note that after I shut down my application it returns the
> connection to the pool. This does not happen in the "working"
> version.
what doesn't make much sense about this log is that the pool is indicating that
its checking out a connection from the pool right before "Completed
transaction", then is not returned (this is unconditional when
session.rollback() or session.commit() is called, assuming there is not a
subtransaction taking place). The fact that Session.close() is called means
all objects are detached so there wouldn't be any issue with lazy loads later
on. The code example above does not illustrate where these log lines are
emitted or any example use so its hard to say beyond that what produces the log.
So there's nothing visible here without more specific code that reproduces the
condition.
>
>
> 2011-02-23 18:19:36 EST INFO Application starting up
> 2011-02-23 18:19:36 EST INFO Created new connection <connection
> object at 0x29e2590; dsn:
>
> 'dbname=xxxxxxx host=xxxxxx port=5432 user=xxxxxx password=xxxx',
> closed: 0>
> 2011-02-23 18:19:36 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:19:36 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:19:36 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:19:36 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Beginning transaction (from
> application)
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:43 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:44 EST INFO Completed transaction (from
> application)
> 2011-02-23 18:21:51 EST INFO Beginning transaction (from
> application)
> 2011-02-23 18:21:51 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:51 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:51 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
> 2011-02-23 18:21:51 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> checked
> out from pool
> 2011-02-23 18:21:51 EST INFO Completed transaction (from
> application)
> 2011-02-23 18:22:06 EST INFO Beginning transaction (from
> application)
> 2011-02-23 18:22:06 EST ERROR AssertionError
> (snip)
> 2011-02-23 18:22:06 EST ERROR File "xxxxxx.py", line 88, in
> transaction
> 2011-02-23 18:22:06 EST ERROR result = callback(session)
> 2011-02-23 18:22:06 EST ERROR File "xxxxxxx.py", line 208, in
> txn
> 2011-02-23 18:22:06 EST ERROR .filter(xxxxxxx ==
> xxxxxxxxx).one()
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/orm/query.py", line
>
> 1252, in one
> 2011-02-23 18:22:06 EST ERROR ret = list(self[0:2])
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/orm/query.py", line
>
> 1152, in __getitem__
> 2011-02-23 18:22:06 EST ERROR return list(res)
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/orm/query.py", line
>
> 1292, in __iter__
> 2011-02-23 18:22:06 EST ERROR return
> self._execute_and_instances(context)
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/orm/query.py", line
>
> 1295, in _execute_and_instances
> 2011-02-23 18:22:06 EST ERROR result =
> self.session.execute(querycontext.statement,
>
> params=self._params, mapper=self._mapper_zero_or_none())
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/orm/session.py",
>
> line 754, in execute
> 2011-02-23 18:22:06 EST ERROR return self.__connection(engine,
> close_with_result=True).execute(
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/orm/session.py",
>
> line 719, in __connection
> 2011-02-23 18:22:06 EST ERROR return
> self.transaction._connection_for_bind(engine)
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/orm/session.py",
>
> line 329, in _connection_for_bind
> 2011-02-23 18:22:06 EST ERROR conn = bind.contextual_connect()
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/engine/base.py",
>
> line 1229, in contextual_connect
> 2011-02-23 18:22:06 EST ERROR return self.Connection(self,
> self.pool.connect(),
>
> close_with_result=close_with_result, **kwargs)
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/pool.py", line 142,
>
> in connect
> 2011-02-23 18:22:06 EST ERROR return
> _ConnectionFairy(self).checkout()
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/pool.py", line 304,
>
> in __init__
> 2011-02-23 18:22:06 EST ERROR rec = self._connection_record =
> pool.get()
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/pool.py", line 161,
>
> in get
> 2011-02-23 18:22:06 EST ERROR return self.do_get()
> 2011-02-23 18:22:06 EST ERROR File "/usr/lib/python2.6/site-
> packages/sqlalchemy/pool.py", line 849,
>
> in do_get
> 2011-02-23 18:22:06 EST ERROR assert self.connection is not
> None
> 2011-02-23 18:52:46 EST WARNING Application shutting down
> 2011-02-23 18:52:46 EST INFO Connection <connection object at
> 0x29e2590; dsn: 'dbname=xxxxxxx
>
> host=xxxxxx port=5432 user=xxxxxx password=xxxx', closed: 0> being
> returned to pool
>
> --
> You received this message because you are subscribed to the Google Groups
> "sqlalchemy" group.
> To post to this group, send email to [email protected].
> To unsubscribe from this group, send email to
> [email protected].
> For more options, visit this group at
> http://groups.google.com/group/sqlalchemy?hl=en.
>
--
You received this message because you are subscribed to the Google Groups
"sqlalchemy" group.
To post to this group, send email to [email protected].
To unsubscribe from this group, send email to
[email protected].
For more options, visit this group at
http://groups.google.com/group/sqlalchemy?hl=en.
