Query.first() sometimes returns None

[Ryan Chapman]

Oracle database via cx_Oracle on SQLAlchemy 1.0.6 (also tested on some older versions, got same result).

About 50% of the time, using Query.first() on a query will return None. The rest of the time the query returns results as expected. The same behavior is not seen when using the expression language by itself or when using any other client on this or any other computer to retrieve the data. This issue can be duplicated on other machines.

Here is the code I used to generate this error:

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

# Fix environment variables
import os
try:
    del os.environ['ORACLE_HOME']
except KeyError:
    pass
os.environ['TNS_ADMIN'] = r'C:\product\11.1.0\client_1\network\admin'
os.environ['PATH'] = r'C:\product\11.1.0\client_1\BIN;' + os.environ['PATH']

engine = create_engine(r'oracle+cx_oracle://{username}:{password}@{service_name}'.format(username='USER', password='PASSWORD', service_name='SERVICE'))
session_maker = sessionmaker(bind=engine)
base_class = declarative_base()

class Lot(base_class):
    __tablename__ = 'lot'
    __table_args__ = {'schema': 'SCHEMA_NAME'}
    lot_key = Column(Integer, primary_key=True)
    lot_id = Column(String)

session = session_maker()
cursor = session.query(Lot)
result = cursor.first()
if result is None:
    raise Exception

[Mike Bayer]

first() will return None if either A. there's no row returned by the query or B. the row that is returned does not have a non-NULL value in the columns noted as the primary key. Without data there's no bug illustrated here.

[Ryan Chapman]

Sorry, Mike. I should have stated that the Lot table is populated with thousands of rows. None of the values for lot_key or lot_id are NULL.

So when this query is run using the code above, I will sometimes get the first row of the Lot table back. Sometimes it just returns None.

When this query is run using the expression language, however, it always returns the first row.

[Mike Bayer]

OK can you turn on "echo='debug'" on your engine and also is this somethign that reproduces in a self-contained enviroment? There's no reason first() would erroneously return None here I'd need a test case that reproduces it locally.

[Ryan Chapman]

I don't have that level of access to our Oracle server, so I can't guarantee that it will reproduce. What would you need? Oracle version, drivers, windows version, python version?

Here is the echo output:

2015-07-20 13:33:11,850 INFO sqlalchemy.engine.base.Engine b'SELECT USER FROM DUAL'
2015-07-20 13:33:11,850 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:33:11,852 INFO sqlalchemy.engine.base.Engine SELECT CAST('test plain returns' AS VARCHAR(60 CHAR)) AS anon_1 FROM DUAL
2015-07-20 13:33:11,852 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:33:11,853 INFO sqlalchemy.engine.base.Engine SELECT CAST('test unicode returns' AS NVARCHAR2(60)) AS anon_1 FROM DUAL
2015-07-20 13:33:11,853 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:33:11,856 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
2015-07-20 13:33:11,857 INFO sqlalchemy.engine.base.Engine b'SELECT "SCHEMA_lot_lot_key", "SCHEMA_lot_lot_id" \nFROM (SELECT "SCHEMA".lot.lot_key AS "SCHEMA_lot_lot_key", "SCHEMA".lot.lot_id AS "SCHEMA_lot_lot_id" \nFROM "SCHEMA".lot) \nWHERE ROWNUM <= :param_1'
2015-07-20 13:33:11,858 INFO sqlalchemy.engine.base.Engine {b'param_1': 1}

[Mike Bayer]

I meant echo='debug' which shows the rows coming back:

engine = create_engine("oracle://..", echo='debug')

What result do you get running this query in sqlplus ?

SELECT "SCHEMA_lot_lot_key", "SCHEMA_lot_lot_id" 
FROM (SELECT "SCHEMA".lot.lot_key AS "SCHEMA_lot_lot_key", "SCHEMA".lot.lot_id AS "SCHEMA_lot_lot_id" 
FROM "SCHEMA".lot) 
WHERE ROWNUM <= 1

[Ryan Chapman]

Here's the output with echo='debug' when the query returns no rows:

2015-07-20 13:49:41,436 INFO sqlalchemy.engine.base.Engine b'SELECT USER FROM DUAL'
2015-07-20 13:49:41,437 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:49:41,438 DEBUG sqlalchemy.engine.base.Engine Col ('USER',)
2015-07-20 13:49:41,439 DEBUG sqlalchemy.engine.base.Engine Row ('DPUSER',)
2015-07-20 13:49:41,439 INFO sqlalchemy.engine.base.Engine SELECT CAST('test plain returns' AS VARCHAR(60 CHAR)) AS anon_1 FROM DUAL
2015-07-20 13:49:41,439 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:49:41,440 INFO sqlalchemy.engine.base.Engine SELECT CAST('test unicode returns' AS NVARCHAR2(60)) AS anon_1 FROM DUAL
2015-07-20 13:49:41,440 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:49:41,443 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
2015-07-20 13:49:41,444 INFO sqlalchemy.engine.base.Engine b'SELECT "SCHEMA_lot_lot_key", "SCHEMA_lot_lot_id" \nFROM (SELECT "SCHEMA".lot.lot_key AS "SCHEMA_lot_lot_key", "SCHEMA".lot.lot_id AS "SCHEMA_lot_lot_id" \nFROM "SCHEMA".lot) \nWHERE ROWNUM <= :param_1'
2015-07-20 13:49:41,444 INFO sqlalchemy.engine.base.Engine {b'param_1': 1}
2015-07-20 13:49:41,445 DEBUG sqlalchemy.engine.base.Engine Col ('SCHEMA_lot_lot_key', 'SCHEMA_lot_lot_id')

And here is the same piece of code when it returns rows:

2015-07-20 13:52:27,579 INFO sqlalchemy.engine.base.Engine b'SELECT USER FROM DUAL'
2015-07-20 13:52:27,579 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:52:27,580 DEBUG sqlalchemy.engine.base.Engine Col ('USER',)
2015-07-20 13:52:27,581 DEBUG sqlalchemy.engine.base.Engine Row ('DPUSER',)
2015-07-20 13:52:27,581 INFO sqlalchemy.engine.base.Engine SELECT CAST('test plain returns' AS VARCHAR(60 CHAR)) AS anon_1 FROM DUAL
2015-07-20 13:52:27,581 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:52:27,583 INFO sqlalchemy.engine.base.Engine SELECT CAST('test unicode returns' AS NVARCHAR2(60)) AS anon_1 FROM DUAL
2015-07-20 13:52:27,583 INFO sqlalchemy.engine.base.Engine {}
2015-07-20 13:52:27,586 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
2015-07-20 13:52:27,587 INFO sqlalchemy.engine.base.Engine b'SELECT "SCHEMA_lot_lot_key", "SCHEMA_lot_lot_id" \nFROM (SELECT "SCHEMA".lot.lot_key AS "SCHEMA_lot_lot_key", "SCHEMA".lot.lot_id AS "SCHEMA_lot_lot_id" \nFROM "SCHEMA".lot) \nWHERE ROWNUM <= :param_1'
2015-07-20 13:52:27,587 INFO sqlalchemy.engine.base.Engine {b'param_1': 1}
2015-07-20 13:52:27,588 DEBUG sqlalchemy.engine.base.Engine Col ('SCHEMA_lot_lot_key', 'SCHEMA_lot_lot_id')
2015-07-20 13:52:27,588 DEBUG sqlalchemy.engine.base.Engine Row (1581, 'S9343.S')

Here is the output from sqlplus:

SCHEMA_lot_lot_key SCHEMA_lot_lot_id
------------------ -----------------
              1581 S9343.S

[Mike Bayer]

yeah. There's no row returned in the first case, and the identical SQL is returning a row in one case and not in another. So there's no bug in query(), there's an issue either with the database driver, or the database, or something in your application making that table seem empty. But there's no bug for me to fix here, unfortunately.

[Ryan Chapman]

Ok. I was mostly trying to figure out why this only happens when I use the SA ORM layer and why using only the expression language, which uses the same driver and database (and ostensibly uses the same SQL calls), would always return the correct result. I'll just stop using the ORM, I guess.

Thank you for your help.

[Mike Bayer]

if you run that identical qeury in Core you'd see the same issue. the ORM is only doing that, after all. i think there's some DB or driver level issue with the "ROWNUM" part of it, is my guess.

[Ryan Chapman]

If I replace

cursor = session.query(Lot)

with the SQL output from that query:

cursor = session.execute('SELECT "SCHEMA_lot_lot_key", "SCHEMA_lot_lot_id" \nFROM (SELECT "SCHEMA".lot.lot_key AS "SCHEMA_lot_lot_key", "SCHEMA".lot.lot_id AS "SCHEMA_lot_lot_id" \nFROM "SCHEMA".lot) \nWHERE ROWNUM <= :param_1', {'param_1':1})

then the issue disappears; this new query, although using identical SQL, always returns one row.

[Mike Bayer]

no other queries, no other tables, no other databases. right? just this one table in this one database?

[Ryan Chapman]

That query was the first to fail in a short list of queries, so that's all I focused on. I'll perform some tests to check other tables, databases, queries...

[Ryan Chapman]

I finally found something that resolved this issue.

• cx_Oracle 5.2 fails using the SA ORM 50% of the time
• cx_Oracle 5.1.3 never fails

I don't know why this affects the ORM layer only (there must be something else going on under the hood that I don't understand), but that was a huge red herring.

Sorry for the wild goose chase. Thank you again, so much, for helping me through this problem and for building SQLAlchemy.

Other notes from tests:

If one ORM query fails when using first(), then all subsequent ORM queries fail if also using first().

For example, if this line returns None:

cursor = session.query(Lot).first()

Then this code is also guaranteed to return None:

cursor = session.query(Program).first()

Where Program is defined as:

class Program(base_class):
    __tablename__ = 'program'
    __table_args__ = {'schema': 'SCHEMA'}
    pg_key = Column(Integer, primary_key=True)
    ppid = Column(String)

But using cursor.all() will always return results, even if first() returns None.

[Mike Bayer]

OK, the "all()" verifies my hunch that this probably has to do with the ROWNUM part of it, which doesn't occur with all() vs. first().

The cx_Oracle 5.2 part of it verifies my hunch that this has something to do with the driver.

But we still need to figure out what the cx_Oracle 5.2 bug is, I'm 95% sure it's on their end, but need to identify it.

[Mike Bayer]

hi @vijchti - can you take a look at the thread under discussion at http://blog.gmane.org/gmane.comp.python.db.cx-oracle/day=20150723 and provide either to me here, or by subscribing to that mailing list, more detail on the problem? thanks.

[Mike Bayer]

per the ML discussion this is possibly related to a library version mismatch in the target environment, but at the least no issue is demonstrated on the SQLAlchemy side.

[Mike Bayer]

this logic in cx_oracle.py:

        elif self.cx_oracle_ver >= (5,) and not \
                hasattr(self.dbapi, 'UNICODE'):
            # cx_Oracle WITH_UNICODE mode.  *only* python
            # unicode objects accepted for anything
            self.supports_unicode_statements = True
            self.supports_unicode_binds = True
            self._cx_oracle_with_unicode = True

should be taking effect. Based on the logs here as well as those from another user in https://groups.google.com/forum/#!topic/sqlalchemy/OTwV1GZwgQo, it is not. Need to test with cx_oracle 5.2 that we are doing version detection correctly and perhaps a UNICODE identifier found its way into cx_oracle here and we need to adjust for that.

[Mike Bayer]

• Fixed support for cx_Oracle version 5.2, which was tripping up SQLAlchemy's version detection under Python 3 and inadvertently not using the correct unicode mode for Python 3. This would cause issues such as bound variables mis-interpreted as NULL and rows silently not being returned. fixes #3491

→ <<cset d8efa2257ec6>>

[Mike Bayer]

• Fixed support for cx_Oracle version 5.2, which was tripping up SQLAlchemy's version detection under Python 3 and inadvertently not using the correct unicode mode for Python 3. This would cause issues such as bound variables mis-interpreted as NULL and rows silently not being returned. fixes #3491

(cherry picked from commit d8efa2257ec650b345ec6e840984387263a957a6)

→ <<cset bd0f65400ed2>>

[Mike Bayer]

• Fixed support for cx_Oracle version 5.2, which was tripping up SQLAlchemy's version detection under Python 3 and inadvertently not using the correct unicode mode for Python 3. This would cause issues such as bound variables mis-interpreted as NULL and rows silently not being returned. fixes #3491

(cherry picked from commit d8efa2257ec650b345ec6e840984387263a957a6)

→ <<cset fd6c64609cbf>>