[jboss-jira] [JBoss JIRA] (WFWIP-21) [Artemis 2.x upgrade] Lost message when MDB is resending messages under high load
Justin Bertram (JIRA)
issues at jboss.org
Tue Aug 21 15:35:00 EDT 2018
[ https://issues.jboss.org/browse/WFWIP-21?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13622259#comment-13622259 ]
Justin Bertram edited comment on WFWIP-21 at 8/21/18 3:34 PM:
--------------------------------------------------------------
The test reported that the message {{5dd55392-a548-11e8-9496-001b217d6d93}} was lost:
{noformat}
09:56:47,764 Thread-2 INFO [org.jboss.qa.artemis.test.failover.Lodh5DoubleSendToDbTestCase:901] Lost Message: ID:5dd55392-a548-11e8-9496-001b217d6d93
{noformat}
However, the message does not appear to be lost. Searching the logs for this ID reveals that the message failed to be consumed 10 times and was moved to the DLQ:
{noformat}
WARN [org.apache.activemq.artemis.core.server] (Thread-10 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$5 at 1794a30)) AMQ222149: Message PagedReferenceImpl [position=PagePositionImpl [pageNr=83, messageNr=2, recordID=8102], message=PagedMessageImpl [queueIDs=[52], transactionID=2974, message=LargeServerMessage[messageID=2971,durable=true,userID=93da3726-a548-11e8-98d9-001b217d6d93,priority=4, timestamp=Tue Aug 21 09:46:17 EDT 2018,expiration=0, durable=true, address=jms.queue.InQueue, properties=TypedProperties[inMessageId=ID:5dd55392-a548-11e8-9496-001b217d6d93,__AMQ_CID=81b178d4-a548-11e8-98d9-001b217d6d93,_AMQ_ROUTING_TYPE=1,_AMQ_DUPL_ID=961feb8a-fde8-4131-9243-975744f42d9f1534859086529,_AMQ_LARGE_SIZE=153821]]@1758182812], deliveryTime=null, persistedCount=0, deliveryCount=10, subscription=PageSubscriptionImpl [cursorId=52, queue=QueueImpl[name=jms.queue.InQueue, postOffice=PostOfficeImpl [server=ActiveMQServerImpl::serverUUID=06c0d90a-a548-11e8-870a-0015178e70d2], temp=false]@6fe30d1a, filter = null]] has reached maximum delivery attempts, sending it to Dead Letter Address jms.queue.DLQ from jms.queue.InQueue
{noformat}
It appears the failure was due to a potential bug (NullPointerException) in the test. This stack-trace is reported 10 times:
{noformat}
ERROR [org.apache.activemq.artemis.ra] (Thread-44 (ActiveMQ-client-global-threads)) AMQ154004: Failed to deliver message: javax.ejb.EJBTransactionRolledbackException
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:203)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:364)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:144)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:57)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.messagedriven.MessageDrivenComponentDescription$5$1.processInvocation(MessageDrivenComponentDescription.java:245)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:619)
at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb$$$view1.onMessage(Unknown Source)
at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) [:1.8.0_181]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181]
at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:139)
at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73)
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb$$$endpoint1.onMessage(Unknown Source)
at org.apache.activemq.artemis.ra.inflow.ActiveMQMessageHandler.onMessage(ActiveMQMessageHandler.java:308) [artemis-ra-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1011) [artemis-core-client-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl.access$400(ClientConsumerImpl.java:50) [artemis-core-client-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1134) [artemis-core-client-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:42) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:31) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:66) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_181]
at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
Caused by: java.lang.NullPointerException
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb.processMessageInfo(SimpleMdbToDb.java:98)
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb.onMessage(SimpleMdbToDb.java:59)
at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) [:1.8.0_181]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181]
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:185)
... 48 more
{noformat}
was (Author: jbertram):
The test reported that the message {{5dd55392-a548-11e8-9496-001b217d6d93}} was lost:
{noformat}
09:56:47,764 Thread-2 INFO [org.jboss.qa.artemis.test.failover.Lodh5DoubleSendToDbTestCase:901] Lost Message: ID:5dd55392-a548-11e8-9496-001b217d6d93
{noformat}
However, the message does not appear to be lost. Searching the logs for this ID reveals that the message failed to be consumed 10 times and was moved to the DLQ:
{noformat}
WARN [org.apache.activemq.artemis.core.server] (Thread-10 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$5 at 1794a30)) AMQ222149: Message PagedReferenceImpl [position=PagePositionImpl [pageNr=83, messageNr=2, recordID=8102], message=PagedMessageImpl [queueIDs=[52], transactionID=2974, message=LargeServerMessage[messageID=2971,durable=true,userID=93da3726-a548-11e8-98d9-001b217d6d93,priority=4, timestamp=Tue Aug 21 09:46:17 EDT 2018,expiration=0, durable=true, address=jms.queue.InQueue, properties=TypedProperties[inMessageId=ID:5dd55392-a548-11e8-9496-001b217d6d93,__AMQ_CID=81b178d4-a548-11e8-98d9-001b217d6d93,_AMQ_ROUTING_TYPE=1,_AMQ_DUPL_ID=961feb8a-fde8-4131-9243-975744f42d9f1534859086529,_AMQ_LARGE_SIZE=153821]]@1758182812], deliveryTime=null, persistedCount=0, deliveryCount=10, subscription=PageSubscriptionImpl [cursorId=52, queue=QueueImpl[name=jms.queue.InQueue, postOffice=PostOfficeImpl [server=ActiveMQServerImpl::serverUUID=06c0d90a-a548-11e8-870a-0015178e70d2], temp=false]@6fe30d1a, filter = null]] has reached maximum delivery attempts, sending it to Dead Letter Address jms.queue.DLQ from jms.queue.InQueue
{noformat}
It appears the failure was due to a potential bug in the test. This stack-trace is reported 10 times:
{noformat}
ERROR [org.apache.activemq.artemis.ra] (Thread-44 (ActiveMQ-client-global-threads)) AMQ154004: Failed to deliver message: javax.ejb.EJBTransactionRolledbackException
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:203)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:364)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:144)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:57)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.messagedriven.MessageDrivenComponentDescription$5$1.processInvocation(MessageDrivenComponentDescription.java:245)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:619)
at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb$$$view1.onMessage(Unknown Source)
at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) [:1.8.0_181]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181]
at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:139)
at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73)
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb$$$endpoint1.onMessage(Unknown Source)
at org.apache.activemq.artemis.ra.inflow.ActiveMQMessageHandler.onMessage(ActiveMQMessageHandler.java:308) [artemis-ra-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1011) [artemis-core-client-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl.access$400(ClientConsumerImpl.java:50) [artemis-core-client-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1134) [artemis-core-client-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:42) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:31) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:66) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_181]
at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118) [artemis-commons-2.7.0-SNAPSHOT.jar:2.7.0-SNAPSHOT]
Caused by: java.lang.NullPointerException
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb.processMessageInfo(SimpleMdbToDb.java:98)
at org.jboss.qa.hornetq.apps.mdb.SimpleMdbToDb.onMessage(SimpleMdbToDb.java:59)
at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) [:1.8.0_181]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181]
at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181]
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:185)
... 48 more
{noformat}
> [Artemis 2.x upgrade] Lost message when MDB is resending messages under high load
> ---------------------------------------------------------------------------------
>
> Key: WFWIP-21
> URL: https://issues.jboss.org/browse/WFWIP-21
> Project: WildFly WIP
> Issue Type: Bug
> Components: Artemis
> Reporter: Miroslav Novak
> Assignee: Martyn Taylor
> Priority: Blocker
> Labels: activemq, feature-branch-blocker
>
> Test scenario:
> * Start cluster A of nodes node-1, node-3
> * Start cluster B of nodes node-2, node-4
> * Send messages to queue on node-1
> * Deploy mdbs to servers in cluster A. This mdb reads messages from local queue, sends them to remote queue on cluster B and inserts them into database
> * Deploy mdbs to servers in cluster B. This mdb reads messages from local queue and inserts them into database
> * Cause CPU overload (for 5 min) on server node-2 when mdbs on cluster1 and 2 are processing mesages
> * Restart failed server
> * Let MDBs to process remaining messages
> Pass Criteria: Number of sent message is equal number of records(lines) in database and messages in
> Actual Result:
> Sometimes happens that one record is missing in database which means that one message was not processed be MDB in cluster 2.
> This looks like broker related regression against Artemis 1.5.
> Wildfly: https://github.com/jmesnil/wildfly/tree/WFLY-9407_upgrade_artemis_2.4.0_with_prefix (06c878a313d3cad323889d017e60fd5533204d1a)
> Artemis tag 2.5.0.Final
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the jboss-jira
mailing list