Uploaded image for project: 'IronJacamar'
  1. IronJacamar
  2. JBJCA-1445

Race condition between threads getting connections and removing idle ones results in a closed connection when used

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • None
    • 1.4.10
    • Core
    • None
    • Hide

      1. I used the following config, mainly one connection at most and idle timeout = 1 minute.

                          <driver>oracle</driver>
                          <pool>
                              <min-pool-size>0</min-pool-size>
                              <max-pool-size>1</max-pool-size>
                              <prefill>true</prefill>
                              <use-strict-min>true</use-strict-min>
                              <capacity>
                                  <decrementer class-name="org.jboss.jca.core.connectionmanager.pool.capacity.SizeDecrementer">
                                      <config-property name="Size">
                                          1
                                      </config-property>
                                  </decrementer>
                              </capacity>
                          </pool>
                          <validation>
                              <valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleValidConnectionChecker"/>
                              <validate-on-match>true</validate-on-match>
                              <background-validation>true</background-validation>
                              <background-validation-millis>30000</background-validation-millis>
                              <use-fast-fail>true</use-fast-fail>
                              <stale-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleStaleConnectionChecker"/>
                              <exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleExceptionSorter"/>
                          </validation>
                          <timeout>
                              <set-tx-query-timeout>false</set-tx-query-timeout>
                              <blocking-timeout-millis>10000</blocking-timeout-millis>
                              <idle-timeout-minutes>1</idle-timeout-minutes>
                              <use-try-lock>0</use-try-lock>
                              <allocation-retry>3</allocation-retry>
                              <allocation-retry-wait-millis>500</allocation-retry-wait-millis>
                          </timeout>

       

      2. Then set two breakpoint (thread only, not whole JVM)

      (a) inside removeConnectionListenerFromPool and

      (b) at this line:

      log.tracef("supplying ManagedConnection from pool: %s", clw.getConnectionListener());

      3. Do some DB operation from application so that a connection is created and idle for 1 minute so that  breakpoint 2a) is hit.

      4. Trigger another DB operation, so that the same DB connection is retrieved from pool inside getConnection() and breakpoint 2b) is hit. 

      5. Continue breakpoint 2a) so that the connection is destroyed.

      6. Continue breakpoint 2b) so that the now destroyed connection is used

      Show
      1. I used the following config, mainly one connection at most and idle timeout = 1 minute.                     <driver>oracle</driver>                     <pool>                         <min-pool-size>0</min-pool-size>                         <max-pool-size>1</max-pool-size>                         <prefill>true</prefill>                         <use-strict-min>true</use-strict-min>                         <capacity>                             <decrementer class-name="org.jboss.jca.core.connectionmanager.pool.capacity.SizeDecrementer">                                 <config-property name="Size">                                     1                                 </config-property>                             </decrementer>                         </capacity>                     </pool>                     <validation>                         <valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleValidConnectionChecker"/>                         <validate-on-match>true</validate-on-match>                         <background-validation>true</background-validation>                         <background-validation-millis>30000</background-validation-millis>                         <use-fast-fail>true</use-fast-fail>                         <stale-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleStaleConnectionChecker"/>                         <exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleExceptionSorter"/>                     </validation>                     <timeout>                         <set-tx-query-timeout>false</set-tx-query-timeout>                         <blocking-timeout-millis>10000</blocking-timeout-millis>                         <idle-timeout-minutes>1</idle-timeout-minutes>                         <use-try-lock>0</use-try-lock>                         <allocation-retry>3</allocation-retry>                         <allocation-retry-wait-millis>500</allocation-retry-wait-millis>                     </timeout>   2. Then set two breakpoint (thread only, not whole JVM) (a) inside removeConnectionListenerFromPool and (b) at this line: log.tracef("supplying ManagedConnection from pool: %s", clw.getConnectionListener()); 3. Do some DB operation from application so that a connection is created and idle for 1 minute so that  breakpoint 2a) is hit. 4. Trigger another DB operation, so that the same DB connection is retrieved from pool inside getConnection() and breakpoint 2b) is hit.  5. Continue breakpoint 2a) so that the connection is destroyed. 6. Continue breakpoint 2b) so that the now destroyed connection is used

      Using Wildfly 17.0.0 with IronJacamar 1.4.16, during stress test , very infrequently, I see the following exception:

      TRACE 2022-05-03 18:05:49.710 [default task-1] [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory]  webapi-restricted()  RQT_W2lkk5hA - <Not broadcasting error, already dest
      royed org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@d2a9c98>: java.sql.SQLRecoverableException: Closed Connection
              at com.oracle@19.3.0.0.0//oracle.jdbc.driver.PhysicalConnection.prepareStatementInternal(PhysicalConnection.java:1812)
              at com.oracle@19.3.0.0.0//oracle.jdbc.driver.PhysicalConnection.prepareStatement(PhysicalConnection.java:1763)
              at com.oracle@19.3.0.0.0//oracle.jdbc.driver.PhysicalConnection.prepareStatement(PhysicalConnection.java:1755)
              at org.jboss.ironjacamar.jdbcadapters@1.4.16.Final//org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.doPrepareStatement(BaseWrapperManagedConnection.java:758)
              at org.jboss.ironjacamar.jdbcadapters@1.4.16.Final//org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.prepareStatement(BaseWrapperManagedConnection.java:744)
              at org.jboss.ironjacamar.jdbcadapters@1.4.16.Final//org.jboss.jca.adapters.jdbc.WrappedConnection$4.produce(WrappedConnection.java:478)
              at org.jboss.ironjacamar.jdbcadapters@1.4.16.Final//org.jboss.jca.adapters.jdbc.WrappedConnection$4.produce(WrappedConnection.java:476)
              at org.jboss.ironjacamar.jdbcadapters@1.4.16.Final//org.jboss.jca.adapters.jdbc.SecurityActions.executeInTccl(SecurityActions.java:97)
              at org.jboss.ironjacamar.jdbcadapters@1.4.16.Final//org.jboss.jca.adapters.jdbc.WrappedConnection.prepareStatement(WrappedConnection.java:476)
              at org.hibernate@5.3.10.Final//org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
              at org.hibernate@5.3.10.Final//org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
              at org.hibernate@5.3.10.Final//org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
              at org.hibernate@5.3.10.Final//org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1984)
              at org.hibernate@5.3.10.Final//org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1914)
              at org.hibernate@5.3.10.Final//org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1892)
              at org.hibernate@5.3.10.Final//org.hibernate.loader.Loader.doQuery(Loader.java:937)

      I enabled the trace log and obtained the log of two similar cases: Example1.txt Example2.txt

      In Example 1, the application thread 'default task-78' obtained the connection "LocalManagedConnection@50eb89b0" from the pool when the IdleRemover thread was in the mid way of destroying it. Its state changed from NORMAL to DESTROYED at 21:05:07.829 so that in the end, java.sql.SQLRecoverableException was thrown.

       

      After some debugging sessions, I found that in the class 

      org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool, it seems there's no synchronization between the methods removeIdleConnections() and getConnection(), so that when IdleRemover thread triggers the former, in between the time when a connection is marked as to be destroyed and the time the connection is removed from the pool, another application thread could get the connection from the pool and then the IdleRemover thread continues to remove it from the pool and destroys (closes) it. Thus when the application thread tries to use the retrieved the connection, it has been closed already.

        1. example_deadlock.txt
          31 kB
          Tomasz Kozieł
        2. Example1.txt
          10 kB
          Sammy Chan
        3. Example2.txt
          8 kB
          Sammy Chan

              tadamski@redhat.com Tomasz Adamski
              sammychanocl Sammy Chan (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Created:
                Updated: