Dfyjkt

I am testing global transaction and timeout in atomikos. I created test where I am inserting data to first db and then call procedure in second db so I am using global transaction. Here is my test service code:

@Transactional(timeout = 5)
public void rollbackTest2x() 
 SqlSession sqlLogSession = getSession(LOGRWX);
 wsZadostDao.insert(sqlLogSession, new Record().withUUID(UUID.randomUUID().toString()));

 SqlSession sqlSession = getSession(REFRWX);
 procDelayDao.procDelay(sqlSession, new ProcDelay().withSecond(10));
 // procDelayDao.procDelay(sqlSession, new ProcDelay().withSecond(10));

This test throw no exception but the data are rollback. There is just exception in Atomikos PooledAlarmTimer which is not propagated to main thread. So my test ends OK but data are not inserted. Any idea how should I fix it ?

2018-11-12 11:57:39.948 [main] DEBUG o.sqlproc.engine.spring.SpringQuery - callUpdate, query=call PROC_DELAY(?)
2018-11-12 11:57:40.021 [main] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): registering listener atomikos connection pool 'REFRW1X'
2018-11-12 11:57:40.023 [main] TRACE com.atomikos.thread.TaskManager - ThreadFactory: creating new thread: Atomikos:6
2018-11-12 11:57:40.025 [main] TRACE c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'REFRW1X': init done.
2018-11-12 11:57:40.025 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:40.025 [main] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): updating last time acquired
2018-11-12 11:57:40.025 [main] TRACE c.a.jdbc.AtomikosXAPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): testing connection with query [SELECT 1 FROM DUAL]
2018-11-12 11:57:40.026 [main] TRACE c.a.jdbc.AtomikosXAPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): connection tested OK
2018-11-12 11:57:40.026 [main] TRACE c.a.jdbc.AtomikosXAPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): creating connection proxy...
2018-11-12 11:57:40.026 [main] DEBUG c.a.jdbc.JdbcConnectionProxyHelper - setting isolation level to 2
2018-11-12 11:57:40.026 [main] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 0 context(s): notifySessionBorrowed
2018-11-12 11:57:40.026 [main] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@6f07d414
2018-11-12 11:57:40.026 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:40.026 [main] DEBUG c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: calling toString...
2018-11-12 11:57:40.026 [main] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: toString returning oracle.jdbc.driver.LogicalConnection@40faff12
2018-11-12 11:57:40.026 [main] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): returning proxy oracle.jdbc.driver.LogicalConnection@40faff12
2018-11-12 11:57:40.026 [main] TRACE c.a.datasource.pool.ConnectionPool - atomikos connection pool 'REFRW1X': current size: 0/1
2018-11-12 11:57:40.026 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:40.026 [main] DEBUG c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: calling toString...
2018-11-12 11:57:40.026 [main] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: toString returning oracle.jdbc.driver.LogicalConnection@40faff12
2018-11-12 11:57:40.026 [main] TRACE c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'REFRW1X': returning oracle.jdbc.driver.LogicalConnection@40faff12
2018-11-12 11:57:40.026 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:40.026 [main] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: notifyBeforeUse a SessionHandleState with 1 context(s)
2018-11-12 11:57:40.026 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:40.027 [main] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@f881a272
2018-11-12 11:57:40.027 [main] TRACE c.atomikos.icatch.imp.CoordinatorImp - Coordinator my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 entering state: ACTIVE
2018-11-12 11:57:40.027 [main] DEBUG c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 726F622D6170702D3738373963323832356230323338393833363738356563666637636132633434313534323032303235393538363030303031:726F622D6170702D373837396332383235623032333839383336373835656366663763613263343432 ) for transaction my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:40.027 [main] TRACE c.a.d.xa.XAResourceTransaction - XAResourceTransaction: 726F622D6170702D3738373963323832356230323338393833363738356563666637636132633434313534323032303235393538363030303031:726F622D6170702D373837396332383235623032333839383336373835656366663763613263343432: about to switch to XAResource oracle.jdbc.driver.T4CXAResource@223967ea
2018-11-12 11:57:40.027 [main] TRACE c.a.d.xa.XAResourceTransaction - XAResourceTransaction my-app-7879c2825b02389836785ecff7ca2c44154202025958600001my-app-7879c2825b02389836785ecff7ca2c442: switched to XAResource oracle.jdbc.driver.T4CXAResource@223967ea
2018-11-12 11:57:40.027 [main] DEBUG c.a.d.xa.XAResourceTransaction - XAResource.start ( 726F622D6170702D3738373963323832356230323338393833363738356563666637636132633434313534323032303235393538363030303031:726F622D6170702D373837396332383235623032333839383336373835656366663763613263343432 , XAResource.TMNOFLAGS ) on resource REFRW1X represented by XAResource instance oracle.jdbc.driver.T4CXAResource@223967ea
2018-11-12 11:57:40.027 [main] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEnlistedStateHandler@4a6a6a69
2018-11-12 11:57:40.027 [main] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@f881a272
2018-11-12 11:57:40.027 [main] DEBUG c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@f881a272 ) for transaction my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:40.027 [main] DEBUG c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: calling prepareCall( call PROC_DELAY(?))...
2018-11-12 11:57:40.048 [main] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: prepareCall returning oracle.jdbc.driver.OracleCallableStatementWrapper@16ac4d3d
2018-11-12 11:57:44.703 [Atomikos:4] WARN c.a.icatch.imp.ActiveStateHandler - Transaction my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 has timed out - rolling back...
2018-11-12 11:57:44.704 [Atomikos:4] TRACE c.atomikos.icatch.imp.CoordinatorImp - Coordinator my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 entering state: ABORTING
2018-11-12 11:57:44.708 [Atomikos:4] TRACE com.atomikos.thread.TaskManager - ThreadFactory: creating new thread: Atomikos:7
2018-11-12 11:57:44.708 [Atomikos:4] TRACE com.atomikos.thread.TaskManager - ThreadFactory: creating new thread: Atomikos:8
2018-11-12 11:57:44.710 [Atomikos:8] DEBUG c.a.d.xa.XAResourceTransaction - XAResource.end ( 726F622D6170702D3738373963323832356230323338393833363738356563666637636132633434313534323032303235393538363030303031:726F622D6170702D373837396332383235623032333839383336373835656366663763613263343432 , XAResource.TMSUCCESS ) on resource REFRW1X represented by XAResource instance oracle.jdbc.driver.T4CXAResource@223967ea
2018-11-12 11:57:44.711 [Atomikos:7] DEBUG c.a.d.xa.XAResourceTransaction - XAResource.end ( 726F622D6170702D3738373963323832356230323338393833363738356563666637636132633434313534323032303235393538363030303031:726F622D6170702D373837396332383235623032333839383336373835656366663763613263343431 , XAResource.TMSUCCESS ) on resource LOGRW1X represented by XAResource instance oracle.jdbc.driver.T4CXAResource@446c8c72
2018-11-12 11:57:50.055 [Atomikos:7] DEBUG c.a.d.xa.XAResourceTransaction - XAResource.rollback ( 726F622D6170702D3738373963323832356230323338393833363738356563666637636132633434313534323032303235393538363030303031:726F622D6170702D373837396332383235623032333839383336373835656366663763613263343431 ) on resource LOGRW1X represented by XAResource instance oracle.jdbc.driver.T4CXAResource@446c8c72
2018-11-12 11:57:50.058 [Atomikos:8] DEBUG c.a.d.xa.XAResourceTransaction - XAResource.rollback ( 726F622D6170702D3738373963323832356230323338393833363738356563666637636132633434313534323032303235393538363030303031:726F622D6170702D373837396332383235623032333839383336373835656366663763613263343432 ) on resource REFRW1X represented by XAResource instance oracle.jdbc.driver.T4CXAResource@223967ea
2018-11-12 11:57:50.059 [main] DEBUG o.sqlproc.engine.spring.SpringQuery - callUpdate, number of updated rows=-1
2018-11-12 11:57:50.059 [main] DEBUG o.sqlproc.engine.SqlProcedureEngine - << callUpdate, result=-1
2018-11-12 11:57:50.059 [main] TRACE org.my.app.db.ProcDelayDao - sql procDelay result: -1
2018-11-12 11:57:50.060 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:50.060 [Atomikos:4] TRACE c.atomikos.icatch.imp.CoordinatorImp - Coordinator my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 entering state: TERMINATED
2018-11-12 11:57:50.060 [main] DEBUG c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@72eed547: close()...
2018-11-12 11:57:50.060 [main] TRACE c.a.jdbc.AbstractConnectionProxy - Forcing close of pending statement: oracle.jdbc.driver.OraclePreparedStatementWrapper@37b1149b
2018-11-12 11:57:50.060 [main] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 1 context(s): entering notifySessionClosed
2018-11-12 11:57:50.060 [main] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 1 context(s): delegating session close to a TransactionContext
2018-11-12 11:57:50.061 [main] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing state to com.atomikos.datasource.xa.session.BranchEndedStateHandler@5409dfdd
2018-11-12 11:57:50.061 [main] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEndedStateHandler@5409dfdd
2018-11-12 11:57:50.061 [main] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@72eed547: closed.
2018-11-12 11:57:50.061 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:50.061 [main] DEBUG c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: close()...
2018-11-12 11:57:50.061 [main] TRACE c.a.jdbc.AbstractConnectionProxy - Forcing close of pending statement: oracle.jdbc.driver.OracleCallableStatementWrapper@16ac4d3d
2018-11-12 11:57:50.061 [main] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 1 context(s): entering notifySessionClosed
2018-11-12 11:57:50.061 [main] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 1 context(s): delegating session close to a TransactionContext
2018-11-12 11:57:50.061 [main] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing state to com.atomikos.datasource.xa.session.BranchEndedStateHandler@45f9d394
2018-11-12 11:57:50.061 [main] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEndedStateHandler@45f9d394
2018-11-12 11:57:50.061 [main] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: closed.
2018-11-12 11:57:50.061 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:50.062 [Atomikos:4] TRACE c.atomikos.icatch.imp.CoordinatorImp - Coordinator my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 : stopping timer...
2018-11-12 11:57:50.062 [Atomikos:4] TRACE c.atomikos.icatch.imp.CoordinatorImp - Coordinator my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 : disposing statehandler TERMINATED...
2018-11-12 11:57:50.062 [Atomikos:4] TRACE c.atomikos.icatch.imp.CoordinatorImp - Coordinator my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 : disposed.
2018-11-12 11:57:50.062 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:50.062 [main] TRACE c.a.i.i.CompositeTransactionManagerImp - getCompositeTransaction() returning instance with id my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:50.064 [main] DEBUG c.a.i.imp.CompositeTransactionImp - commit() done (by application) of transaction my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:50.064 [main] TRACE c.atomikos.icatch.imp.CoordinatorImp - prepare() of Coordinator my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 returning READONLY
2018-11-12 11:57:50.066 [Atomikos:4] TRACE c.atomikos.icatch.imp.CoordinatorImp - Error during setRollbackOnly
java.lang.IllegalStateException: my-app-7879c2825b02389836785ecff7ca2c44154202025958600001 is no longer active but in state TERMINATED
 at com.atomikos.icatch.imp.CoordinatorImp.addParticipant(CoordinatorImp.java:383)
 at com.atomikos.icatch.imp.CoordinatorImp.setRollbackOnly(CoordinatorImp.java:703)
 at com.atomikos.icatch.imp.TransactionStateHandler.setRollbackOnly(TransactionStateHandler.java:260)
 at com.atomikos.icatch.imp.CompositeTransactionImp.setRollbackOnly(CompositeTransactionImp.java:262)
 at com.atomikos.icatch.imp.CompositeTransactionImp.entered(CompositeTransactionImp.java:343)
 at com.atomikos.finitestates.FSMImp.notifyListeners(FSMImp.java:166)
 at com.atomikos.finitestates.FSMImp.setState(FSMImp.java:256)
 at com.atomikos.icatch.imp.CoordinatorImp.setState(CoordinatorImp.java:312)
 at com.atomikos.icatch.imp.CoordinatorImp.setStateHandler(CoordinatorImp.java:222)
 at com.atomikos.icatch.imp.CoordinatorStateHandler.rollbackFromWithinCallback(CoordinatorStateHandler.java:506)
 at com.atomikos.icatch.imp.ActiveStateHandler$1.doRollback(ActiveStateHandler.java:85)
 at com.atomikos.icatch.imp.CoordinatorStateHandler.rollbackWithAfterCompletionNotification(CoordinatorStateHandler.java:563)
 at com.atomikos.icatch.imp.ActiveStateHandler.onTimeout(ActiveStateHandler.java:80)
 at com.atomikos.icatch.imp.CoordinatorImp.alarm(CoordinatorImp.java:650)
 at com.atomikos.timing.PooledAlarmTimer.notifyListeners(PooledAlarmTimer.java:95)
 at com.atomikos.timing.PooledAlarmTimer.run(PooledAlarmTimer.java:82)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 at java.lang.Thread.run(Thread.java:748)
2018-11-12 11:57:50.067 [Atomikos:4] DEBUG c.a.i.imp.CompositeTransactionImp - setRollbackOnly() called for transaction my-app-7879c2825b02389836785ecff7ca2c44154202025958600001
2018-11-12 11:57:50.068 [Atomikos:4] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@72eed547: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@f881a272
2018-11-12 11:57:50.069 [Atomikos:4] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing to state com.atomikos.datasource.xa.session.TerminatedStateHandler@3a06f087
2018-11-12 11:57:50.069 [Atomikos:4] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 0 context(s): all contexts terminated, firing TerminatedEvent for a SessionHandleState with 0 context(s)
2018-11-12 11:57:50.069 [Atomikos:4] TRACE c.a.jdbc.AtomikosXAPooledConnection - SessionHandleState terminated, firing XPooledConnectionTerminated event for an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s)
2018-11-12 11:57:50.069 [Atomikos:4] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): updating last time released
2018-11-12 11:57:50.069 [Atomikos:4] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): notifying listener: atomikos connection pool 'LOGRW1X'
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.datasource.pool.ConnectionPool - atomikos connection pool 'LOGRW1X': connection an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s) became available, notifying potentially waiting threads
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): updating last time released
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@40faff12: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@f881a272
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.d.xa.session.TransactionContext - a TransactionContext: changing to state com.atomikos.datasource.xa.session.TerminatedStateHandler@38415c0d
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.d.xa.session.SessionHandleState - a SessionHandleState with 0 context(s): all contexts terminated, firing TerminatedEvent for a SessionHandleState with 0 context(s)
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.jdbc.AtomikosXAPooledConnection - SessionHandleState terminated, firing XPooledConnectionTerminated event for an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s)
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): updating last time released
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): notifying listener: atomikos connection pool 'REFRW1X'
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.datasource.pool.ConnectionPool - atomikos connection pool 'REFRW1X': connection an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s) became available, notifying potentially waiting threads
2018-11-12 11:57:50.070 [Atomikos:4] TRACE c.a.d.pool.AbstractXPooledConnection - an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): updating last time released

UPDATE:

I dont understand this atomikos code. I have two participants in transaction with state: TerminatedState which return READ_ONLY in prepare method so there is no commit and no exception is thrown

protected void terminate ( boolean commit ) throws HeurRollbackException,
 HeurMixedException, SysException, java.lang.SecurityException,
 HeurCommitException, HeurHazardException, RollbackException,
 IllegalStateException

 
 synchronized ( fsm_ ) 
 if ( commit ) 
 if ( participants_.size () <= 1 ) 
 commit ( true );
 else 
 int prepareResult = prepare ();
 // make sure to only do commit if NOT read only
 if ( prepareResult != Participant.READ_ONLY )
 commit ( false );
 
 else 
 rollback ();
 
 

If all the work is READ_ONLY then there is nothing to commit. It means your SQL did not change any records.