iBatis for Java [READ ONLY]
  1. iBatis for Java [READ ONLY]
  2. IBATIS-539

When using IBATIS with Caching getting "Closed Connection" when using proxy connections and closing

    Details

    • Type: Bug Bug
    • Status: Reopened
    • Priority: Blocker Blocker
    • Resolution: Unresolved
    • Affects Version/s: 2.3.0, 2.3.1, 2.3.2, 2.3.3
    • Fix Version/s: None
    • Component/s: Core
    • Labels:
      None
    • Environment:
      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

      { 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 '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] -

      {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]

        Activity

        Hide
        George H. Marvin added a comment -

        In SQLMapExecutorDelegate.queryForList the RequestScope is pushed and popped from a Stack. My processing is the following: Execute Request #1, Close Request #1 and execute Request #2. My question is this, could this popping and pushing overlay state information. Request #1 always executes properly but Request #2 abends with a close connection error.

        If I take out the close statement both requests execute properly.

        Show
        George H. Marvin added a comment - In SQLMapExecutorDelegate.queryForList the RequestScope is pushed and popped from a Stack. My processing is the following: Execute Request #1, Close Request #1 and execute Request #2. My question is this, could this popping and pushing overlay state information. Request #1 always executes properly but Request #2 abends with a close connection error. If I take out the close statement both requests execute properly.
        Hide
        Kai Grabfelder added a comment -

        I don't have enough insight information and I don't want to change any code without a unit test for reproducing the issue. Therefore removing the fix version for now

        Show
        Kai Grabfelder added a comment - I don't have enough insight information and I don't want to change any code without a unit test for reproducing the issue. Therefore removing the fix version for now

          People

          • Assignee:
            Unassigned
            Reporter:
            George H. Marvin
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:

              Time Tracking

              Estimated:
              Original Estimate - 72h
              72h
              Remaining:
              Remaining Estimate - 72h
              72h
              Logged:
              Time Spent - Not Specified
              Not Specified

                Development