Atomikos Forum
transaction timeout allows some sql to commit |
Hi,
I've upgraded to the latest atomikos (3.5.3), and based upon what I saw in the topic default82df.html?community.6.413.3, I made a test, and it appears to indicate the same problem still exists.
In that posting, the test was starting a transaction, getting a connection, creating a statement and executing some SQL against it. Then it waited for the transaction to time out, created a different statement and executed some SQL against that statement. The transaction (correctly) would not commit, but the SQL from the 2nd statement would be committed.
That appears to be fixed, as now in that case, an exception is thrown if you try to create a statement from that connection after the transaction has timed out. However, if you create the statement *before* the transaction times out, then execute some sql with the statement *after* the transaction times out, the sql issued after the transaction timeout will autocommit.
Here is some sample code in the form of a spring/testng test that illustrates this. It uses Spring's transaction template to wrap the creation & committing of the transaction:
@Test
public void autoCommitProblem() {
TransactionTemplate tt = new TransactionTemplate(mPlatformTransactionManager);
tt.setPropagationBehavior(TransactionDefinition.PROPAGATION_REQUIRES_NEW);
// Set the timeout to 10 seconds so we'll timeout when we want to below
tt.setTimeout(10);
tt.execute(new TransactionCallbackWithoutResult() {
@Override
public void doInTransactionWithoutResult(final TransactionStatus txnStatus) {
try {
Connection c = mDataSource.getConnection();
Statement statement = c.createStatement();
statement.execute("insert into client values(sys_guid(), 'NO WAY', 0, 'NO WAY', systimestamp, systimestamp)");
System.out.println("\n\nGOING TO SLEEP\n\n");
Thread.sleep(25000);
System.out.println("\n\nWAKING UP\n\n");
statement.execute("insert into client values(sys_guid(), 'NO WAY2', 0, 'NO WAY2', systimestamp, systimestamp)");
} catch (Exception e) {
throw new RuntimeException(e);
}
}
});
System.out.println("here");
}
Notice that it doesn't matter if the same statement is reused or another one is created before the sleep (and used to execute after the sleep). In the test case above, the first insert (issued before the timeout) is correctly rolled back (no row in the client table for "NO WAY"). However, the second insert (issued after the transaction timeout) is improperly committed (a row in the client table for "NO WAY2").
The same thing happens whether run against Oracle or Postgres.
Thanks,
Greg
I've upgraded to the latest atomikos (3.5.3), and based upon what I saw in the topic default82df.html?community.6.413.3, I made a test, and it appears to indicate the same problem still exists.
In that posting, the test was starting a transaction, getting a connection, creating a statement and executing some SQL against it. Then it waited for the transaction to time out, created a different statement and executed some SQL against that statement. The transaction (correctly) would not commit, but the SQL from the 2nd statement would be committed.
That appears to be fixed, as now in that case, an exception is thrown if you try to create a statement from that connection after the transaction has timed out. However, if you create the statement *before* the transaction times out, then execute some sql with the statement *after* the transaction times out, the sql issued after the transaction timeout will autocommit.
Here is some sample code in the form of a spring/testng test that illustrates this. It uses Spring's transaction template to wrap the creation & committing of the transaction:
@Test
public void autoCommitProblem() {
TransactionTemplate tt = new TransactionTemplate(mPlatformTransactionManager);
tt.setPropagationBehavior(TransactionDefinition.PROPAGATION_REQUIRES_NEW);
// Set the timeout to 10 seconds so we'll timeout when we want to below
tt.setTimeout(10);
tt.execute(new TransactionCallbackWithoutResult() {
@Override
public void doInTransactionWithoutResult(final TransactionStatus txnStatus) {
try {
Connection c = mDataSource.getConnection();
Statement statement = c.createStatement();
statement.execute("insert into client values(sys_guid(), 'NO WAY', 0, 'NO WAY', systimestamp, systimestamp)");
System.out.println("\n\nGOING TO SLEEP\n\n");
Thread.sleep(25000);
System.out.println("\n\nWAKING UP\n\n");
statement.execute("insert into client values(sys_guid(), 'NO WAY2', 0, 'NO WAY2', systimestamp, systimestamp)");
} catch (Exception e) {
throw new RuntimeException(e);
}
}
});
System.out.println("here");
}
Notice that it doesn't matter if the same statement is reused or another one is created before the sleep (and used to execute after the sleep). In the test case above, the first insert (issued before the timeout) is correctly rolled back (no row in the client table for "NO WAY"). However, the second insert (issued after the transaction timeout) is improperly committed (a row in the client table for "NO WAY2").
The same thing happens whether run against Oracle or Postgres.
Thanks,
Greg
Greg Thoen 
Friday, March 27, 2009
Friday, March 27, 2009
Fogbugz apparently couldn't handle a longer message, so I had to take out the log that I wanted to include in the original post, so....
Here is the portion of the log file that begins at the start of this method, with atomikos turned up to DEBUG (note that the "T:" part towards the beginning of each log line shows the thread id):
Well, apparently, this needs to be broken up further still, so here's the first part of the log:
17:49:56.476 T:1 DEBUG o.s.t.j.JtaTransactionManager: Using transaction object [org.springframework.transaction.jta.JtaTransactionObject@1b6a1c4]
17:49:56.476 T:1 DEBUG atomikos: getCompositeTransaction() returning NULL!
17:49:56.476 T:1 DEBUG atomikos: getCompositeTransaction() returning NULL!
17:49:56.476 T:1 DEBUG o.s.t.j.JtaTransactionManager: Creating new transaction with name [null]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,timeout_10
17:49:56.476 T:1 DEBUG atomikos: getCompositeTransaction() returning NULL!
17:49:56.507 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.507 T:1 DEBUG atomikos: (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@12342ed
17:49:56.507 T:1 DEBUG atomikos: ThreadFactory: creating new thread: Atomikos:1
17:49:56.507 T:1 DEBUG atomikos: Creating composite transaction: be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.507 T:1 INFO atomikos: createCompositeTransaction ( 10000 ): created new ROOT transaction with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.507 T:1 DEBUG o.s.t.s.TransactionSynchronizationManager: Initializing transaction synchronization
17:49:56.523 T:1 INFO atomikos: AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
17:49:56.523 T:1 INFO atomikos: AtomikosDataSoureBean 'XADBMS': init...
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: atomikos connection pool 'XADBMS': current size: 1/1
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): updating last time acquired
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): testing connection with query [select 1 from dual]
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): connection tested OK
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): creating connection proxy...
17:49:56.523 T:1 DEBUG atomikos: a SessionHandleState with 0 context(s): notifySessionBorrowed
17:49:56.523 T:1 DEBUG atomikos: a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@37504d
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling toString...
17:49:56.523 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: toString returning oracle.jdbc.driver.LogicalConnection@e86614
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): returning proxy oracle.jdbc.driver.LogicalConnection@e86614
Here is the portion of the log file that begins at the start of this method, with atomikos turned up to DEBUG (note that the "T:" part towards the beginning of each log line shows the thread id):
Well, apparently, this needs to be broken up further still, so here's the first part of the log:
17:49:56.476 T:1 DEBUG o.s.t.j.JtaTransactionManager: Using transaction object [org.springframework.transaction.jta.JtaTransactionObject@1b6a1c4]
17:49:56.476 T:1 DEBUG atomikos: getCompositeTransaction() returning NULL!
17:49:56.476 T:1 DEBUG atomikos: getCompositeTransaction() returning NULL!
17:49:56.476 T:1 DEBUG o.s.t.j.JtaTransactionManager: Creating new transaction with name [null]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,timeout_10
17:49:56.476 T:1 DEBUG atomikos: getCompositeTransaction() returning NULL!
17:49:56.507 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.507 T:1 DEBUG atomikos: (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@12342ed
17:49:56.507 T:1 DEBUG atomikos: ThreadFactory: creating new thread: Atomikos:1
17:49:56.507 T:1 DEBUG atomikos: Creating composite transaction: be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.507 T:1 INFO atomikos: createCompositeTransaction ( 10000 ): created new ROOT transaction with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.507 T:1 DEBUG o.s.t.s.TransactionSynchronizationManager: Initializing transaction synchronization
17:49:56.523 T:1 INFO atomikos: AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
17:49:56.523 T:1 INFO atomikos: AtomikosDataSoureBean 'XADBMS': init...
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: atomikos connection pool 'XADBMS': current size: 1/1
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): updating last time acquired
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): testing connection with query [select 1 from dual]
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): connection tested OK
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): creating connection proxy...
17:49:56.523 T:1 DEBUG atomikos: a SessionHandleState with 0 context(s): notifySessionBorrowed
17:49:56.523 T:1 DEBUG atomikos: a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@37504d
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling toString...
17:49:56.523 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: toString returning oracle.jdbc.driver.LogicalConnection@e86614
17:49:56.523 T:1 DEBUG atomikos: an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): returning proxy oracle.jdbc.driver.LogicalConnection@e86614
Greg Thoen
Friday, March 27, 2009
Friday, March 27, 2009
Next part of the log:
17:49:56.523 T:1 DEBUG atomikos: atomikos connection pool 'XADBMS': got connection from pool, new size: 0/1
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling toString...
17:49:56.523 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: toString returning oracle.jdbc.driver.LogicalConnection@e86614
17:49:56.523 T:1 DEBUG atomikos: AtomikosDataSoureBean 'XADBMS': returning oracle.jdbc.driver.LogicalConnection@e86614
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: notifyBeforeUse a SessionHandleState with 1 context(s)
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.523 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.523 T:1 INFO atomikos: addParticipant ( XAResourceTransaction: 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 ) for transaction be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: XAResourceTransaction: 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231: about to switch to XAResource oracle.jdbc.driver.T4CXAResource@1d5b945
17:49:56.523 T:1 DEBUG atomikos: XAResourceTransaction be5bc884c64947d2be7bf3ef081f7e5b0000100001be5bc884c64947d2be7bf3ef081f7e5b1: switched to XAResource oracle.jdbc.driver.T4CXAResource@1d5b945
17:49:56.538 T:1 INFO atomikos: XAResource.start ( 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 , XAResource.TMNOFLAGS ) called on resource XADBMS represented by XAResource instance oracle.jdbc.driver.T4CXAResource@1d5b945
17:49:56.538 T:1 DEBUG atomikos: a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEnlistedStateHandler@1b9e7fc
17:49:56.523 T:1 DEBUG atomikos: atomikos connection pool 'XADBMS': got connection from pool, new size: 0/1
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling toString...
17:49:56.523 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: toString returning oracle.jdbc.driver.LogicalConnection@e86614
17:49:56.523 T:1 DEBUG atomikos: AtomikosDataSoureBean 'XADBMS': returning oracle.jdbc.driver.LogicalConnection@e86614
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: notifyBeforeUse a SessionHandleState with 1 context(s)
17:49:56.523 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.523 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.523 T:1 INFO atomikos: addParticipant ( XAResourceTransaction: 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 ) for transaction be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.523 T:1 DEBUG atomikos: XAResourceTransaction: 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231: about to switch to XAResource oracle.jdbc.driver.T4CXAResource@1d5b945
17:49:56.523 T:1 DEBUG atomikos: XAResourceTransaction be5bc884c64947d2be7bf3ef081f7e5b0000100001be5bc884c64947d2be7bf3ef081f7e5b1: switched to XAResource oracle.jdbc.driver.T4CXAResource@1d5b945
17:49:56.538 T:1 INFO atomikos: XAResource.start ( 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 , XAResource.TMNOFLAGS ) called on resource XADBMS represented by XAResource instance oracle.jdbc.driver.T4CXAResource@1d5b945
17:49:56.538 T:1 DEBUG atomikos: a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEnlistedStateHandler@1b9e7fc
Greg Thoen
Friday, March 27, 2009
Friday, March 27, 2009
Next part:
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.538 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.538 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling createStatement...
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: createStatement returning oracle.jdbc.driver.OracleStatementWrapper@423606
17:49:56.538 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: notifyBeforeUse a SessionHandleState with 1 context(s)
17:49:56.538 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.538 T:1 DEBUG atomikos: a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.538 T:1 DEBUG atomikos: a TransactionContext: changing to state null
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.538 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.538 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling createStatement...
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: createStatement returning oracle.jdbc.driver.OracleStatementWrapper@1176e5f
GOING TO SLEEP
17:50:06.585 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ABORTING
17:50:06.585 T:12 DEBUG atomikos: (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@88a970
17:50:06.585 T:12 DEBUG atomikos: ThreadFactory: creating new thread: Atomikos:2
17:50:06.585 T:12 DEBUG atomikos: (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@4e50ee
17:50:06.585 T:12 DEBUG atomikos: ThreadFactory: creating new thread: Atomikos:3
17:50:06.585 T:13 INFO atomikos: XAResource.end ( 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 , XAResource.TMSUCCESS ) called on resource XADBMS represented by XAResource instance oracle.jdbc.driver.T4CXAResource@1d5b945
17:50:06.585 T:13 DEBUG atomikos: About to call rollback on XAResource instance: oracle.jdbc.driver.T4CXAResource@1d5b945
17:50:06.601 T:13 INFO atomikos: XAResource.rollback ( 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 ) called on resource XADBMS represented by XAResource instance oracle.jdbc.driver.T4CXAResource@1d5b945
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: TERMINATED
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 : stopping timer...
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.538 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.538 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling createStatement...
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: createStatement returning oracle.jdbc.driver.OracleStatementWrapper@423606
17:49:56.538 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: notifyBeforeUse a SessionHandleState with 1 context(s)
17:49:56.538 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:49:56.538 T:1 DEBUG atomikos: a SessionHandleState with 1 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.538 T:1 DEBUG atomikos: a TransactionContext: changing to state null
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:49:56.538 T:1 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ACTIVE
17:49:56.538 T:1 INFO atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: calling createStatement...
17:49:56.538 T:1 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: createStatement returning oracle.jdbc.driver.OracleStatementWrapper@1176e5f
GOING TO SLEEP
17:50:06.585 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: ABORTING
17:50:06.585 T:12 DEBUG atomikos: (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@88a970
17:50:06.585 T:12 DEBUG atomikos: ThreadFactory: creating new thread: Atomikos:2
17:50:06.585 T:12 DEBUG atomikos: (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@4e50ee
17:50:06.585 T:12 DEBUG atomikos: ThreadFactory: creating new thread: Atomikos:3
17:50:06.585 T:13 INFO atomikos: XAResource.end ( 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 , XAResource.TMSUCCESS ) called on resource XADBMS represented by XAResource instance oracle.jdbc.driver.T4CXAResource@1d5b945
17:50:06.585 T:13 DEBUG atomikos: About to call rollback on XAResource instance: oracle.jdbc.driver.T4CXAResource@1d5b945
17:50:06.601 T:13 INFO atomikos: XAResource.rollback ( 626535626338383463363439343764326265376266336566303831663765356230303030313030303031:626535626338383463363439343764326265376266336566303831663765356231 ) called on resource XADBMS represented by XAResource instance oracle.jdbc.driver.T4CXAResource@1d5b945
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 entering state: TERMINATED
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 : stopping timer...
Greg Thoen
Friday, March 27, 2009
Friday, March 27, 2009
Next part:
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 : disposing statehandler TERMINATED...
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 : disposed.
17:50:06.601 T:12 DEBUG atomikos: Error during setRollbackOnly
java.lang.IllegalStateException: Wrong state for addParticipant: TERMINATED in coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001
at com.atomikos.icatch.imp.CoordinatorImp.addParticipant(CoordinatorImp.java:573)
at com.atomikos.icatch.imp.TransactionStateHandler.addParticipant(TransactionStateHandler.java:108)
at com.atomikos.icatch.imp.TransactionStateHandler.setRollbackOnly(TransactionStateHandler.java:295)
at com.atomikos.icatch.imp.CompositeTransactionImp.setRollbackOnly(CompositeTransactionImp.java:546)
at com.atomikos.icatch.imp.CompositeTransactionImp.entered(CompositeTransactionImp.java:609)
at com.atomikos.finitestates.FSMImp.notifyListeners(FSMImp.java:197)
at com.atomikos.finitestates.FSMImp.setState(FSMImp.java:288)
at com.atomikos.icatch.imp.CoordinatorImp.setState(CoordinatorImp.java:481)
at com.atomikos.icatch.imp.CoordinatorImp.setStateHandler(CoordinatorImp.java:312)
at com.atomikos.icatch.imp.CoordinatorStateHandler.rollback(CoordinatorStateHandler.java:857)
at com.atomikos.icatch.imp.ActiveStateHandler.onTimeout(ActiveStateHandler.java:143)
at com.atomikos.icatch.imp.CoordinatorImp.alarm(CoordinatorImp.java:1049)
at com.atomikos.timing.PooledAlarmTimer.notifyListeners(PooledAlarmTimer.java:87)
at com.atomikos.timing.PooledAlarmTimer.run(PooledAlarmTimer.java:74)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
17:50:06.601 T:12 INFO atomikos: setRollbackOnly() called for transaction be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:06.601 T:12 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:50:06.601 T:12 DEBUG atomikos: a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@1b7a553
17:50:06.601 T:12 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:50:06.601 T:12 DEBUG atomikos: a TransactionContext: changing to state null
WAKING UP
17:50:21.554 T:1 DEBUG o.s.t.j.JtaTransactionManager: Triggering beforeCommit synchronization
17:50:21.554 T:1 DEBUG o.s.t.j.JtaTransactionManager: Triggering beforeCompletion synchronization
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 : disposing statehandler TERMINATED...
17:50:06.601 T:12 DEBUG atomikos: Coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001 : disposed.
17:50:06.601 T:12 DEBUG atomikos: Error during setRollbackOnly
java.lang.IllegalStateException: Wrong state for addParticipant: TERMINATED in coordinator be5bc884c64947d2be7bf3ef081f7e5b0000100001
at com.atomikos.icatch.imp.CoordinatorImp.addParticipant(CoordinatorImp.java:573)
at com.atomikos.icatch.imp.TransactionStateHandler.addParticipant(TransactionStateHandler.java:108)
at com.atomikos.icatch.imp.TransactionStateHandler.setRollbackOnly(TransactionStateHandler.java:295)
at com.atomikos.icatch.imp.CompositeTransactionImp.setRollbackOnly(CompositeTransactionImp.java:546)
at com.atomikos.icatch.imp.CompositeTransactionImp.entered(CompositeTransactionImp.java:609)
at com.atomikos.finitestates.FSMImp.notifyListeners(FSMImp.java:197)
at com.atomikos.finitestates.FSMImp.setState(FSMImp.java:288)
at com.atomikos.icatch.imp.CoordinatorImp.setState(CoordinatorImp.java:481)
at com.atomikos.icatch.imp.CoordinatorImp.setStateHandler(CoordinatorImp.java:312)
at com.atomikos.icatch.imp.CoordinatorStateHandler.rollback(CoordinatorStateHandler.java:857)
at com.atomikos.icatch.imp.ActiveStateHandler.onTimeout(ActiveStateHandler.java:143)
at com.atomikos.icatch.imp.CoordinatorImp.alarm(CoordinatorImp.java:1049)
at com.atomikos.timing.PooledAlarmTimer.notifyListeners(PooledAlarmTimer.java:87)
at com.atomikos.timing.PooledAlarmTimer.run(PooledAlarmTimer.java:74)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
17:50:06.601 T:12 INFO atomikos: setRollbackOnly() called for transaction be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:06.601 T:12 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:50:06.601 T:12 DEBUG atomikos: a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@1b7a553
17:50:06.601 T:12 DEBUG atomikos: atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@e86614: detected termination of transaction com.atomikos.icatch.imp.CompositeTransactionImp@81933a
17:50:06.601 T:12 DEBUG atomikos: a TransactionContext: changing to state null
WAKING UP
17:50:21.554 T:1 DEBUG o.s.t.j.JtaTransactionManager: Triggering beforeCommit synchronization
17:50:21.554 T:1 DEBUG o.s.t.j.JtaTransactionManager: Triggering beforeCompletion synchronization
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
Greg Thoen
Friday, March 27, 2009
Friday, March 27, 2009
And finally:
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG o.s.t.j.JtaTransactionManager: Initiating transaction commit
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.570 T:1 DEBUG o.s.t.j.JtaTransactionManager: Triggering afterCompletion synchronization
17:50:21.570 T:1 DEBUG o.s.t.s.TransactionSynchronizationManager: Clearing transaction synchronization
17:50:21.570 T:1 DEBUG o.s.t.c.s.DirtiesContextTestExecutionListener: After test method: context [[TestContext@15db314 testClass = TestClass, locations = array<String>['classpath*:META-INF/*-context.xml', 'classpath:db-spring.xml'], testInstance = TestClass@89cc5e, testMethod = autoCommitProblem@TestClass, testException = java.lang.reflect.InvocationTargetException]], dirtiesContext [false].
FAILED: autoCommitProblem
org.springframework.transaction.UnexpectedRollbackException: JTA transaction unexpectedly rolled back (maybe due to a timeout); nested exception is javax.transaction.RollbackException: Transaction set to rollback only
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1031)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:709)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:678)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140)
at TestClass.autoCommitProblem(TestClass.java:161)
at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.run(AbstractTestNGSpringContextTests.java:140)
Caused by: javax.transaction.RollbackException: Transaction set to rollback only
at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:309)
at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:608)
at com.atomikos.icatch.jta.UserTransactionImp.commit(UserTransactionImp.java:168)
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1028)
... 33 more
... Removed 28 stack frames
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG o.s.t.j.JtaTransactionManager: Initiating transaction commit
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.554 T:1 DEBUG atomikos: getCompositeTransaction() returning instance with id be5bc884c64947d2be7bf3ef081f7e5b0000100001
17:50:21.570 T:1 DEBUG o.s.t.j.JtaTransactionManager: Triggering afterCompletion synchronization
17:50:21.570 T:1 DEBUG o.s.t.s.TransactionSynchronizationManager: Clearing transaction synchronization
17:50:21.570 T:1 DEBUG o.s.t.c.s.DirtiesContextTestExecutionListener: After test method: context [[TestContext@15db314 testClass = TestClass, locations = array<String>['classpath*:META-INF/*-context.xml', 'classpath:db-spring.xml'], testInstance = TestClass@89cc5e, testMethod = autoCommitProblem@TestClass, testException = java.lang.reflect.InvocationTargetException]], dirtiesContext [false].
FAILED: autoCommitProblem
org.springframework.transaction.UnexpectedRollbackException: JTA transaction unexpectedly rolled back (maybe due to a timeout); nested exception is javax.transaction.RollbackException: Transaction set to rollback only
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1031)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:709)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:678)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140)
at TestClass.autoCommitProblem(TestClass.java:161)
at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.run(AbstractTestNGSpringContextTests.java:140)
Caused by: javax.transaction.RollbackException: Transaction set to rollback only
at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:309)
at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:608)
at com.atomikos.icatch.jta.UserTransactionImp.commit(UserTransactionImp.java:168)
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1028)
... 33 more
... Removed 28 stack frames
Greg Thoen
Friday, March 27, 2009
Friday, March 27, 2009
Hi Greg,
Thanks for the detailed report!
I made a case out of this - we will look at this ASAP.
Cheers
Thanks for the detailed report!
I made a case out of this - we will look at this ASAP.
Cheers
Guy Pardon 
Friday, March 27, 2009
Friday, March 27, 2009
Hi,
Since I don't have access to any bug/issue created, just wondering if there's any update on this? :)
Thanks,
Greg
Since I don't have access to any bug/issue created, just wondering if there's any update on this? :)
Thanks,
Greg
Greg Thoen
Tuesday, March 31, 2009
Tuesday, March 31, 2009
Great - thanks for the quick turnaround! BTW, I didn't test, but presumably this also happened with PreparedStatements -- was this fixed as well?
Thanks,
Greg
Thanks,
Greg
Greg Thoen
Wednesday, April 01, 2009
Wednesday, April 01, 2009
Other recent topics