warn for exception squashed by autorollback exception

[Daniel Eisner]

Hi,

If I try to run a bad "SELECT" statement without starting a transaction, SQLAlchemy tries to roll back the transaction, which fails, and then raises a ProgrammingError execption, obscuring the original exception.

I think the problem is with this bit of code in sqlalchemy.engine.base:

def _autorollback(self):
    if not self._root.in_transaction():
        self._root._rollback_impl()

That logic looks backwards to me. Was this the original intent? Below is an example stack trace from a case like this.

---

Traceback:

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/pandas/io/sql.pyc in read_sql(sql, con, index_col, coerce_float, params, parse_dates, columns, chunksize) 492 sql, index_col=index_col, params=params, 493 coerce_float=coerce_float, parse_dates=parse_dates, --> 494 chunksize=chunksize) 495 496

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/pandas/io/sql.pyc in read_query(self, sql, index_col, coerce_float, parse_dates, params, chunksize) 1126 args = _convert_params(sql, params) 1127 -> 1128 result = self.execute(*args) 1129 columns = result.keys() 1130

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/pandas/io/sql.pyc in execute(self, args, kwargs) 1020 def execute(self, args, kwargs): 1021 """Simple passthrough to SQLAlchemy engine""" -> 1022 return self.engine.execute(*args, kwargs) 1023 1024 def read_table(self, table_name, index_col=None, coerce_float=True,

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in execute(self, statement, multiparams, params) 2053 2054 connection = self.contextual_connect(close_with_result=True) -> 2055 return connection.execute(statement, multiparams, params) 2056 2057 def scalar(self, statement, *multiparams, params):

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in execute(self, object, multiparams, *params) 937 """ 938 if isinstance(object, util.string_types[0]): --> 939 return self._execute_text(object, multiparams, params) 940 try: 941 meth = object._execute_on_connection

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in _execute_text(self, statement, multiparams, params) 1095 statement, 1096 parameters, -> 1097 statement, parameters 1098 ) 1099 if self._has_events or self.engine._has_events:

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in _execute_context(self, dialect, constructor, statement, parameters, *args) 1187 parameters, 1188 cursor, -> 1189 context) 1190 1191 if self._has_events or self.engine._has_events:

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in _handle_dbapi_exception(self, e, statement, parameters, cursor, context) 1384 if cursor: 1385 self._safe_close_cursor(cursor) -> 1386 self._autorollback() 1387 1388 if newraise:

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in _autorollback(self) 822 def _autorollback(self): 823 if not self._root.in_transaction(): --> 824 self._root._rollback_impl() 825 826 def close(self):

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in _rollback_impl(self) 701 self.engine.dialect.do_rollback(self.connection) 702 except BaseException as e: --> 703 self._handle_dbapi_exception(e, None, None, None, None) 704 finally: 705 if not self.__invalid and \

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in _handle_dbapi_exception(self, e, statement, parameters, cursor, context) 1313 self.dialect.dbapi.Error, 1314 dialect=self.dialect), -> 1315 exc_info 1316 ) 1317 self._reentrant_error = True

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/util/compat.pyc in raise_from_cause(exception, exc_info) 201 exc_type, exc_value, exc_tb = exc_info 202 cause = exc_value if exc_value is not exception else None --> 203 reraise(type(exception), exception, tb=exc_tb, cause=cause) 204 205 if py3k:

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/base.pyc in _rollback_impl(self) 699 self.engine.logger.info("ROLLBACK") 700 try: --> 701 self.engine.dialect.do_rollback(self.connection) 702 except BaseException as e: 703 self._handle_dbapi_exception(e, None, None, None, None)

/home/developer/.conda/envs/core_runtime/lib/python2.7/site-packages/sqlalchemy/engine/default.pyc in do_rollback(self, dbapi_connection) 438 439 def do_rollback(self, dbapi_connection): --> 440 dbapi_connection.rollback() 441 442 def do_commit(self, dbapi_connection):

ProgrammingError: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')

[Mike Bayer]

Python DBAPI is always in a transaction, it is always valid to call ROLLBACK, and in the case of the Connection's "autocommit" mode, we emit ROLLBACK when the statement fails in order to reset the connection's state back to zero so that another statement can be invoked upon it. I need example code here in order to help with this problem, however this looks like a pyodbc bug to start with as if it did not emit "BEGIN" (which it is supposed to), it should not be attempting the ROLLBACK.

[Daniel Eisner]

Is it desirable to be within a transaction even when running read-only queries? My DBA co-worker tells me the using transactions needlessly in read-only cases puts more load on the database, and also makes MS SQL Server unable to route connections to read-only replicas.

I any case, I had disabled auto-commit in this case, so I wouldn't expect it to try to ROLLBACK. The exception comes from pyodbc, but it is sqlalchemy which is issuing the ROLLBACK.

I'll post a code snippet in a minute.

[Daniel Eisner]

Here's an example, similar to what generated the exception stack posted earlier. If the SELECT statement has an error in it, it will raise an exception. SQLAlchemy catches the exception, and tries to do a ROLLBACK, even though there is no active transaction. This creates a secondary exception that masks the original one. This makes debugging your SQL statements very difficult.

On further testing, this doesn't happen on any arbitrary error. For example, if I literally use "select foo from bar," then I get expected behavior and it gives me a real error message.

It seems to happen reproducibly under the following condition:

I SELECT for a "synonym object" in MS SQL, which is an alias for a view for which I don't have permission to query (or a synonym to a view which doesn't exist).

Possibly what's happening here is that the database is returning some sort of "permission denied" error, and SQLAlchemy isn't handling that properly?

I noticed similar problems when establishing connections -- pyodbc doesn't distinguish between "permission denied" on connection vs any other connection problem (default database doesn't exist, wrong IP, etc).

       import pandas as pd

        # Disable connection pooling at pyodbc level as sqlalchemy provides it
        pyodbc.pooling = False

        exec_opts = dict(autocommit=False)
        db_url = 'mssql+pyodbc://MYSERVER:1433/MYDB?trusted=True&APP=ipython&TDS_Version=7.3&PORT=1433&DRIVER=FreeTDS&read-only=true'
        engine = sqlalchemy.create_engine(db_url,
                                                                 pool_size=4,
                                                                 pool_recycle=600,
                                                                 execution_options=exec_opts)
        dataframe = pd.read('SELECT foo from bar', engine)

[Mike Bayer]

Is it desirable to be within a transaction even when running read-only queries? My DBA co-worker tells me the using transactions needlessly in read-only cases puts more load on the database, and also makes MS SQL Server unable to route connections to read-only replicas.

This is an issue of the pyodbc driver. SQLAlchemy does not emit the "BEGIN" statement. You can pass "autocommit=True" to the driver like this:

create_engine("mssql+pyodbc://", connect_args=dict(autocommit=True))

SQLAlchemy supports per-connection DBAPI driver "autocommit" for the Postgresql currently, this could be added as a feature for the pyodbc/mssql backend as well, it would look like:

   with engine.connect().execution_options(isolation_level='AUTOCOMMIT') as conn:
       ...

for now, you can get it on a per-statement basis like this:

   with engine.connect() as conn:
       conn.connection.connection.autocommit = True
       try:
            result = conn.execute(stmt)
       finally:
           conn.connection.connection.autocommit = False

however this is off topic for the error you're getting which is still a bug in pyodbc.

[Mike Bayer]

Possibly what's happening here is that the database is returning some sort of "permission denied" error,

that is likely

and SQLAlchemy isn't handling that properly?

SQLAlchemy raises this error correctly, it's just in this case, pyodbc is also refusing to let its own rollback() method work correctly, in that per pep-249 it should roll back "any pending transaction" (meaning, if there's no transaction, don't roll back) which is a bug in pyodbc.

But also, this is a bug in Python 2, because you can't see another exception as the "cause" of an exception. If you run on Python 3 you should see both.

In some critical sections, we've added a warning to allow for illustrating an exception that may be obscured, in Python 2, when the "rollback" also fails. This would look like this:

diff --git a/lib/sqlalchemy/engine/base.py b/lib/sqlalchemy/engine/base.py
index 0334d2d..ec6d00f 100644
--- a/lib/sqlalchemy/engine/base.py
+++ b/lib/sqlalchemy/engine/base.py
@@ -821,7 +821,8 @@ class Connection(Connectable):

     def _autorollback(self):
         if not self._root.in_transaction():
-            self._root._rollback_impl()
+            with util.safe_reraise():
+                self._root._rollback_impl()

     def close(self):
         """Close this :class:`.Connection`.

However, work would be needed here because some tests fail when that's added. If you can please try this patch and see if you get a warning in your logs for the ultimate error. Of course if you really want to know what the error is right now, just use pdb.

[Daniel Eisner]

Yes, that reraises the original root cause, thanks! Are you going to commit that to master?

[Mike Bayer]

i need to determine why it's getting in the way of some tests. the same exception has to be raised, the "cause" that's being obscured for you should be in a warning message only, not a reraise of the cause for the rollback failure.

[Mike Bayer]

Add safe_reraise() + warnings only to Connection._autorollback

Added an exception handler that will warn for the "cause" exception on Py2K when the "autorollback" feature of :class:.Connection itself raises an exception. In Py3K, the two exceptions are naturally reported by the interpreter as one occurring during the handling of the other. This is continuing with the series of changes for rollback failure handling that were last visited as part of 2696 in 1.0.12.

Change-Id: I600ba455a14ebaea27c6189889181f97c632f179 Fixes: #3946 (cherry picked from commit c0a224aba3d4e2a41f92a29f9d18c6cb9d09d61f)

→ <<cset 08f42a915a40>>

[Mike Bayer]

Add safe_reraise() + warnings only to Connection._autorollback

Added an exception handler that will warn for the "cause" exception on Py2K when the "autorollback" feature of :class:.Connection itself raises an exception. In Py3K, the two exceptions are naturally reported by the interpreter as one occurring during the handling of the other. This is continuing with the series of changes for rollback failure handling that were last visited as part of 2696 in 1.0.12.

Change-Id: I600ba455a14ebaea27c6189889181f97c632f179 Fixes: #3946

→ <<cset c0a224aba3d4>>