Error closing cursor: not open

[Former user]

Hello,

I am getting this cursor not open error. The database connection appears to be returned to the pool prematurely? I have tried several configs all with no joy. My app is a web server that executes a sql select to load some static data at startup which is ok. When the first web request comes in I get this error. If I replace the request sql with a simplier (& faster) sql statement it works fine. Any ideas on how to proceeed?

SQLAlchemy 0.5.0rc1, cxOracle 4.4 on winNT. I have tried SQLAlchemy 0.4 & cxOracle 4.3.1 (same results). I have tried the non TL engine and various pool options.

Thanks

-- ok run log -- 14:05:05,430 INFO sqlalchemy.pool.QueuePool.0x...06b0 MainThread Created new connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> 14:05:05,430 INFO sqlalchemy.pool.QueuePool.0x...06b0 MainThread Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> checked out from pool 14:05:05,430 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...0750 MainThread select fid , feed_id , feed_type , case instr(feed_desc, '@@') when 0 then '' else substr(feed_desc, instr(feed_desc, '@@')+2) end as GROUPNAME from emd.energy_exchange_feeds where exchange = 'BMRA'

14:05:05,430 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...0750 MainThread {} 14:05:05,430 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 MainThread Col ('FID', 'FEED_ID', 'FEED_TYPE', 'GROUPNAME') 14:05:05,461 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 MainThread Row (957, 'BMRA.BM.T_LITTD1.FPN', 'Volume', 'T\Oil') 6, 'BMRA.BM.I_IMG-RWEM1.MEL', 'Volume', 'I\UK-IreInterconnector') 14:05:05,743 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 MainThread Row (2487, 'BMRA.BM.I_IMG-RWEM1.FPN', 'Volume', 'I\UK-IreInterconnector')

<result rows snipped>

14:05:05,743 INFO sqlalchemy.pool.QueuePool.0x...06b0 MainThread Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> being returned to pool Starting server in PID 2364. serving on 0.0.0.0:5000 view at http://127.0.0.1:5000 14:05:14,822 INFO bmraweb.lib.graph worker 0 pre result 14:05:14,822 INFO sqlalchemy.pool.QueuePool.0x...06b0 worker 0 Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> checked out from pool 14:05:14,822 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...0750 worker 0 select * from mel

14:05:14,822 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...0750 worker 0 {} 14:05:14,822 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 worker 0 Col ('DATETIME', 'ID', 'VALUE') 14:05:14,836 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 worker 0 Row (datetime.datetime(2008, 10, 6, 13, 30), 'E_KLYN-A-1', 291.0) 14:05:14,836 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 worker 0 Row (datetime.datetime(2008, 10, 6, 13, 30), 'T_DINO-1', 288.0) 14:05:14,914 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 worker 0 Row (datetime.datetime(2008, 10, 6, 13, 30), 'M_SLOY-4', 32.0) 14:05:14,914 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...0750 worker 0 Row (datetime.datetime(2008, 10, 6, 13, 30), 'I_IMG-RWEM1', 0.0) <result rows snipped> 14:05:14,914 INFO sqlalchemy.pool.QueuePool.0x...06b0 worker 0 Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> being returned to pool 14:05:14,914 INFO bmraweb.lib.graph worker 0 post result 14:05:14,914 INFO bmraweb.lib.base worker 0 remove session <sqlalchemy.orm.scoping.ScopedSession object at 0x023507D0> 14:05:15,039 INFO bmraweb.lib.base worker 1 remove session <sqlalchemy.orm.scoping.ScopedSession object at 0x023507D0> 14:05:15,118 INFO bmraweb.lib.base worker 1 remove session <sqlalchemy.orm.scoping.ScopedSession object at 0x023507D0>

-- failed run log -- 13:51:34,450 INFO sqlalchemy.pool.QueuePool.0x...46d0 MainThread Created new connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> 13:51:34,450 INFO sqlalchemy.pool.QueuePool.0x...46d0 MainThread Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> checked out from pool 13:51:34,450 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...4770 MainThread select fid , feed_id , feed_type , case instr(feed_desc, '@@') when 0 then '' else substr(feed_desc, instr(feed_desc, '@@')+2) end as GROUPNAME from emd.energy_exchange_feeds where exchange = 'BMRA'

13:51:34,450 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...4770 MainThread {} 13:51:34,450 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...4770 MainThread Col ('FID', 'FEED_ID', 'FEED_TYPE', 'GROUPNAME') 13:51:34,497 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...4770 MainThread Row (957, 'BMRA.BM.T_LITTD1.FPN', 'Volume', 'T\Oil') 13:51:34,763 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...4770 MainThread Row (2486, 'BMRA.BM.I_IMG-RWEM1.MEL', 'Volume', 'I\UK-IreInterconnector') 13:51:34,763 DEBUG sqlalchemy.engine.threadlocal.TLEngine.0x...4770 MainThread Row (2487, 'BMRA.BM.I_IMG-RWEM1.FPN', 'Volume', 'I\UK-IreInterconnector') <result rows snipped> 13:51:34,763 INFO sqlalchemy.pool.QueuePool.0x...46d0 MainThread Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> being returned to pool Starting server in PID 5324. serving on 0.0.0.0:5000 view at http://127.0.0.1:5000 13:51:45,497 INFO bmraweb.lib.graph worker 0 pre result 13:51:45,513 INFO sqlalchemy.pool.QueuePool.0x...46d0 worker 0 Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> checked out from pool 13:51:45,513 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...4770 worker 0 /+ standby & outage datetime is latest from status
/ select u.party_id as party_id, u.bmu_id as bmunit, concat(to_char(s.datetime, 'YYYY-MM-DD'), concat('T', to_char(s.datetime, 'HH24:MI:SS'))) as datetime , s.status, s.group_name, round(u.gc - m.value, 1) as capacity , round((100 - (m.value * 100)/ u.gc), 1) as percent, u.gc from status s, emd.energy_bmunits u, mel m where u.bmu_id = s.id and s.status not like 'running%' and u.bmu_id = m.id and m.value < u.gc * 90/100 union /+ running & partial outage datetime is latest from status
/ select a.party_id as party_id, a.bmu_id as bmunit, concat(to_char(s.datetime, 'YYYY-MM-DD'), concat('T', to_char(s.datetime, 'HH24:MI:SS'))) as datetime, a.status as status, a.group_name, round(a.capacity, 1) as capacity, null as percent, a.gc
from status s, (select run.bmu_id, run.party_id, run.group_name, min(run.value) as capacity, null as percent, run.gc, 'running' as status from (/+ get all mels excluding boals / select
u.bmu_id, u.party_id, s.group_name, m.value, null as percent, u.gc, 'running' as status
from status s, emd.energy_bmunits u, mel m where u.bmu_id = s.id and u.bmu_id = m.id /and not exists (select 1 from boal b where b.id=u.bmu_id)/ union /+ get all fpns excluding boals / select u.bmu_id, u.party_id, group_name, f.value, null as percent, u.gc, 'running' as status from status s, emd.energy_bmunits u, fpn f where u.bmu_id = s.id and u.bmu_id = f.id /and not exists (select 1 from boal boal where b.id=u.bmu_id)/ ) run /+ return units (not boal affected) where min(fpn, mel) > 0 / group by run.bmu_id, run.party_id, run.group_name, run.gc having min(run.value) > 0
) a where a.bmu_id = s.id union /+ boal affected units tagged as running_acceptance using boal from_level as datetime value / select u.party_id as party_id, u.bmu_id as bmunit, concat(to_char(b.from_datetime, 'YYYY-MM-DD'), concat('T', to_char(b.from_datetime, 'HH24:MI:SS'))) as datetime, 'running_acceptance' as status, s.group_name, round((b.to_level+b.from_level)/2, 1) as capacity, null as percent, u.gc from status s, emd.energy_bmunits u, boal b where u.bmu_id = s.id
and u.bmu_id = b.id
order by status desc

13:51:45,513 INFO sqlalchemy.engine.threadlocal.TLEngine.0x...4770 worker 0 {} 13:51:45,529 INFO sqlalchemy.pool.QueuePool.0x...46d0 worker 0 Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> being returned to pool 13:51:45,529 WARNI sqlalchemy.pool.QueuePool.0x...46d0 worker 0 Error closing cursor: not open 13:51:45,529 INFO bmraweb.lib.base worker 0 remove session <sqlalchemy.orm.scoping.ScopedSession object at 0x023547F0> Debug at: http://127.0.0.1:5000/_debug/view/1223297493

[Mike Bayer]

theres no code here in which to comment on but it sounds like you are sharing a single connection between threads. threadlocal strategy does not prevent this if you pass a Connection object to another thread.

[Former user]

code is as follows

At startup

engine = create_engine('oracle://emd:emd@ved-emd1:1521/EMDD2', strategy='threadlocal', threaded=True)

init_model(engine)

def init_model(engine): sm = orm.sessionmaker(autocommit=True, bind=engine # ,expire_on_commit=False )

store.sqlEngine = engine
store.sqlSession = orm.scoped_session(sm)
rows = store.sqlSession.execute(sa.text(get_feeds)).fetchall()
store.feeds = dict([store.Feed(row)) for row in rows]((row.feed_id,))
store.sqlSession.remove()

On request

I use the scoped session which is stored in a global in the store module to execute my request sql. I call the function operator () on the scoped session. Isn't this supposed to give me a thread local session & therefore connection? Is this usage wrong?

i.e. store.sqlSession().execute(sa.text(sqlText), kwargs)

What I am trying to configure is having one connection per thread.

[Mike Bayer]

Usage of scoped_session etc. is correct. If store.Feed is an ORM mapped object, these objects should never be associated with a Session since they are held in a global scope. "threadlocal" scope is also unnecessary here unless you are calling begin()/commit() on engine objects directly (which it appears you are not) - threadlocal scope is used only for sharing transactional state within a thread without the need to pass explicit Connection objects (see http://www.sqlalchemy.org/docs/05/dbengine.html#dbengine_implicit_strategies). It is a very rare use case these days since most people use scoped_session() to broker engine access.

If you truly want one connection per thread held persistently without the usage of the Pool, you can bind each individual Session to a connection using sess = store.sqlSession(bind=engine.connect()), and even using NullPool to eliminate QueuePool entirely, though SQLA's connection pools work quite well and this pattern should not be needed - it would add overhead to your application if threads are not long-lived or if the threadpool grows to be very large.

Still missing where your usage of cursor is, no stack trace has been posted here. The connection pool does not call cursor.close(). If your application is accessing a cursor directly, care should be taken to ensure that close() isn't being called in a case where SQLA has already called it.

[Former user]

The error is caused by including an oracle comment (/+ ... /) at the start of the sql text. I have a select 1 from dual statement here that re-produces the issue. If I remove the oracle comment it works. Maybe an issue within your sql text compiler?

Starting server in PID 6240. serving on 0.0.0.0:5000 view at http://127.0.0.1:5000 11:33:55,936 INFO bmraweb.model.data worker 0 pre result 11:33:56,076 INFO sqlalchemy.pool.QueuePool.0x...07f0 worker 0 Created new connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> 11:33:56,076 INFO sqlalchemy.pool.QueuePool.0x...07f0 worker 0 Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> checked out from pool 11:33:56,076 INFO sqlalchemy.engine.base.Engine.0x...0890 worker 0 /+ this comment causes an error / select 1 from dual

11:33:56,076 INFO sqlalchemy.engine.base.Engine.0x...0890 worker 0 {} 11:33:56,076 INFO sqlalchemy.pool.QueuePool.0x...07f0 worker 0 Connection <cx_Oracle.Connection to emd@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=ved-emd1)(PORT=1521)))(CONNECT_DATA=(SID=EMDD2)))> being returned to pool 11:33:56,076 WARNI sqlalchemy.pool.QueuePool.0x...07f0 worker 0 Error closing cursor: not open 11:33:56,076 INFO bmraweb.lib.base worker 0 remove session <sqlalchemy.orm.scoping.ScopedSession object at 0x02350910> Debug at: http://127.0.0.1:5000/_debug/view/1223375627

[Mike Bayer]

I dont understand how you would be even inserting a comment in the SQL if using the compiler - but in any case the compiler has no awareness of cursors.

Closing this ticket as invalid until reproducing test code can be attached.

[Mike Bayer]

test case:

from sqlalchemy import *

engine = create_engine('oracle://scott:tiger@127.0.0.1:5432', echo=True)
result = engine.execute("SELECT 1 FROM DUAL /*+ this is a test comment */")
print result.fetchall()

output (paraphrased since i cant copy and paste from parallels):

SELECT 1 FROM DUAL /*+ this is a test comment */
{}
[(1,)]((1,))

[Mike Bayer]

with cursor at start, bug reproduces.

[Mike Bayer]

fixed in ff3df488f5d84a1fa6288adaaa48948fe1614e7d

[Mike Bayer]

Removing milestone: 0.5.0 (automated comment)