Thread [KFS/KSB-pool-1-thread-19] GTRID [737072696E672D62746D000000001D441F0B000040B4]
11:55:09,917
btm.log.43:30728 creating new transaction with GTRID [737072696E672D62746D000000001D441F0B000040B4]
btm.log.43, btm.log.42, many occurences
enlisting a JdbcPooledConnection from datasource riceDataSource in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@43462edf into a Bitronix Transaction with GTRID [737072696E672D62746D000000001D441F0B000040B4], status=ACTIVE, 2 resource(s) enlisted (started Tue Jan 06 11:23:23 EST 1970)
11:55:18,375
btm.log.42:18555 removing transaction from in-flight transactions: a Bitronix Transaction with GTRID [737072696E672D62746D000000001D441F0B000040B4], status=COMMITTED, 0 resource(s) enlisted (started Tue Jan 06 11:23:23 EST 1970)
Thread [http-localhost%2F127.0.0.1-8108-Processor32] GTRID [737072696E672D62746D000000001D44304D000041AD]
11:55:14,539
btm.log.42:8262 enlisting a JdbcPooledConnection from datasource riceDataSource in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@43462edf into a Bitronix Transaction with GTRID [737072696E672D62746D000000001D44304D000041AD], status=ACTIVE, 2 resource(s) enlisted (started Tue Jan 06 11:23:28 EST 1970)
11:55:14,583
catalina.out:7197 ERROR org.apache.ojb.broker.accesslayer.StatementsForClassImpl :: * Can't prepare statement: (...)
Caused by: java.sql.SQLException: error enlisting a JdbcConnectionHandle of a JdbcPooledConnection from datasource riceDataSource in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on oracle.jdbc.driver.T4CConnection@43462edf on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state STARTED
Caused by: bitronix.tm.internal.BitronixXAException: resource already started on XID a Bitronix XID [737072696E672D62746D000000001D441F0B000040B4 : 737072696E672D62746D000000001D441F16000040B8]
11:55:14,718
btm.log.42:8314 marking transaction as rollback only: a Bitronix Transaction with GTRID [737072696E672D62746D000000001D44304D000041AD], status=ACTIVE, 2 resource(s) enlisted (started Tue Jan 06 11:23:28 EST 1970)
Bug
Resolved
Major
As far as I can tell for the logs, this is not a BTM bug but an application level one.
Here are the relevant bits I found in the log files:
Here is what happened in a more human-readable way:
You definitely shared an open JDBC connection within 2 threads which is strictly forbidden by the JDBC spec so the BTM connection pool prevented the 2nd thread from using it.
I nevertheless do have a couple remarks about some weird info I collected in your log files:
I'm going to close this issue as 'Not a bug' as it definitely appears that the problem is somewhere else. If you find evidences that this analysis is wrong, please reopen it.
- Thread [http-localhost%2F127.0.0.1-8108-Processor32] works on transaction [737072696E672D62746D000000001D44304D000041AD]
- Thread [http-localhost%2F127.0.0.1-8108-Processor32] tries using connection oracle.jdbc.driver.T4CConnection@43462edf at 11:55:14,539 for the very first time
- Thread [http-localhost%2F127.0.0.1-8108-Processor32] usage of connection oracle.jdbc.driver.T4CConnection@43462edf rejected at 11:55:14,583 with BitronixXAException: resource already started on XID a Bitronix XID [737072696E672D62746D000000001D441F0B000040B4 : 737072696E672D62746D000000001D441F16000040B8]
- Thread [KFS/KSB-pool-1-thread-19] marks transaction for rollback only at 11:55:14,718
You definitely shared an open JDBC connection within 2 threads which is strictly forbidden by the JDBC spec so the BTM connection pool prevented the 2nd thread from using it. I nevertheless do have a couple remarks about some weird info I collected in your log files:- Transactions started all in 1970. Could there be a problem with your machine's clock???
- It would have been much easier to read the logs if you switched on the GTRID MDC by simply adding %X{btm-gtrid} in your log4j pattern, this is all explained here: http://docs.codehaus.org/display/BTM/DebugLogging
- What is the exact BTM version you're using? I've seen no reference of that anywhere.
I'm going to close this issue as 'Not a bug' as it definitely appears that the problem is somewhere else. If you find evidences that this analysis is wrong, please reopen it.