Disconnect via IDLE_TIME resource limit not handled by SQLAlchemy

tl;dr: Error code ORA-02396 is missing in OracleDialect_cx_oracle.is_disconnect.

We have an application where the Oracle server is configured to automatically disconnect clients by the IDLE_TIME resource limit. This leads to the ORA-02396 error code, which is never seen from the application side.

Example code:

import logging
from sqlalchemy import *
from sqlalchemy.exc import DBAPIError

demo_query = "select 42 from dual"

if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO)
    engine = create_engine("oracle://loco_tl:loco_tl@loco_tl")  # XXX: Adjust database URL
    print "Running a query from a fresh engine:"
    print "SQL: %r -> %r" % (demo_query, engine.execute(demo_query).scalar())

    print "Status of the connection pool: %s" % engine.pool.status()
    print "Press enter after connection was sniped by Oracle."
    raw_input()

    try:
        print "Running the query from the same engine:"
        print "SQL: %r -> %r" % (demo_query, engine.execute(demo_query).scalar())
    except DBAPIError, e:
        if not e.connection_invalidated:
            raise
        print "Connection was invalidated, retrying:"
        print "SQL: %r -> %r" % (demo_query, engine.execute(demo_query).scalar())

Expected output in my case:

$ python initial.py
Running a query from a fresh engine:
SQL: 'select 42 from dual' -> 42
Status of the connection pool: Pool size: 5  Connections in pool: 1 Current Overflow: -4 Current Checked out connections: 0
Press enter after connection was sniped by Oracle.

Running the query from the same engine:
Connection was invalidated, retrying:
SQL: 'select 42 from dual' -> 42

Instead I get the following output:

$ python initial.py 
Running a query from a fresh engine:
SQL: 'select 42 from dual' -> 42
Status of the connection pool: Pool size: 5  Connections in pool: 1 Current Overflow: -4 Current Checked out connections: 0
Press enter after connection was sniped by Oracle.

Running the query from the same engine:
ERROR:sqlalchemy.pool.QueuePool:Exception closing connection <cx_Oracle.Connection to loco_tl@loco_tl>
Traceback (most recent call last):
  File "../python2.7/site-packages/sqlalchemy/pool.py", line 191, in _close_connection
    self._dialect.do_close(connection)
  File "../python2.7/site-packages/sqlalchemy/engine/default.py", line 352, in do_close
    dbapi_connection.close()
OperationalError: ORA-01012: not logged on
Process ID: 25873
Session ID: 25 Serial number: 10916

Traceback (most recent call last):
  File "initial.py", line 23, in <module>
    print "SQL: %r -> %r" % (demo_query, engine.execute(demo_query).scalar())
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 1598, in execute
    return connection.execute(statement, *multiparams, **params)
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 656, in execute
    return self._execute_text(object, multiparams, params)
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 805, in _execute_text
    statement, parameters
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
    context)
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 1013, in _handle_dbapi_exception
    self._autorollback()
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 556, in _autorollback
    self._rollback_impl()
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 476, in _rollback_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 991, in _handle_dbapi_exception
    exc_info
  File "../python2.7/site-packages/sqlalchemy/util/compat.py", line 185, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "../python2.7/site-packages/sqlalchemy/engine/base.py", line 473, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "../python2.7/site-packages/sqlalchemy/engine/default.py", line 346, in do_rollback
    dbapi_connection.rollback()
sqlalchemy.exc.OperationalError: (OperationalError) ORA-01012: not logged on
Process ID: 25873
Session ID: 25 Serial number: 10916
 None None

My current solution is to replace the Oracle dialect like this (which would also make a nice addition to the documentation I think because it shows how to overwrite specifics of a dialect class):

from sqlalchemy.dialects import registry, oracle

class MyOracleDialect(oracle.cx_oracle.OracleDialect_cx_oracle):

    def is_disconnect(self, e, connection, cursor):
        error, = e.args
        if isinstance(e, self.dbapi.InterfaceError):
            return "not connected" in str(e)
        elif hasattr(error, 'code'):
            # logging.info("MyOracleDialect.is_disconnect: ORA-%s", error.code)
            # ORA-00028: your session has been killed
            # ORA-03114: not connected to ORACLE
            # ORA-03113: end-of-file on communication channel
            # ORA-03135: connection lost contact
            # ORA-01033: ORACLE initialization or shutdown in progress
            # ORA-02396: exceeded maximum idle time, please connect again
            # TODO: Others ?
            return error.code in (28, 3114, 3113, 3135, 1033, 2396)
        else:
            return False

registry.register("oracle", __name__, "MyOracleDialect")

With this addition the actual behaviour still falls a bit short but is good enough for us:

$ python fixed.py 
Running a query from a fresh engine:
SQL: 'select 42 from dual' -> 42
Status of the connection pool: Pool size: 5  Connections in pool: 1 Current Overflow: -4 Current Checked out connections: 0
Press enter after connection was sniped by Oracle.

Running the query from the same engine:
ERROR:sqlalchemy.pool.QueuePool:Exception closing connection <cx_Oracle.Connection to loco_tl@loco_tl>
Traceback (most recent call last):
  File "../python2.7/site-packages/sqlalchemy/pool.py", line 191, in _close_connection
    self._dialect.do_close(connection)
  File "../python2.7/site-packages/sqlalchemy/engine/default.py", line 352, in do_close
    dbapi_connection.close()
OperationalError: ORA-01012: not logged on
Process ID: 23387
Session ID: 58 Serial number: 6081

Connection was invalidated, retrying:
SQL: 'select 42 from dual' -> 42

It is unfortunate that closing the connection fails here as it was in fact closed (or rather disabled) on the server side. Doesn't really matter for us as the message does not do any harm other than adding a bit to the log files.

Tested with the following version of SQLAlchemy:

torsten@sharokan:~/workspace/sqlalchemy$ git describe --tags
rel_0_9_0b1-12-g5d0e844

Comments (11)