MessageInflowLocalProxy retains previous transaction

[girish_n]

We are using WM Broker as JMS provider with JBoss Application Server (jboss-eap-5.1).

We are using container managed MDB that is deployed in JBoss.

While JBoss receives messages from Broker we get Exception:

2012-08-16 08:50:23,197 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (WorkManager(2)-4) [com.arjuna.ats.internal.jta.resources.arjunacore.opcerror] [com.arjuna.ats.internal.jta.resources.arjunacore.opcerror] XAResourceRecord.commit_one_phase caught: java.util.ConcurrentModificationException

2012-08-16 08:50:23,197 SEVERE [com.sun.genericjmsra] (WorkManager(2)-4) After delivery failed javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Could not commit transaction.

javax.resource.ResourceException: javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Could not commit transaction.

          at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:263)

          at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140)

          at $Proxy120.afterDelivery(Unknown Source)

          at com.sun.genericra.inbound.async.InboundJmsResource.releaseEndpoint(InboundJmsResource.java:157)

          at com.sun.genericra.inbound.async.WorkImpl.run(WorkImpl.java:59)

          at org.jboss.resource.work.WorkWrapper.execute(WorkWrapper.java:205)

          at org.jboss.util.threadpool.BasicTaskWrapper.run(BasicTaskWrapper.java:260)

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

          at java.lang.Thread.run(Thread.java:679)

Caused by: javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Could not commit transaction.

          at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1443)

          at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)

          at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

          at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:464)

          at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:343)

          at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:259)

          ... 9 more

I did some investigation and found that New Transaction is not created ( if there is a Transaction already) always in MessageInflowLocalProxy.

Traces from JBoss server logs:

Success case:

2012-08-16 10:50:47,219 INFO  [com.sun.genericjmsra] (WorkManager(2)-36) Creating message endpoint : com.webmethods.jms.loadbalance.connection.WmClusterXAQueueSessionImpl[com.webmethods.jms.impl.WmXASessionImpl[state=started transacted=true acknowledgeMode=Session-Transacted messageConsumerCount=0 messageProducerCount=0]com.webmethods.jms.impl.WmXASessionImpl[state=started transacted=true acknowledgeMode=Session-Transacted messageConsumerCount=0 messageProducerCount=0]]

2012-08-16 10:50:47,219 TRACE [org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory] (WorkManager(2)-36) createEndpoint org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory@51b343e9{ resourceAdapter=webm-jmsra.rar, messagingType=interface javax.jms.MessageListener, ejbName=TestMDB, activationConfig=[ActivationConfigProperty(ReconnectInterval=60), ActivationConfigProperty(DestinationType=javax.jms.Queue), ActivationConfigProperty(ReconnectAttempts=5), ActivationConfigProperty(RedeliveryAttempts=5), ActivationConfigProperty(ConnectionFactoryJndiName=grip-qcf), ActivationConfigProperty(RedeliveryInterval=30), ActivationConfigProperty(DestinationJndiName=ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue), ActivationConfigProperty(SupportsXA=TRUE)], activationSpec=com.sun.genericra.inbound.ActivationSpec@7ca58b69{ConnectionFactoryClassName = com.webmethods.jms.impl.WmConnectionFactoryImpl},{QueueConnectionFactoryClassName = com.webmethods.jms.impl.WmQueueConnectionFactoryImpl},{TopicConnectionFactoryClassName = com.webmethods.jms.impl.WmTopicConnectionFactoryImpl},{XAConnectionFactoryClassName = com.webmethods.jms.impl.WmXAConnectionFactoryImpl},{XAQueueConnectionFactoryClassName = com.webmethods.jms.impl.WmXAQueueConnectionFactoryImpl},{XATopicConnectionFactoryClassName = com.webmethods.jms.impl.WmXATopicConnectionFactoryImpl},{QueueClassName = com.webmethods.jms.impl.WmQueueImpl},{TopicClassName = com.webmethods.jms.impl.WmTopicImpl},{UnifiedDestinationClassName = null},{ConnectionFactoryProperties = null},{JndiProperties = java.naming.factory.initial=com.webmethods.jms.naming.WmJmsNamingCtxFactory,java.naming.provider.url=wmjmsnaming://lon-2-a@10.60.29.136:6849,com.webmethods.jms.naming.clientgroup=admin},{ProviderIntegrationMode = jndi},{CommonSetterMethodName = null},{SupportsXA = true},{DeliveryType = null},{RedeliveryInterval = 30},{RedeliveryAttempts = 5},{ClientID = null},{MessageSelector = null},{SubscriptionDurability = Non-Durable},{ConnectionFactoryJNDIName = grip-qcf},{SubscriptionName = null},{DestinationJNDIName = ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue},{DestinationType = javax.jms.Queue},{DeadMessageDestinationType = javax.jms.Destination},{MaxPoolSize = 8},{DestinationProperties = null},{DeadMessageDestinationJndiName = null},{DeadMessageConnectionFactoryJndiName = null},{DeadMessageConnectionFactoryProperties = null},{DeadMessageDestinationClassName = null},{DeadMessageDestinationProperties = null},{SendBadMessagesToDMD = false},{EndpointReleaseTimeOut = 180},{InstanceCount = 1},{LoadBalancingRequired = true},{Instance ID = 0},{CustomLoadBalancingMessageSelector = },{ShareClientID = false}{DeliveryType = null}} xaResource=com.sun.genericra.inbound.InboundXAResourceProxy@95fe6d2

2012-08-16 10:50:47,219 TRACE [org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory] (WorkManager(2)-36) Created endpoint jboss.j2ee:jar=jboss-seam-testmdb.jar,name=TestMDB,service=EJB3 from org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory@51b343e9{ resourceAdapter=webm-jmsra.rar, messagingType=interface javax.jms.MessageListener, ejbName=TestMDB, activationConfig=[ActivationConfigProperty(ReconnectInterval=60), ActivationConfigProperty(DestinationType=javax.jms.Queue), ActivationConfigProperty(ReconnectAttempts=5), ActivationConfigProperty(RedeliveryAttempts=5), ActivationConfigProperty(ConnectionFactoryJndiName=grip-qcf), ActivationConfigProperty(RedeliveryInterval=30), ActivationConfigProperty(DestinationJndiName=ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue), ActivationConfigProperty(SupportsXA=TRUE)], activationSpec=com.sun.genericra.inbound.ActivationSpec@7ca58b69{ConnectionFactoryClassName = com.webmethods.jms.impl.WmConnectionFactoryImpl},{QueueConnectionFactoryClassName = com.webmethods.jms.impl.WmQueueConnectionFactoryImpl},{TopicConnectionFactoryClassName = com.webmethods.jms.impl.WmTopicConnectionFactoryImpl},{XAConnectionFactoryClassName = com.webmethods.jms.impl.WmXAConnectionFactoryImpl},{XAQueueConnectionFactoryClassName = com.webmethods.jms.impl.WmXAQueueConnectionFactoryImpl},{XATopicConnectionFactoryClassName = com.webmethods.jms.impl.WmXATopicConnectionFactoryImpl},{QueueClassName = com.webmethods.jms.impl.WmQueueImpl},{TopicClassName = com.webmethods.jms.impl.WmTopicImpl},{UnifiedDestinationClassName = null},{ConnectionFactoryProperties = null},{JndiProperties = java.naming.factory.initial=com.webmethods.jms.naming.WmJmsNamingCtxFactory,java.naming.provider.url=wmjmsnaming://lon-2-a@10.60.29.136:6849,com.webmethods.jms.naming.clientgroup=admin},{ProviderIntegrationMode = jndi},{CommonSetterMethodName = null},{SupportsXA = true},{DeliveryType = null},{RedeliveryInterval = 30},{RedeliveryAttempts = 5},{ClientID = null},{MessageSelector = null},{SubscriptionDurability = Non-Durable},{ConnectionFactoryJNDIName = grip-qcf},{SubscriptionName = null},{DestinationJNDIName = ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue},{DestinationType = javax.jms.Queue},{DeadMessageDestinationType = javax.jms.Destination},{MaxPoolSize = 8},{DestinationProperties = null},{DeadMessageDestinationJndiName = null},{DeadMessageConnectionFactoryJndiName = null},{DeadMessageConnectionFactoryProperties = null},{DeadMessageDestinationClassName = null},{DeadMessageDestinationProperties = null},{SendBadMessagesToDMD = false},{EndpointReleaseTimeOut = 180},{InstanceCount = 1},{LoadBalancingRequired = true},{Instance ID = 0},{CustomLoadBalancingMessageSelector = },{ShareClientID = false}{DeliveryType = null}}

2012-08-16 10:50:47,220 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-36) MessageEndpoint TestMDB in use by public abstract void javax.resource.spi.endpoint.MessageEndpoint.beforeDelivery(java.lang.reflect.Method) throws java.lang.NoSuchMethodException,javax.resource.ResourceException Thread[WorkManager(2)-36,5,JBoss Pooled Threads]

2012-08-16 10:50:47,220 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-36) MessageEndpoint TestMDB before

2012-08-16 10:50:47,220 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-36) MessageEndpoint TestMDB set context classloader to BaseClassLoader@72538db1{vfszip:/home/gina/jboss-eap-5.1/jboss-as/server/default/deploy/jboss-seam-testmdb.jar/}

2012-08-16 10:50:47,220 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-36) MessageEndpoint TestMDB beforeDelivery method=public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message) xaResource=com.sun.genericra.inbound.InboundXAResourceProxy@95fe6d2 transacted=true

2012-08-16 10:50:47,220 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-36) MessageEndpoint TestMDB beforeDelivery currentTx=null

2012-08-16 10:50:47,220 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-36) MessageEndpoint TestMDB started transaction=TransactionImple < ac, BasicAction: a3c1d88:a8b5:502c82c5:722 status: ActionStatus.RUNNING >

2012-08-16 10:50:47,220 INFO  [com.sun.genericjmsra] (WorkManager(2)-36) InboundXAResourceProxy::start: setting xid 613363316438383A613862353A35303263383263353A373233312D613363316438383A613862353A35303263383263353A373232

2012-08-16 10:50:47,220 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-36) MessageEndpoint TestMDB enlisted=com.sun.genericra.inbound.InboundXAResourceProxy@95fe6d2

2012-08-16 10:50:47,220 INFO  [com.sun.genericjmsra] (WorkManager(2)-36) Created endpoint :

Failure case:

2012-08-16 10:50:47,233 INFO  [com.sun.genericjmsra] (WorkManager(2)-40) Creating message endpoint : com.webmethods.jms.loadbalance.connection.WmClusterXAQueueSessionImpl[com.webmethods.jms.impl.WmXASessionImpl[state=started transacted=true acknowledgeMode=Session-Transacted messageConsumerCount=0 messageProducerCount=0]com.webmethods.jms.impl.WmXASessionImpl[state=started transacted=true acknowledgeMode=Session-Transacted messageConsumerCount=0 messageProducerCount=0]]

2012-08-16 10:50:47,233 TRACE [org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory] (WorkManager(2)-40) createEndpoint org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory@51b343e9{ resourceAdapter=webm-jmsra.rar, messagingType=interface javax.jms.MessageListener, ejbName=TestMDB, activationConfig=[ActivationConfigProperty(ReconnectInterval=60), ActivationConfigProperty(DestinationType=javax.jms.Queue), ActivationConfigProperty(ReconnectAttempts=5), ActivationConfigProperty(RedeliveryAttempts=5), ActivationConfigProperty(ConnectionFactoryJndiName=grip-qcf), ActivationConfigProperty(RedeliveryInterval=30), ActivationConfigProperty(DestinationJndiName=ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue), ActivationConfigProperty(SupportsXA=TRUE)], activationSpec=com.sun.genericra.inbound.ActivationSpec@7ca58b69{ConnectionFactoryClassName = com.webmethods.jms.impl.WmConnectionFactoryImpl},{QueueConnectionFactoryClassName = com.webmethods.jms.impl.WmQueueConnectionFactoryImpl},{TopicConnectionFactoryClassName = com.webmethods.jms.impl.WmTopicConnectionFactoryImpl},{XAConnectionFactoryClassName = com.webmethods.jms.impl.WmXAConnectionFactoryImpl},{XAQueueConnectionFactoryClassName = com.webmethods.jms.impl.WmXAQueueConnectionFactoryImpl},{XATopicConnectionFactoryClassName = com.webmethods.jms.impl.WmXATopicConnectionFactoryImpl},{QueueClassName = com.webmethods.jms.impl.WmQueueImpl},{TopicClassName = com.webmethods.jms.impl.WmTopicImpl},{UnifiedDestinationClassName = null},{ConnectionFactoryProperties = null},{JndiProperties = java.naming.factory.initial=com.webmethods.jms.naming.WmJmsNamingCtxFactory,java.naming.provider.url=wmjmsnaming://lon-2-a@10.60.29.136:6849,com.webmethods.jms.naming.clientgroup=admin},{ProviderIntegrationMode = jndi},{CommonSetterMethodName = null},{SupportsXA = true},{DeliveryType = null},{RedeliveryInterval = 30},{RedeliveryAttempts = 5},{ClientID = null},{MessageSelector = null},{SubscriptionDurability = Non-Durable},{ConnectionFactoryJNDIName = grip-qcf},{SubscriptionName = null},{DestinationJNDIName = ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue},{DestinationType = javax.jms.Queue},{DeadMessageDestinationType = javax.jms.Destination},{MaxPoolSize = 8},{DestinationProperties = null},{DeadMessageDestinationJndiName = null},{DeadMessageConnectionFactoryJndiName = null},{DeadMessageConnectionFactoryProperties = null},{DeadMessageDestinationClassName = null},{DeadMessageDestinationProperties = null},{SendBadMessagesToDMD = false},{EndpointReleaseTimeOut = 180},{InstanceCount = 1},{LoadBalancingRequired = true},{Instance ID = 0},{CustomLoadBalancingMessageSelector = },{ShareClientID = false}{DeliveryType = null}} xaResource=com.sun.genericra.inbound.InboundXAResourceProxy@97e2437

2012-08-16 10:50:47,234 TRACE [org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory] (WorkManager(2)-40) Created endpoint jboss.j2ee:jar=jboss-seam-testmdb.jar,name=TestMDB,service=EJB3 from org.jboss.ejb3.mdb.inflow.JBossMessageEndpointFactory@51b343e9{ resourceAdapter=webm-jmsra.rar, messagingType=interface javax.jms.MessageListener, ejbName=TestMDB, activationConfig=[ActivationConfigProperty(ReconnectInterval=60), ActivationConfigProperty(DestinationType=javax.jms.Queue), ActivationConfigProperty(ReconnectAttempts=5), ActivationConfigProperty(RedeliveryAttempts=5), ActivationConfigProperty(ConnectionFactoryJndiName=grip-qcf), ActivationConfigProperty(RedeliveryInterval=30), ActivationConfigProperty(DestinationJndiName=ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue), ActivationConfigProperty(SupportsXA=TRUE)], activationSpec=com.sun.genericra.inbound.ActivationSpec@7ca58b69{ConnectionFactoryClassName = com.webmethods.jms.impl.WmConnectionFactoryImpl},{QueueConnectionFactoryClassName = com.webmethods.jms.impl.WmQueueConnectionFactoryImpl},{TopicConnectionFactoryClassName = com.webmethods.jms.impl.WmTopicConnectionFactoryImpl},{XAConnectionFactoryClassName = com.webmethods.jms.impl.WmXAConnectionFactoryImpl},{XAQueueConnectionFactoryClassName = com.webmethods.jms.impl.WmXAQueueConnectionFactoryImpl},{XATopicConnectionFactoryClassName = com.webmethods.jms.impl.WmXATopicConnectionFactoryImpl},{QueueClassName = com.webmethods.jms.impl.WmQueueImpl},{TopicClassName = com.webmethods.jms.impl.WmTopicImpl},{UnifiedDestinationClassName = null},{ConnectionFactoryProperties = null},{JndiProperties = java.naming.factory.initial=com.webmethods.jms.naming.WmJmsNamingCtxFactory,java.naming.provider.url=wmjmsnaming://lon-2-a@10.60.29.136:6849,com.webmethods.jms.naming.clientgroup=admin},{ProviderIntegrationMode = jndi},{CommonSetterMethodName = null},{SupportsXA = true},{DeliveryType = null},{RedeliveryInterval = 30},{RedeliveryAttempts = 5},{ClientID = null},{MessageSelector = null},{SubscriptionDurability = Non-Durable},{ConnectionFactoryJNDIName = grip-qcf},{SubscriptionName = null},{DestinationJNDIName = ReferentialsSsdProcessing_MsgConInstrument_ResubmitQueue},{DestinationType = javax.jms.Queue},{DeadMessageDestinationType = javax.jms.Destination},{MaxPoolSize = 8},{DestinationProperties = null},{DeadMessageDestinationJndiName = null},{DeadMessageConnectionFactoryJndiName = null},{DeadMessageConnectionFactoryProperties = null},{DeadMessageDestinationClassName = null},{DeadMessageDestinationProperties = null},{SendBadMessagesToDMD = false},{EndpointReleaseTimeOut = 180},{InstanceCount = 1},{LoadBalancingRequired = true},{Instance ID = 0},{CustomLoadBalancingMessageSelector = },{ShareClientID = false}{DeliveryType = null}}

2012-08-16 10:50:47,234 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-40) MessageEndpoint TestMDB in use by public abstract void javax.resource.spi.endpoint.MessageEndpoint.beforeDelivery(java.lang.reflect.Method) throws java.lang.NoSuchMethodException,javax.resource.ResourceException Thread[WorkManager(2)-40,5,JBoss Pooled Threads]

2012-08-16 10:50:47,234 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-40) MessageEndpoint TestMDB before

2012-08-16 10:50:47,234 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-40) MessageEndpoint TestMDB set context classloader to BaseClassLoader@72538db1{vfszip:/home/gina/jboss-eap-5.1/jboss-as/server/default/deploy/jboss-seam-testmdb.jar/}

2012-08-16 10:50:47,234 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-40) MessageEndpoint TestMDB beforeDelivery method=public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message) xaResource=com.sun.genericra.inbound.InboundXAResourceProxy@97e2437 transacted=true

2012-08-16 10:50:47,235 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-40) MessageEndpoint TestMDB beforeDelivery currentTx=TransactionImple < ac, BasicAction: a3c1d88:a8b5:502c82c5:5a2 status: ActionStatus.COMMITTING >

2012-08-16 10:50:47,235 TRACE [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (WorkManager(2)-40) MessageEndpoint TestMDB transaction=null already active, IGNORED=com.sun.genericra.inbound.InboundXAResourceProxy@97e2437

2012-08-16 10:50:47,235 INFO  [com.sun.genericjmsra] (WorkManager(2)-40) Created endpoint :

Why the above mentioned exception is thrown? Is it related to Traces above?

Found the similar bug fix here https://issues.jboss.org/browse/EJBTHREE-1142?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel is this related?

Attached Server logs.

Let me know if you need any further information.

[tomjenkinson]

Hi Girish,

It could be related, you could try to get involvement from the team that worked on that Jira.

Are you using EAP 5.1.2?

Also, the first message implies you are using XA but with only one resource, is that correct?

Finally, I would recommend you to try to work out where the java.util.ConcurrentModificationException comes from as it appears first in the messages you provided:

2012-08-16 08:50:23,197 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (WorkManager(2)-4) [com.arjuna.ats.internal.jta.resources.arjunacore.opcerror] [com.arjuna.ats.internal.jta.resources.arjunacore.opcerror] XAResourceRecord.commit_one_phase caught: java.util.ConcurrentModificationException

Hope that gives you some ideas where to look into!

Tom

[girish_n]

After investigation found that JBoss throws this exception because of a bug in JMS Provider. No issue in JBoss.