DefaultMessageListenerContainer transacted session race condition if no messages for a while when using shared/cached sessions [SPR-7366]

[spring-projects-issues]

Greg Thoenen opened SPR-7366 and commented

When using a DefaultMessageListenerContainer with transacted sessions, such as that created by the following spring integration bean definition:

<jms:message-driven-channel-adapter id="inboundChannelAdapter"
    destination-resolver="jmsDestinationResolver" destination-name="jms/myqueue"
    connection-factory="jmsQueueConnectionFactory"
    concurrent-consumers="4" max-concurrent-consumers="4" max-messages-per-task="1"
    channel="importProcessChannel" acknowledge="transacted" 
/>

If you receive no messages on the queue for whatever you have your transaction timeout set for your QueueConnectionFactory (it's one hour by default in Weblogic 10.3), you will see messages like this in the logs (as #8267 also seemed to be talking about):

2010-07-01 15:49:21,304 INFO [tid=2242,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.handleListenerSetupFailure():747] Setup of JMS message listener invoker failed for destination 'jms/myqueue' - trying to recover. Cause: Attempt to resume an inactive transaction: BEA1-000598DE4AF4FDE2FECA:error resuming transacted session's internal transaction
weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000598DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.DispatcherAdapter.convertToJMSExceptionAndThrow(DispatcherAdapter.java:110)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:61)
at weblogic.jms.client.JMSSession.receiveMessage(JMSSession.java:870)
at weblogic.jms.client.JMSConsumer.receiveInternal(JMSConsumer.java:644)
at weblogic.jms.client.JMSConsumer.receive(JMSConsumer.java:523)
at weblogic.jms.client.WLConsumerImpl.receive(WLConsumerImpl.java:184)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:405)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:308)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:261)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:982)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:881)
at java.lang.Thread.run(Thread.java:619)
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000598DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.Request.handleThrowable(Request.java:87)
at weblogic.jms.dispatcher.Request.getResult(Request.java:52)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:1124)
at weblogic.messaging.dispatcher.DispatcherImpl.syncRequest(DispatcherImpl.java:184)
at weblogic.messaging.dispatcher.DispatcherImpl.dispatchSyncNoTran(DispatcherImpl.java:287)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:59)
... 10 more
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000598DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.frontend.FESession.transactedException(FESession.java:2062)
at weblogic.jms.frontend.FESession.throwTransactedException(FESession.java:2077)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2178)
at weblogic.jms.frontend.FEConsumer.receive(FEConsumer.java:553)
at weblogic.jms.frontend.FEConsumer.invoke(FEConsumer.java:805)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:961)
... 13 more
Caused by: javax.transaction.InvalidTransactionException: Attempt to resume an inactive transaction: BEA1-000598DE4AF4FDE2FECA
at weblogic.transaction.internal.TransactionManagerImpl.resume(TransactionManagerImpl.java:360)
at weblogic.transaction.internal.ServerTransactionManagerImpl.resume(ServerTransactionManagerImpl.java:376)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2123)
... 16 more
2010-07-01 15:49:21,351 INFO [tid=2242,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.refreshConnectionUntilSuccessful():791] Successfully refreshed JMS Connection
2010-07-01 15:49:21,367 DEBUG [tid=2243,tgn=Pooled Threads] [springframework.jms.support.destination.JndiDestinationResolver.lookup():111] Located object with JNDI name [jms/myqueue]

This will repeat every hour on the hour (or whatever you have your QueueConnectionFactory's transaction timeout set to) if you have no messages on the queue to receive for that hour, which is annoying, but not a big deal. The main problem is that if you happen to receive a message right before the transaction timeout would occur - say, at 59 minutes and 50 seconds - and it takes more than 10 seconds to process the message, the JMS transaction will timeout so the message gets redelivered to another consumer while the first consumer still successfully processes it -- and because XA transactions are not being used, the db work from the first delivery commits before it tries to commit the JMS session [which throws an exception], and the 2nd delivery also succeeds so that you end up successfully processing the message twice. Here's some output demonstrating this, where, for ease of reproducing, I set my QueueConnectionFactory transaction timeout to 5 minutes then purposely put a message on the queue a few seconds before I expected to have an "inactive transaction" message like above. The receiver of the message is just sleeping for a random time b/w 2 and 3 minutes (so, it should be within the transaction timeout of 5 minutes, but the problem is that it gets picked up a few minutes into the transaction [i.e. since the last session commit/rollback]. Note that the "tid=" part in the log lines is the thread id, for help in showing what thread is doing what.

2010-07-01 15:53:33,839 DEBUG [tid=3719,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.doReceiveAndExecute():311] Received message of type [class weblogic.jms.common.ObjectMessageImpl] from consumer [weblogic.jms.client.WLConsumerImpl@23fea4a] of session [weblogic.jms.client.WLSessionImpl@23fe6da]
2010-07-01 15:53:34,198 INFO [tid=3719,tgn=Pooled Threads] [mycompany.Test.receiveFromQueue():132] message received from queue: testmessage1
2010-07-01 15:53:34,198 INFO [tid=3719,tgn=Pooled Threads] [mycompany.Test.receiveFromQueue():137] sleeping
2010-07-01 15:54:32,074 INFO [tid=3798,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.handleListenerSetupFailure():747] Setup of JMS message listener invoker failed for destination 'jms/myqueue' - trying to recover. Cause: Attempt to resume an inactive transaction: BEA1-000B98DE4AF4FDE2FECA:error resuming transacted session's internal transaction
weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000B98DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.DispatcherAdapter.convertToJMSExceptionAndThrow(DispatcherAdapter.java:110)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:61)
at weblogic.jms.client.JMSSession.receiveMessage(JMSSession.java:870)
at weblogic.jms.client.JMSConsumer.receiveInternal(JMSConsumer.java:644)
at weblogic.jms.client.JMSConsumer.receive(JMSConsumer.java:523)
at weblogic.jms.client.WLConsumerImpl.receive(WLConsumerImpl.java:184)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:405)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:308)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:261)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:982)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:881)
at java.lang.Thread.run(Thread.java:619)
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000B98DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.Request.handleThrowable(Request.java:87)
at weblogic.jms.dispatcher.Request.getResult(Request.java:52)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:1124)
at weblogic.messaging.dispatcher.DispatcherImpl.syncRequest(DispatcherImpl.java:184)
at weblogic.messaging.dispatcher.DispatcherImpl.dispatchSyncNoTran(DispatcherImpl.java:287)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:59)
... 10 more
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000B98DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.frontend.FESession.transactedException(FESession.java:2062)
at weblogic.jms.frontend.FESession.throwTransactedException(FESession.java:2077)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2178)
at weblogic.jms.frontend.FEConsumer.receive(FEConsumer.java:553)
at weblogic.jms.frontend.FEConsumer.invoke(FEConsumer.java:805)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:961)
... 13 more
Caused by: javax.transaction.InvalidTransactionException: Attempt to resume an inactive transaction: BEA1-000B98DE4AF4FDE2FECA
at weblogic.transaction.internal.TransactionManagerImpl.resume(TransactionManagerImpl.java:360)
at weblogic.transaction.internal.ServerTransactionManagerImpl.resume(ServerTransactionManagerImpl.java:376)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2123)
... 16 more
2010-07-01 15:54:32,074 INFO [tid=3798,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.refreshConnectionUntilSuccessful():791] Successfully refreshed JMS Connection
2010-07-01 15:54:32,074 DEBUG [tid=3804,tgn=Pooled Threads] [springframework.jms.support.destination.JndiDestinationResolver.lookup():111] Located object with JNDI name [jms/myqueue]
2010-07-01 15:54:47,855 DEBUG [tid=3802,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.handleListenerSetupFailure():739] Setup of JMS message listener invoker failed - already recovered by other invoker
weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000898DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.DispatcherAdapter.convertToJMSExceptionAndThrow(DispatcherAdapter.java:110)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:61)
at weblogic.jms.client.JMSSession.receiveMessage(JMSSession.java:870)
at weblogic.jms.client.JMSConsumer.receiveInternal(JMSConsumer.java:644)
at weblogic.jms.client.JMSConsumer.receive(JMSConsumer.java:523)
at weblogic.jms.client.WLConsumerImpl.receive(WLConsumerImpl.java:184)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:405)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:308)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:261)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:982)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:881)
at java.lang.Thread.run(Thread.java:619)
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000898DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.Request.handleThrowable(Request.java:87)
at weblogic.jms.dispatcher.Request.getResult(Request.java:52)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:1124)
at weblogic.messaging.dispatcher.DispatcherImpl.syncRequest(DispatcherImpl.java:184)
at weblogic.messaging.dispatcher.DispatcherImpl.dispatchSyncNoTran(DispatcherImpl.java:287)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:59)
... 10 more
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000898DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.frontend.FESession.transactedException(FESession.java:2062)
at weblogic.jms.frontend.FESession.throwTransactedException(FESession.java:2077)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2178)
at weblogic.jms.frontend.FEConsumer.receive(FEConsumer.java:553)
at weblogic.jms.frontend.FEConsumer.invoke(FEConsumer.java:805)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:961)
... 13 more
Caused by: javax.transaction.InvalidTransactionException: Attempt to resume an inactive transaction: BEA1-000898DE4AF4FDE2FECA
at weblogic.transaction.internal.TransactionManagerImpl.resume(TransactionManagerImpl.java:360)
at weblogic.transaction.internal.ServerTransactionManagerImpl.resume(ServerTransactionManagerImpl.java:376)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2123)
... 16 more
2010-07-01 15:54:47,871 DEBUG [tid=3805,tgn=Pooled Threads] [springframework.jms.support.destination.JndiDestinationResolver.lookup():111] Located object with JNDI name [jms/myqueue]
2010-07-01 15:54:47,887 DEBUG [tid=3806,tgn=Pooled Threads] [springframework.jms.support.destination.JndiDestinationResolver.lookup():111] Located object with JNDI name [jms/myqueue]
2010-07-01 15:54:47,949 DEBUG [tid=3806,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.doReceiveAndExecute():311] Received message of type [class weblogic.jms.common.ObjectMessageImpl] from consumer [weblogic.jms.client.WLConsumerImpl@38bae4a] of session [weblogic.jms.client.WLSessionImpl@370ffce]
2010-07-01 15:54:47,965 INFO [tid=3806,tgn=Pooled Threads] [mycompany.Test.receiveFromQueue():132] message received from queue: testmessage1
2010-07-01 15:54:47,965 INFO [tid=3806,tgn=Pooled Threads] [mycompany.Test.receiveFromQueue():137] sleeping
2010-07-01 15:56:52,529 INFO [tid=3719,tgn=Pooled Threads] [mycompany.Test.receiveFromQueue():161] Done processing testmessage1
2010-07-01 15:57:16,763 INFO [tid=3806,tgn=Pooled Threads] [mycompany.Test.receiveFromQueue():161] Done processing testmessage1
2010-07-01 15:57:24,139 WARN [tid=3719,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.handleListenerException():646] Execution of JMS message listener failed
weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.DispatcherAdapter.convertToJMSExceptionAndThrow(DispatcherAdapter.java:110)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:61)
at weblogic.jms.client.JMSSession.commit(JMSSession.java:1200)
at weblogic.jms.client.JMSSession.commit(JMSSession.java:1174)
at weblogic.jms.client.WLSessionImpl.commit(WLSessionImpl.java:108)
at org.springframework.jms.support.JmsUtils.commitIfNecessary(JmsUtils.java:217)
at org.springframework.jms.listener.AbstractMessageListenerContainer.commitIfNecessary(AbstractMessageListenerContainer.java:558)
at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:465)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:323)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:261)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:982)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:881)
at java.lang.Thread.run(Thread.java:619)
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.Request.handleThrowable(Request.java:87)
at weblogic.jms.dispatcher.Request.getResult(Request.java:52)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:1124)
at weblogic.messaging.dispatcher.DispatcherImpl.syncRequest(DispatcherImpl.java:184)
at weblogic.messaging.dispatcher.DispatcherImpl.dispatchSyncNoTran(DispatcherImpl.java:287)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:59)
... 11 more
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.frontend.FESession.transactedException(FESession.java:2062)
at weblogic.jms.frontend.FESession.throwTransactedException(FESession.java:2077)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2178)
at weblogic.jms.frontend.FESession.acknowledge(FESession.java:1846)
at weblogic.jms.frontend.FESession.invoke(FESession.java:2923)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:961)
... 14 more
Caused by: javax.transaction.InvalidTransactionException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA
at weblogic.transaction.internal.TransactionManagerImpl.resume(TransactionManagerImpl.java:360)
at weblogic.transaction.internal.ServerTransactionManagerImpl.resume(ServerTransactionManagerImpl.java:376)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2123)
... 17 more
2010-07-01 15:57:24,139 DEBUG [tid=3719,tgn=Pooled Threads] [org.springframework.jms.listener.DefaultMessageListenerContainer.handleListenerSetupFailure():739] Setup of JMS message listener invoker failed - already recovered by other invoker
weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.DispatcherAdapter.convertToJMSExceptionAndThrow(DispatcherAdapter.java:110)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:61)
at weblogic.jms.client.JMSSession.commit(JMSSession.java:1200)
at weblogic.jms.client.JMSSession.commit(JMSSession.java:1174)
at weblogic.jms.client.WLSessionImpl.commit(WLSessionImpl.java:108)
at org.springframework.jms.support.JmsUtils.commitIfNecessary(JmsUtils.java:217)
at org.springframework.jms.listener.AbstractMessageListenerContainer.commitIfNecessary(AbstractMessageListenerContainer.java:558)
at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:465)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:323)
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:261)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:982)
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:881)
at java.lang.Thread.run(Thread.java:619)
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.dispatcher.Request.handleThrowable(Request.java:87)
at weblogic.jms.dispatcher.Request.getResult(Request.java:52)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:1124)
at weblogic.messaging.dispatcher.DispatcherImpl.syncRequest(DispatcherImpl.java:184)
at weblogic.messaging.dispatcher.DispatcherImpl.dispatchSyncNoTran(DispatcherImpl.java:287)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSyncNoTran(DispatcherAdapter.java:59)
... 11 more
Caused by: weblogic.jms.common.TransactionRolledBackException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA:error resuming transacted session's internal transaction
at weblogic.jms.frontend.FESession.transactedException(FESession.java:2062)
at weblogic.jms.frontend.FESession.throwTransactedException(FESession.java:2077)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2178)
at weblogic.jms.frontend.FESession.acknowledge(FESession.java:1846)
at weblogic.jms.frontend.FESession.invoke(FESession.java:2923)
at weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:961)
... 14 more
Caused by: javax.transaction.InvalidTransactionException: Attempt to resume an inactive transaction: BEA1-000998DE4AF4FDE2FECA
at weblogic.transaction.internal.TransactionManagerImpl.resume(TransactionManagerImpl.java:360)
at weblogic.transaction.internal.ServerTransactionManagerImpl.resume(ServerTransactionManagerImpl.java:376)
at weblogic.jms.frontend.FESession.transactedInfect(FESession.java:2123)
... 17 more
2010-07-01 15:57:24,154 DEBUG [tid=3937,tgn=Pooled Threads] [springframework.jms.support.destination.JndiDestinationResolver.lookup():111] Located object with JNDI name [jms/myqueue]

I know that's a lot of detail, but the general idea is that thread id 3719 picked up the message and then slept. About a minute into its sleep, the JMS transactions have timed out and another thread (thread id 3806) creates a new JMS session and picks up the same message. Eventually, both threads get done sleeping and have successfully processed the message and committed to the db. Thread id 3719 then prints out the exception when it tries to then commit the JMS session b/c its transaction timed out.

It appears the root of the problem is the use of the cached JMS session and the lack of periodic commit/rollback on it if no messages are received. According to the JMS spec, the transaction of a JMS session is started when you create the session, commit it, or roll it back. The problem is that if no messages are received, Spring JMS is never calling commit or rollback on the shared/cached session (it only does so after a message is processed, in AbstractMessageListenerContainer.doExecuteListener()). So, if you process a message, then commit/rollback the session, then keep polling to receive messages and keep receiving none, you are using up time in that transaction. When you do eventually get a message in the receive(), if you're close to being an hour [or whatever your timeout is set to] from when you last received a message with that session, you have very little time to process the message before you will timeout the transaction. Since XA is not being used, Spring is doing the logical thing of letting your work [and presumably your db transaction commit] before calling commit on the JMS session. So this consumer will think everything's fine and commit its work, only to find out afterwards that it timed out and someone else did the work too, even though it took well under the transaction timeout to complete its work.

There seem to be a number of ways to fix this. It seems like calling commit or rollback on the shared/cached Session before using its consumer to receive a new message (perhaps in DefaultMessageListenerContainer.invokeListener()) is one way of fixing it, but I'm not sure what other side effects something like this may have (for instance, will calling rollback() on the session cause any client-side cached JMS messages to be returned to the JMS server so that message "pipelining" [as Weblogic calls it] can not be used).

Hopefully this makes sense.

---

Affects: 2.5.6

Issue Links:

• Spring Application getting into hung state while refreshing transacted JMS connection [SPR-7926] #12581 Spring Application getting into hung state while refreshing transacted JMS connection ("is duplicated by")
• Setup of JMS message listener invoker failed for destination when upgrading from 3.0.2 to 3.0.4 [SPR-7478] #12136 Setup of JMS message listener invoker failed for destination when upgrading from 3.0.2 to 3.0.4
• JMS integration with Tibco causes deadlock due to commitIfNecessary in AbstractPollingMessageListenerContainer [SPR-7558] #12215 JMS integration with Tibco causes deadlock due to commitIfNecessary in AbstractPollingMessageListenerContainer

Referenced from: commits b456bc1

[spring-projects-issues]

Juergen Hoeller commented

Interesting, I wasn't aware of that sort of local transaction timeout - we've just encountered that with JTA before. In any case, thanks for the analysis - as of Spring 3.0.4, DefaultMessageListenerContainer triggers a local Session commit even if no message has been received. This should be safe and is also consistent with our use of an external transaction manager (if specified), where we always commit as well - for a similar reason.

This will be available in tonight's 3.0.4 snapshot. Please give it a try and let us know whether it works for you now...

Juergen

[spring-projects-issues]

Igor Mihalik commented

I'm not 100% sure, but after looking at the diff and the code:
https://fisheye.springsource.org/browse/spring-framework/trunk/org.springframework.jms/src/main/java/org/springframework/jms/listener/AbstractPollingMessageListenerContainer.java?r1=3486&r2=3289

I suppose there should be:
commitIfNecessary(sessionToUse, message);

instead of:
commitIfNecessary(session, message);

There's an issue #12136 which might be caused just by this.