Spring Unit Tests won't roll back when using Atomikos JTA Transaction Manager

Question

We want to use the Atomikos JTA Transaction Manager. We have a unit test which we want to roll back once it completes, thereby leaving the table clean for the next run.

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(locations = {"classpath:spring/appContext-test.xml"})
@TransactionConfiguration(transactionManager = "txManager")
public class InboundEmailDaoTest extends AbstractTransactionalJUnit4SpringContextTests {

    @Autowired
    private InboundEmailDao dao;

    @BeforeTransaction
    public void beforeTransaction() {
        System.out.println("InboundEmailDaoTest: Rows before: " + this.countRowsInTable("myapp.polin2fos_inbound_email"));
    }

    @AfterTransaction
    public void afterTransaction() {
        System.out.println("InboundEmailDaoTest: Rows after: " + this.countRowsInTable("myapp.polin2fos_inbound_email"));
    }

    @Test
    public void when_inserting_then_record_is_created() {

        String subject = "subject here";
        InboundEmail inboundEmail = new InboundEmail();
        inboundEmail.setEmailSubject(subject);
        //More here...
        inboundEmail.setOriginator("originator");
        inboundEmail.setOriginSystem("myapp");
        inboundEmail.setProcessingStatus("RECEIVED");
        inboundEmail.setAttachment("big fat attachment here");
        inboundEmail.setAttachmentFilename("Big fat attachment filename here");

        int rowsBefore  = this.countRowsInTable("myapp.polin2fos_inbound_email");

        System.out.println("Rows before: " + rowsBefore); 
        dao.insert(inboundEmail);

        int rowsAfter  = this.countRowsInTable("myapp.polin2fos_inbound_email");

        System.out.println("Rows after: " + rowsAfter);

        assertTrue((rowsAfter == rowsBefore + 1));
    }

}

When we run with the Spring-bundled JTA transaction manager configged as below

<tx:annotation-driven transaction-manager="txManager"/>
<bean id="txManager" class="org.springframework.jdbc.datasource.DataSourceTransactionManager">
    <property name="dataSource" ref="dataSource"/>
</bean>

... we get:

Running co.myco.myapp.repository.dao.InboundEmailDaoTest

12:02:22.751 INFO  [main][org.springframework.beans.factory.support.DefaultListableBeanFactory] Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@13785d3: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.support.PropertySourcesPlaceholderConfigurer#0,caseTypeDaoImpl,inboundEmailDaoImpl,inboundEmailRepositoryImpl,propertyPlaceholderConfigurer,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0,org.springframework.transaction.interceptor.TransactionInterceptor#0,org.springframework.transaction.config.internalTransactionAdvisor,txManager,dataSource,org.mybatis.spring.mapper.MapperScannerConfigurer#0,sqlSessionFactory,org.springframework.context.annotation.ConfigurationClassPostProcessor$ImportAwareBeanPostProcessor#0,caseTypeMapper,inboundEmailMapper]; root of factory hierarchy
12:02:22.798 INFO  [main][org.springframework.jdbc.datasource.DriverManagerDataSource] Loaded JDBC driver: oracle.jdbc.OracleDriver
InboundEmailDaoTest: Rows before: 0
12:02:23.770 INFO  [main][org.springframework.test.context.transaction.TransactionalTestExecutionListener] Began transaction (1): transaction manager [org.springframework.jdbc.datasource.DataSourceTransactionManager@8e4805]; rollback [true]
Rows before: 0
12:02:23.832 DEBUG [main][com.myco.repository.mybatis.InboundEmailMapper.insert] ooo Using Connection [oracle.jdbc.driver.T4CConnection@44d990]
12:02:23.835 DEBUG [main][com.myco.repository.mybatis.InboundEmailMapper.insert] ==>  Preparing: insert into myapp.polin2fos_inbound_email (EMAIL_SUBJECT, RECEIVED_DATE, ORIGINATOR, ORIGIN_SYSTEM, PROCESSING_STATUS, ATTACHMENT, ATTACHMENT_FILENAME) values (?, sysdate, ?, ?, ?, ?, ?) 
12:02:23.888 DEBUG [main][com.myco.repository.mybatis.InboundEmailMapper.insert] ==> Parameters: subject here(String), originator(String), myapp(String), RECEIVED(String), big fat attachment here(String), Big fat attachment filename here(String)
Rows after: 1
12:02:23.927 INFO  [main][org.springframework.test.context.transaction.TransactionalTestExecutionListener] Rolled back transaction after test execution for test context [[TestContext@1958cc2 testClass = InboundEmailDaoTest, testInstance = co.myco.myapp.repository.dao.InboundEmailDaoTest@14c28db, testMethod = when_inserting_then_record_is_created@InboundEmailDaoTest, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@10e687b testClass = InboundEmailDaoTest, locations = '{classpath:spring/appContext-test.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.springframework.test.context.support.DelegatingSmartContextLoader']]]
InboundEmailDaoTest: Rows after: 0
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.252 sec

But when we run with the Atomikos Transaction Manager configged as follows:

<bean id="txManager" class="org.springframework.transaction.jta.JtaTransactionManager">
    <property name="transactionManager" ref="AtomikosTransactionManager" />
    <property name="userTransaction" ref="AtomikosUserTransaction" />
</bean>

<!-- ATOMIKOS Transaction-Manager-Specific Setup -->
<bean id="AtomikosTransactionManager"
      class="com.atomikos.icatch.jta.UserTransactionManager"
      init-method="init" destroy-method="close">

    <!-- when close is called, should we force
         transactions to terminate or not? -->
    <property name="forceShutdown" value="false" />
</bean>

<bean id="AtomikosUserTransaction"
      class="com.atomikos.icatch.jta.UserTransactionImp">
    <property name="transactionTimeout" value="300" />
</bean>

... we get:

Running co.myco.myapp.repository.dao.InboundEmailDaoTest
12:12:42.267 INFO  [main][org.springframework.beans.factory.support.DefaultListableBeanFactory] Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@13785d3: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.support.PropertySourcesPlaceholderConfigurer#0,caseTypeDaoImpl,inboundEmailDaoImpl,inboundEmailRepositoryImpl,propertyPlaceholderConfigurer,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0,org.springframework.transaction.interceptor.TransactionInterceptor#0,org.springframework.transaction.config.internalTransactionAdvisor,txManager,AtomikosTransactionManager,AtomikosUserTransaction,dataSource,org.mybatis.spring.mapper.MapperScannerConfigurer#0,sqlSessionFactory,org.springframework.context.annotation.ConfigurationClassPostProcessor$ImportAwareBeanPostProcessor#0,caseTypeMapper,inboundEmailMapper]; root of factory hierarchy
12:12:42.310 INFO  [main][org.springframework.jdbc.datasource.DriverManagerDataSource] Loaded JDBC driver: oracle.jdbc.OracleDriver
12:12:42.853 INFO  [main][com.atomikos.logging.LoggerFactory] Using Slf4J for logging.
12:12:42.854 WARN  [main][com.atomikos.icatch.config.UserTransactionServiceImp] No properties path set - looking for transactions.properties in classpath...
12:12:42.855 WARN  [main][com.atomikos.icatch.config.UserTransactionServiceImp] transactions.properties not found - looking for jta.properties in classpath...
12:12:42.855 WARN  [main][com.atomikos.icatch.config.UserTransactionServiceImp] Failed to open transactions properties file - using default values
12:12:42.893 INFO  [main][com.atomikos.persistence.imp.FileLogStream] Starting read of logfile C:\Code\unblocking-workspace-29-05-12\myapp-master\myapp-repository\.\tmlog47.log
12:12:42.893 INFO  [main][com.atomikos.persistence.imp.FileLogStream] Done read of logfile
12:12:42.893 INFO  [main][com.atomikos.persistence.imp.FileLogStream] Logfile closed: C:\Code\unblocking-workspace-29-05-12\myapp-master\myapp-repository\.\tmlog47.log
12:12:42.899 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING core version: 3.8.0
12:12:42.899 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.console_file_name = tm.out
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.console_file_count = 1
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.automatic_resource_registration = true
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.client_demarcation = false
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.threaded_2pc = false
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.serial_jta_transactions = true
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.log_base_dir = .\
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.console_log_level = WARN
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.max_actives = 50
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.checkpoint_interval = 500
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.enable_logging = true
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.output_dir = .\
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.log_base_name = tmlog
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.console_file_limit = -1
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.max_timeout = 300000
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.tm_unique_name = 100.100.100.100.tm
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING java.naming.provider.url = rmi://localhost:1099
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.service = com.atomikos.icatch.standalone.UserTransactionServiceFactory
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.force_shutdown_on_vm_exit = false
12:12:42.900 INFO  [main][com.atomikos.icatch.config.imp.AbstractUserTransactionService] USING com.atomikos.icatch.default_jta_timeout = 10000
12:12:42.906 INFO  [main][org.springframework.transaction.jta.JtaTransactionManager] Using JTA UserTransaction: com.atomikos.icatch.jta.UserTransactionImp@1568654 
12:12:42.906 INFO  [main][org.springframework.transaction.jta.JtaTransactionManager] Using JTA TransactionManager: com.atomikos.icatch.jta.UserTransactionManager@18d30fb
InboundEmailDaoTest: Rows before: 1
12:12:43.149 DEBUG [main][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction() returning NULL!
12:12:43.149 DEBUG [main][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction() returning NULL!
12:12:43.149 DEBUG [main][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction() returning NULL!
12:12:43.165 DEBUG [main][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 100.100.100.100.tm0000100049 entering state: ACTIVE
12:12:43.170 DEBUG [main][com.atomikos.icatch.imp.thread.TaskManager] TaskManager: initializing...
12:12:43.170 INFO  [main][com.atomikos.icatch.imp.thread.TaskManager] THREADS: using JDK thread pooling...
12:12:43.176 DEBUG [main][com.atomikos.icatch.imp.thread.TaskManager] THREADS: using executor class com.atomikos.icatch.imp.thread.Java15ExecutorFactory$Executor
12:12:43.177 DEBUG [main][com.atomikos.icatch.imp.thread.Java15ExecutorFactory] (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@160bf50
12:12:43.177 DEBUG [main][com.atomikos.icatch.imp.thread.ThreadFactory] ThreadFactory: creating new thread: Atomikos:0
12:12:43.178 DEBUG [main][com.atomikos.icatch.imp.TransactionServiceImp] Creating composite transaction: 100.100.100.100.tm0000100049
12:12:43.182 INFO  [main][com.atomikos.icatch.imp.BaseTransactionManager] createCompositeTransaction ( 300000 ): created new ROOT transaction with id 100.100.100.100.tm0000100049
12:12:43.185 INFO  [main][org.springframework.test.context.transaction.TransactionalTestExecutionListener] Began transaction (1): transaction manager [org.springframework.transaction.jta.JtaTransactionManager@ed9f47]; rollback [true]
Rows before: 1
12:12:43.376 DEBUG [main][co.myco.myapp.repository.mybatis.InboundEmailMapper.insert] ooo Using Connection [oracle.jdbc.driver.T4CConnection@96ad7c]
12:12:43.379 DEBUG [main][co.myco.myapp.repository.mybatis.InboundEmailMapper.insert] ==>  Preparing: insert into myapp.polin2fos_inbound_email (EMAIL_SUBJECT, RECEIVED_DATE, ORIGINATOR, ORIGIN_SYSTEM, PROCESSING_STATUS, ATTACHMENT, ATTACHMENT_FILENAME) values (?, sysdate, ?, ?, ?, ?, ?) 
12:12:43.429 DEBUG [main][co.myco.myapp.repository.mybatis.InboundEmailMapper.insert] ==> Parameters: subject here(String), originator(String), myapp(String), RECEIVED(String), big fat attachment here(String), Big fat attachment filename here(String)
12:12:43.494 INFO  [main][org.springframework.beans.factory.xml.XmlBeanDefinitionReader] Loading XML bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml]
12:12:43.529 INFO  [main][org.springframework.jdbc.support.SQLErrorCodesFactory] SQLErrorCodes loaded: [DB2, Derby, H2, HSQL, Informix, MS-SQL, MySQL, Oracle, PostgreSQL, Sybase]
12:12:43.532 DEBUG [main][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 100.100.100.100.tm0000100049
12:12:43.532 DEBUG [main][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 100.100.100.100.tm0000100049
12:12:43.532 DEBUG [main][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 100.100.100.100.tm0000100049
12:12:43.532 DEBUG [main][com.atomikos.icatch.imp.BaseTransactionManager] getCompositeTransaction()  returning instance with id 100.100.100.100.tm0000100049
12:12:43.533 DEBUG [main][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 100.100.100.100.tm0000100049 entering state: ABORTING
12:12:43.534 DEBUG [main][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 100.100.100.100.tm0000100049 entering state: TERMINATED
12:12:43.534 DEBUG [main][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 100.100.100.100.tm0000100049 : stopping timer...
12:12:43.534 DEBUG [main][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 100.100.100.100.tm0000100049 : disposing statehandler TERMINATED...
12:12:43.534 DEBUG [main][com.atomikos.icatch.imp.CoordinatorImp] Coordinator 100.100.100.100.tm0000100049 : disposed.
12:12:43.536 DEBUG [main][com.atomikos.icatch.imp.CompositeTransactionImp] Ignoring error during event callback
java.lang.IllegalStateException: Transaction no longer active
at     com.atomikos.icatch.imp.TxTerminatedStateHandler.rollbackWithStateCheck(TxTerminatedStateHandler.java:106)
at com.atomikos.icatch.imp.CompositeTransactionImp.doRollback(CompositeTransactionImp.java:237)
at com.atomikos.icatch.imp.CompositeTerminatorImp.rollback(CompositeTerminatorImp.java:123)
at com.atomikos.icatch.imp.CompositeTransactionImp.rollback(CompositeTransactionImp.java:346)
at com.atomikos.icatch.imp.CompositeTransactionImp.entered(CompositeTransactionImp.java:373)
at com.atomikos.finitestates.FSMImp.notifyListeners(FSMImp.java:186)
at com.atomikos.finitestates.FSMImp.setState(FSMImp.java:277)
at com.atomikos.icatch.imp.CoordinatorImp.setState(CoordinatorImp.java:429)
at com.atomikos.icatch.imp.CoordinatorImp.setStateHandler(CoordinatorImp.java:286)
at com.atomikos.icatch.imp.CoordinatorStateHandler.rollback(CoordinatorStateHandler.java:764)
at com.atomikos.icatch.imp.ActiveStateHandler.rollback(ActiveStateHandler.java:264)
at com.atomikos.icatch.imp.CoordinatorImp.rollback(CoordinatorImp.java:747)
at com.atomikos.icatch.imp.TransactionStateHandler.rollback(TransactionStateHandler.java:179)
at com.atomikos.icatch.imp.TransactionStateHandler.rollbackWithStateCheck(TransactionStateHandler.java:197)
at com.atomikos.icatch.imp.CompositeTransactionImp.doRollback(CompositeTransactionImp.java:237)
at com.atomikos.icatch.imp.CompositeTerminatorImp.rollback(CompositeTerminatorImp.java:123)
at com.atomikos.icatch.imp.CompositeTransactionImp.rollback(CompositeTransactionImp.java:346)
at com.atomikos.icatch.jta.TransactionImp.rollback(TransactionImp.java:234)
at com.atomikos.icatch.jta.TransactionManagerImp.rollback(TransactionManagerImp.java:524)
at com.atomikos.icatch.jta.UserTransactionImp.rollback(UserTransactionImp.java:141)
at org.springframework.transaction.jta.JtaTransactionManager.doRollback(JtaTransactionManager.java:1037)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:845)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:822)
at org.springframework.test.context.transaction.TransactionalTestExecutionListener$TransactionContext.endTransaction(TransactionalTestExecutionListener.java:518)
at org.springframework.test.context.transaction.TransactionalTestExecutionListener.endTransaction(TransactionalTestExecutionListener.java:292)
at org.springframework.test.context.transaction.TransactionalTestExecutionListener.afterTestMethod(TransactionalTestExecutionListener.java:185)
at org.springframework.test.context.TestContextManager.afterTestMethod(TestContextManager.java:406)
at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:91)
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:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
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:300)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:174)
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:236)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:134)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:113)
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.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:103)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74)
12:12:43.537 INFO  [main][com.atomikos.icatch.imp.CompositeTransactionImp] rollback() done of transaction 100.100.100.100.tm0000100049

In short, it seems Atomikos is ABORTING and TERMINATING our Tx mid flight for no apparent reason. Does anyone have any idea why?

Answer 1

The problem can be in a configuration that is not present in your code snippets.
Datasource should be wrapped into com.atomikos.jdbc.AtomikosDataSourceBean.

If you use Hibernate in your DAO implementation, there are properties that should be set up, like hibernate.transaction.factory_class or hibernate.transaction.manager_lookup_class.

Answer 2

I have a similar set-up and this works for me.

@TransactionConfiguration(transactionManager = "txManager", defaultrollback=true)

You can also set individual @Test methods with @Rollback(true/false)

Depending on what you are calling in your tests you may have to set @Transactional on the class or

@Transactional(propagation=Propagation.REQUIRES_NEW) per transaction @Test method