AssertionError in rollback on failed commit.

[zoomorph]

My commit code...

SESSIONMAKER = sessionmaker(bind=ENGINE, expire_on_commit=False)

class Database(object):

    def __init__(self):
        self._session = None

    @property
    def session(self):
        if self._session is None:
            self._session = SESSIONMAKER()
            self._session.autocommit = False
            self._session.autoflush = False
        return self._session

    def commit(self):
        if self._session:
            try:
                self._session.commit()
            except Exception as e:
                logger.exception("Caught exception in commit.")
                self.rollback()

    def add(self, obj):
        self.session.add(obj)

    def delete(self, obj):
        session = self.session
        if obj in session.new:
            logger.info("Expunging item %s", obj)
            session.expunge(obj)
        else:
            logger.info("Deleting item %s", obj)
            session.delete(obj)

    def expire(self, obj):
        try:
            self.session.expire(obj)
        except InvalidRequestError:
            pass

    def rollback(self):
        if self._session:
            logger.info("Rolling back.")
            self._session.rollback()

    def close_session(self):
        if self._session:
            logger.info("Closing session.")
            self._session.close()

Caught the following exception when calling commit():

Traceback (most recent call last):
  File "/myapp/tpcommon/db/core.py", line 111, in commit
    self._session.commit()
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 779, in commit
    self.transaction.commit()
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 384, in commit
    self._prepare_impl()
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 364, in _prepare_impl
    self.session.flush()
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 1993, in flush
    self._flush(objects)
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 2111, in _flush
    transaction.rollback(_capture_exception=True)
  File "/myapp/env_pypy/site-packages/sqlalchemy/util/langhelpers.py", line 63, in __exit__
    compat.reraise(type_, value, traceback)
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 2111, in _flush
    transaction.rollback(_capture_exception=True)
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 426, in rollback
    self._restore_snapshot(dirty_only=self.nested)
  File "/myapp/env_pypy/site-packages/sqlalchemy/orm/session.py", line 266, in _restore_snapshot
    assert self._is_transaction_boundary
AssertionError

When the exception handler subsequently called rollback(), it again raised this exception. After that, my code received the following when trying to continue using the session:

InvalidRequestError: This Session's transaction has been rolled back by a nested rollback() call. To begin a new transaction, issue Session.rollback() first.

I'm using master branch code from about a week ago. I'm not sure what causes this error but it's happening infrequently and seems like a problem in SQLAlchemy. My code doesn't do anything fancy beyond adding, deleting, expiring, and modifying ORM objects.

[Mike Bayer]

You also should be seeing a warning "Session's state has been changed on a non-active transaction". I can't see how you're getting this to happen with the code as illustrated unless your exception is originating from an after_flush() or after_flush_postexec() event handler, which is not shared here. I can try to reproduce based on that theory but preferably just need more detail, e.g. full reproducing test case.

[zoomorph]

Hi Mike,

I have an after_flash handler for maintaining some statistics, only. I don't think this should cause any exceptions....

PERF = {
    'query_start': None,
    'flush_start': None,
    'commit_start': None,
    'total_query': 0.0,
    'total_flush': 0.0,
    'total_commit': 0.0,
    'total_query_count': 0,
    'total_flush_count': 0,
    'total_commit_count': 0,
    'max_query': 0.0,
    'max_flush': 0.0,
    'max_commit': 0.0
}

@event.listens_for(SESSIONMAKER, 'before_flush')
def before_flush(session, flush_context, instances):
    PERF['flush_start'] = time.time()

@event.listens_for(SESSIONMAKER, 'after_flush')
def after_flush(session, flush_context):
    delta = (time.time() - PERF['flush_start']) * 1000
    logger.info("Flush took: %.2f ms", delta)
    PERF['total_flush'] += delta
    PERF['total_flush_count'] += 1
    PERF['max_flush'] = max(PERF['max_flush'], delta)
    if delta > 100:
        logger.warning("Long flush! %.2f ms", delta)

I've only logged this exception 3x over the past 12 hours so it's happening quite rarely in my application. I'm having no luck seeing a pattern so far. The server is single-threaded and uses a single session with expire_on_commit=False. It does nothing fancy, just query/add/delete/expire ORM objects. I can message you the tables if that would be helpful.

I don't think SQLAlchemy warnings make it to my logs so I can't confirm that.

[Mike Bayer]

OK, I'll look at it, but maybe if you could throw logging in there to illustrate the original stack trace being thrown by the commit(). something is happening in commit() or flush() within that throws the session into an unexpected state.

[Mike Bayer]

the code is the same in 0.9 so likely there as well.

[Mike Bayer]

it's also likely pypy and garbage collection is involved.

[Mike Bayer]

this is the first script that can produce the identical stack trace:

from sqlalchemy import Column, create_engine, Integer
from sqlalchemy.orm import Session
from sqlalchemy.ext.declarative import declarative_base
from sqlalchemy import event

Base = declarative_base()


class A(Base):
    __tablename__ = 'a'
    id = Column(Integer, primary_key=True)

e = create_engine("sqlite://", echo=True)
Base.metadata.create_all(e)

s = Session(e)

from sqlalchemy.orm import session


@event.listens_for(s, "after_flush")
def foob(s, ctx):
    trans = s.transaction
    trans._state = session.DEACTIVE
    s.rollback()

s.add(A(id=2))
s.commit()

[Mike Bayer]

OK. Do you have an after_rollback handler? If you change the session's state in such a handler, and you encounter a rollback, that causes this stack trace (which can be fixed):

from sqlalchemy import Column, create_engine, Integer
from sqlalchemy.orm import Session
from sqlalchemy.ext.declarative import declarative_base
from sqlalchemy import event

Base = declarative_base()


class A(Base):
    __tablename__ = 'a'
    id = Column(Integer, primary_key=True)

e = create_engine("sqlite://", echo=True)
Base.metadata.create_all(e)

s = Session(e)
s.add(A(id=1))
s.commit()


@event.listens_for(s, "after_rollback")
def foob(s):
    s.add(A(id=34))


s.add(A(id=1))
s.commit()

[Mike Bayer]

• Fixed bug where internal assertion would fail in the case where an after_rollback() handler for a :class:.Session incorrectly adds state to that :class:.Session within the handler, and the task to warn and remove this state (established by 2389) attempts to proceed. fixes #3309

→ <<cset ad66266d3d27>>

[Mike Bayer]

• Fixed bug where internal assertion would fail in the case where an after_rollback() handler for a :class:.Session incorrectly adds state to that :class:.Session within the handler, and the task to warn and remove this state (established by 2389) attempts to proceed. fixes #3309

(cherry picked from commit ad66266d3d275a6129e3270eaacdad171bc10817)

→ <<cset f5d8a1859409>>

[Mike Bayer]

OK I'm not sure this is fixed, because I still don't know what you are doing on your end. I added support for the one case I could figure out that would hit that assertion, which involves changing the session's state inside of a rollback event. Let me know if that fixes it.

[zoomorph]

Hi Mike. I don't have an after_rollback handler, only the ones above and analogous ones for timing query/commit. I'm adding more logging and will work on reproducing this when I can find some time. Thanks.