Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Duplicate messages in FIFO queue consumption #625

Open
wangxye opened this issue Nov 14, 2023 · 2 comments
Open

Duplicate messages in FIFO queue consumption #625

wangxye opened this issue Nov 14, 2023 · 2 comments
Assignees
@ShadowySpirits

Comments

@wangxye
Copy link
Contributor

wangxye commented Nov 14, 2023

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
Copy link
Contributor Author

wangxye commented Nov 15, 2023 •
edited
Loading

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
Copy link
Contributor Author

wangxye commented Nov 15, 2023

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 !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ShadowySpirits ShadowySpirits

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ShadowySpirits @wangxye