search

AutoMQ / automq-for-rocketmq

A cloud native implementation for Apache RocketMQ 5.0
https://www.automq.com
196 stars 34 forks source link

Duplicate messages in FIFO queue consumption #625

Open wangxye opened 11 months ago

wangxye commented 11 months ago

Client creates fifo queue in broker and uses pop subscription mode to consume 100 messages, the following occurs:

send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_bnUUzv, tag=tag-server-lySaO6s3Vf8qvhWql8tY, messageGroup=d4898dfc-0ac8-4956-8785-03f7f86779e61, deliveryTimestamp=null, keys=[], properties={}}
2023-11-14 10:52:52 INFO  [o.a.r.u.VerifyUtils           #aitForMessageConsume: 373] Set timeout: 90000ms
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B030000004D, body:77, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:79, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e61}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0300000050, body:80, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:80, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B030000004C, body:76, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:81, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0300000052, body:82, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:82, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B030000004F, body:79, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:83, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e61}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B030000004E, body:78, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:84, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000054, body:84, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:85, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0300000051, body:81, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:86, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e61}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0300000050, body:80, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:87, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000056, body:86, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:88, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0300000053, body:83, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:89, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e61}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0300000052, body:82, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:90, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000055, body:85, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:91, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e61}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000054, body:84, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:92, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000057, body:87, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:93, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e61}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000056, body:86, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:94, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000058, body:88, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:95, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B040000005A, body:90, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:96, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B040000005C, body:92, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:97, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B040000005E, body:94, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:98, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000060, body:96, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:99, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.l.r.RMQNormalListener   #consume             :  85] 49be207c-e64e-48a0-b7bf-a82441f63b73 - MessageId:01664E1A972D66802005647B0400000062, body:98, tag:tag-server-lySaO6s3Vf8qvhWql8tY,  key:[], recvIndex:100, property:{__SHARDINGKEY=d4898dfc-0ac8-4956-8785-03f7f86779e60}, action:SUCCESS
2023-11-14 10:52:52 INFO  [o.a.r.c.r.RMQNormalProducer   #close               : 172] Producer shutdown !!!
2023-11-14 10:53:12 INFO  [o.a.r.c.r.RMQNormalConsumer   #close               : 280] DefaultMQPushConsumer shutdown !!!

org.opentest4j.AssertionFailedError: More retry messages were consumed than expected (including one original message) Except:1, Actual:2, MsgId:01664E1A972D66802005647B0300000050

    at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)
    at org.junit.jupiter.api.Assertions.fail(Assertions.java:117)
    at org.apache.rocketmq.util.VerifyUtils.waitForMessageConsume(VerifyUtils.java:395)
    at org.apache.rocketmq.util.VerifyUtils.verifyOrderMessage(VerifyUtils.java:170)
    at org.apache.rocketmq.broker.server.OrderMessageTest.testOrder_Send_PushConsumeOrderly(OrderMessageTest.java:104)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
    at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:210)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:206)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:131)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:185)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.invokeAll(ForkJoinPoolHierarchicalTestExecutorService.java:129)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:185)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.invokeAll(ForkJoinPoolHierarchicalTestExecutorService.java:129)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:185)
    at java.base/java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:194)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)

2023-11-14 10:53:12 INFO  [o.a.r.f.BaseOperate           #run                 :  56] Shutdown Hook is running !
2023-11-14 10:53:12 INFO  [RocketmqRemoting              #info                : 130] closeChannel: close the connection to remote address[127.0.0.1:8081] result: true

Process finished with exit code 255
wangxye commented 11 months ago

More details found that duplicate messages are in the same message group. According to the contents of the print log, we found that messages with body data of 65, 67 and 70 were repeated twice.

09:40:59.408 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAA00000058, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.409 [RocketmqMessageConsumption-0-78] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBA900000041, body:65, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:66, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.425 [RocketmqMessageConsumption-0-84] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000042, body:66, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:67, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.445 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAA00000059, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.446 [RocketmqMessageConsumption-0-80] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000043, body:67, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:68, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.447 [RocketmqMessageConsumption-0-85] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000044, body:68, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:69, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.551 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB0000005A, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.551 [RocketmqMessageConsumption-0-82] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000046, body:70, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:70, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.568 [RocketmqMessageConsumption-0-70] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000045, body:69, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:71, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.570 [RocketmqMessageConsumption-0-69] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBA900000041, body:65, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:72, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.584 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB0000005B, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.587 [RocketmqMessageConsumption-0-87] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000048, body:72, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:73, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.604 [RocketmqMessageConsumption-0-74] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000047, body:71, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:74, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.621 [RocketmqMessageConsumption-0-72] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000043, body:67, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:75, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.622 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB0000005C, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.640 [RocketmqMessageConsumption-0-76] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004A, body:74, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:76, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.640 [RocketmqMessageConsumption-0-78] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000049, body:73, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:77, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.657 [RocketmqMessageConsumption-0-84] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000045, body:69, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:78, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.673 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB0000005D, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.692 [RocketmqMessageConsumption-0-80] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004C, body:76, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:79, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.709 [RocketmqMessageConsumption-0-85] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004B, body:75, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:80, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.709 [RocketmqMessageConsumption-0-86] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000047, body:71, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:81, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.726 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB0000005E, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.728 [RocketmqMessageConsumption-0-69] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004E, body:78, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:82, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.729 [RocketmqMessageConsumption-0-71] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004D, body:77, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:83, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.747 [RocketmqMessageConsumption-0-74] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000049, body:73, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:84, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.748 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB0000005F, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.766 [RocketmqMessageConsumption-0-75] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000050, body:80, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:85, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:40:59.783 [RocketmqMessageConsumption-0-77] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004F, body:79, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:86, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.800 [RocketmqMessageConsumption-0-76] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004B, body:75, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:87, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.817 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB00000060, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.836 [RocketmqMessageConsumption-0-80] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004D, body:77, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:88, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.853 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB00000061, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.855 [RocketmqMessageConsumption-0-82] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA0000004F, body:79, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:89, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.872 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB00000062, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.889 [RocketmqMessageConsumption-0-85] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000051, body:81, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:90, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.964 [RocketmqMessageConsumption-0-70] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000053, body:83, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:91, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:40:59.984 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 017A4C1BD5194247160565BBAB00000063, MessageGroup: 2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_WfkvKG, tag=tag-server-otbClpL9tLnhSLWv3R7N, messageGroup=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1, deliveryTimestamp=null, keys=[], properties={}}
09:40:59.986 [RocketmqMessageConsumption-0-87] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000052, body:82, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:92, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:41:00.002 [RocketmqMessageConsumption-0-71] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000055, body:85, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:93, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:41:00.005 [main] INFO org.apache.rocketmq.util.VerifyUtils - Set timeout: 90000ms
09:42:25.607 [RocketmqMessageConsumption-0-74] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000054, body:84, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:94, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e0]
09:42:25.607 [RocketmqMessageConsumption-0-72] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message a7f5f98e-9ffd-4bcf-ab43-20158d2d6e77 - MessageId:017A4C1BD5194247160565BBAA00000057, body:87, tag:tag-server-otbClpL9tLnhSLWv3R7N,  key:[], recvIndex:95, property:{__SHARDINGKEY=2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1}, action:SUCCESS, messageGroup:Optional[2a7ba6a4-594e-498f-aa8f-a5cf6b2ebf5e1]
09:42:25.658 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - Producer shutdown !!!
09:42:45.651 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalConsumer - DefaultMQPushConsumer shutdown !!!

org.opentest4j.AssertionFailedError: More retry messages were consumed than expected (including one original message) Except:1, Actual:2, MsgId:017A4C1BD5194247160565BBA900000041

    at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)
    at org.junit.jupiter.api.Assertions.fail(Assertions.java:117)
    at org.apache.rocketmq.util.VerifyUtils.waitForMessageConsume(VerifyUtils.java:395)
    at org.apache.rocketmq.util.VerifyUtils.verifyOrderMessage(VerifyUtils.java:170)
    at org.apache.rocketmq.broker.server.OrderMessageTest.testOrder_Send_PushConsumeOrderly(OrderMessageTest.java:103)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
    at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:210)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:206)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:131)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
    at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
    at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
    at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
    at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)

09:42:45.669 [NettyClientSelector_1] INFO RocketmqRemoting - closeChannel: close the connection to remote address[127.0.0.1:8081] result: true
09:42:45.670 [Thread-2] INFO org.apache.rocketmq.frame.BaseOperate - Shutdown Hook is running !
wangxye commented 11 months ago

Tests show that the queue id and queue offset of duplicate messages are consistent. According to the contents of the print log, messages with message bodies of 56, 58, and 60 are consumed twice, and the queue ID and queue offset of these three are the same in the two consumptions.

10:14:10.303 [RocketmqMessageConsumption-0-82] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37000000038, QueueId:6, QueueOffset:28, body:56, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:57, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.377 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C3720000005A, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.377 [RocketmqMessageConsumption-0-86] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003A, QueueId:6, QueueOffset:29, body:58, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:58, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.380 [RocketmqMessageConsumption-0-85] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37000000039, QueueId:1, QueueOffset:28, body:57, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:59, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.500 [RocketmqMessageConsumption-0-84] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003B, QueueId:1, QueueOffset:29, body:59, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:60, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.500 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C3720000005B, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.500 [RocketmqMessageConsumption-0-87] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003C, QueueId:6, QueueOffset:30, body:60, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:61, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.504 [RocketmqMessageConsumption-0-70] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37000000038, QueueId:6, QueueOffset:28, body:56, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:62, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.504 [RocketmqMessageConsumption-0-71] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003E, QueueId:6, QueueOffset:31, body:62, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:63, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.506 [RocketmqMessageConsumption-0-74] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003D, QueueId:1, QueueOffset:30, body:61, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:64, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.522 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C3720000005C, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.539 [RocketmqMessageConsumption-0-76] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003A, QueueId:6, QueueOffset:29, body:58, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:65, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.556 [RocketmqMessageConsumption-0-77] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003F, QueueId:1, QueueOffset:31, body:63, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:66, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.573 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C3720000005D, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.573 [RocketmqMessageConsumption-0-78] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000040, QueueId:6, QueueOffset:32, body:64, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:67, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.590 [RocketmqMessageConsumption-0-79] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003C, QueueId:6, QueueOffset:30, body:60, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:68, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.592 [RocketmqMessageConsumption-0-86] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000041, QueueId:1, QueueOffset:32, body:65, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:69, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.609 [RocketmqMessageConsumption-0-83] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000042, QueueId:6, QueueOffset:33, body:66, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:70, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.626 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C3720000005E, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.643 [RocketmqMessageConsumption-0-84] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3700000003E, QueueId:6, QueueOffset:31, body:62, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:71, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.660 [RocketmqMessageConsumption-0-87] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000044, QueueId:6, QueueOffset:34, body:68, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:72, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.677 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C3720000005F, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.677 [RocketmqMessageConsumption-0-71] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000043, QueueId:1, QueueOffset:33, body:67, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:73, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.694 [RocketmqMessageConsumption-0-73] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000040, QueueId:6, QueueOffset:32, body:64, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:74, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.696 [RocketmqMessageConsumption-0-76] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000046, QueueId:6, QueueOffset:35, body:70, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:75, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.713 [RocketmqMessageConsumption-0-75] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000045, QueueId:1, QueueOffset:34, body:69, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:76, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.730 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C37200000060, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.765 [RocketmqMessageConsumption-0-78] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000048, QueueId:6, QueueOffset:36, body:72, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:77, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.765 [RocketmqMessageConsumption-0-79] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000042, QueueId:6, QueueOffset:33, body:66, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:78, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.765 [RocketmqMessageConsumption-0-81] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000047, QueueId:1, QueueOffset:35, body:71, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:79, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.766 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C37200000061, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.786 [RocketmqMessageConsumption-0-85] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3710000004A, QueueId:6, QueueOffset:37, body:74, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:80, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.786 [RocketmqMessageConsumption-0-83] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000044, QueueId:6, QueueOffset:34, body:68, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:81, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.787 [RocketmqMessageConsumption-0-87] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000049, QueueId:1, QueueOffset:36, body:73, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:82, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.804 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C37200000062, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.838 [RocketmqMessageConsumption-0-69] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000046, QueueId:6, QueueOffset:35, body:70, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:83, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.838 [RocketmqMessageConsumption-0-73] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3710000004C, QueueId:6, QueueOffset:38, body:76, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:84, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:14:10.838 [RocketmqMessageConsumption-0-76] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3710000004B, QueueId:1, QueueOffset:37, body:75, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:85, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:14:10.840 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - 0196564DA3872A05200565C37200000063, MessageGroup: 8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, Topic: topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE
send message MessageImpl{topic=topic_FIFO_testOrder_Send_PushConsumeOrderly_elQgOE, tag=tag-server-tgqAqpbI8I2C6e5IAP4i, messageGroup=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11, deliveryTimestamp=null, keys=[], properties={}}
10:14:10.845 [main] INFO org.apache.rocketmq.util.VerifyUtils - Set timeout: 90000ms
10:15:35.079 [main] ERROR org.apache.rocketmq.util.VerifyUtils - More retry messages were consumed than expected, Except:1, Actual:2
10:15:35.081 [RocketmqMessageConsumption-0-77] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3710000004D, QueueId:1, QueueOffset:38, body:77, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:86, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b11}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b11]
10:15:35.081 [RocketmqMessageConsumption-0-75] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C37100000048, QueueId:6, QueueOffset:36, body:72, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:87, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:15:35.081 [RocketmqMessageConsumption-0-80] INFO org.apache.rocketmq.listener.rmq.RMQNormalListener - consume message 5dee4ec1-bfe3-4876-8bf6-4330aaa48ecd - MessageId:0196564DA3872A05200565C3710000004E, QueueId:6, QueueOffset:39, body:78, tag:tag-server-tgqAqpbI8I2C6e5IAP4i,  key:[], recvIndex:88, property:{__SHARDINGKEY=8adf4ede-3aeb-48d0-851e-b3ef69fda3b10}, action:SUCCESS, messageGroup:Optional[8adf4ede-3aeb-48d0-851e-b3ef69fda3b10]
10:16:04.140 [NettyClientSelector_1] INFO RocketmqRemoting - closeChannel: close the connection to remote address[127.0.0.1:8081] result: true
10:16:04.151 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalProducer - Producer shutdown !!!
10:16:05.158 [main] INFO org.apache.rocketmq.client.rmq.RMQNormalConsumer - DefaultMQPushConsumer shutdown !!!

org.opentest4j.AssertionFailedError: More retry messages were consumed than expected (including one original message) Except:1, Actual:2, MsgId:0196564DA3872A05200565C37000000038

    at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)
    at org.junit.jupiter.api.Assertions.fail(Assertions.java:117)
    at org.apache.rocketmq.util.VerifyUtils.waitForMessageConsume(VerifyUtils.java:396)
    at org.apache.rocketmq.util.VerifyUtils.verifyOrderMessage(VerifyUtils.java:170)
    at org.apache.rocketmq.broker.server.OrderMessageTest.testOrder_Send_PushConsumeOrderly(OrderMessageTest.java:104)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
    at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:210)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:206)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:131)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
    at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
    at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
    at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
    at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)

Disconnected from the target VM, address: '127.0.0.1:51219', transport: 'socket'
10:16:05.169 [NettyClientSelector_1] INFO RocketmqRemoting - closeChannel: close the connection to remote address[127.0.0.1:8081] result: true
10:16:05.170 [Thread-2] INFO org.apache.rocketmq.frame.BaseOperate - Shutdown Hook is running !