JBoss JTA, Spring, Hibernate and DB2 outside container or standalone. Rollback ignored by Hibernate
jkafeero Jan 12, 2012 12:04 PMI am having an issue setting up XA for use with Spring and Hibernate.
JBoss TS 4.15.0, Spring 3.0.5, Hibernate 3.5.3, DB2 Universal Driver 3.53.95
Spring Config
<bean id="dataSource" class="org.springframework.jdbc.datasource.DriverManagerDataSource" >
<property name="driverClassName" value="com.ibm.db2.jcc.DB2Driver"/>
<property name="url" value="jdbc:db2://<remote_hostname>/<dbname>"/>
<property name="username" value="<username>" />
<property name="password" value="<password>" />
</bean>
<bean id="sessionFactory" class="org.springframework.orm.hibernate3.LocalSessionFactoryBean" >
<property name="dataSource" ref="dataSource"/>
<property name="mappingResources">
<list>
<value>......hbm.xml</value>
</list>
<property name="hibernateProperties">
<props>
<prop key="hibernate.dialect"> DB2 ...</prop>
<prop key="hibernate.default.schema"> ...schema_name .....</prop>
</props>
</property>
</bean>
<bean id="jbossTransactionManager" class="org.arjuna.ats.internal.jta.transaction.arjunacore.TransactionManagerImple"/>
<bean id="transactionManager" class="org.springframework.transaction.jta.JtaTransactionManager" >
<property name="transactionManager" ref="jbossTransactionManager"/>
<property name="autodetectedUserTransaction" value="false"/>
</bean>
<tx:advice id="txAdvice" transaction-manager="transactionManager">
<tx:attributes>
<tx:method name="methodWithRollback" rollback-for="Exception" />
</tx:attributes>
</tx:advice>
<aop:config proxy-target-class="true">
<aop:pointcut id="txServiceOperation" expression="execution(* <package>..*(..)) "/>
<aop:advisor advice-ref="txAdvice" pointcut-ref="txServiceOperation" />
</aop:config>
<bean id="beanWithMethodWithRollback" class="<classname>" />
Rollback is started but the Hibernate session in the "methodWithRollback" is saved regardless, i.e. the rollback is ignored.
09:42:53,062 DEBUG [main] springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(458) | Finished creating instance of bean 'beanWithMethodWithRollback'
09:42:53,062 DEBUG [main] org.springframework.context.support.AbstractApplicationContext.initLifecycleProcessor(827) | Unable to locate LifecycleProcessor with name 'lifecycleProcessor': using default [org.springframework.context.support.DefaultLifecycleProcessor@6c8e6c8e]
09:42:53,062 DEBUG [main] springframework.beans.factory.support.AbstractBeanFactory.doGetBean(242) | Returning cached instance of singleton bean 'lifecycleProcessor'
09:42:53,078 DEBUG [main] springframework.beans.factory.support.AbstractBeanFactory.doGetBean(242) | Returning cached instance of singleton bean 'anotherClass'
09:42:53,078 DEBUG [main] springframework.beans.factory.support.AbstractBeanFactory.doGetBean(242) | Returning cached instance of singleton bean 'beanWithMethodWithRollback'
09:42:53,094 TRACE [main] internal.jta.transaction.arjunacore.BaseTransaction.getStatus(158) | BaseTransaction.getStatus
09:42:53,094 DEBUG [main] org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(365) | Creating new transaction with name [package...BeanWithMethodWithRollback.methodWithRollback]:
09:42:53,094 TRACE [main] internal.jta.transaction.arjunacore.BaseTransaction.begin(49) | BaseTransaction.begin 09:42:53,094 TRACE [main] ats.internal.arjuna.common.ClassloadingUtility.loadClass(79) | Loading class com.arjuna.ats.arjuna.recovery.ActionStatusService 09:42:53,109 TRACE [main] ats.internal.arjuna.common.ClassloadingUtility.loadClass(79) | Loading class com.arjuna.ats.internal.arjuna.objectstore.ShadowNoFileLockStore 09:42:53,109 TRACE [main] ats.internal.arjuna.objectstore.FileSystemStore.createHierarchy(623) | FileSystemStore.createHierarchy(PutObjectStoreDirHere\ShadowNoFileLockStore\defaultStore\) 09:42:53,141 INFO [main] arjuna.ats.arjuna.recovery.TransactionStatusManager.addService(87) | ARJUNA12163: Starting service com.arjuna.ats.arjuna.recovery.ActionStatusService on port 1934 09:42:53,156 TRACE [main] ats.internal.arjuna.common.ClassloadingUtility.loadClass(79) | Loading class com.arjuna.ats.internal.arjuna.utils.SocketProcessId 09:42:53,156 INFO [main] ats.internal.arjuna.recovery.TransactionStatusManagerItem.<init>(326) | ARJUNA12337: TransactionStatusManagerItem host: 127.0.0.1 port: 1934 09:42:53,156 TRACE [main] arjuna.ats.arjuna.state.OutputObjectState.<init>(60) | OutputObjectState::OutputObjectState()
09:42:53,172 TRACE [main] ats.internal.arjuna.common.ClassloadingUtility.loadClass(79) | Loading class com.arjuna.ats.internal.arjuna.objectstore.ShadowNoFileLockStore 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.FileSystemStore.createHierarchy(623) | FileSystemStore.createHierarchy(---pathname---\ObjectStore\ShadowNoFileLockStore\defaultStore\) 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.FileSystemStore.write_committed(131) | FileSystemStore.write_committed(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager) 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.ShadowingStore.write_state(536) | ShadowingStore.write_state(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, StateType.OS_ORIGINAL) 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.ShadowingStore.genPathName(342) | ShadowingStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, StateType.OS_ORIGINAL) 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.FileSystemStore.genPathName(544) | FileSystemStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, 11) 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.FileSystemStore.openAndLock(356) | FileSystemStore.openAndLock(---pathename----\ShadowNoFileLockStore\defaultStore\Recovery\TransactionStatusManager\0_ffff071c8026_78f_4f0d9fed_0, FileLock.F_WRLCK, true) 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.FileSystemStore.createHierarchy(623) | FileSystemStore.createHierarchy(---pathename---\ShadowNoFileLockStore\defaultStore\Recovery\TransactionStatusManager\0_ffff071c8026_78f_4f0d9fed_0) 09:42:53,172 TRACE [main] ats.internal.arjuna.objectstore.FileSystemStore.closeAndUnlock(333) | FileSystemStore.closeAndUnlock(---pathaname---\ObjectStore\ShadowNoFileLockStore\defaultStore\Recovery\TransactionStatusManager\0_ffff071c8026_78f_4f0d9fed_0, null, java.io.FileOutputStream@37d837d8) 09:42:53,172 INFO [main] arjuna.ats.arjuna.recovery.TransactionStatusManager.start(137) | ARJUNA12170: TransactionStatusManager started on port 1934 and host 127.0.0.1 with service com.arjuna.ats.arjuna.recovery.ActionStatusService 09:42:53,172 TRACE [main] com.arjuna.ats.arjuna.StateManager.<init>(832) | StateManager::StateManager( 2, 0 )
09:42:53,172 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.<init>(68) | BasicAction::BasicAction() 09:42:53,172 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.Begin(1339) | BasicAction::Begin() for action-id 0:ffff071c8026:78f:4f0d9fed:2 09:42:53,172 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.actionInitialise(3345) | BasicAction::actionInitialise() for action-id 0:ffff071c8026:78f:4f0d9fed:2 09:42:53,172 TRACE [main] arjuna.ats.arjuna.coordinator.ActionHierarchy.<init>(65) | ActionHierarchy::ActionHierarchy(5) 09:42:53,172 TRACE [main] arjuna.ats.arjuna.coordinator.ActionHierarchy.add(210) | ActionHierarchy::add(0:ffff071c8026:78f:4f0d9fed:2, 1) 09:42:53,172 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.addChildThread(579) | BasicAction::addChildThread () action 0:ffff071c8026:78f:4f0d9fed:2 adding Thread[main,5,main] 09:42:53,187 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.addChildThread(606) | BasicAction::addChildThread () action 0:ffff071c8026:78f:4f0d9fed:2 adding Thread[main,5,main] result = true 09:42:53,187 TRACE [main] arjuna.ats.arjuna.coordinator.TransactionReaper.instantiate(805) | TransactionReaper::instantiate() 09:42:53,187 TRACE [main] arjuna.ats.arjuna.coordinator.TransactionReaper.<init>(68) | TransactionReaper::TransactionReaper ( 9223372036854775807 ) 09:42:53,187 TRACE [Transaction Reaper] ats.internal.arjuna.coordinator.ReaperThread.run(62) | ReaperThread.run () 09:42:53,187 TRACE [Transaction Reaper Worker 0] ats.internal.arjuna.coordinator.ReaperWorkerThread.run(54) | ReaperWorkerThread.run () 09:42:53,187 TRACE [Transaction Reaper] ats.internal.arjuna.coordinator.ReaperThread.run(88) | Thread Thread[Transaction Reaper,5,main] sleeping for 9223370710561802620
09:42:53,187 TRACE [Transaction Reaper Worker 0] ats.internal.arjuna.coordinator.ReaperWorkerThread.run(63) | Thread Thread[Transaction Reaper Worker 0,5,main] waiting for cancelled TXs
09:42:53,187 TRACE [main] arjuna.ats.arjuna.coordinator.TransactionReaper.insert(509) | TransactionReaper::insert ( BasicAction: 0:ffff071c8026:78f:4f0d9fed:2 status: ActionStatus.RUNNING, 60 )
09:42:53,187 TRACE [main] ats.internal.arjuna.coordinator.ReaperElement.<init>(51) | ReaperElement::ReaperElement ( BasicAction: 0:ffff071c8026:78f:4f0d9fed:2 status: ActionStatus.RUNNING, 60 )
09:42:53,187 TRACE [Transaction Reaper] ats.internal.arjuna.coordinator.ReaperThread.run(104) | ReaperThread.run ()
09:42:53,187 TRACE [Transaction Reaper] arjuna.ats.arjuna.coordinator.TransactionReaper.check(112) | TransactionReaper::check ()
09:42:53,187 TRACE [Transaction Reaper] arjuna.ats.arjuna.coordinator.TransactionReaper.check(123) | TransactionReaper::check - comparing 1326293033187
09:42:53,187 TRACE [Transaction Reaper] ats.internal.arjuna.coordinator.ReaperThread.run(88) | Thread Thread[Transaction Reaper,5,main] sleeping for 60000
09:42:53,203 DEBUG [main] org.springframework.orm.hibernate3.SessionFactoryUtils.doGetSession(316) | Opening Hibernate Session
09:42:53,219 DEBUG [main] org.springframework.orm.hibernate3.SessionFactoryUtils.doGetSession(324) | Registering Spring transaction synchronization for new Hibernate Session
09:42:53,250 DEBUG [main] org.springframework.jdbc.datasource.DriverManagerDataSource.getConnectionFromDriver(162) | Creating new JDBC DriverManager Connection to [jdbc:db2://<remote_hostname>:<portnumber>/<database-name>]
Hibernate:
insert
into
SCHEMA.TABLE (ID, CREATED_BY, CREATED_DATE, LAST_MODIFIED_BY, LAST_MODIFIED_DATE, NAME)
values
(default, ?, ?, ?, ?, ?)
09:42:53,359 DEBUG [main] org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(843) | Initiating transaction rollback 09:42:53,359 TRACE [main] internal.jta.transaction.arjunacore.BaseTransaction.getStatus(158) | BaseTransaction.getStatus 09:42:53,359 TRACE [main] internal.jta.transaction.arjunacore.TransactionImple.getStatus(317) | TransactionImple.getStatus 09:42:53,359 TRACE [main] internal.jta.transaction.arjunacore.BaseTransaction.rollback(126) | BaseTransaction.rollback 09:42:53,359 TRACE [main] internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(1226) | TransactionImple.rollbackAndDisassociate 09:42:53,359 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.Abort(1571) | BasicAction::Abort() for action-id 0:ffff071c8026:78f:4f0d9fed:2 09:42:53,359 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.removeChildThread(638) | BasicAction::removeChildThread () action 0:ffff071c8026:78f:4f0d9fed:2 removing TSThread:1 09:42:53,359 TRACE [main] arjuna.ats.arjuna.coordinator.BasicAction.removeChildThread(661) | BasicAction::removeChildThread () action 0:ffff071c8026:78f:4f0d9fed:2 removing TSThread:1 result = true 09:42:53,359 TRACE [main] arjuna.ats.arjuna.coordinator.TransactionReaper.remove(562) | TransactionReaper::remove ( BasicAction: 0:ffff071c8026:78f:4f0d9fed:2 status: ActionStatus.ABORTED ) 09:42:53,359 DEBUG [main] org.springframework.orm.hibernate3.SessionFactoryUtils.closeSession(789) | Closing Hibernate Session
09:42:53,375 DEBUG [Listener:1934] ats.internal.arjuna.recovery.Listener.run(151) | Recovery listener existing com.arjuna.ats.arjuna.recovery.ActionStatusService
09:42:53,375 TRACE [Thread-6] ats.internal.arjuna.objectstore.FileSystemStore.remove_committed(113) | FileSystemStore.remove_committed(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager)
09:42:53,375 TRACE [Thread-6] ats.internal.arjuna.objectstore.ShadowingStore.remove_state(454) | ShadowingStore.remove_state(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, StateType.OS_ORIGINAL)
09:42:53,375 TRACE [Thread-6] ats.internal.arjuna.objectstore.ShadowingStore.genPathName(342) | ShadowingStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, StateType.OS_SHADOW)
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.FileSystemStore.genPathName(544) | FileSystemStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, 10)
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.ShadowingStore.genPathName(342) | ShadowingStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, StateType.OS_ORIGINAL)
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.FileSystemStore.genPathName(544) | FileSystemStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, 11)
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.ShadowingStore.currentState(110) | ShadowingStore.currentState(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager) - returning StateStatus.OS_COMMITTED
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.ShadowingStore.genPathName(342) | ShadowingStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, StateType.OS_ORIGINAL)
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.FileSystemStore.genPathName(544) | FileSystemStore.genPathName(0:ffff071c8026:78f:4f0d9fed:0, /Recovery/TransactionStatusManager, 11)
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.FileSystemStore.openAndLock(356) | FileSystemStore.openAndLock(---pathname---\ObjectStore\ShadowNoFileLockStore\defaultStore\Recovery\TransactionStatusManager\0_ffff071c8026_78f_4f0d9fed_0, FileLock.F_WRLCK, false)
09:42:53,391 TRACE [Thread-6] ats.internal.arjuna.objectstore.FileSystemStore.closeAndUnlock(333) | FileSystemStore.closeAndUnlock(---pathname---\ObjectStore\ShadowNoFileLockStore\defaultStore\Recovery\TransactionStatusManager\0_ffff071c8026_78f_4f0d9fed_0, null, null)