Agfdhyk

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.