Announcement Announcement Module
Collapse
No announcement yet.
Continual Transactiion commit after adding 'transactionManager' to jms backed channel Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

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

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

    Code:
    <int-jms:channel id="ackPublishJMSChannel" queue="ackPublishDestination" 
          	transaction-manager="transactionManager" concurrency="1-10"/>
    Our transactionManager is currently (but will become JTA)

    Code:
        
       <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 :-


    Code:
    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 [email protected]: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 :-

    Code:
    	<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.

  • #2
    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().

    Comment


    • #3
      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 :-

      Code:
      <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 :-

      Code:
        <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.

      Comment


      • #4
        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.

        Comment


        • #5
          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

          Code:
          		 
          <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 :-

          Code:
          <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.
          Last edited by PeteTh; Jan 23rd, 2013, 08:07 AM.

          Comment


          • #6
            Thanks for your explanations Gary. I have a similar problem running transactional jms channels in Glassfish which floods my log with the following message

            Code:
            [2013-08-26T08:13:38.851+1000] [glassfish 4.0] [WARNING] [] [org.springframework.jms.listener.DefaultMessageListenerContainer] [tid: _ThreadID=288 _ThreadName=DefaultMessageListenerContainer-25] [timeMillis: 1377468818851] [levelValue: 900] [[
              Setup of JMS message listener invoker failed for destination 'Oracle GlassFish(tm) Server MQ Destination
            getName():		emailNotificationQueue
            Class:			com.sun.messaging.Queue
            getVERSION():		3.0
            isReadonly():		false
            getProperties():	{imqDestinationName=emailNotificationQueue, imqDestinationDescription=A Description for the Destination Object}' - trying to recover. Cause: Local JMS transaction failed to commit; nested exception is javax.jms.IllegalStateException: MQJMSRA_DS4001: commit():Illegal for a non-transacted Session:sessionId=5453648830806034433]]
            
            [2013-08-26T08:13:38.852+1000] [glassfish 4.0] [INFO] [] [org.springframework.jms.listener.DefaultMessageListenerContainer] [tid: _ThreadID=288 _ThreadName=DefaultMessageListenerContainer-25] [timeMillis: 1377468818852] [levelValue: 800] [[
              Successfully refreshed JMS Connection]]
            To get around the issue for now I have set my logger for org.springframework.jms.listener.DefaultMessageLis tenerContainer to only log [SEVERE] messages which supresses the WARNING and INFO messages above. After I did this then glassfish started logging another warning:

            Code:
            [2013-08-26T08:14:18.210+1000] [glassfish 4.0] [WARNING] [] [javax.jms.Session.mqjmsra] [tid: _ThreadID=302 _ThreadName=org.springframework.jms.listener.DefaultMessageListenerContainer#0-28] [timeMillis: 1377468858210] [levelValue: 900] [[
              MQJMSRA_DS4001: commit():Illegal for a non-transacted Session:sessionId=5453648830817390337]]
            So I suppressed that also by setting the logger for javax.jms.Session.mqjmsra to be [SEVERE]

            Can anyone see any problems with doing this?
            Any better suggestions so my production logs don't end up flooded with these messages in them?
            Last edited by stewartevans; Aug 25th, 2013, 05:54 PM.

            Comment

            Working...
            X