I've setup JTA for our unit tests using:
- Atomikos (3.8)
- Hibernate (3.2.6/3.3.2)
- Spring (3.1)
After quite some effort I managed to get it up and running with a HyperSQL memory database, 2 XA Datasources and org.apache.naming.java.javaURLContextFactory for setting up a JNDI registry and the following jta.properties:
com.atomikos.icatch.enable_logging=true
com.atomikos.icatch.service=com.atomikos.icatch.standalone.UserTransactionServiceFactory
com.atomikos.icatch.max_timeout=2000000
com.atomikos.icatch.log_base_dir=./
com.atomikos.icatch.output_dir=./
com.atomikos.icatch.console_log_level=DEBUG
java.naming.factory.initial=org.apache.naming.java.javaURLContextFactory
com.atomikos.icatch.tm_unique_name=transactionManager
In a unit test (class annotated to require a transaction) I create and fill the database with test data (before) and in the test I try to acquire a table listing.
However, after I have executed the first sql statement (schema, tables and data creation in 1 SQL statement) Atomikos seems to close my connections, preventing me to continue and get a list of the contents from the new table. The exception states:
XA resource 'jdbc/loaniq/reader': resume for XID '7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231' raised 0: unknown
This also happens when I create the database and acquire the data in only one test method of this transactional Unit test.
This post suggests to add a test query to the datasource bean, how ever in this case this results in a infinite loop failing to find any working connection.
Hence my question: How do I prevent Atomikos from closing by JDBCXAResource connections in the pool?
Below some logging from the test showing that I was able to create the database, but afterwards can no longer use my datasource:
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: toString returning org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [AbstractXPooledConnection ] an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): returning proxy org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [ConnectionPool ] atomikos connection pool 'jdbc/loaniq/reader': got connection from pool, new size: 14/15
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: calling toString...
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: toString returning org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [AbstractDataSourceBean ] AtomikosDataSoureBean 'jdbc/loaniq/reader': returning org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: notifyBeforeUse a SessionHandleState with 1 context(s)
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
DEBUG 17:22:30 [SessionHandleState ] a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@6708d6d4
DEBUG 17:22:30 [CoordinatorImp ] Coordinator transactionManager0000100006 entering state: ACTIVE
INFO 17:22:30 [CompositeTransactionImp ] addParticipant ( XAResourceTransaction: 7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231 ) for transaction transactionManager0000100006
DEBUG 17:22:30 [XAResourceTransaction ] XAResourceTransaction: 7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231: about to switch to XAResource org.hsqldb.jdbc.pool.JDBCXAResource@17082d8
DEBUG 17:22:30 [XAResourceTransaction ] XAResourceTransaction transactionManager0000100006transactionManager1: switched to XAResource org.hsqldb.jdbc.pool.JDBCXAResource@17082d8
INFO 17:22:30 [XAResourceTransaction ] XAResource.start ( 7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231 , XAResource.TMNOFLAGS ) on resource jdbc/loaniq/reader represented by XAResource instance org.hsqldb.jdbc.pool.JDBCXAResource@17082d8
DEBUG 17:22:30 [TransactionContext ] a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEnlistedStateHandler@19e733e
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@6708d6d4
DEBUG 17:22:30 [CoordinatorImp ] Coordinator transactionManager0000100006 entering state: ACTIVE
INFO 17:22:30 [CompositeTransactionImp ] registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@6708d6d4 ) for transaction transactionManager0000100006
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: calling prepareStatement...
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: prepareStatement returning org.hsqldb.jdbc.JDBCPreparedStatement@1a0eec3[sql=[
CREATE SCHEMA LSUSER AUTHORIZATION SA
CREATE TABLE "LSUSER"."VLS_CUSTOMER"
(
"CUS_CID_CUST_ID" CHAR(8),
"CUS_XID_CUST_ID" CHAR(15),
"CUS_NME_SHORT_NAME" CHAR(30),
"CUS_NME_FULL_NAME" VARCHAR(140),
"CUS_CDE_COUNTRY" CHAR(2),
"CUS_CDE_CUST_STAT" CHAR(5),
"CUS_IND_INVESTOR" CHAR(1),
"CUS_IND_BORROWER" CHAR(1),
"CUS_IND_GUARANTOR" CHAR(1),
"CUS_IND_BENEFIC" CHAR(1),
"CUS_IND_INTRL_ENT" CHAR(1),
"CUS_IND_RESTRICT" CHAR(1),
"CUS_CDE_BANK" CHAR(5),
"CUS_TSP_REC_CREATE" TIMESTAMP,
"CUS_TSP_REC_UPDATE" TIMESTAMP,
"CUS_UID_REC_CREATE" CHAR(8),
"CUS_UID_REC_UPDATE" CHAR(8),
"CUS_IND_SLG" CHAR(1),
"CUS_IND_MAJ_UNDWRT" CHAR(1),
"CUS_IND_CRA" CHAR(1),
"CUS_CDE_TRS_RPT_AR" CHAR(5),
"CUS_IND_SIMPLIFIED" CHAR(1),
"CUS_CDE_CUST_DESC" CHAR(5),
"CUS_CID_ULT_PARENT" CHAR(8),
"CUS_CDE_DEPT" CHAR(5),
"CUS_CID_IMM_PARENT" CHAR(8),
"CUS_CDE_EXPENSE" CHAR(15),
"CUS_CDE_PRIM_SIC" CHAR(10),
"CUS_CDE_PROSPECT" CHAR(5),
"CUS_CDE_LEGAL" CHAR(5),
"CUS_CDE_SIC_CNTRY" CHAR(2),
"CUS_CDE_BRANCH" CHAR(5),
"CUS_CDE_ORIGIN" CHAR(5),
"CUS_CDE_LANGUAGE" CHAR(5),
"CUS_IND_VAT_SUBJCT" CHAR(1),
"CUS_TXT_VAT_NUMBER" CHAR(15),
"CUS_AMT_OS_LIMIT" DECIMAL(31,3),
"CUS_CDE_OS_LIM_CCY" CHAR(3),
"CUS_IND_OS_LIM_ERL" CHAR(1),
"CUS_CDE_MASTER_ACT" CHAR(5),
"CUS_IND_BROKER" CHAR(1),
"CUS_CDE_DEP_SUBTYP" CHAR(5)
)
]]
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: isClosed()...
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: isClosed() returning false
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: calling getWarnings...
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: getWarnings returning null
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: calling clearWarnings...
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: clearWarnings returning null
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: close()...
DEBUG 17:22:30 [AbstractConnectionProxy ] Forcing close of pending statement: org.hsqldb.jdbc.JDBCPreparedStatement@1a0eec3[closed]
DEBUG 17:22:30 [SessionHandleState ] a SessionHandleState with 1 context(s): entering notifySessionClosed
DEBUG 17:22:30 [SessionHandleState ] a SessionHandleState with 1 context(s): delegeting session close to a TransactionContext
INFO 17:22:30 [XAResourceTransaction ] XAResource.end ( 7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231 , XAResource.TMSUCCESS ) on resource jdbc/loaniq/reader represented by XAResource instance org.hsqldb.jdbc.pool.JDBCXAResource@17082d8
DEBUG 17:22:30 [TransactionContext ] a TransactionContext: changing state to com.atomikos.datasource.xa.session.BranchEndedStateHandler@b5d05b
DEBUG 17:22:30 [TransactionContext ] a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEndedStateHandler@b5d05b
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: closed.
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
INFO 17:22:30 [AbstractDataSourceBean ] AtomikosDataSoureBean 'jdbc/loaniq/reader': getConnection ( null )...
INFO 17:22:30 [AbstractDataSourceBean ] AtomikosDataSoureBean 'jdbc/loaniq/reader': init...
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
DEBUG 17:22:30 [AbstractXPooledConnection ] an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): updating last time acquired
DEBUG 17:22:30 [AtomikosXAPooledConnection ] an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): no test query, skipping test
DEBUG 17:22:30 [AtomikosXAPooledConnection ] an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): creating connection proxy...
DEBUG 17:22:30 [SessionHandleState ] a SessionHandleState with 1 context(s): notifySessionBorrowed
DEBUG 17:22:30 [TransactionContext ] a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@98a8b8
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: calling toString...
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: toString returning org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [AbstractXPooledConnection ] an AtomikosXAPooledConnection with a SessionHandleState with 2 context(s): returning proxy org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [ConnectionPool ] atomikos connection pool 'jdbc/loaniq/reader': recycling connection from pool...
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
INFO 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: calling toString...
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: toString returning org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [AbstractDataSourceBean ] AtomikosDataSoureBean 'jdbc/loaniq/reader': returning org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
DEBUG 17:22:30 [AtomikosConnectionProxy ] atomikos connection proxy for org.hsqldb.jdbc.pool.JDBCXAConnectionWrapper@14492fb: notifyBeforeUse a SessionHandleState with 2 context(s)
DEBUG 17:22:30 [BaseTransactionManager ] getCompositeTransaction() returning instance with id transactionManager0000100006
DEBUG 17:22:30 [SessionHandleState ] a SessionHandleState with 2 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@6708d6d4
DEBUG 17:22:30 [CoordinatorImp ] Coordinator transactionManager0000100006 entering state: ACTIVE
INFO 17:22:30 [CompositeTransactionImp ] addParticipant ( XAResourceTransaction: 7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231 ) for transaction transactionManager0000100006
DEBUG 17:22:30 [XAResourceTransaction ] XAResourceTransaction: 7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231: about to switch to XAResource org.hsqldb.jdbc.pool.JDBCXAResource@17082d8
DEBUG 17:22:30 [XAResourceTransaction ] XAResourceTransaction transactionManager0000100006transactionManager1: switched to XAResource org.hsqldb.jdbc.pool.JDBCXAResource@17082d8
INFO 17:22:30 [XAResourceTransaction ] XAResource.start ( 7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231 , XAResource.TMJOIN ) on resource jdbc/loaniq/reader represented by XAResource instance org.hsqldb.jdbc.pool.JDBCXAResource@17082d8
WARN 17:22:30 [XAResourceTransaction ] XA resource 'jdbc/loaniq/reader': resume for XID '7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231' raised 0: unknown
javax.transaction.xa.XAException: Invalid XAResource state
at org.hsqldb.jdbc.pool.JDBCXAResource.start(Unknown Source)
at com.atomikos.datasource.xa.XAResourceTransaction.resume(XAResourceTransaction.java:498)
at com.atomikos.datasource.xa.session.BranchEnlistedStateHandler.<init>(BranchEnlistedStateHandler.java:59)
at com.atomikos.datasource.xa.session.NotInBranchStateHandler.checkEnlistBeforeUse(NotInBranchStateHandler.java:65)
at com.atomikos.datasource.xa.session.TransactionContext.checkEnlistBeforeUse(TransactionContext.java:88)
at com.atomikos.datasource.xa.session.SessionHandleState.notifyBeforeUse(SessionHandleState.java:179)
at com.atomikos.jdbc.AtomikosConnectionProxy.enlist(AtomikosConnectionProxy.java:208)
at com.atomikos.jdbc.AtomikosConnectionProxy.invoke(AtomikosConnectionProxy.java:142)
at com.sun.proxy.$Proxy41.prepareStatement(Unknown Source)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:534)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:452)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1577)
at org.hibernate.loader.Loader.doQuery(Loader.java:696)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
at org.hibernate.loader.Loader.doList(Loader.java:2232)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2129)
at org.hibernate.loader.Loader.list(Loader.java:2124)
at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:312)
at org.hibernate.impl.SessionImpl.listCustomQuery(SessionImpl.java:1723)
at org.hibernate.impl.AbstractSessionImpl.list(AbstractSessionImpl.java:165)
at org.hibernate.impl.SQLQueryImpl.list(SQLQueryImpl.java:175)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:65)
at com.ing.liqmw.trade.dao.DataStubTest.test(DataStubTest.java:171)
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:597)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:74)
at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:83)
at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:72)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:231)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:49)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:71)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:174)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
WARN 17:22:30 [JdbcConnectionProxyHelper ] Error enlisting in transaction - connection might be broken? Please check the logs for more information...
com.atomikos.datasource.ResourceException: XA resource 'jdbc/loaniq/reader': resume for XID '7472616E73616374696F6E4D616E6167657230303030313030303036:7472616E73616374696F6E4D616E6167657231' raised 0: unknown
at com.atomikos.datasource.xa.XAResourceTransaction.resume(XAResourceTransaction.java:505)
at com.atomikos.datasource.xa.session.BranchEnlistedStateHandler.<init>(BranchEnlistedStateHandler.java:59)
at com.atomikos.datasource.xa.session.NotInBranchStateHandler.checkEnlistBeforeUse(NotInBranchStateHandler.java:65)
at com.atomikos.datasource.xa.session.TransactionContext.checkEnlistBeforeUse(TransactionContext.java:88)
at com.atomikos.datasource.xa.session.SessionHandleState.notifyBeforeUse(SessionHandleState.java:179)
at com.atomikos.jdbc.AtomikosConnectionProxy.enlist(AtomikosConnectionProxy.java:208)
at com.atomikos.jdbc.AtomikosConnectionProxy.invoke(AtomikosConnectionProxy.java:142)
at com.sun.proxy.$Proxy41.prepareStatement(Unknown Source)
