When using IBATIS with OSCache getting "Closed Connection" when using proxy
connections and closing
---------------------------------------------------------------------------------------------------
Key: IBATIS-539
URL: https://issues.apache.org/jira/browse/IBATIS-539
Project: iBatis for Java
Issue Type: Bug
Components: SQL Maps
Affects Versions: 2.3.0
Environment: Microsoft Windows XP Professional, Oracle 10g, BEA
Weblogic 10,
Reporter: George H. Marvin
Fix For: 2.3.3, 2.3.2, 2.3.1, 2.3.0
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).
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 {
logger.debug("Error closing proxyConn -
[getReference]");
proxyConn.close();
} 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
{cache.capacity=100000, cache.event.listeners=SimpleStatisticListenerImpl}
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] - {conn-100000} 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] - {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,079 DEBUG [sql.PreparedStatement] - {pstm-100001}
Parameters: [AEQ%, %]
2008-09-30 15:34:31,079 DEBUG [sql.PreparedStatement] - {pstm-100001} Types:
[java.lang.String, java.lang.String]
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 '[EMAIL PROTECTED],
[EMAIL PROTECTED], [EMAIL PROTECTED], [EMAIL PROTECTED]'
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] - {pstm-100001}
Parameters: [B%, %]
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]
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
