3 Replies Latest reply on Nov 3, 2010 6:37 AM by ataylor

Message Queue Stalled

joydeep.sarkar Nov 3, 2010 4:31 AM

Hello,

I am running HornetQ in symmetric mode in two servers.

Things were working well untill it started observing NullPointerExceptions. At this point many transactions started getting times out. Few transactions were even marked as zombies.

Also, "Timed out waiting for handler to complete processing" messages are seen.

Now, at some point the message queue is stuck and stopped responding. Though bouncing the servers started the queue, the cause is not clear.

Does anyone have any idea what could be the reason? How to avoid it in the future?

Added the log trace below.

TIA,

Joydeep

2010-11-02 04:44:47,011 ERROR [STDERR] java.lang.NullPointerException
2010-11-02 04:44:47,012 ERROR [STDERR]  at com.getty.mm.metadata.indexing.XMLGenerator.processMessage(XMLGenerator.java:108)
2010-11-02 04:44:47,012 ERROR [STDERR]  at com.getty.mm.metadata.indexing.Grp4XMLGenerator.onMessage(Grp4XMLGenerator.java:39)
2010-11-02 04:44:47,012 ERROR [STDERR]  at sun.reflect.GeneratedMethodAccessor328.invoke(Unknown Source)
2010-11-02 04:44:47,012 ERROR [STDERR]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2010-11-02 04:44:47,012 ERROR [STDERR]  at java.lang.reflect.Method.invoke(Method.java:597)
2010-11-02 04:44:47,012 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeTarget(MethodInvocation.java:122)
2010-11-02 04:44:47,012 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
2010-11-02 04:44:47,012 ERROR [STDERR]  at org.jboss.ejb3.EJBContainerInvocationWrapper.invokeNext(EJBContainerInvocationWrapper.java:69)
2010-11-02 04:44:47,012 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.invoke(InterceptorSequencer.java:73)
2010-11-02 04:44:47,012 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.aroundInvoke(InterceptorSequencer.java:59)
2010-11-02 04:44:47,013 ERROR [STDERR]  at sun.reflect.GeneratedMethodAccessor324.invoke(Unknown Source)
2010-11-02 04:44:47,013 ERROR [STDERR]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2010-11-02 04:44:47,013 ERROR [STDERR]  at java.lang.reflect.Method.invoke(Method.java:597)
2010-11-02 04:44:47,013 ERROR [STDERR]  at org.jboss.aop.advice.PerJoinpointAdvice.invoke(PerJoinpointAdvice.java:174)
2010-11-02 04:44:47,013 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,013 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.fillMethod(InvocationContextInterceptor.java:72)
2010-11-02 04:44:47,013 ERROR [STDERR]  at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_fillMethod_646128166.invoke(InvocationContextInterceptor_z_fillMethod_646128166.java)
2010-11-02 04:44:47,013 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,013 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.setup(InvocationContextInterceptor.java:88)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_setup_646128166.invoke(InvocationContextInterceptor_z_setup_646128166.java)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.ejb3.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:62)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:56)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,014 ERROR [STDERR]  at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:68)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:194)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3AuthenticationInterceptorv2.java:80)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,015 ERROR [STDERR]  at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)
2010-11-02 04:44:47,016 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 04:44:47,016 ERROR [STDERR]  at org.jboss.ejb3.mdb.MessagingContainer.localInvoke(MessagingContainer.java:282)
2010-11-02 04:44:47,016 ERROR [STDERR]  at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.delivery(MessageInflowLocalProxy.java:270)
2010-11-02 04:44:47,016 ERROR [STDERR]  at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140)
2010-11-02 04:44:47,017 ERROR [STDERR]  at $Proxy284.onMessage(Unknown Source)
2010-11-02 04:44:47,017 ERROR [STDERR]  at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:219)
2010-11-02 04:44:47,017 ERROR [STDERR]  at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:767)
2010-11-02 04:44:47,017 ERROR [STDERR]  at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:45)
2010-11-02 04:44:47,017 ERROR [STDERR]  at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:885)
2010-11-02 04:44:47,017 ERROR [STDERR]  at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:96)
2010-11-02 04:44:47,017 ERROR [STDERR]  at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
2010-11-02 04:44:47,017 ERROR [STDERR]  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
2010-11-02 04:44:47,017 ERROR [STDERR]  at java.lang.Thread.run(Thread.java:619)

2010-11-02 05:21:57,949 SEVERE [general] Transaction which began on 2010/11/02 05:19:49:475 has timed out after 2 minutes. Progress message: null
java.lang.Throwable: Transaction has timed out
        at imagenet.system.util.Transaction.<init>(Transaction.java:73)
        at imagenet.system.util.TransactionManager.beginTransaction(TransactionManager.java:56)
        at com.getty.mm.metadata.indexing.XMLGenerator.processMessage(XMLGenerator.java:110)
        at com.getty.mm.metadata.indexing.DefaultXMLGenerator.onMessage(DefaultXMLGenerator.java:40)
        at sun.reflect.GeneratedMethodAccessor326.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeTarget(MethodInvocation.java:122)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
        at org.jboss.ejb3.EJBContainerInvocationWrapper.invokeNext(EJBContainerInvocationWrapper.java:69)
        at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.invoke(InterceptorSequencer.java:73)
        at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.aroundInvoke(InterceptorSequencer.java:59)
        at sun.reflect.GeneratedMethodAccessor324.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.jboss.aop.advice.PerJoinpointAdvice.invoke(PerJoinpointAdvice.java:174)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.fillMethod(InvocationContextInterceptor.java:72)
        at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_fillMethod_646128166.invoke(InvocationContextInterceptor_z_fillMethod_646128166.java)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.setup(InvocationContextInterceptor.java:88)
        at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_setup_646128166.invoke(InvocationContextInterceptor_z_setup_646128166.java)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:62)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:56)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:68)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
        at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:194)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3AuthenticationInterceptorv2.java:80)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)
        at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
        at org.jboss.ejb3.mdb.MessagingContainer.localInvoke(MessagingContainer.java:282)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.delivery(MessageInflowLocalProxy.java:270)
        at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140)
        at $Proxy284.onMessage(Unknown Source)
        at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:219)
        at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:767)
        at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:45)
        at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:885)
        at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:96)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
2010-11-02 05:22:12,450 ERROR [STDERR] java.sql.SQLException: Unable to get connection from pool
2010-11-02 05:22:12,450 ERROR [STDERR]  at imagenet.system.sql.GenericConnectionPool.getConnection(GenericConnectionPool.java:152)
2010-11-02 05:22:12,450 ERROR [STDERR]  at imagenet.system.util.Transaction.lockRows(Transaction.java:353)
2010-11-02 05:22:12,451 ERROR [STDERR]  at imagenet.system.util.TransactionManager.lockRows(TransactionManager.java:107)
2010-11-02 05:22:12,451 ERROR [STDERR]  at com.getty.mm.metadata.indexing.XMLGenerator.processMessage(XMLGenerator.java:119)
2010-11-02 05:22:12,451 ERROR [STDERR]  at com.getty.mm.metadata.indexing.DefaultXMLGenerator.onMessage(DefaultXMLGenerator.java:40)
2010-11-02 05:22:12,451 ERROR [STDERR]  at sun.reflect.GeneratedMethodAccessor326.invoke(Unknown Source)
2010-11-02 05:22:12,451 ERROR [STDERR]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2010-11-02 05:22:12,451 ERROR [STDERR]  at java.lang.reflect.Method.invoke(Method.java:597)
2010-11-02 05:22:12,451 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeTarget(MethodInvocation.java:122)
2010-11-02 05:22:12,451 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
2010-11-02 05:22:12,451 ERROR [STDERR]  at org.jboss.ejb3.EJBContainerInvocationWrapper.invokeNext(EJBContainerInvocationWrapper.java:69)
2010-11-02 05:22:12,451 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.invoke(InterceptorSequencer.java:73)
2010-11-02 05:22:12,451 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.aroundInvoke(InterceptorSequencer.java:59)
2010-11-02 05:22:12,452 ERROR [STDERR]  at sun.reflect.GeneratedMethodAccessor324.invoke(Unknown Source)
2010-11-02 05:22:12,452 ERROR [STDERR]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2010-11-02 05:22:12,452 ERROR [STDERR]  at java.lang.reflect.Method.invoke(Method.java:597)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.aop.advice.PerJoinpointAdvice.invoke(PerJoinpointAdvice.java:174)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.fillMethod(InvocationContextInterceptor.java:72)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_fillMethod_646128166.invoke(InvocationContextInterceptor_z_fillMethod_646128166.java)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.setup(InvocationContextInterceptor.java:88)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_setup_646128166.invoke(InvocationContextInterceptor_z_setup_646128166.java)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,452 ERROR [STDERR]  at org.jboss.ejb3.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:62)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:56)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:68)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:194)
2010-11-02 05:22:12,453 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3AuthenticationInterceptorv2.java:80)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.ejb3.mdb.MessagingContainer.localInvoke(MessagingContainer.java:282)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.delivery(MessageInflowLocalProxy.java:270)
2010-11-02 05:22:12,454 ERROR [STDERR]  at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140)
2010-11-02 05:22:12,455 ERROR [STDERR]  at $Proxy284.onMessage(Unknown Source)
2010-11-02 05:22:12,455 ERROR [STDERR]  at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:219)
2010-11-02 05:22:12,455 ERROR [STDERR]  at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:767)
2010-11-02 05:22:12,455 ERROR [STDERR]  at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:45)
2010-11-02 05:22:12,455 ERROR [STDERR]  at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:885)
2010-11-02 05:22:12,455 ERROR [STDERR]  at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:96)
2010-11-02 05:22:12,455 ERROR [STDERR]  at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
2010-11-02 05:22:12,455 ERROR [STDERR]  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
2010-11-02 05:22:12,455 ERROR [STDERR]  at java.lang.Thread.run(Thread.java:619)
2010-11-02 05:22:12,456 ERROR [STDERR] Caused by: java.lang.IllegalStateException: Transaction which began on 2010/11/02 05:19:54:516 has timed out after 2 minutes. Progress message: null
2010-11-02 05:22:12,456 ERROR [STDERR]  at imagenet.system.util.Transaction.throwExceptionIfExpired(Transaction.java:126)
2010-11-02 05:22:12,456 ERROR [STDERR]  at imagenet.system.util.TransactionManager.getElement(TransactionManager.java:157)
2010-11-02 05:22:12,456 ERROR [STDERR]  at imagenet.system.sql.GenericConnectionPool.getConnection(GenericConnectionPool.java:148)
2010-11-02 05:22:12,456 ERROR [STDERR]  ... 56 more
2010-11-02 05:22:12,456 ERROR [STDERR] Caused by: java.lang.Throwable: Transaction has timed out
2010-11-02 05:22:12,456 ERROR [STDERR]  at imagenet.system.util.Transaction.<init>(Transaction.java:73)
2010-11-02 05:22:12,456 ERROR [STDERR]  at imagenet.system.util.TransactionManager.beginTransaction(TransactionManager.java:56)
2010-11-02 05:22:12,456 ERROR [STDERR]  at com.getty.mm.metadata.indexing.XMLGenerator.processMessage(XMLGenerator.java:110)
2010-11-02 05:22:12,457 ERROR [STDERR]  ... 53 more

2010-11-02 05:27:12,533 WARN  [org.hornetq.core.transaction.impl.ResourceManagerImpl] transaction with xid XidImpl (633958270 bq:97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.49.101 formatID:131075 gtxid:49.45.97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.49.100 timed out
2010-11-02 05:27:12,533 WARN  [org.hornetq.core.transaction.impl.ResourceManagerImpl] transaction with xid XidImpl (1311829434 bq:97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.50.50 formatID:131075 gtxid:49.45.97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.50.49 timed out
2010-11-02 05:27:12,553 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce1d in state  RUN
2010-11-02 05:27:12,553 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce21 in state  RUN
2010-11-02 05:27:12,553 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce25 in state  RUN
2010-11-02 05:27:12,563 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  RUN
2010-11-02 05:27:12,563 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id af084d9:a589:4cac374e:6ce1d invoked while multiple threads active within it.
2010-11-02 05:27:12,575 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action af084d9:a589:4cac374e:6ce1d aborting with 1 threads active!
2010-11-02 05:27:13,063 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce1d in state  CANCEL
2010-11-02 05:27:13,063 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce21 in state  SCHEDULE_CANCEL
2010-11-02 05:27:13,063 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce25 in state  SCHEDULE_CANCEL
2010-11-02 05:27:13,063 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  SCHEDULE_CANCEL
2010-11-02 05:27:13,531 WARN  [org.hornetq.core.transaction.impl.ResourceManagerImpl] transaction with xid XidImpl (1091242899 bq:97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.50.54 formatID:131075 gtxid:49.45.97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.50.53 timed out
2010-11-02 05:27:13,541 WARN  [org.hornetq.core.transaction.impl.ResourceManagerImpl] transaction with xid XidImpl (626930153 bq:97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.50.97 formatID:131075 gtxid:49.45.97.102.48.56.52.100.57.58.97.53.56.57.58.52.99.97.99.51.55.52.101.58.54.99.101.50.57 timed out
2010-11-02 05:27:13,572 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce1d in state  CANCEL_INTERRUPTED
2010-11-02 05:27:13,572 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_6] - TransactionReaper::check worker Thread[Thread-15,5,jboss] not responding to interrupt when cancelling TX af084d9:a589:4cac374e:6ce1d -- worker marked as zombie and TX scheduled for mark-as-rollback
2010-11-02 05:27:13,572 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_11] - TransactionReaper::check failed to mark TX af084d9:a589:4cac374e:6ce1d  as rollback only
2010-11-02 05:27:13,572 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce21 in state  SCHEDULE_CANCEL
2010-11-02 05:27:13,572 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce25 in state  SCHEDULE_CANCEL
2010-11-02 05:27:13,572 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  SCHEDULE_CANCEL
2010-11-02 05:27:13,574 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id af084d9:a589:4cac374e:6ce21 invoked while multiple threads active within it.
2010-11-02 05:27:13,574 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action af084d9:a589:4cac374e:6ce21 aborting with 1 threads active!
2010-11-02 05:27:14,081 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce21 in state  CANCEL
2010-11-02 05:27:14,082 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce25 in state  SCHEDULE_CANCEL
2010-11-02 05:27:14,082 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  SCHEDULE_CANCEL
2010-11-02 05:27:14,595 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce21 in state  CANCEL_INTERRUPTED
2010-11-02 05:27:14,595 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_6] - TransactionReaper::check worker Thread[Thread-40,5,jboss] not responding to interrupt when cancelling TX af084d9:a589:4cac374e:6ce21 -- worker marked as zombie and TX scheduled for mark-as-rollback
2010-11-02 05:27:14,596 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_11] - TransactionReaper::check failed to mark TX af084d9:a589:4cac374e:6ce21  as rollback only
2010-11-02 05:27:14,596 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce25 in state  SCHEDULE_CANCEL
2010-11-02 05:27:14,596 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  SCHEDULE_CANCEL
2010-11-02 05:27:14,598 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id af084d9:a589:4cac374e:6ce25 invoked while multiple threads active within it.
2010-11-02 05:27:14,598 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action af084d9:a589:4cac374e:6ce25 aborting with 1 threads active!
2010-11-02 05:27:15,099 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce25 in state  CANCEL
2010-11-02 05:27:15,100 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  SCHEDULE_CANCEL
2010-11-02 05:27:15,616 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce25 in state  CANCEL_INTERRUPTED
2010-11-02 05:27:15,617 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_6] - TransactionReaper::check worker Thread[Thread-41,5,jboss] not responding to interrupt when cancelling TX af084d9:a589:4cac374e:6ce25 -- worker marked as zombie and TX scheduled for mark-as-rollback
2010-11-02 05:27:15,617 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_11] - TransactionReaper::check failed to mark TX af084d9:a589:4cac374e:6ce25  as rollback only
2010-11-02 05:27:15,617 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  SCHEDULE_CANCEL
2010-11-02 05:27:15,619 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id af084d9:a589:4cac374e:6ce29 invoked while multiple threads active within it.
2010-11-02 05:27:15,620 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action af084d9:a589:4cac374e:6ce29 aborting with 1 threads active!
2010-11-02 05:27:16,120 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  CANCEL
2010-11-02 05:27:16,632 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce29 in state  CANCEL_INTERRUPTED
2010-11-02 05:27:16,633 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_6] - TransactionReaper::check worker Thread[Thread-42,5,jboss] not responding to interrupt when cancelling TX af084d9:a589:4cac374e:6ce29 -- worker marked as zombie and TX scheduled for mark-as-rollback
2010-11-02 05:27:16,633 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_11] - TransactionReaper::check failed to mark TX af084d9:a589:4cac374e:6ce29  as rollback only
2010-11-02 05:27:22,584 WARN  [org.hornetq.core.client.impl.ClientConsumerImpl] Timed out waiting for handler to complete processing
2010-11-02 05:27:23,584 WARN  [org.hornetq.core.client.impl.ClientConsumerImpl] Timed out waiting for handler to complete processing
2010-11-02 05:27:24,617 WARN  [org.hornetq.core.client.impl.ClientConsumerImpl] Timed out waiting for handler to complete processing
2010-11-02 05:27:25,630 WARN  [org.hornetq.core.client.impl.ClientConsumerImpl] Timed out waiting for handler to complete processing
2010-11-02 05:27:27,460 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX af084d9:a589:4cac374e:6ce30 in state  RUN

1. Re: Message Queue Stalled

ataylor Nov 3, 2010 5:26 AM (in response to joydeep.sarkar)

Firstly you havent said what AS/HQ version you are using, also whats your topology, are your HQ servers invm or remote and also what tx management is your ejb using etc etc.

Its hard to know what exactly is going on here, first thing i see is that the exception being thrown is from within your ejb , there also seems to be an sql issue, both of which are not really a HornetQ issue. Lso the Transaction manager timeout seems to be from the imagenet code so cant comment on that.

I would suggest simplifying your code to see if there is a HornetQ issue here or not, theres too much complexity to be able to comment or provide advice.
Actions
2. Re: Message Queue Stalled

joydeep.sarkar Nov 3, 2010 6:30 AM (in response to ataylor)

My apologies...
I am using JBoss5.1.0GA and HornetQ2.0. The servers are deployed in clustered environment.

I posted the NullPointerException and SQLException messages for understanding what took place earlier. What I am more concerned about is the queue getting stalled and the message "2010-11-02 05:27:22,584 WARN [org.hornetq.core.client.impl.ClientConsumerImpl] Timed out waiting for handler to complete processing".
How do I increase the number of handlers? Will the above exceptions cause the queue to be stalled?

Regards,
Joydeep
Actions
3. Re: Message Queue Stalled

ataylor Nov 3, 2010 6:37 AM (in response to joydeep.sarkar)

ok, i think this is whats happening. The tx is being rolled back because of some non HornetQ issue, the transaction manager will call rollback on the session however before we process the rollback we need to wait for the onMessage call to complete. It looks like this isnt happening which poiunts to the onMessage never returning. This would mean that problems could occur when acking or rolling back delivered messages, the queue stalls probably because its waiting for the consumer to finish. I would dump a stack trace and see what is hanging your onMessage.
Actions

Go to original post