Atomikos Forum

We are using Atomikos 3.6.5 in combination with Spring annotation based transactions and this running on Tomcat 6. When the Spring JtaTransactionManager commits it calls commit() on the Atomikos UserTransactionImp. This eventually ends up in CoordinatorImp.terminate(). However the participants_ vector is empty. As a matter of fact, the addParticipant() method is never called on the CoordinatorImp object.

Just to avoid any misunderstanding, am I supposed to see participants when I use Spring transaction annotation? Stepping through the Spring and Atomikos source while debugging the application, I can see the Spring TransactionInterceptor create a transaction, which is done by the correct implementation, i.e. the Atomikos UserTransactionManager. Yet, when Spring does its JDBC stuff, the SQL operation is never registered as a participant in the Atomikos CompositeTransaction and as a result, a commit is never executed.

This leaves us with dangling connections at the end of our business, basically blocking the record for all other applications wanting to access it. The only solution is to stop Tomcat to free up the connection.

Surely there must be something simple that we are overlooking. All help is very much appreciated.

Forgot to add that this is with an XA datasource. Below is the configuration.

Tomcat context.xml
<Resource auth="Container" factory="com.atomikos.tomcat.BeanFactory" maxPoolSize="150" minPoolSize="5" name="jdbc/HORA_XA_Managed" type="com.atomikos.jdbc.AtomikosDataSourceBean" uniqueResourceName="AtomikosDataSourceJDBCOracle.HORA_WS" xaDataSourceClassName="oracle.jdbc.xa.client.OracleXADataSource" xaProperties.URL="..." xaProperties.password="..." xaProperties.user="..."/>

Spring config:

<bean id="atomikosTransactionManager" class="com.atomikos.icatch.jta.J2eeTransactionManager" />

<bean id="atomikosUserTransaction" class="com.atomikos.icatch.jta.UserTransactionImp" />

<bean id="springTxManager" class="org.springframework.transaction.jta.JtaTransactionManager">
    <property name="transactionManager" ref="atomikosTransactionManager" />
    <property name="userTransaction" ref="atomikosUserTransaction" />
</bean>

<tx:annotation-driven transaction-manager="springTxManager" />

What does the tm.out file in INFO mode say?

Hi Guy,
Sorry for the late reply. I have been out of the office for a couple of days.

Below is the tm.out log file in INFO mode.

As you can see the last line is a commit(). However, since no participants are registered, the commit itself does not do anything at all.

Any idea why our JDBC operations are not participating in the Atomikos transaction?

Regards,
Rik

10-06-07 09:56:13,312 [http-8080-2] USING core version: 3.6.5
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.console_file_name = tm.out
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.console_file_count = 1
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.automatic_resource_registration = true
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.client_demarcation = false
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.threaded_2pc = true
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.serial_jta_transactions = true
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.log_base_dir = c:\Tomcat6\logs\Atomikos
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.console_log_level = INFO
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.max_actives = 50
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.checkpoint_interval = 500
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.enable_logging = true
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.output_dir = c:\Tomcat6\logs\Atomikos
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.log_base_name = tmlog
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.console_file_limit = -1
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.max_timeout = 3000000
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.tm_unique_name = 172.16.203.64.tm
10-06-07 09:56:13,312 [http-8080-2] USING java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
10-06-07 09:56:13,312 [http-8080-2] USING java.naming.provider.url = rmi://localhost:1099
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.service = com.atomikos.icatch.standalone.UserTransactionServiceFactory
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.force_shutdown_on_vm_exit = false
10-06-07 09:56:13,312 [http-8080-2] USING com.atomikos.icatch.default_jta_timeout = 3000000
10-06-07 09:56:13,327 [http-8080-2] createCompositeTransaction ( 3000000 ): created new ROOT transaction with id 172.16.203.64.tm0000100001
10-06-07 09:56:13,343 [http-8080-2] AtomikosDataSoureBean 'AtomikosDataSourceJDBCOracle.HORA_WS': getConnection ( null )...
10-06-07 09:56:13,343 [http-8080-2] AtomikosDataSoureBean 'AtomikosDataSourceJDBCOracle.HORA_WS': init...
10-06-07 09:56:13,343 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: calling toString...
10-06-07 09:56:13,343 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: calling toString...
10-06-07 09:56:13,343 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: calling getMetaData...
10-06-07 09:56:13,343 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: close()...
10-06-07 09:56:13,359 [http-8080-2] AtomikosDataSoureBean 'AtomikosDataSourceJDBCOracle.HORA_WS': getConnection ( null )...
10-06-07 09:56:13,359 [http-8080-2] AtomikosDataSoureBean 'AtomikosDataSourceJDBCOracle.HORA_WS': init...
10-06-07 09:56:13,359 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: calling toString...
10-06-07 09:56:13,359 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: calling toString...
10-06-07 09:56:13,359 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: calling getMetaData...
10-06-07 09:56:13,421 [http-8080-2] AtomikosDataSoureBean 'AtomikosDataSourceJDBCOracle.HORA_WS': getConnection ( null )...
10-06-07 09:56:13,421 [http-8080-2] AtomikosDataSoureBean 'AtomikosDataSourceJDBCOracle.HORA_WS': init...
10-06-07 09:56:13,421 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling toString...
10-06-07 09:56:13,421 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling toString...
10-06-07 09:56:13,421 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling getMetaData...
10-06-07 09:56:13,421 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling getDescriptor...
10-06-07 09:56:13,421 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling physicalConnectionWithin...
10-06-07 09:56:13,452 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling putDescriptor...
10-06-07 09:56:13,452 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling physicalConnectionWithin...
10-06-07 09:56:13,452 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling physicalConnectionWithin...
10-06-07 09:56:13,452 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: calling physicalConnectionWithin...
10-06-07 09:56:13,468 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@210a0e: close()...
10-06-07 09:56:13,468 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: calling getMetaData...
10-06-07 09:56:13,889 [http-8080-2] atomikos connection proxy for oracle.jdbc.driver.LogicalConnection@8f7e20: close()...
10-06-07 09:56:13,889 [http-8080-2] commit() done (by application) of transaction 172.16.203.64.tm0000100001

Hi again Guy,
I managed to reduce our scenario to a very simple unit test, which reproduces the problem. As long as I use Spring's DataSourceTransactionManager, my JDBC operation gets enrolled in a transaction and responds to the commit/rollback at the end. As soon as I switch to the Atomikos transaction manager, the JDBC operation no longer takes part in the transaction.

The unit test is quite simple. It consists of a transactionTestDao which updates one single field in one single row in an Oracle table. It gets called from the transactionTestService, which is made transactional by Spring's
@Transactional(propagation = Propagation.REQUIRED, rollbackFor = Exception.class)
annotation.

Below is the Spring configuration for all this:

    <bean id="datasource" class="org.springframework.jdbc.datasource.DriverManagerDataSource">
        <property name="driverClassName" value="oracle.jdbc.driver.OracleDriver" />
        <property name="url" value="jdbc:oracle:thin:@..." />
        <property name="username" value="..." />
        <property name="password" value="..." />
    </bean>

    <bean id="jdbcTemplate" class="org.springframework.jdbc.core.JdbcTemplate">
        <property name="dataSource" ref="datasource" />
    </bean>

    <bean id="transactionTestDao" class="be.admb.transactiontest.persistence.TransactionTestJdbcDao">
        <property name="jdbcTemplate" ref="jdbcTemplate" />
    </bean>

    <bean id="transactionTestService" class="be.admb.transactiontest.service.TransactionTestServiceImpl">
        <property name="transactionTestDao" ref="transactionTestDao" />
    </bean>

    <bean id="atomikosTransactionManager" class="com.atomikos.icatch.jta.J2eeTransactionManager" />

    <bean id="atomikosUserTransaction" class="com.atomikos.icatch.jta.UserTransactionImp" />

    <bean id="springTxManager" class="org.springframework.transaction.jta.JtaTransactionManager">
        <property name="transactionManager" ref="atomikosTransactionManager" />
        <property name="userTransaction" ref="atomikosUserTransaction" />
    </bean>

    <tx:annotation-driven transaction-manager="springTxManager" />


Below is the tm.out in DEBUG:
0-06-07 11:26:58,938 [main] Logfile closed: c:\temp\Atomikos\tmlog-1.log
10-06-07 11:26:58,969 [main] USING core version: 3.6.5
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.console_file_name = tm.out
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.console_file_count = 1
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.automatic_resource_registration = true
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.client_demarcation = false
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.threaded_2pc = true
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.serial_jta_transactions = true
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.log_base_dir = c:\temp\Atomikos
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.console_log_level = DEBUG
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.max_actives = 50
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.checkpoint_interval = 500
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.enable_logging = true
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.output_dir = c:\temp\Atomikos
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.log_base_name = tmlog
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.console_file_limit = -1
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.max_timeout = 3000000
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.tm_unique_name = 172.16.203.64.tm
10-06-07 11:26:58,969 [main] USING java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
10-06-07 11:26:58,969 [main] USING java.naming.provider.url = rmi://localhost:1099
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.service = com.atomikos.icatch.standalone.UserTransactionServiceFactory
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.force_shutdown_on_vm_exit = false
10-06-07 11:26:58,969 [main] USING com.atomikos.icatch.default_jta_timeout = 3000000
10-06-07 11:26:58,969 [main] getCompositeTransaction() returning NULL!
10-06-07 11:26:58,969 [main] getCompositeTransaction() returning NULL!
10-06-07 11:26:58,969 [main] getCompositeTransaction() returning NULL!
10-06-07 11:26:58,984 [main] Coordinator 172.16.203.64.tm0000100001 entering state: ACTIVE
10-06-07 11:26:58,984 [main] Coordinator 172.16.203.64.tm0000100001 entered state: ACTIVE
10-06-07 11:26:58,984 [main] TaskManager: initializing...
10-06-07 11:26:58,984 [main] THREADS: using JDK thread pooling...
10-06-07 11:26:58,984 [main] THREADS: using executor class com.atomikos.icatch.imp.thread.Java15ExecutorFactory$Executor
10-06-07 11:26:58,984 [main] (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@18e4327
10-06-07 11:26:59,000 [main] ThreadFactory: creating new thread: Atomikos:0
10-06-07 11:26:59,000 [main] Creating composite transaction: 172.16.203.64.tm0000100001
10-06-07 11:26:59,000 [main] createCompositeTransaction ( 3000000 ): created new ROOT transaction with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,000 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,000 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] getCompositeTransaction()  returning instance with id 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] commit() done (by application) of transaction 172.16.203.64.tm0000100001
10-06-07 11:26:59,281 [main] Coordinator 172.16.203.64.tm0000100001 entering state: COMMITTING
10-06-07 11:26:59,375 [main] Coordinator 172.16.203.64.tm0000100001 entered state: COMMITTING
10-06-07 11:26:59,375 [main] Coordinator 172.16.203.64.tm0000100001 entering state: TERMINATED
10-06-07 11:26:59,375 [main] Coordinator 172.16.203.64.tm0000100001 : stopping timer...
10-06-07 11:26:59,375 [main] Coordinator 172.16.203.64.tm0000100001 : disposing statehandler TERMINATED...
10-06-07 11:26:59,375 [main] Coordinator 172.16.203.64.tm0000100001 : disposed.
10-06-07 11:26:59,453 [main] Coordinator 172.16.203.64.tm0000100001 entered state: TERMINATED

OK, I finally found the cause of the problem. As a matter of fact, I believe it to be a bug in the Atomikos library when the Spring JDCB template is configured in a certain. Took quite a while to find though...

Hi,

The unit test's config above uses org.springframework.jdbc.datasource.DriverManagerDataSource - so it is no surprise that it does not react to JTA commit/rollback. You would have to use the Atomikos datasource.

The other log shows no statements being created on the Atomikos JDBC connections. That is why there is no participation in commit either. I am not sure what it is that you are doing there, but that explains the lack of participation at least.

Guy,
I agree that the use of the DriverManagerDataSource prevents proper JTA rollback/commit. However, even when I use the AtomikosDataSource I still have the problem. The reason being that there is a flaw in the Atomikos source code which prevents the connection participating in the ongoing transaction. This only happens when the Spring JdbcTemplate is configured in a certain way. When using Spring's DataSourceTransactionManager this problem does not occur, because Spring has neatly catered for this situation.

Regards,
Rik

What 'certain way' are you referring to?

Thanks