1. Michael Bayer
  2. sqlalchemy

Issues

Issue #2864 resolved

Disconnect via IDLE_TIME resource limit not handled by SQLAlchemy

Anonymous created an issue

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)

  1. Anonymous

    I forgot to mention how to configure the database server so that the connection is actually sniped. I used the following SQL commands (as sysdba) to restrict the example user loco_tl to one minute of idle time before being sniped. Note that Oracle does not check the expiration very often which means that I had to wait three minutes on average to have the connection really cut. I used attachment:list_sessions.sql to check when my connection was really sniped.

    CREATE PROFILE short_idle LIMIT IDLE_TIME 1; # see http://docs.oracle.com/cd/B28359_01/server.111/b28286/statements_6010.htm#SQLRF54200 ALTER USER loco_tl PROFILE short_idle; # see http://docs.oracle.com/cd/B28359_01/server.111/b28286/statements_4003.htm ALTER SYSTEM SET RESOURCE_LIMIT = TRUE; # see http://docs.oracle.com/cd/B28359_01/server.111/b28286/statements_2013.htm#i2198497

  2. Anonymous

    Replying to zzzeek:

    OK so we just need to add 2396 to the list, right?

    Correct. For bonus points it would be great if closing a closed connection would not log to the error level. We currently generate automatic bug reports from that :-) However I have no idea how to fix that and I guess that's more of a bug in cx_Oracle.

  3. Michael Bayer repo owner

    well the connection is "invalidated" when we detect disconnect but we don't assume that means "closed", for safety we run a "safe close", as you've noticed we don't propagate the exception there as we're expecting it to fail in many cases, this gets logged. it's normal when an unexpected disconnect happens. this could be improved if is_disconnect also gave out info regarding "try to close" or not, then we'd have to get that all into the pool logic and such, not sure if I'm eager to get into that as the pool's stability is pretty critical.

  4. Anonymous

    Replying to zzzeek:

    this could be improved if is_disconnect also gave out info regarding "try to close" or not, then we'd have to get that all into the pool logic and such, not sure if I'm eager to get into that as the pool's stability is pretty critical.

    I would try to improve the Oracle dialect class to check if the connection is still alive before trying to close it. I did not find any method in cx_Oracle to check that though. Perhaps later :)

  5. Log in to comment