1 Reply Latest reply on Dec 27, 2007 1:58 PM by Brent Atkinson

    Connection with active local transaction being reused?

    Brent Atkinson Newbie

      I have an MBean that accesses a database using a datasource configured as a local-tx-datasource. The usual client code (which is used by multiple applications) is a stateless session bean, but the MBean uses straight JDBC with autocommit set to false. The code has been running for quite a while in production with no snags, until a connection timeout on a connection causes an SQL statement to fail, and prevents the rollback code from executing.

      Since that happened, I see the following behavior again and again in the logs. It appears that the managed connection is being reused even though it hasn't rolled back, and the connection manager is detecting that and trying to clean it up. The end result is that anything calling getConnection() on that datasource and gets that connection continues to fail with the same error, the connection is not being removed and the rollbacks are not completing. Because the applications are not under heavy load this is effectively causing all client apps to fail as most (all) of the getConnection() calls are returning the offending connection.

      I am using JBoss 4.0.5 GA, using a datasource configured as the following:

      <datasources>
       <local-tx-datasource>
       <jndi-name>jdbc/AppName</jndi-name>
      
       <connection-url>
       jdbc:oracle:thin:@host:1521:DEV
       </connection-url>
       <driver-class>oracle.jdbc.driver.OracleDriver</driver-class>
      
       <exception-sorter-class-name>
       org.jboss.resource.adapter.jdbc.vendor.OracleExceptionSorter
       </exception-sorter-class-name>
       <metadata>
       <type-mapping>Oracle9i</type-mapping>
       </metadata>
       </local-tx-datasource>
      
      </datasources>


      with client code that does the following:

      DataSource ds = (DataSource)ctx.lookup("java:jdbc/AppName");
      Connection c = null;
      
      try {
       c = ds.getConnection();
       c.setAutoCommit(false);
      ... do important *stuff*
       c.commit();
      }
      catch (Throwable t) {
       if (c != null) try { c.rollback(); } catch (SQLException sqle) { /* log... */ }
      }
      finally {
       if (c != null) try { c.close(); } catch (SQLException sqle) { /* log... */ }
      }


      yields:

      java.sql.SQLException: Io exception: Connection timed out
       at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:125)
       at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:162)
       at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:274)
       at oracle.jdbc.driver.T4CPreparedStatement.execute_for_describe(T4CPreparedStatement.java:432)
       at oracle.jdbc.driver.OracleStatement.execute_maybe_describe(OracleStatement.java:896)
       at oracle.jdbc.driver.T4CPreparedStatement.execute_maybe_describe(T4CPreparedStatement.java:452)
       at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:986)
       at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:2888)
       at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:2929)
       at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:236)
      ...


      and then when trying to rollback because of the exception...

      2007-12-23 07:06:28,532 ERROR [MBeanCode] failed to roll back
      java.sql.SQLException: Closed Connection
       at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:125)
       at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:162)
       at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:227)
       at oracle.jdbc.driver.PhysicalConnection.rollback(PhysicalConnection.java:994)
       at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.jdbcRollback(BaseWrapperManagedConnection.java:581)
       at org.jboss.resource.adapter.jdbc.WrappedConnection.rollback(WrappedConnection.java:340)
      ...


      After this occurs, I see the JCA connection manager try to cleanup...

      2007-12-23 07:06:28,533 DEBUG [org.jboss.resource.connectionmanager.TxConnectionManager] Unfinished local transaction was rolled back.org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@172e189[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@d2c59f handles=0 lastUse=1198410045635 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1ac4e3f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@1452dd5 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@c4153f txSync=null]
      


      I then see the same managed connection and the same LocalXAResource fail when other requests are given what seems to be the same connection?

      For instance, one of many log messages the appear after that (for 2 days in production at least):

      2007-12-23 07:26:28,556 DEBUG [org.jboss.resource.connectionmanager.TxConnectionManager] Unfinished local transaction was rolled back.org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@172e189[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@d2c59f handles=0 lastUse=1198412188545 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1ac4e3f context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@1452dd5 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@c4153f txSync=null]


      1.) Why is the connection being reused?
      2.) What can I do to prevent this from occurring?

        • 1. Re: Connection with active local transaction being reused?
          Brent Atkinson Newbie

          Ok, after digging a little deeper it appears that there were really multiple things going on and while they appeared to be connected they weren't. I have been able to reproduce the issue by setting up a similar (but simpler) application that uses a similarly configured datasource. I simulate the disconnected database by setting a breakpoint after the getConnection() call to get the connection and enabling an IPSec policy that blocks all traffic to the target database.

          First, the sticky transaction issue was taken care of by converting from the JDBC transaction programming style to using UserTransaction. I believe (please correct me if I am wrong), this succeeds because the UserTransaction rollback when the underlying connection is closed still cleans up. The JDBC style transaction throws an exception when trying to rollback (because the connection is closed) and so whatever hooks that usually cleanup don't complete. This results in an unfinished local JTA transaction being associated with the connection. Once I changed to using JTA transaction handling using the pattern shown in the wiki at http://www.jboss.com/wiki/Wiki.jsp?page=WhatIsTheCorrectPatternForUserTransactions, I no longer get the "Unfinished local transaction" messages. This however, did not fix the problem of the closed connection still being handed out as if it was connected, effectively killing all the applications using the connection pool.

          I worked around the dead connection in the pool by configuring my datasource like the following:

          <datasources>
           <local-tx-datasource>
           <jndi-name>jdbc/AppName</jndi-name>
          
           <connection-url>
           jdbc:oracle:thin:@host:1521:DEV
           </connection-url>
           <driver-class>oracle.jdbc.driver.OracleDriver</driver-class>
          
           <!-- This checks the connections are good before handing them out -->
           <valid-connection-checker-class-name>
           org.jboss.resource.adapter.jdbc.vendor.OracleValidConnectionChecker
           </valid-connection-checker-class-name>
          
           <exception-sorter-class-name>
           org.jboss.resource.adapter.jdbc.vendor.OracleExceptionSorter
           </exception-sorter-class-name>
           <metadata>
           <type-mapping>Oracle9i</type-mapping>
           </metadata>
           </local-tx-datasource>
          </datasources>


          Once configured this way, I ran my test again and I now see this after the call to getConnection():

          12:01:57,656 INFO [SampleJTAServlet] getting connection from datasource
          12:01:57,656 WARN [TxConnectionManager] Connection error occured: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1ecbac8[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@6c9b2 handles=0 lastUse=1198774893984 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a3d58b context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@118a7e0 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1b59c1b txSync=null]
          java.sql.SQLException: pingDatabase failed status=-1
           at org.jboss.resource.adapter.jdbc.vendor.OracleValidConnectionChecker.isValidConnection(OracleValidConnectionChecker.java:72)
           at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnectionFactory.isValidConnection(BaseWrapperManagedConnectionFactory.java:435)
           at org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.checkValid(BaseWrapperManagedConnection.java:231)
           at org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory.matchManagedConnections(LocalManagedConnectionFactory.java:200)
           at org.jboss.resource.connectionmanager.InternalManagedConnectionPool.getConnection(InternalManagedConnectionPool.java:209)
           at org.jboss.resource.connectionmanager.JBossManagedConnectionPool$BasePool.getConnection(JBossManagedConnectionPool.java:529)
           at org.jboss.resource.connectionmanager.BaseConnectionManager2.getManagedConnection(BaseConnectionManager2.java:341)
           at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:301)
           at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:396)
           at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:842)
           at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88)
           at pkg.sample.SampleJTAServlet.doGet(SampleJTAServlet.java:70)
           at javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
           at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
           at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
           at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
           at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
           at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
           at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
           at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
           at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
           at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:175)
           at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:74)
           at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
           at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
           at org.jboss.web.tomcat.tc5.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:156)
           at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
           at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
           at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
           at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
           at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
           at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
           at java.lang.Thread.run(Thread.java:595)
          12:01:57,671 WARN [JBossManagedConnectionPool] Destroying connection that could not be successfully matched: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1ecbac8[state=DESTROYED mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@6c9b2 handles=0 lastUse=1198774893984 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a3d58b context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@118a7e0 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1b59c1b txSync=null]


          The query then continues as normal and the transaction completes - problem(s) solved. I am still left with the question, why doesn't the connection pool cleanup the managed connection when usage of it results in a connection closed SQLException? The solution I used seems to handle it ok, but it needs to check on every access rather than lazily being handled when the exception occurs. Am I missing something obvious here?