[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:29: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:28 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 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. 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