Misleading exception triggered on session.commit() low-level error

[Former user]

We got weird ("(OperationalError) (1305, 'SAVEPOINT sa_savepoint_1 does not exist') in our prod, and after investigation, this is due to the fact that our mysql server fails a commit (we don't know why), and the handling of that exception in sqlalchemy leads to an automatic rollback to last savepoint. But that auto-rollback fails too (probably because mysql has already automatically rolled back by itself, and so destroyed savepoints), and thus the new exception "SAVEPOINT does not exist" hides the original error that caused all that trouble.

Here is the faulting code line, in latest development branch, in sqlalchemy/orm/session.py, line 1930:

        except:
            transaction.rollback(_capture_exception=True)
            raise

Since we don't know the actual state of the mysql transaction at that moment, I guess that this automatic rollback should be protected by a try...except, so that if it fails, it's the original error that will be reraised in any case. Or shouldn't it ?

Here is the full traceback we got in prod (with sqlalchemy 0.7.3, but the faulty lines are still present in latest sqlalchemy versions):

File "/home/pimsprod/PIMS/src/pims/processing/processor_abstract.py", line 213, in retrieve_user
    session.commit() # COMMIT SAVEPOINT
  File "/home/pimsprod/PIMS/src/pims/database_tools.py", line 85, in commit
    super(SafeSessionClass, self).commit(*args, **kwargs)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 645, in commit
    self.transaction.commit()
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 313, in commit
    self._prepare_impl()
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 297, in _prepare_impl
    self.session.flush()
  File "/home/pimsprod/PIMS/src/pims/database_tools.py", line 77, in flush
    super(SafeSessionClass, self).flush(*args, **kwargs)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1547, in flush
    self._flush(objects)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1634, in _flush
    transaction.rollback(_capture_exception=True)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 338, in rollback
    transaction._rollback_impl()
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 356, in _rollback_impl
    t[1](1).rollback()
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1960, in rollback
    self._do_rollback()
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2020, in _do_rollback
    self._savepoint, self._parent)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1249, in _rollback_to_savepoint_impl
    self.engine.dialect.do_rollback_to_savepoint(self, name)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 321, in do_rollback_to_savepoint
    connection.execute(expression.RollbackToSavepointClause(name))
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1399, in execute
    params)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1532, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1640, in _execute_context
    context)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1633, in _execute_context
    context)
  File "/usr/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 330, in do_execute
    cursor.execute(statement, parameters)
  File "/usr/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute
    self.errorhandler(self, exc, value)
  File "/usr/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (OperationalError) (1305, 'SAVEPOINT sa_savepoint_1 does not exist') 'ROLLBACK TO SAVEPOINT sa_savepoint_1' ()

[Mike Bayer]

the transaction knows that its a savepoint so it's probably reasonable to be ready for the SAVEPOINT to be missing. this condition should be easy to simulate in a test by just manually reverting the savepoint, then throwing an exception.

[Mike Bayer]

ok here's that stack trace matched up exactly:

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

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

e = create_engine("mysql://scott:tiger@localhost/test", echo=True)
Base.metadata.drop_all(e)
Base.metadata.create_all(e)

s = Session(e)
t = s.begin_nested()
s.execute("rollback")
s.add(A(id=None))
s.commit()

[Mike Bayer]

this problem really fixes itself in python3. If I add a straight exception throw to SessionTransaction.rollback() (because on Py3K I can only test sqlite or postgresql), then run a bad flush, in Python2 we get just the exception in rollback, with no mention of the flush exception:

Traceback (most recent call last):
  File "../sa3k/test.py", line 17, in <module>
    s.commit()
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 722, in commit
    self.transaction.commit()
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 353, in commit
    self._prepare_impl()
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 333, in _prepare_impl
    self.session.flush()
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 1817, in flush
    self._flush(objects)
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 1935, in _flush
    transaction.rollback(_capture_exception=True)
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/util/langhelpers.py", line 61, in __exit__
    compat.reraise(type_, value, traceback)
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 1935, in _flush
    transaction.rollback(_capture_exception=True)
  File "/Users/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 371, in rollback
    raise Exception("crap")
Exception: crap

but on Py3K, repeated stack traces are chained together using __cause__. The interpreter gives all the information without us doing anything:

Traceback (most recent call last):
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/engine/base.py", line 872, in _execute_context
    context)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/engine/default.py", line 326, in do_execute
    cursor.execute(statement, parameters)
psycopg2.IntegrityError: null value in column "id" violates not-null constraint


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/session.py", line 1896, in _flush
    flush_context.execute()
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/unitofwork.py", line 372, in execute
    rec.execute(self)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/unitofwork.py", line 525, in execute
    uow
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/persistence.py", line 63, in save_obj
    table, insert)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/persistence.py", line 565, in _emit_insert_statements
    execute(statement, params)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/engine/base.py", line 665, in execute
    params)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/engine/base.py", line 765, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/engine/base.py", line 879, in _execute_context
    context)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/engine/base.py", line 1035, in _handle_dbapi_exception
    from e
sqlalchemy.exc.IntegrityError: (IntegrityError) null value in column "id" violates not-null constraint
 'INSERT INTO a DEFAULT VALUES RETURNING a.id' {}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "test.py", line 17, in <module>
    s.commit()
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/session.py", line 719, in commit
    self.transaction.commit()
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/session.py", line 352, in commit
    self._prepare_impl()
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/session.py", line 332, in _prepare_impl
    self.session.flush()
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/session.py", line 1814, in flush
    self._flush(objects)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/session.py", line 1931, in _flush
    transaction.rollback(_capture_exception=True)
  File "/Users/classic/dev/sa3k/lib/sqlalchemy/orm/session.py", line 374, in rollback
    raise Exception("crap")
Exception: crap

Py3k has already solved this issue so anything we do is going to be redundant. Since it's an extremely rare MySQL issue in the first place I think we're better off waiting for Py3K adoption.

[Former user]

Indeed, I had forgotten that py3k nicety :-) Let's just wait for its adoption then (only 2-3 dependencies missing on my side to eventually be able to jump the gap).

[Mike Bayer]

Removing milestone: 0.8.xx (automated comment)

[Mike Bayer]

fixing resolution which seems to have gotten lost in trac migration

[Mike Bayer]

now, we are seeing this in neutron, so need to potentially revisit this: https://bugs.launchpad.net/oslo.db/+bug/1496651

[Mike Bayer]

Issue #3535 was marked as a duplicate of this issue.

[Mike Bayer]

this is really getting in the way now. not sure what i can do though.

[Mike Bayer]

let's apply this patch and backport to 1.0:

diff --git a/lib/sqlalchemy/util/compat.py b/lib/sqlalchemy/util/compat.py
index 5b6f691..f400031 100644
--- a/lib/sqlalchemy/util/compat.py
+++ b/lib/sqlalchemy/util/compat.py
@@ -8,6 +8,7 @@
 """Handle Python version/platform incompatibilities."""

 import sys
+import warnings

 try:
     import threading
@@ -188,6 +189,8 @@ if py3k:
         reraise(type(exception), exception, tb=exc_tb, cause=exc_value)
 else:
     exec("def reraise(tp, value, tb=None, cause=None):\n"
+         "    if cause:\n"
+         "        warnings.warn('Original exception cause: %r' % cause)\n"
          "    raise tp, value, tb\n")

     def raise_from_cause(exception, exc_info=None):
@@ -196,7 +199,7 @@ else:
         if exc_info is None:
             exc_info = sys.exc_info()
         exc_type, exc_value, exc_tb = exc_info
-        reraise(type(exception), exception, tb=exc_tb)
+        reraise(type(exception), exception, tb=exc_tb, cause=exc_value)

 if py3k:
     exec_ = getattr(builtins, 'exec')

it's not spectacular but will dump into logs a pretty good clue of what happened.

[Mike Bayer]

unfortunately we can't do it that way because caught exceptions cant be distinguished; we get lots of this in the logs:

/Users/classic/dev/redhat/openstack/oslo.db/.tox/py27/lib/python2.7/site-packages/sqlalchemy/util/compat.py:3: UserWarning: nested exception: (1146, u"Table 'test.foo' doesn't exist")

[Mike Bayer]

OK, then we will do this:

diff --git a/lib/sqlalchemy/orm/session.py b/lib/sqlalchemy/orm/session.py
index c726443..b987ab4 100644
--- a/lib/sqlalchemy/orm/session.py
+++ b/lib/sqlalchemy/orm/session.py
@@ -412,7 +412,17 @@ class SessionTransaction(object):
         if self._state in (ACTIVE, PREPARED):
             for transaction in self._iterate_parents():
                 if transaction._parent is None or transaction.nested:
-                    transaction._rollback_impl()
+                    try:
+                        transaction._rollback_impl()
+                    except Exception as e:
+                        if _capture_exception:
+                            util.warn(
+                                "While handling a Session error during "
+                                "a persistence operation, encountered an "
+                                "additional error attempting to ROLLBACK a "
+                                "transaction: %s" % e)
+                        else:
+                            raise
                     transaction._state = DEACTIVE
                     boundary = transaction
                     break

however I'm nervous about this being a 1.0 thing.

[Mike Bayer]

here's a patch with a test:

diff --git a/lib/sqlalchemy/orm/session.py b/lib/sqlalchemy/orm/session.py
index c726443..b987ab4 100644
--- a/lib/sqlalchemy/orm/session.py
+++ b/lib/sqlalchemy/orm/session.py
@@ -412,7 +412,17 @@ class SessionTransaction(object):
         if self._state in (ACTIVE, PREPARED):
             for transaction in self._iterate_parents():
                 if transaction._parent is None or transaction.nested:
-                    transaction._rollback_impl()
+                    try:
+                        transaction._rollback_impl()
+                    except Exception as e:
+                        if _capture_exception:
+                            util.warn(
+                                "While handling a Session error during "
+                                "a persistence operation, encountered an "
+                                "additional error attempting to ROLLBACK a "
+                                "transaction: %s" % e)
+                        else:
+                            raise
                     transaction._state = DEACTIVE
                     boundary = transaction
                     break
diff --git a/lib/sqlalchemy/testing/assertions.py b/lib/sqlalchemy/testing/assertions.py
index 21dc3e7..6366765 100644
--- a/lib/sqlalchemy/testing/assertions.py
+++ b/lib/sqlalchemy/testing/assertions.py
@@ -121,7 +121,7 @@ def uses_deprecated(*messages):
 def _expect_warnings(exc_cls, messages, regex=True, assert_=True):

     if regex:
-        filters = [re.compile(msg, re.I) for msg in messages]
+        filters = [re.compile(msg, re.I | re.S) for msg in messages]
     else:
         filters = messages

diff --git a/test/orm/test_transaction.py b/test/orm/test_transaction.py
index 73c6b97..6ca1d5e 100644
--- a/test/orm/test_transaction.py
+++ b/test/orm/test_transaction.py
@@ -657,6 +657,33 @@ class SessionTransactionTest(FixtureTest):
         assert session.transaction is not None, \
             'autocommit=False should start a new transaction'

+    @testing.requires.savepoints
+    def test_report_primary_error_when_rollback_fails(self):
+        User, users = self.classes.User, self.tables.users
+
+        mapper(User, users)
+
+        session = Session(testing.db)
+
+        with expect_warnings(
+                ".*ROLLBACK TO SAVEPOINT",
+                ".*Session's state has been changed"):
+            session.begin_nested()
+            savepoint = session.\
+                connection()._Connection__transaction._savepoint
+
+            # force the savepoint to disappear
+            session.execute("RELEASE SAVEPOINT %s" % savepoint)
+
+            # now do a broken flush
+            session.add_all([User(id=1), User(id=1)])
+
+            assert_raises_message(
+                sa_exc.DBAPIError,
+                "INSERT INTO ",
+                session.flush
+            )
+

 class _LocalFixture(FixtureTest):
     run_setup_mappers = 'once'

however, this still is dangerous: if code is specifically trying to catch certain IntegrityErrors in code that's inside of a SAVEPOINT, then retrying, in this case the SAVEPOINT is not being rolled back. This code would normally except out fully due to the failing ROLLBACK. We would be making assumptions here as to what conditions are causing the savepoint rollback to fail.

So, still not seeing a solution here.

[Mike Bayer]

yeah, here is exactly a common use case that will no longer throw an exception if the rollback fails:

from sqlalchemy import *
from sqlalchemy.orm import *
from sqlalchemy.ext.declarative import declarative_base
from sqlalchemy import exc

Base = declarative_base()


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

e = create_engine("postgresql://scott:tiger@localhost/test", echo=True)
Base.metadata.drop_all(e)
Base.metadata.create_all(e)


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

try:
    with s.begin_nested():
        s.connection()

        # force the savepoint to disappear; e.g. simulate the SAVEPOINT
        # has been broken
        s.execute("RELEASE SAVEPOINT sa_savepoint_1")

        s.add(A(id=1))
        s.flush()
except exc.IntegrityError:
    pass

With the patch in place, we end up at the IntegrityError, but the ROLLBACK TO SAVEPOINT has failed! Again, the cases we're seeing with MySQL as well as this "fake" case sort of end up working anyway, but this is still a huge behavioral change and has the risk that rollback failures are going to be squashed.

[Mike Bayer]

next idea - warn on the original exception! this might be better.

diff --git a/lib/sqlalchemy/orm/session.py b/lib/sqlalchemy/orm/session.py
index c726443..4272d7d 100644
--- a/lib/sqlalchemy/orm/session.py
+++ b/lib/sqlalchemy/orm/session.py
@@ -408,11 +408,23 @@ class SessionTransaction(object):
             for subtransaction in stx._iterate_parents(upto=self):
                 subtransaction.close()

+        if _capture_exception:
+            captured_exception = sys.exc_info()[1]
+
         boundary = self
         if self._state in (ACTIVE, PREPARED):
             for transaction in self._iterate_parents():
                 if transaction._parent is None or transaction.nested:
-                    transaction._rollback_impl()
+                    try:
+                        transaction._rollback_impl()
+                    except Exception:
+                        if _capture_exception:
+                            util.warn(
+                                "An exception raised during a Session "
+                                "persistence operation cannot be raised "
+                                "due to an additional ROLLBACK exception; "
+                                "the exception is: %s" % captured_exception)
+                        raise
                     transaction._state = DEACTIVE
                     boundary = transaction
                     break
@@ -434,7 +446,7 @@ class SessionTransaction(object):

         self.close()
         if self._parent and _capture_exception:
-            self._parent._rollback_exception = sys.exc_info()[1]
+            self._parent._rollback_exception = captured_exception

         sess.dispatch.after_soft_rollback(sess, self)

[Mike Bayer]

here's that in full...this is probably good

diff --git a/lib/sqlalchemy/orm/session.py b/lib/sqlalchemy/orm/session.py
index c726443..4272d7d 100644
--- a/lib/sqlalchemy/orm/session.py
+++ b/lib/sqlalchemy/orm/session.py
@@ -408,11 +408,23 @@ class SessionTransaction(object):
             for subtransaction in stx._iterate_parents(upto=self):
                 subtransaction.close()

+        if _capture_exception:
+            captured_exception = sys.exc_info()[1]
+
         boundary = self
         if self._state in (ACTIVE, PREPARED):
             for transaction in self._iterate_parents():
                 if transaction._parent is None or transaction.nested:
-                    transaction._rollback_impl()
+                    try:
+                        transaction._rollback_impl()
+                    except Exception:
+                        if _capture_exception:
+                            util.warn(
+                                "An exception raised during a Session "
+                                "persistence operation cannot be raised "
+                                "due to an additional ROLLBACK exception; "
+                                "the exception is: %s" % captured_exception)
+                        raise
                     transaction._state = DEACTIVE
                     boundary = transaction
                     break
@@ -434,7 +446,7 @@ class SessionTransaction(object):

         self.close()
         if self._parent and _capture_exception:
-            self._parent._rollback_exception = sys.exc_info()[1]
+            self._parent._rollback_exception = captured_exception

         sess.dispatch.after_soft_rollback(sess, self)

diff --git a/lib/sqlalchemy/testing/assertions.py b/lib/sqlalchemy/testing/assertions.py
index 21dc3e7..6366765 100644
--- a/lib/sqlalchemy/testing/assertions.py
+++ b/lib/sqlalchemy/testing/assertions.py
@@ -121,7 +121,7 @@ def uses_deprecated(*messages):
 def _expect_warnings(exc_cls, messages, regex=True, assert_=True):

     if regex:
-        filters = [re.compile(msg, re.I) for msg in messages]
+        filters = [re.compile(msg, re.I | re.S) for msg in messages]
     else:
         filters = messages

diff --git a/test/orm/test_transaction.py b/test/orm/test_transaction.py
index 73c6b97..3ec6b9c 100644
--- a/test/orm/test_transaction.py
+++ b/test/orm/test_transaction.py
@@ -657,6 +657,31 @@ class SessionTransactionTest(FixtureTest):
         assert session.transaction is not None, \
             'autocommit=False should start a new transaction'

+    @testing.requires.savepoints
+    def test_report_primary_error_when_rollback_fails(self):
+        User, users = self.classes.User, self.tables.users
+
+        mapper(User, users)
+
+        session = Session(testing.db)
+
+        with expect_warnings(".*due to an additional ROLLBACK.*INSERT INTO"):
+            session.begin_nested()
+            savepoint = session.\
+                connection()._Connection__transaction._savepoint
+
+            # force the savepoint to disappear
+            session.execute("RELEASE SAVEPOINT %s" % savepoint)
+
+            # now do a broken flush
+            session.add_all([User(id=1), User(id=1)])
+
+            assert_raises_message(
+                sa_exc.DBAPIError,
+                "ROLLBACK TO SAVEPOINT ",
+                session.flush
+            )
+

 class _LocalFixture(FixtureTest):
     run_setup_mappers = 'once'

[Mike Bayer]

• A rare case which occurs when a :meth:.Session.rollback fails in the scope of a :meth:.Session.flush operation that's raising an exception, as has been observed in some MySQL SAVEPOINT cases, prevents the original database exception from being observed when it was emitted during flush, but only on Py2K because Py2K does not support exception chaining; on Py3K the originating exception is chained. As a workaround, a warning is emitted in this specific case showing at least the string message of the original database error before we proceed to raise the rollback-originating exception. fixes #2696

→ <<cset a6fe4dc0c8eb>>

[Mike Bayer]

• A rare case which occurs when a :meth:.Session.rollback fails in the scope of a :meth:.Session.flush operation that's raising an exception, as has been observed in some MySQL SAVEPOINT cases, prevents the original database exception from being observed when it was emitted during flush, but only on Py2K because Py2K does not support exception chaining; on Py3K the originating exception is chained. As a workaround, a warning is emitted in this specific case showing at least the string message of the original database error before we proceed to raise the rollback-originating exception. fixes #2696

(cherry picked from commit a6fe4dc0c8ebc346a90dd849a86dac9345d74515)

→ <<cset caef13d8cf01>>

[Timothy Cardenas]

On latest sqlalchemy (1.0.10) a related issue occurs with the "core" (not using the ORM) where a given transaction will have a "is_active" set to True despite the database having already rolledback the transaction.

connection = engine.connect()
trans = connection.begin()
try:
    r1 = connection.execute(table1.select())
    connection.execute(table1.insert(), col1=7, col2='this insert causes a mysql deadlock')
    trans.commit()
except:
    # This property reports True after mysql deadlock exception has occurred, the 
    # transaction is actually closed already
    if trans.is_active:  
       trans.rollback()
    raise

When we trigger a rollback we get the same error message as the original reporter noticed which is:

sqlalchemy.exc.ProgrammingError: (mysql.connector.errors.ProgrammingError) 1305 (42000): SAVEPOINT sa_savepoint_1 does not exist [SQL: 'ROLLBACK TO SAVEPOINT sa_savepoint_1']

Do you know if this is known issue or if we need to do anything special to get the transaction state to update correctly after a deadlock exception?

[Mike Bayer]

hi Timothy -

the issue up here is strictly one of reporting exceptions within the ORM. so the issue you're dealing with as part of Core would be something separate.

It seems though that perhaps you've come across what the actual MySQL issue is that people are having. That is, with MySQL deadlock exceptions (need to know the exact message, version of MySQL / MariaDB / Galera / Percona / etc. in use, how to reproduce, thanks) are automatically rolling back transactions.

I'd love to know what specific case that is so if you can please produce a fully reproducing case (e.g. follow guidlelines at http://stackoverflow.com/help/mcve) we can perhaps add rules to the dialect such that we can accomodate this. Though the Core overall would need new architectures to support accomodation of exceptions that don't invalidate the whole connection but do invalidate a transaction. This would be an all new issue once we have your reproduction case, thanks!

[Former user]

I'm experiencing a very similar (if not the same) issue as Timothy. I'm currently running MySQL version: 5.6.26-74.0 Percona Server (GPL), Release 74.0, Revision 32f8dfd I'm attempting to use SQLAlchemy CORE to perform an update to a MySQL table within two nested transactions (started with begin_nested) and receiving:

  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1585, in __exit__
    self.rollback()
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 63, in __exit__
    compat.reraise(type_, value, traceback)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1585, in __exit__
    self.rollback()
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1559, in rollback
    self._do_rollback()
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1621, in _do_rollback
    self._savepoint, self._parent)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 717, in _rollback_to_savepoint_impl
    self.engine.dialect.do_rollback_to_savepoint(self, name)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 441, in do_rollback_to_savepoint
    connection.execute(expression.RollbackToSavepointClause(name))
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
    return meth(self, multiparams, params)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
    context)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception
    exc_info
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
    context)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
    cursor.execute(statement, parameters)
  File "/env/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute
    self.errorhandler(self, exc, value)
  File "/env/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (_mysql_exceptions.OperationalError) (1305, 'SAVEPOINT sa_savepoint_2 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_2']

Unfortunately while I am able to reproduce the issue, it occurs within my company's code, so I cannot exactly copy paste table schemas/queries.

It does appear however, that sqlalchemy is performing an invalid sequence of operations on the database, from the contents of my general query log:

#!
                143394 Query    SAVEPOINT sa_savepoint_2
                143394 Query    UPDATE mytable ... # Query 
                143394 Query    RELEASE SAVEPOINT sa_savepoint_2
                143394 Query    ROLLBACK TO SAVEPOINT sa_savepoint_2

I have also narrowed it down to this function within /engine/base.py

    def __exit__(self, type, value, traceback):
        if type is None and self.is_active:
            try:
                self.commit()
            except:
                with util.safe_reraise():
                    self.rollback()
        else:
            self.rollback()

When the code within the with statement has finished and exit is called, self.is_active is True and traceback is None, the savepoint has been acquired and the query has been run. From checking the general query log I can assert that sqlalchemy has not tried to release the savepoint, but also that it doesn't appear to be active (from show innodb status:)

#!
---TRANSACTION 555453261, not started
MySQL thread id 144053, OS thread handle 0x7f67b6dcf700, query id 1231274943 localhost user_write cleaning up

Then, within the try except a :

Traceback (most recent call last):
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1582, in __exit__
    self.commit()
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1570, in commit
    self._do_commit()
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1630, in _do_commit
    self._savepoint, self._parent)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 727, in _release_savepoint_impl
    self.engine.dialect.do_release_savepoint(self, name)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 444, in do_release_savepoint
    connection.execute(expression.ReleaseSavepointClause(name))
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
    return meth(self, multiparams, params)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
    context)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception
    exc_info
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
    context)
  File "/env/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
    cursor.execute(statement, parameters)
  File "/env/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute
    self.errorhandler(self, exc, value)
  File "/env/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (_mysql_exceptions.OperationalError) (1305, 'SAVEPOINT sa_savepoint_2 does not exist') [SQL: u'RELEASE SAVEPOINT sa_savepoint_2']

is raised within the self.commit function call, and SQLAlchemy has also attempted to release the savepoint.

#!
                143781 Query    RELEASE SAVEPOINT sa_savepoint_2

This error is likely caused by, as you mentioned, a deadlock causing MySQL to rollback the initial transaction that SQLAlchemy is attempting to commit - however after this has all happened SQLAlchemy then attempts to roll back the exception (within the util.safe_reraise() call), which results in the error in the first traceback I've posted.

If there's anything else I can do to assist investigation into this please let me know.

Cheers

EDIT: I am less convinced now that MySQL is rolling back the transaction because of a deadlock; after setting deadlock reporting to true I am seeing none being reported to the error log.

[Mike Bayer]

Hi @warrenspe -

There is one way that this codepath could perform that way and it's if the RELEASE itself fails.

That is, if I make this adjustment:

diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py
index 0b92856..8200528 100644
--- a/lib/sqlalchemy/engine/base.py
+++ b/lib/sqlalchemy/engine/base.py
@@ -1671,6 +1671,7 @@ class NestedTransaction(Transaction):
         if self.is_active:
             self.connection._release_savepoint_impl(
                 self._savepoint, self._parent)
+            raise Exception("release failed")


 class TwoPhaseTransaction(Transaction):

then we use any block that is of the commit/rollback form, e.g.:

try:
    s.commit()
except:
    s.rollback()
    raise

which is what we see in the __exit__() method of both base.Connection as well as Session:

from sqlalchemy import *
from sqlalchemy.orm import *
from sqlalchemy.ext.declarative import declarative_base

Base = declarative_base()

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

e = create_engine("mysql://scott:tiger@localhost/test", echo=True)
Base.metadata.drop_all(e)
Base.metadata.create_all(e)

s = Session(e)

with s.begin_nested()
    s.add(A(data=1))

then I can get that sequence of calls:

#!

2016-01-28 10:53:26,437 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
2016-01-28 10:53:26,438 INFO sqlalchemy.engine.base.Engine SAVEPOINT sa_savepoint_1
2016-01-28 10:53:26,438 INFO sqlalchemy.engine.base.Engine ()
2016-01-28 10:53:26,439 INFO sqlalchemy.engine.base.Engine INSERT INTO a (data) VALUES (%s)
2016-01-28 10:53:26,439 INFO sqlalchemy.engine.base.Engine (1,)
2016-01-28 10:53:26,441 INFO sqlalchemy.engine.base.Engine RELEASE SAVEPOINT sa_savepoint_1
2016-01-28 10:53:26,441 INFO sqlalchemy.engine.base.Engine ()
2016-01-28 10:53:26,441 INFO sqlalchemy.engine.base.Engine ROLLBACK TO SAVEPOINT sa_savepoint_1
2016-01-28 10:53:26,441 INFO sqlalchemy.engine.base.Engine ()
Traceback (most recent call last):
  File "test.py", line 25, in <module>
    s.rollback()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 768, in rollback
    self.transaction.rollback()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 419, in rollback
    transaction._rollback_impl()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 457, in _rollback_impl
    t[1].rollback()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1606, in rollback
    self._do_rollback()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1668, in _do_rollback
    self._savepoint, self._parent)
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 748, in _rollback_to_savepoint_impl
    self.engine.dialect.do_rollback_to_savepoint(self, name)
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/default.py", line 453, in do_rollback_to_savepoint
    connection.execute(expression.RollbackToSavepointClause(name))
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 945, in execute
    return meth(self, multiparams, params)
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/sql/elements.py", line 262, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1189, in _execute_context
    context)
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1384, in _handle_dbapi_exception
    exc_info
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/util/compat.py", line 200, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1182, in _execute_context
    context)
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/default.py", line 462, in do_execute
    cursor.execute(statement, parameters)
  File "/home/classic/.venv/lib/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute
    self.errorhandler(self, exc, value)
  File "/home/classic/.venv/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
sqlalchemy.exc.OperationalError: (_mysql_exceptions.OperationalError) (1305, 'SAVEPOINT sa_savepoint_1 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_1']

so the assumption here would be MySQL fails the RELEASE for an unknown reason, but then erases the savepoint anyway. That's unexpected on MySQL's part.

However, it also means that the thing we fixed in this issue is still not working; in this codepath, we aren't sending this exception over to the warning that we added here; this patch would resolve that:

diff --git a/lib/sqlalchemy/orm/session.py b/lib/sqlalchemy/orm/session.py
index 5651386..fcfd405 100644
--- a/lib/sqlalchemy/orm/session.py
+++ b/lib/sqlalchemy/orm/session.py
@@ -492,9 +492,9 @@ class SessionTransaction(object):
         if type is None:
             try:
                 self.commit()
-            except:
+            except Exception as e:
                 with util.safe_reraise():
-                    self.rollback()
+                    self.rollback(_capture_exception=e)
         else:
             self.rollback()

Care to try the latter patch, reproduce your error, and get us some clue what MySQL is actually raising?

[Mike Bayer]

there's at least one codepath that still does not warn, if the release itself fails.

[Former user]

Absolutely, however I'm using the CORE library; not the ORM; and the CORE library doesn't seem to accept a _capture_exceptions parameter.

[Mike Bayer]

right, i will add it there also. can you patch a warning in there for now and reproduce your issue?

[Mike Bayer]

also, Py3K handles this situation already as well:

#!

Traceback (most recent call last):
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 494, in __exit__
    self.commit()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/orm/session.py", line 392, in commit
    t[1].commit()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1617, in commit
    self._do_commit()
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1674, in _do_commit
    raise Exception("release failed")
Exception: release failed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py", line 1182, in _execute_context
    context)

  ...

  File "/home/classic/.venv3/lib/python3.4/site-packages/MySQLdb/connections.py", line 280, in query
    _mysql.connection.query(self, query)
_mysql_exceptions.OperationalError: (1305, 'SAVEPOINT sa_savepoint_1 does not exist')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "test.py", line 19, in <module>
    s.add(A(data=1))
    db.query(q)

...

  File "/home/classic/.venv3/lib/python3.4/site-packages/MySQLdb/connections.py", line 280, in query
    _mysql.connection.query(self, query)
sqlalchemy.exc.OperationalError: (_mysql_exceptions.OperationalError) (1305, 'SAVEPOINT sa_savepoint_1 does not exist') [SQL: 'ROLLBACK TO SAVEPOINT sa_savepoint_1']

but a question to answer here is, if a savepoint actually fails to be released, what should we be doing with it - do we assume it's gone, or what. Easiest approach is to do nothing here and just continue to try to report all the detail for Py2K.

[Mike Bayer]

here's the change I'm considering; move up the exception-warning behavior up to the safe_reraise() level across the board, and do it only for py2k:

diff --git a/lib/sqlalchemy/orm/session.py b/lib/sqlalchemy/orm/session.py
index 5651386..36f339d 100644
--- a/lib/sqlalchemy/orm/session.py
+++ b/lib/sqlalchemy/orm/session.py
@@ -415,16 +415,7 @@ class SessionTransaction(object):
         if self._state in (ACTIVE, PREPARED):
             for transaction in self._iterate_parents():
                 if transaction._parent is None or transaction.nested:
-                    try:
-                        transaction._rollback_impl()
-                    except Exception:
-                        if _capture_exception:
-                            util.warn(
-                                "An exception raised during a Session "
-                                "persistence operation cannot be raised "
-                                "due to an additional ROLLBACK exception; "
-                                "the exception is: %s" % captured_exception)
-                        raise
+                    transaction._rollback_impl()
                     transaction._state = DEACTIVE
                     boundary = transaction
                     break
@@ -2383,7 +2374,7 @@ class Session(_SessionClassMethods):

         except:
             with util.safe_reraise():
-                transaction.rollback(_capture_exception=True)
+                transaction.rollback()
         finally:
             self._flushing = False

diff --git a/lib/sqlalchemy/util/langhelpers.py b/lib/sqlalchemy/util/langhelpers.py
index 11aa938..e530669 100644
--- a/lib/sqlalchemy/util/langhelpers.py
+++ b/lib/sqlalchemy/util/langhelpers.py
@@ -59,6 +59,13 @@ class safe_reraise(object):
             self._exc_info = None   # remove potential circular references
             compat.reraise(exc_type, exc_value, exc_tb)
         else:
+            if not compat.py3k and self._exc_info and self._exc_info[1]:
+                # emulate Py3K's behavior of telling us when an exception
+                # occurs in an exception handler.
+                warn(
+                    "An exception has occurred during handling of a "
+                    "previous exception.  The previous exception "
+                    "is:\n %r\n" % self._exc_info[1])
             self._exc_info = None   # remove potential circular references
             compat.reraise(type_, value, traceback)

[Former user]

So I've stepped through my code to trace the exact command which causes MySQL to roll back the transaction.

It turns out that at some point after creating the initial transaction and second inner transaction a statement, "SET AUTOCOMMIT=1" is being run, which appears to automatically invalidates any current MySQL sessions.

That aside, the issue then becomes that SQLAlchemy and MySQL are out of sync, SQLAlchemy thinking that it is still inside of a transaction with MySQL disagreeing.

I shall apply your patch shortly to ensure it prints out the error

[Former user]

To be explicit, to reproduce this error with SQLAlchemy core, one needs to:

#!
Open a new connection
Start a nested transaction using the with statement
Perform some operation on the database to cause this transaction to move into the ACTIVE state within mysql
Run "SET AUTOCOMMIT=1"
Start a second transaction using the with statement
Perform another operation on the database
End the block

I have applied your patch, which prints the following warning as expected

SAWarning: An exception has occurred during handling of a previous exception.  The previous exception is:
 OperationalError("(_mysql_exceptions.OperationalError) (1305, 'SAVEPOINT sa_savepoint_2 does not exist')",)

It'd obviously be better if the status of the transaction could be acquired from the underlying connection object in order to determine whether any action could be taken; however I suspect this isn't possible / exposed for every database API that SQLAlchemy supports; in lieu of that, this warning seems to be a decent work around.

Also for any future generations reading this thread in order to debug a similar issue (using MySQL); I recommend stepping through your code, running "show engine innodb status\G" narrowing in on the command at which the transaction your connection has opened switches from ACTIVE to "not started"

Thanks for your assistance @zzzeek

[Mike Bayer]

It'd obviously be better if the status of the transaction could be acquired from the underlying connection object in order to determine whether any action could be taken;

well we're already in a transaction that's going to fail. When you're in failure mode you want to minimize how many more decisions you make and especially you want to back off the connection itself as much as possible, since it is in an unknown state. So here, we try to do the rollback as we normally want to do 99% of the time, and if even that fails, we at least try to say what happened. If we tried to anticipate up front that rollback would fail, then our attempt to interrogate the connection for this state could also fail, and the we're even deeper failure-mode decisionmaking. Better to ask forgiveness than permission applies here.

[Mike Bayer]

• revert the change first made in a6fe4dc, as we are now generalizing the warning here to all safe_reraise() cases in Python 2.
• Revisiting 2696, first released in 1.0.10, which attempts to work around Python 2's lack of exception context reporting by emitting a warning for an exception that was interrupted by a second exception when attempting to roll back the already-failed transaction; this issue continues to occur for MySQL backends in conjunction with a savepoint that gets unexpectedly lost, which then causes a "no such savepoint" error when the rollback is attempted, obscuring what the original condition was.

The approach has been generalized to the Core "safe reraise" function which takes place across the ORM and Core in any place that a transaction is being rolled back in response to an error which occurred trying to commit, including the context managers provided by :class:.Session and :class:.Connection, and taking place for operations such as a failure on "RELEASE SAVEPOINT". Previously, the fix was only in place for a specific path within the ORM flush/commit process; it now takes place for all transational context managers as well. fixes #2696

→ <<cset 8a1e619fb20d>>

[Mike Bayer]

• revert the change first made in a6fe4dc, as we are now generalizing the warning here to all safe_reraise() cases in Python 2.
• Revisiting 2696, first released in 1.0.10, which attempts to work around Python 2's lack of exception context reporting by emitting a warning for an exception that was interrupted by a second exception when attempting to roll back the already-failed transaction; this issue continues to occur for MySQL backends in conjunction with a savepoint that gets unexpectedly lost, which then causes a "no such savepoint" error when the rollback is attempted, obscuring what the original condition was.

The approach has been generalized to the Core "safe reraise" function which takes place across the ORM and Core in any place that a transaction is being rolled back in response to an error which occurred trying to commit, including the context managers provided by :class:.Session and :class:.Connection, and taking place for operations such as a failure on "RELEASE SAVEPOINT". Previously, the fix was only in place for a specific path within the ORM flush/commit process; it now takes place for all transational context managers as well. fixes #2696

(cherry picked from commit 8a1e619fb20df1be6ad2e0c563e451e17eb17628)

→ <<cset 7a7483c0cf2f>>