"cannot enlist more than one non-XA resource" with Tomcat

Hej Ludovic,

we are using an LRC datasource in Tomcat 6.0. with Oracle. The datasource
factory is implemented like it described in
http://docs.codehaus.org/display/BTM/LastResourceCommit13.

Transactions are handled with a proxy object, which enwraps all service
calls as a dummy ejb environment. Calls through this proxy may be nested
and DataSource.getConnection() is might be called more then once during
a transaction.

proxy code snippet:
final TransactionManager transactionManager = (TransactionManager) context.lookup("java:comp/env/TransactionManager");
  Transaction transaction = transactionManager.getTransaction();
  if (!EJBJarLoader.EJBConfig.TransactionAttribute.NOT_SUPPORTED.equals(transactionAttribute)) {
    // transaction necessary
    if (transaction == null) {
      newTransaction = true;
      transactionManager.begin();
      transaction = transactionManager.getTransaction();
    } else if (EJBJarLoader.EJBConfig.TransactionAttribute.REQUIRES_NEW.equals(transactionAttribute)) {
      Trace.notice("Transaction [{0}]: Requested transaction type not supported. Invoking within current transaction \"{1}\"",
                     new Object[]{transactionAttribute, transaction}, this);
    }
  }
  // handling service call
  ....
  catch (ReflectionException e) {
    if (newTransaction) {
      rollbackTransaction (transactionManager, transaction, transactionAttribute);
    }
    throw convertedError (e.getCause ());
  }
  if (newTransaction) {
    ...
    if (shouldRollback) {
      rollbackTransaction(transactionManager, transaction, transactionAttribute);
    } else {
      commitTransaction (transactionManager, transaction, transactionAttribute);
    }
  }

Everything works fine as long as the application is not working to
capacity, but during load tests the following exception occurs:
 bitronix.tm.internal.BitronixSystemException: cannot enlist more than one non-XA resource,
  tried enlisting an XAResourceHolderState with uniqueName=jdbc/FxFDataSource
  XAResource=a LrcXAResource in state NO_TX with XID null, already enlisted:
  an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a
  LrcXAResource in state STARTED (started) with XID a Bitronix XID
  [4678465F4170706C69636174696F6E00000123CD0AB6FE000122AC : 4678465F4170706C69636174696F6E00000123CD0AB700000122AE]

Actually we use only one datasource and so we dont need a real XA
transaction manager but on the other hand we need a transaction manager
and can't find any suitable single resource manager.

Any idea what we're doing wrong or is there perhaps a bug in BTM?

Many thanks,
  Tino Strauss

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Ludovic Orban]

Which version of BTM are you using? There is a well known race condition in 1.3.2 that you might have triggered, it happens when you close your JDBC connection after you commit the transaction. The easiest thing to do is to try out 1.3.3-RC2 and see if it helps.

If not, please collect debug logs while reproducing the problem and post them here.

Hej,

Ludovic Orban wrote:
> Which version of BTM are you using? There is a well known race condition in

we are using BTM 1.3.2.

> 1.3.2 that you might have triggered, it happens when you close your JDBC
> connection after you commit the transaction. The easiest thing to do is to
> try out 1.3.3-RC2 and see if it helps.

Actually im sure, that we always close the connection and commit the
transaction in the correct order. But we will try out the newest release
and post the results.

Thanks a lot,
  Tino

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Simon-2745]

tino_usenet@... wrote:
> Actually we use only one datasource and so we dont need a real XA
> transaction manager but on the other hand we need a transaction manager
> and can't find any suitable single resource manager.
>  
Tino,

There is a "hidden gem" within the XA specification on which JTA is
based on which says that if only one source is written to in any
transaction then only single phase commit needs to be undertaken. This
means that there is no need to use LRC just to get single phase commit.
Any mature transaction manager will automatically use single phase
commit if only one resource is written to within a transaction order to
run faster as all transaction managers are keen to have good performance.

Simon


---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

Good evening!

> Actually im sure, that we always close the connection and commit the
> transaction in the correct order. But we will try out the newest release
> and post the results.

Unfortunately the problem continues with 1.3.3-RC2. It seems that the
BitronixSystemException occurs, where Datasource.getConnection() is called a
2nd time before the first connection is closed.

pseudo code:
 getConnection()
  -> call other code e.g. third party lib
      getConnection()
      close()
  <-
 close()

But i have to check this again.

Debug log is attached. The load test produce unmanageable tons of log entries,
therefore i greped for a affected GTRID. I hope no necessary information is
lost.

Thanks and good night,
   Tino

[filtered_tx.log]

---

Caused by: bitronix.tm.internal.BitronixSystemException: cannot enlist more than one non-XA resource, tried enlisting an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XA
Resource=a JDBC LrcXAResource in state NO_TX with XID null, already enlisted: an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state S
TARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
        at bitronix.tm.internal.XAResourceManager.enlist(XAResourceManager.java:85)
        at bitronix.tm.BitronixTransaction.enlistResource(BitronixTransaction.java:79)
        at bitronix.tm.resource.common.TransactionContextHelper.enlist(TransactionContextHelper.java:255)
        at bitronix.tm.resource.common.TransactionContextHelper.enlistInCurrentTransaction(TransactionContextHelper.java:48)
        at bitronix.tm.resource.jdbc.JdbcConnectionHandle.enlistResource(JdbcConnectionHandle.java:59)
        ... 136 more


2009-09-21 15:01:57,876 [http-13530-5] BitronixTransaction - creating new transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:57,876 [http-13530-5] TaskScheduler - scheduling transaction timeout task on a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=NO_TRANSACTION, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009) for Mon Sep 21 15:04:57 CEST 2009
2009-09-21 15:01:57,876 [http-13530-5] TaskScheduler - removing task by a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=NO_TRANSACTION, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:57,876 [http-13530-5] TaskScheduler - scheduled a TransactionTimeoutTask on a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=NO_TRANSACTION, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009) scheduled for Mon Sep 21 15:04:57 CEST 2009, total task(s) queued: 5
2009-09-21 15:01:57,876 [http-13530-5] ThreadContext - assigning <a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=NO_TRANSACTION, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)> to <a ThreadContext with transaction null, default timeout 180s>
2009-09-21 15:01:57,876 [http-13530-5] TransactionLogAppender - between 1706869 and 1706933, writing a Bitronix TransactionLogRecord with status=ACTIVE, recordLength=56, headerLength=28, time=1253538117876, sequenceNumber=70833, crc32=404222, gtrid=4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0, uniqueNames=
2009-09-21 15:01:57,877 [http-13530-5] XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:57,877 [http-13530-5] TransactionContextHelper - enlisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f into a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:57,877 [http-13530-5] TransactionContextHelper - enlisting resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state NO_TX with XID null into a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:57,877 [http-13530-5] XAResourceManager - creating new branch with a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:57,878 [http-13530-5] XAResourceHolderState - assigning <a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]> to <an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state NO_TX with XID null>
2009-09-21 15:01:57,878 [http-13530-5] XAResourceHolderState - starting an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state NO_TX with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:57,878 [http-13530-5] LrcXAResource - OK to start, old state=NO_TX, XID=a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2], flag=NOFLAGS
2009-09-21 15:01:57,878 [http-13530-5] XAResourceManager - started an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2] with NOFLAGS
2009-09-21 15:01:57,903 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:57,963 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:57,965 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,028 [http-13530-5] TransactionContextHelper - delisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,028 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,028 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,028 [http-13530-5] TransactionContextHelper - requeuing a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,028 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,028 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,028 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f is not already registered for deferred release in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,029 [http-13530-5] XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,030 [http-13530-5] XAPool - NOT_ACCESSIBLE xa resource GTRID: 4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0
2009-09-21 15:01:58,030 [http-13530-5] TransactionContextHelper - marking a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f as recycled in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,030 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f has been recycled, unregistering deferred release from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,030 [http-13530-5] TransactionContextHelper - enlisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f into a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,030 [http-13530-5] TransactionContextHelper - avoiding re-enlistment of already enlisted but not ended resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,031 [http-13530-5] TransactionContextHelper - delisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,031 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,031 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,032 [http-13530-5] TransactionContextHelper - requeuing a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,032 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,032 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,032 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f is not already registered for deferred release in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,033 [http-13530-5] XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,033 [http-13530-5] XAPool - NOT_ACCESSIBLE xa resource GTRID: 4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0
2009-09-21 15:01:58,033 [http-13530-5] TransactionContextHelper - marking a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f as recycled in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,033 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f has been recycled, unregistering deferred release from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,033 [http-13530-5] TransactionContextHelper - enlisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f into a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,033 [http-13530-5] TransactionContextHelper - avoiding re-enlistment of already enlisted but not ended resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,034 [http-13530-5] TransactionContextHelper - delisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,034 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,034 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,034 [http-13530-5] TransactionContextHelper - requeuing a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,034 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,034 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,034 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f is not already registered for deferred release in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,034 [http-13530-5] XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,035 [http-13530-5] XAPool - NOT_ACCESSIBLE xa resource GTRID: 4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - marking a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f as recycled in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f has been recycled, unregistering deferred release from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - delisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - requeuing a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,035 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f is not already registered for deferred release in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,035 [http-13530-5] XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,035 [http-13530-5] XAPool - NOT_ACCESSIBLE xa resource GTRID: 4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0
2009-09-21 15:01:58,036 [http-13530-5] TransactionContextHelper - marking a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f as recycled in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,036 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f has been recycled, unregistering deferred release from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,036 [http-13530-5] TransactionContextHelper - enlisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f into a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,036 [http-13530-5] TransactionContextHelper - avoiding re-enlistment of already enlisted but not ended resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,041 [http-13530-5] XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,041 [http-13530-5] TransactionContextHelper - enlisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@427dac02 into a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,041 [http-13530-5] TransactionContextHelper - enlisting resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state NO_TX with XID null into a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,042 [http-13530-5] XAResourceManager - creating new branch with a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B99A000114C5]
2009-09-21 15:01:58,118 [http-13530-5] TransactionContextHelper - delisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@427dac02 from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,119 [http-13530-5] TransactionContextHelper - requeuing a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@427dac02 from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,154 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,156 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,211 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,213 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,327 [http-13530-5] TransactionContextHelper - delisting a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,327 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,328 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,328 [http-13530-5] TransactionContextHelper - requeuing a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f from a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,328 [http-13530-5] TransactionContextHelper - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,328 [http-13530-5] TransactionContextHelper - resource GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]
2009-09-21 15:01:58,328 [http-13530-5] TransactionContextHelper - a JdbcPooledConnection from datasource jdbc/FxFDataSource in state ACCESSIBLE wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@593f5a2f is not already registered for deferred release in a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,329 [http-13530-9] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,333 [http-13530-9] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,378 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,382 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,382 [http-13530-9] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,437 [http-13530-5] BitronixTransactionManager - rolling back transaction a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,438 [http-13530-5] TaskScheduler - cancelling transaction timeout task on a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,438 [http-13530-5] TaskScheduler - removing task by a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,438 [http-13530-5] TaskScheduler - cancelled a TransactionTimeoutTask on a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ACTIVE, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009) scheduled for Mon Sep 21 15:04:57 CEST 2009, total task(s) still queued: 5
2009-09-21 15:01:58,438 [http-13530-5] BitronixTransaction - found unclosed resource to delist: an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,438 [http-13530-5] XAResourceManager - delisting resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,438 [http-13530-5] XAResourceHolderState - ending an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,438 [http-13530-5] LrcXAResource - OK to end, old state=STARTED, XID=a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2], flag=SUCCESS
2009-09-21 15:01:58,438 [http-13530-11] XAPool - NOT_ACCESSIBLE xa resource GTRID: 4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0
2009-09-21 15:01:58,438 [http-13530-5] TransactionLogAppender - between 1710517 and 1710601, writing a Bitronix TransactionLogRecord with status=ROLLING_BACK, recordLength=76, headerLength=28, time=1253538118438, sequenceNumber=70904, crc32=965290034, gtrid=4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0, uniqueNames=jdbc/FxFDataSource
2009-09-21 15:01:58,439 [http-13530-5] Rollbacker - trying to rollback resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state ENDED (ended) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,439 [http-13530-5] LrcXAResource - OK to rollback, old state=ENDED, XID=a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,443 [http-13530-5] Rollbacker - rolled back resource an XAResourceHolderState with uniqueName=jdbc/FxFDataSource XAResource=a JDBC LrcXAResource in state NO_TX (ended) with XID a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B8F5000114B2]
2009-09-21 15:01:58,443 [http-13530-11] XAPool - NOT_ACCESSIBLE xa resource GTRID: 4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0
2009-09-21 15:01:58,444 [http-13530-5] TransactionLogAppender - between 1710857 and 1710941, writing a Bitronix TransactionLogRecord with status=ROLLEDBACK, recordLength=76, headerLength=28, time=1253538118443, sequenceNumber=70909, crc32=-1762245434, gtrid=4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0, uniqueNames=jdbc/FxFDataSource
2009-09-21 15:01:58,444 [http-13530-5] BitronixTransaction - successfully rolled back a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ROLLEDBACK, 1 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,445 [http-13530-10] BitronixTransactionManager - a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ROLLEDBACK, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009)
2009-09-21 15:01:58,445 [http-13530-5] BitronixTransaction - executing synchronization a ClearContextSynchronization for a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ROLLEDBACK, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009) with status=ROLLEDBACK
2009-09-21 15:01:58,445 [http-13530-5] BitronixTransactionManager - clearing thread context: a ThreadContext with transaction a Bitronix Transaction with GTRID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0], status=ROLLEDBACK, 0 resource(s) enlisted (started Mon Sep 21 15:01:57 CEST 2009), default timeout 180s

---

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Ludovic Orban]

Thanks for the logs, I think I have a better idea of what you're doing now.

Let's go back to your pseudo code where I think the root of the problem lies:

 getConnection()
 -> call other code e.g. third party lib
     getConnection()
     close()
 <-
 close()

It looks like that the 'call other code' bit is not always closing the connection it acquires before it returns. What points me to believe this is that you have this line logged:

XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]

immediately followed by that one:

XAPool - NOT_ACCESSIBLE xa resource GTRID: 4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0

which is fine. The problem is that in one case you have that log line:

XAPool - current transaction GTRID is [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0]

not followed by the one indicating that a NOT_ACCESSIBLE connection is available. A few lines below you then have this:

XAResourceManager - creating new branch with a Bitronix XID [4678465F4170706C69636174696F6E00000123DCB1B8F4000114B0 : 4678465F4170706C69636174696F6E00000123DCB1B99A000114C5]

which means that the connection pool could not find a closed connection to be reused it tried creating a new branch on another connection. Unfortunately LRC resources cannot support more than one branch at a time and this is why the TM rejected this request with BitronixSystemException: cannot enlist more than one non-XA resource.


As far as I can say there's no problem with BTM as it's just preventing your code from doing something wrong. I'd suggest you to carefully review your 'call other code' piece of code and look for some connection leak or misuse.

Hej hej!

Ludovic Orban wrote:
[..]
> It looks like that the 'call other code' bit is not always closing the
> connection it acquires before it returns. What points me to believe this is
> that you have this line logged:

Thanks for your advice, we have checked our code and the involved third party
lib. As far as I see, every connection is properly closed in a finally-
statement.
Meanwhile we made a ugly hack, which helps for the moment - caching the first
opened connection during a transaction, reusing and closing it immediately
before 'commit'.
The bug only occurs while the application is under load, so it has the smell
of a concurrency problem.
Any hints yet?

Bye,
 Tino

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Ludovic Orban]

Tino,

Indeed, this smells like a race condition. With the narrow view I have over your application I'm more inclined to say that it probably is in your part of the code but you never know, I could be wrong.

Have you tried looking at the pooled objects in the JMX registry after the problem occurs? This might give you hints about where the problem is happening.

To fully troubleshoot a connection leak I would need a complete debug log file with a reproduction of the problem but as you pointed out, this isn't always practical. If you have any suggestion about what BTM could do more to help you out I'll consider you request to implement it.

Ludovic

2009/9/24 Tino Strauss <tino_usenet@...>

Hej hej!

Ludovic Orban wrote:
[..]

> It looks like that the 'call other code' bit is not always closing the
> connection it acquires before it returns. What points me to believe this is
> that you have this line logged:

Thanks for your advice, we have checked our code and the involved third party
lib. As far as I see, every connection is properly closed in a finally-
statement.
Meanwhile we made a ugly hack, which helps for the moment - caching the first
opened connection during a transaction, reusing and closing it immediately
before 'commit'.
The bug only occurs while the application is under load, so it has the smell
of a concurrency problem.
Any hints yet?

Bye,
 Tino

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

   http://xircles.codehaus.org/manage_email

Hej, hej!

Ludovic Orban wrote:
[..]
> Indeed, this smells like a race condition. With the narrow view I have over
> your application I'm more inclined to say that it probably is in your part
> of the code but you never know, I could be wrong.

Today I was looking again for code, which is able to prevent that connections
will be properly closed. In the end, there was only the little piece of code
in the finally-statement:

if (connection != null) {
  try {
    if (!connection.isClosed()) {
      connection.close();
    }
  } catch (SQLException e) {
     ....
  }
}

After removing the isClosed() check, the application survived the load test.
Unfortunally I haven't had really much time for testing, so I have to check
this again tomorow. But it seems, there is a race condition in isClosed().

 Bye,
  Tino

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Ludovic Orban]

I'm not sure I would call that a race condition as a JDBC connection object cannot be shared by threads.

The BTM JDBC pool's code surrounding this is quite light, in JdbcConnectionHandle.java:

    public boolean isClosed() throws SQLException {
        if (jdbcPooledConnection == null)
            return true;
        return getDelegate().isClosed();
    }

so I highly suspect a bug in your database or JDBC driver. What database and driver are you using and what are their version number?


Please also note that checking for isClosed() is completely useless in this case as the java.sql.Connection.close() javadoc explicity states that closing an already closed connection has no effect (see: http://java.sun.com/j2se/1.4.2/docs/api/java/sql/Connection.html#close%28%29) so I would just leave it out and not bother about it.

2009/9/24 Tino Strauss <tino_usenet@...>

Hej, hej!

Ludovic Orban wrote:
[..]

> Indeed, this smells like a race condition. With the narrow view I have over
> your application I'm more inclined to say that it probably is in your part
> of the code but you never know, I could be wrong.

Today I was looking again for code, which is able to prevent that connections
will be properly closed. In the end, there was only the little piece of code
in the finally-statement:

if (connection != null) {
 try {
   if (!connection.isClosed()) {
     connection.close();
   }
 } catch (SQLException e) {
    ....
 }
}

After removing the isClosed() check, the application survived the load test.
Unfortunally I haven't had really much time for testing, so I have to check
this again tomorow. But it seems, there is a race condition in isClosed().

 Bye,
 Tino

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

   http://xircles.codehaus.org/manage_email

Ludovic Orban wrote:
> I'm not sure I would call that a race condition as a JDBC connection object
> cannot be shared by threads.

Hmm, you are right. But unfortunately, I was wrong with my hasty conclusion:
the bug is still reproducible :(
I've puted a compressed debug log into my webspace but I'm not sure if you want
to inspect it - uncompressed size is 465MB! If so, the affected GTRID is
4678465F4170706C69636174696F6E00000123F07B8067000164BC
http://www.ebene42.de/tx.log.bz2

[..]
> so I highly suspect a bug in your database or JDBC driver. What database and
> driver are you using and what are their version number?

It's Oracle 10.2.0.3.0. with JDBC driver in the same version.

> Please also note that checking for isClosed() is completely useless in this
> case as the java.sql.Connection.close() javadoc explicity states that
> closing an already closed connection has no effect (see:
> http://java.sun.com/j2se/1.4.2/docs/api/java/sql/Connection.html#close%28%29)
> so I would just leave it out and not bother about it.

Again, you're right. However, previousely we had sometimes trouble with double
close and some old connection pools (such as early releases from dbcp).
Therefore the connection was checked before closing it, but its obsolete now.

Bye,
  Tino


---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Ludovic Orban]

Tino,

I've analyzed the log file you posted and unfortunately it confirms my theory: somewhere your code does not close the connection for some reason.

If you look at line 1886880 for instance you can see that BTM found your previously closed connection and is about to recycle it. At this time, it is the 5th time the connection is recycled for the transaction 4678465F4170706C69636174696F6E00000123F07B8067000164BC.

At line 1886894, a 6th recycling is tried but if you look between lines 1886880 and 1886894 you'll find no trace of the connection being closed (line 1886869 shows what the pool logs when a connection is closed). This basically means a fresh connection has to be acquired from the pool and must join the global transaction which is impossible for a LRC resource.

Here's the flow of your transaction using pseudo-code:

tm.begin()

c = pool.getConnection // 1
c.prepareStatement()
c.close()

c = pool.getConnection // 2
c.prepareStatement()
c.close()

c = pool.getConnection // 3
c.prepareStatement()
c.close()

c = pool.getConnection // 4
c.prepareStatement()
c.close()

c = pool.getConnection // 5
c.prepareStatement()

c = pool.getConnection // 6
c.prepareStatement() // "cannot enlist more than one non-XA resource" exception happens here
...


It could very well be that the connection acquired from the 5th getConnection() call is closed in your code somewhere after the 6th getConnection() which would mean there actually is no connection leak.

Does that make sens to you?

There are basically two potential solutions to your problem: either make sure you only use one connection at a time from the pool or stop using the LRCXADataSource and switch to the OracleXADataSource.

There is an issue open in JIRA to improve BTM's pool to pin connections to transactions (http://jira.codehaus.org/browse/BTM-35) but I'm seriously lacking time (or funding) to implement it.

Ludovic

2009/9/25 tino_usenet@... <tino_usenet@...>

Ludovic Orban wrote:
> I'm not sure I would call that a race condition as a JDBC connection object
> cannot be shared by threads.

Hmm, you are right. But unfortunately, I was wrong with my hasty conclusion:
the bug is still reproducible :(
I've puted a compressed debug log into my webspace but I'm not sure if you want
to inspect it - uncompressed size is 465MB! If so, the affected GTRID is
4678465F4170706C69636174696F6E00000123F07B8067000164BC
http://www.ebene42.de/tx.log.bz2

[..]

> so I highly suspect a bug in your database or JDBC driver. What database and
> driver are you using and what are their version number?

It's Oracle 10.2.0.3.0. with JDBC driver in the same version.

> Please also note that checking for isClosed() is completely useless in this
> case as the java.sql.Connection.close() javadoc explicity states that
> closing an already closed connection has no effect (see:
> http://java.sun.com/j2se/1.4.2/docs/api/java/sql/Connection.html#close%28%29)
> so I would just leave it out and not bother about it.

Again, you're right. However, previousely we had sometimes trouble with double
close and some old connection pools (such as early releases from dbcp).
Therefore the connection was checked before closing it, but its obsolete now.

Bye,
  Tino


---------------------------------------------------------------------
To unsubscribe from this list, please visit:

   http://xircles.codehaus.org/manage_email

Hej Ludovic,

sorry for the late response, meanwhile I had to switch to another project.

Ludovic wrote:
[..]
> It could very well be that the connection acquired from the 5th
> getConnection() call is closed in your code somewhere after the 6th
> getConnection() which would mean there actually is no connection leak.
>
> Does that make sens to you?

Not really, there is just only one method with getConnection followed by
closing the connection in a finally-statement. This method is used everywhere,
without shared states or something other suspicious stuff. It's really
strange.

> There are basically two potential solutions to your problem: either make
> sure you only use one connection at a time from the pool or stop using the
> LRCXADataSource and switch to the OracleXADataSource.

That is what our workaround does, caching the first opened connection during a
transaction and reusing it. That's not my favourite solution but it works.

Thanks a lot for your help (especially analyzing the huge log)!

Bye,
  Tino

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email