Continual Transactiion commit after adding 'transactionManager' to jms backed channel

[PeteTh]

I have JMS backed channel, however I changed the transactionManager attribute so it as follows :-

<int-jms:channel id="ackPublishJMSChannel" queue="ackPublishDestination" 
      	transaction-manager="transactionManager" concurrency="1-10"/>

Our transactionManager is currently (but will become JTA)

    
   <bean class="org.springframework.orm.jpa.JpaTransactionManager" id="transactionManager">
        <property name="entityManagerFactory" ref="entityManagerFactory"/>
    </bean>

    <bean class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean" id="entityManagerFactory">
      ...

This then give a continual loop of the following :-

2013-01-21 18:09:23,098 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
2013-01-21 18:09:23,098 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2013-01-21 18:09:23,098 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13587917630
2013-01-21 18:09:23.098:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:8080
2013-01-21 18:09:23,114 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@3fbf43] for JPA transaction
[INFO] Started Jetty Server
2013-01-21 18:09:23,114 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.transaction.JDBCTransaction - begin
2013-01-21 18:09:23,114 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
[INFO] Starting scanner at interval of 5 seconds.
2013-01-21 18:09:23,145 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.transaction.JDBCTransaction - current autocommit status: true
2013-01-21 18:09:23,145 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.transaction.JDBCTransaction - disabling autocommit
2013-01-21 18:09:23,145 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Not exposing JPA transaction [org.hibernate.ejb.EntityManagerImpl@3fbf43] as JDBC transaction because JpaDialect [org.springframewor
k.orm.jpa.DefaultJpaDialect@1a03325] does not support JDBC Connection retrieval
2013-01-21 18:09:24,160 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
2013-01-21 18:09:24,160 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@3fbf43]
2013-01-21 18:09:24,160 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.transaction.JDBCTransaction - commit
2013-01-21 18:09:24,176 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.transaction.JDBCTransaction - re-enabling autocommit
2013-01-21 18:09:24,176 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.transaction.JDBCTransaction - committed JDBC Connection
2013-01-21 18:09:24,176 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
2013-01-21 18:09:24,176 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2013-01-21 18:09:24,207 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@3fbf43] after transaction
2013-01-21 18:09:24,207 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
2013-01-21 18:09:24,207 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2013-01-21 18:09:24,207 [DefaultMessageListenerContainer-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13587917642
2013-01-21 18:09:24,207 [DefaultMessageListenerContainer-1] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@483946] for JPA transaction

and then repeats forever ...

This is without sending any message thru the application - I'm not sure what is happening or why anything is being committed - nothing's happened.


If I remove the transactionManager from the jms backed channel :-

	<int-jms:channel id="ackPublishJMSChannel" queue="ackPublishDestination" 
     		    concurrency="1-10"/>

then all is fine. Here I assume the default acknowledge="transacted" comes in to play.

This happens using both embedded ActiveMQ JMS and Weblogic JMS.

Also once the continual error occurs, I note that shutdown is not clean

I will try to attach the full log.

[Gary Russell]

The underlying message listener container polls the JMS client with a timeout (default 1 second) - this is so it can respond to things like shutdown signals etc.

When you provide an external transaction manager, you are saying you want to synchronize the JMS transaction with a transaction managed by that manager. Therefore a transaction has to start before we call receive().

Since there was no activity (JDBC), there's nothing to commit, so the commit is a no-op (usually ignored by the driver).

You can reduce the log traffic by increasing the receive-timeout if you want (as long as you can live with a slower response to a container.stop().

[PeteTh]

thanks.

I have added a receive-timeout to the int-jms:channel which has quietened it a little.

Just to understand this more fully:-
- When you say "'a transaction has to start before we call receive()." - what is the receive for ? as this is a message driven consumer (the default for JMS backed channel) so there is no polling.

If I may, I now have a related problem...

I have now configured a
<tx:jta-transaction-manager />

such that org.springframework.transaction.jta.WebLogicJtaTra nsactionManager is used when running under weblogic.

I then added a transaction-manager="transactionManager" attribute to the areas of the application that are using JMS Channels

we have :-
- one area we have a "JMS backed channel" and
- another area we have a paired "int-jms:outbound-channel-adapter" with a "int-jms:message-driven-channel-adapter" using the same destination, so that we can specify an errorChannel

So we're using an XA Transaction even though there's an overhead.

No when I start up weblogic (without any messages being processed) I see :-

<22-Jan-2013 18:37:20 o'clock GMT> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to RUNNING>
<22-Jan-2013 18:37:20 o'clock GMT> <Notice> <WebLogicServer> <BEA-000360> <Server started in RUNNING mode>
2013-01-22 18:38:13,760 [DefaultMessageListenerContainer-1] TRACE org.springframework.transaction.support.TransactionSynchronizationManager - Retrieved value [org.springframework.jms.connection.JmsResourceHolder@576b3d] for key [weblogic.jms.client.J
MSConnectionFactory@1bb4081] bound to thread [DefaultMessageListenerContainer-1]
2013-01-22 18:38:13,760 [DefaultMessageListenerContainer-1] TRACE org.springframework.transaction.jta.WebLogicJtaTransactionManager - Triggering beforeCommit synchronization
2013-01-22 18:38:13,760 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] TRACE org.springframework.transaction.jta.WebLogicJtaTransactionManager - Triggering beforeCommit synchronization
2013-01-22 18:38:13,760 [DefaultMessageListenerContainer-1] TRACE org.springframework.transaction.jta.WebLogicJtaTransactionManager - Triggering beforeCompletion synchronization
2013-01-22 18:38:13,760 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] TRACE org.springframework.transaction.jta.WebLogicJtaTransactionManager - Triggering beforeCompletion synchronization
2013-01-22 18:38:13,760 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] TRACE org.springframework.transaction.support.TransactionSynchronizationManager - Removed value [org.springframework.jms.connection.JmsResourceHolder@141a1
27] for key [weblogic.jms.client.JMSConnectionFactory@1bb4081] from thread [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1]
2013-01-22 18:38:13,760 [DefaultMessageListenerContainer-1] TRACE org.springframework.transaction.support.TransactionSynchronizationManager - Removed value [org.springframework.jms.connection.JmsResourceHolder@576b3d] for key [weblogic.jms.client.JMS
ConnectionFactory@1bb4081] from thread [DefaultMessageListenerContainer-1]
2013-01-22 18:38:13,760 [DefaultMessageListenerContainer-1] DEBUG org.springframework.transaction.jta.WebLogicJtaTransactionManager - Initiating transaction commit
2013-01-22 18:38:13,760 [DefaultMessageListenerContainer-1] TRACE org.springframework.transaction.jta.WebLogicJtaTransactionManager - Triggering afterCompletion synchronization
2013-01-22 18:38:13,791 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] DEBUG org.springframework.transaction.jta.WebLogicJtaTransactionManager - Initiating transaction commit
2013-01-22 18:38:13,791 [DefaultMessageListenerContainer-1] TRACE org.springframework.transaction.support.TransactionSynchronizationManager - Clearing transaction synchronization
2013-01-22 18:38:13,791 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] TRACE org.springframework.transaction.jta.WebLogicJtaTransactionManager - Triggering afterCompletion synchronization
2013-01-22 18:38:13,791 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] TRACE org.springframework.transaction.support.TransactionSynchronizationManager - Clearing transaction synchronization
2013-01-22 18:38:18,791 [DefaultMessageListenerContainer-1] WARN  org.springframework.jms.listener.DefaultMessageListenerContainer - Setup of JMS message listener invoker failed for destination 'NovaJMSModule!Nova_ackPublish_JMSQueue' - trying to rec
over. Cause: JTA transaction already rolled back (probably due to a timeout)
org.springframework.transaction.UnexpectedRollbackException: JTA transaction already rolled back (probably due to a timeout)
        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1008)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:257)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
        at java.lang.Thread.run(Thread.java:662)
2013-01-22 18:38:18,791 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] WARN  org.springframework.jms.listener.DefaultMessageListenerContainer - Setup of JMS message listener invoker failed for destination 'NovaJMSModule!test.q
ueue' - trying to recover. Cause: JTA transaction already rolled back (probably due to a timeout)
org.springframework.transaction.UnexpectedRollbackException: JTA transaction already rolled back (probably due to a timeout)
        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1008)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:257)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
        at java.lang.Thread.run(Thread.java:662)
2013-01-22 18:38:18,822 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-1] INFO  org.springframework.jms.listener.DefaultMessageListenerContainer - Successfully refreshed JMS Connection
2013-01-22 18:38:18,822 [DefaultMessageListenerContainer-1] INFO  org.springframework.jms.listener.DefaultMessageListenerContainer - Successfully refreshed JMS Connection
2013-01-22 18:38:18,822 [DefaultMessageListenerContainer-2] DEBUG org.springframework.transaction.jta.WebLogicJtaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2013-01-22 18:38:18,822 [DefaultMessageListenerContainer-2] TRACE org.springframework.transaction.support.TransactionSynchronizationManager - Initializing transaction synchronization
2013-01-22 18:38:18,822 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-2] DEBUG org.springframework.transaction.jta.WebLogicJtaTransactionManager - Creating new transaction with name [org.springframework.jms.listener.DefaultMessa
geListenerContainer#0]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2013-01-22 18:38:18,822 [org.springframework.jms.listener.DefaultMessageListenerContainer#0-2] TRACE org.springframework.transaction.support.TransactionSynchronizationManager - Initializing transaction synchronization

This keeps re-occuring like my original problem, but now less often I guess due to the receive-timeout delay.

The log has 2 timeouts one for each JMS queue

So I can't understand what the "JTA transaction already rolled back (probably due to a timeout)" is about.

But on top of that, if I now process a message although it goes where it is expected, and is processed asynchronously correctly, it now never seems to commit to databsae.


If I run without weblogic and use embedded ActiveMQ but a local Transaction Manager, that references entityManagerFactory as follows :-

  <bean class="org.springframework.orm.jpa.JpaTransactionManager" id="transactionManager">
	        <property name="entityManagerFactory" ref="entityManagerFactory"/>
	    </bean>

instead of <tx:jta-transaction-manager /> then the database commits.

I'm aware using the JTA Transaction Manager I'm not referencing entityManagerFactory
I'm also don't understand the timeouts.

[Gary Russell]

what is the receive for ? as this is a message driven consume

There's no polling from a Spring Integration perspective, but the underlying JMS API has no concept of "message-driven"; the listener container thread executes Consumer.receive().

With a negative timeout, it will block forever and there is no way to get back control of the thread. So, normally, we call Consumer.receive() with a timeout so we can react to shutdowns etc. When the timeout occurs, if there's no shutdown, we immediately do another receive(). So you get message-driven behavior.

I don't have any info for your WebLogic problem.

[PeteTh]

I managed to solve the timeout issue, the reason was now that I'd increased the receive-timeout to 60000 milleseconds, this was now greater than the transaction time out. So I had to override the default transaction timeout

		 
<bean id="transactionManager" class="org.springframework.transaction.jta.WebLogicJtaTransactionManager">
        <property name="defaultTimeout" value="75"/>
</bean>

For info, I then had to make sure JPA/Hibernate was using correct settings via the jpaProperties on the LocalContainerEntityManagerFactoryBean :-

<prop key="hibernate.transaction.factory_class">org.hibernate.transaction.JTATransactionFactory</prop>
<prop key="hibernate.transaction.manager_lookup_class">org.hibernate.transaction.WeblogicTransactionManagerLookup</prop>

without this the JDBC updates were not getting committed (just the JMS was committing), as Hibernate wasn't taking part in the commit.

All works now for the happy path , I'm now left with an issue, where if a runtime exception occurs, the message goes to the errorChannel on the JMS inbound adapter - which is desired. But if the exception is of a certain type the error flow should continue, but now using JTA/XA it seems that the runtime exception has marked the Transaction as rollbackonly. I have posted this is as new Topic see http://forum.springsource.org/showth...ed-rolbackonly

This does not occur if running outside of JTA/XA and Weblogic.