Details
-
Bug
-
Status: Reopened
-
Blocker
-
Resolution: Unresolved
-
2.3.0, 2.3.1, 2.3.2, 2.3.3
-
None
-
None
-
Microsoft Windows XP Professional, Oracle 10g, BEA Weblogic 10,
Description
When an IBATIS Query is run without CACHING, connections are properly closed and everything runs fine. When caching is activated, the first query executes properly, there is a close() issued to the proxy connection, a new proxy connection is obtained and the second query aborts in OracleStatement.ensureOpen(). The last IBATIS class executed is PreparedStatementLogProxy (line 62). One additional thing to note: If Query 1 and Query 2 are identical and Query 2 is found in the Cache everything works correctly.
I tested this under 2.3.0, 2.3.3 and 2.3.4 versions of IBATIS and with OSCache, MEMORY, FIFO and LRU implementations of caching.
The following is an example of the code I am talking about:
public void getReference(VOCSCommand cmd) {
List<?> results = null;
Map<?, ?> paramList = cmd.params;
Connection proxyConn=null;
try
{ BaseVO baseVo = cmd.basevo; logger.debug("userid=" + baseVo.getUserCredentials().getUserId()); logger.debug("password=" + baseVo.getUserCredentials().getPassword()); proxyConn = getProxyConnection(baseVo); smc.setUserConnection(proxyConn); results = smc.queryForList(cmd.cmdName.trim(), paramList); // proxyConn.close(); }catch (Exception e)
{ e.printStackTrace(); } finally {
if (proxyConn != null) {
try
catch (SQLException e)
{ // TODO Auto-generated catch block e.printStackTrace(); } }
}
if (results != null)
cmd.result.addAll(results);
}
I get the following results for 2 executions:
2008-09-30 15:34:24,262 INFO [common.DCapesObjectFactory] - BEGIN: loading Spring config:DCAPES_DYNAMIC_DEFS
2008-09-30 15:34:27,921 DEBUG [base.Config] - OSCache: Config called
2008-09-30 15:34:27,921 INFO [base.Config] - OSCache: Getting properties from URL file:/C:/gmarvin_ts_Spiral2/dcapes_lc/dcapes/dcapes-dms/classes/oscache.properties for the default configuration
2008-09-30 15:34:27,952 INFO [base.Config] - OSCache: Properties read
2008-09-30 15:34:27,952 DEBUG [base.AbstractCacheAdministrator] - Constructed AbstractCacheAdministrator()
2008-09-30 15:34:27,952 INFO [general.GeneralCacheAdministrator] - Constructed GeneralCacheAdministrator()
2008-09-30 15:34:27,952 INFO [general.GeneralCacheAdministrator] - Creating new cache
2008-09-30 15:34:28,015 INFO [SimpleStatisticListenerImpl] - Creation of SimpleStatisticListenerImpl
2008-09-30 15:34:28,765 DEBUG [vocs.VoCacheDDMSImpl] - In VoCacheDDMSImpl...
2008-09-30 15:34:28,906 INFO [common.DCapesObjectFactory] - END: loading Spring config:DCAPES_DYNAMIC_DEFS
2008-09-30 15:34:28,906 DEBUG [vocs.VoCacheCloseProblemTest] - testInvokeService
2008-09-30 15:34:29,516 DEBUG [vocs.VoCacheDDMSImpl] - userid=billbinz
2008-09-30 15:34:29,516 DEBUG [vocs.VoCacheDDMSImpl] - password=bil6bil!
2008-09-30 15:34:30,313 DEBUG [sql.Connection] -
2008-09-30 15:34:30,344 DEBUG [algorithm.AbstractConcurrentReadCache] - get called (key=748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999)
2008-09-30 15:34:30,344 DEBUG [algorithm.AbstractConcurrentReadCache] - persistRetrieve called (key=748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999)
2008-09-30 15:34:30,344 DEBUG [base.Cache] - No cache entry exists for key='748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999', creating
2008-09-30 15:34:30,360 DEBUG [SimpleStatisticListenerImpl] - accessed
2008-09-30 15:34:30,360 DEBUG [SimpleStatisticListenerImpl] - ACCESS : MISS: 748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999
2008-09-30 15:34:30,360 DEBUG [SimpleStatisticListenerImpl] - STATISTIC : Hit = 0, stale hit =0, miss = 1
2008-09-30 15:34:30,360 DEBUG [cache.CacheModel] - Cache 'ServSiteLookupVO.ServSiteLookupVO-cache': cache miss
2008-09-30 15:34:30,391 DEBUG [sql.Connection] - {conn-100000}
Preparing Statement: select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ?
2008-09-30 15:34:31,079 DEBUG [sql.PreparedStatement] -
2008-09-30 15:34:31,079 DEBUG [sql.PreparedStatement] - {pstm-100001}
Parameters: [AEQ%, %]
2008-09-30 15:34:31,079 DEBUG [sql.PreparedStatement] -
2008-09-30 15:34:31,142 DEBUG [sql.ResultSet] - {rset-100002} ResultSet
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Header: [GLC_CD, GLC_NM]
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQA, ALFORDSVILLE]
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQB, ALFRED]
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQC, ALFRED]
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQD, ALFRED STATION]
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQE, ALFREDO VASQUEZ C]
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQF, ALFRED]
2008-09-30 15:34:31,204 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQG, ALFRED]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQH, ALEGRETE]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQJ, ALGENRODT]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQK, ALEGRETE NOVO]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQM, ALGER-HOUARI BOUM]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQN, ALFRED 01]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQQ, ALGIERS]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQS, ALGHERO]
2008-09-30 15:34:31,220 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQT, ALGECIRAS]
2008-09-30 15:34:31,235 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQU, ALGIERS]
2008-09-30 15:34:31,235 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQV, ALGER]
2008-09-30 15:34:31,235 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQW, ALEKSANDROVSK SAK]
2008-09-30 15:34:31,235 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQX, ALGHERO]
2008-09-30 15:34:31,235 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQY, ALFONSO LOPEZ PUM]
2008-09-30 15:34:31,235 DEBUG [sql.ResultSet] - {rset-100002} Result: [AEQZ, ALFTAVER]
2008-09-30 15:34:31,251 DEBUG [algorithm.AbstractConcurrentReadCache] - get called (key=748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999)
2008-09-30 15:34:31,251 DEBUG [algorithm.AbstractConcurrentReadCache] - persistRetrieve called (key=748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999)
2008-09-30 15:34:31,251 DEBUG [base.Cache] - No cache entry exists for key='748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999', creating
2008-09-30 15:34:31,251 DEBUG [algorithm.AbstractConcurrentReadCache] - persistStore called (key=748120546|-1124938390|AEQ%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999)
2008-09-30 15:34:31,251 DEBUG [algorithm.AbstractConcurrentReadCache] - persistRetrieveGroup called (groupName=ServSiteLookupVO.ServSiteLookupVO-cache)
2008-09-30 15:34:31,251 DEBUG [algorithm.AbstractConcurrentReadCache] - persistStoreGroup called (groupName=ServSiteLookupVO.ServSiteLookupVO-cache)
2008-09-30 15:34:31,267 DEBUG [SimpleStatisticListenerImpl] - cacheEntryAdded
2008-09-30 15:34:31,267 DEBUG [cache.CacheModel] - Cache 'ServSiteLookupVO.ServSiteLookupVO-cache': stored object 'mil.af.dcapes.common.data.ServSiteLookupVO@9b6220, mil.af.dcapes.common.data.ServSiteLookupVO@1474e45, mil.af.dcapes.common.data.ServSiteLookupVO@63a721, mil.af.dcapes.common.data.ServSiteLookupVO@71...'
2008-09-30 15:34:31,267 DEBUG [vocs.VoCacheDDMSImpl] - Error closing proxyConn - [getReference]
[servSite]=AEQA [servSiteDescription]=ALFORDSVILLE
[servSite]=AEQB [servSiteDescription]=ALFRED
[servSite]=AEQC [servSiteDescription]=ALFRED
[servSite]=AEQD [servSiteDescription]=ALFRED STATION
[servSite]=AEQE [servSiteDescription]=ALFREDO VASQUEZ C
[servSite]=AEQF [servSiteDescription]=ALFRED
[servSite]=AEQG [servSiteDescription]=ALFRED
[servSite]=AEQH [servSiteDescription]=ALEGRETE
[servSite]=AEQJ [servSiteDescription]=ALGENRODT
[servSite]=AEQK [servSiteDescription]=ALEGRETE NOVO
[servSite]=AEQM [servSiteDescription]=ALGER-HOUARI BOUM
[servSite]=AEQN [servSiteDescription]=ALFRED 01
[servSite]=AEQQ [servSiteDescription]=ALGIERS
[servSite]=AEQS [servSiteDescription]=ALGHERO
[servSite]=AEQT [servSiteDescription]=ALGECIRAS
[servSite]=AEQU [servSiteDescription]=ALGIERS
[servSite]=AEQV [servSiteDescription]=ALGER
[servSite]=AEQW [servSiteDescription]=ALEKSANDROVSK SAK
[servSite]=AEQX [servSiteDescription]=ALGHERO
[servSite]=AEQY [servSiteDescription]=ALFONSO LOPEZ PUM
[servSite]=AEQZ [servSiteDescription]=ALFTAVER
2008-09-30 15:34:31,282 DEBUG [vocs.VoCacheDDMSImpl] - userid=billbinz
2008-09-30 15:34:31,282 DEBUG [vocs.VoCacheDDMSImpl] - password=bil6bil!
2008-09-30 15:34:31,423 DEBUG [sql.Connection] - {conn-100003} Connection
2008-09-30 15:34:31,423 DEBUG [algorithm.AbstractConcurrentReadCache] - get called (key=1869442161|-1126941579|B%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999)
2008-09-30 15:34:31,423 DEBUG [algorithm.AbstractConcurrentReadCache] - persistRetrieve called (key=1869442161|-1126941579|B%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999)
2008-09-30 15:34:31,423 DEBUG [base.Cache] - No cache entry exists for key='1869442161|-1126941579|B%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999', creating
2008-09-30 15:34:31,423 DEBUG [SimpleStatisticListenerImpl] - accessed
2008-09-30 15:34:31,423 DEBUG [SimpleStatisticListenerImpl] - ACCESS : MISS: 1869442161|-1126941579|B%|%|getServSiteLookupInfo|11512063| select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ? |executeQueryForList|0|-999999
2008-09-30 15:34:31,423 DEBUG [SimpleStatisticListenerImpl] - STATISTIC : Hit = 0, stale hit =0, miss = 2
2008-09-30 15:34:31,423 DEBUG [cache.CacheModel] - Cache 'ServSiteLookupVO.ServSiteLookupVO-cache': cache miss
2008-09-30 15:34:31,423 DEBUG [sql.PreparedStatement] - {pstm-100001}
Executing Statement: select GLC_CD,GLC_NM from DCAPES_JOPES_REF.S_GEOLOCATION where GLC_CD like ? and GLC_NM like ?
2008-09-30 15:34:31,423 DEBUG [sql.PreparedStatement] -
2008-09-30 15:34:31,423 DEBUG [sql.PreparedStatement] - {pstm-100001}
Types: [java.lang.String, java.lang.String]
com.ibatis.common.jdbc.exception.NestedSQLException:
— The error occurred in mil/af/dcapes/ddms/vocs/data/ServSiteLookupVO.xml.
— The error occurred while applying a parameter map.
— Check the ServSiteLookupVO.ServSiteParamMap.
— Check the statement (query failed).
— Cause: java.sql.SQLException: Closed Connection
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(GeneralStatement.java:185)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryForList(GeneralStatement.java:123)
at com.ibatis.sqlmap.engine.mapping.statement.CachingStatement.executeQueryForList(CachingStatement.java:97)
at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForList(SqlMapExecutorDelegate.java:615)
at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForList(SqlMapExecutorDelegate.java:589)
at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForList(SqlMapSessionImpl.java:118)
at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.queryForList(SqlMapClientImpl.java:95)
at mil.af.dcapes.ddms.vocs.VoCacheDDMSImpl.getReference(VoCacheDDMSImpl.java:39)
at mil.af.dcapes.ddms.vocs.VoCacheDDMSImpl.invokeService(VoCacheDDMSImpl.java:61)
at mil.af.dcapes.ddms.vocs.VoCacheCloseProblemTest.closeConnectionTest(VoCacheCloseProblemTest.java:62)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99)
at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81)
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34)
at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75)
at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45)
at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66)
at org.junit.internal.runners.TestClassMethodsRunner.run(TestClassMethodsRunner.java:35)
at org.junit.internal.runners.TestClassRunner$1.runUnprotected(TestClassRunner.java:42)
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34)
at org.junit.internal.runners.TestClassRunner.run(TestClassRunner.java:52)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:38)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
Caused by: java.sql.SQLException: Closed Connection
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112)
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146)
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:208)
at oracle.jdbc.driver.OracleStatement.ensureOpen(OracleStatement.java:3517)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3297)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3422)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at com.ibatis.common.jdbc.logging.PreparedStatementLogProxy.invoke(PreparedStatementLogProxy.java:62)
at $Proxy7.execute(Unknown Source)
at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(SqlExecutor.java:186)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.sqlExecuteQuery(GeneralStatement.java:205)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(GeneralStatement.java:173)
... 29 more
2008-09-30 15:34:31,501 DEBUG [vocs.VoCacheDDMSImpl] - Error closing proxyConn - [getReference]