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?
