You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@rocketmq.apache.org by "pxd98 (via GitHub)" <gi...@apache.org> on 2023/07/31 04:32:02 UTC
[GitHub] [rocketmq] pxd98 created a discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
GitHub user pxd98 created a discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
RocketMQ版本为4.9.1，在重启一个Broker主节点的时候发现在该节点刚重启完的时候出现了超时（sendDefaultImpl call timeout），生产者的超时时间设置为3s，使用mqadmin 查询该消息显示该消息已被成功投递。怀疑是刚重启完成后生产者准备往这个节点发送消息，但发送失败，此时已经判断与该节点无法连接的用时已经超过了3s，导致直接发送超时。日志如下：
```
2023-07-31 11:55:49,776 WARN RocketmqClient - mq retry time: 0, cost time : 0
2023-07-31 11:55:49,776 INFO RocketmqRemoting - createChannel: begin to connect remote host[127.0.0.1:10784] asynchronously
2023-07-31 11:55:49,777 INFO RocketmqRemoting - NETTY CLIENT PIPELINE: CONNECT UNKNOWN => 127.0.0.1/172.16.0.93:10784
2023-07-31 11:55:49,777 INFO RocketmqRemoting - createChannel: connect remote host[127.0.0.1:10784] success, AbstractBootstrap$PendingRegistrationPromise@4e515669(success)
2023-07-31 11:55:52,163 WARN RocketmqClient - get Topic [TBW102] RouteInfoFromNameServer is not exist value
2023-07-31 11:55:52,163 WARN RocketmqClient - updateTopicRouteInfoFromNameServer Exception
org.apache.rocketmq.client.exception.MQClientException: CODE: 17 DESC: No topic route info in name server for the topic: TBW102
See http://rocketmq.apache.org/docs/faq/ for further details.
at org.apache.rocketmq.client.impl.MQClientAPIImpl.getTopicRouteInfoFromNameServer(MQClientAPIImpl.java:1385)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.getTopicRouteInfoFromNameServer(MQClientAPIImpl.java:1355)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:622)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:509)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:358)
at org.apache.rocketmq.client.impl.factory.MQClientInstance$3.run(MQClientInstance.java:275)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2023-07-31 11:55:52,776 INFO RocketmqRemoting - closeChannel: begin close the channel[127.0.0.1:10784] Found: true
2023-07-31 11:55:52,777 INFO RocketmqRemoting - closeChannel: the channel[127.0.0.1:10784] was removed from channel table
2023-07-31 11:55:52,777 WARN RocketmqRemoting - invokeSync: close socket because of timeout, 3000ms, 127.0.0.1:10784
2023-07-31 11:55:52,777 WARN RocketmqRemoting - invokeSync: wait response timeout exception, the channel[127.0.0.1:10784]
2023-07-31 11:55:52,777 INFO RocketmqRemoting - NETTY CLIENT PIPELINE: CLOSE 172.16.0.93:10784
2023-07-31 11:55:52,777 INFO RocketmqRemoting - eventCloseChannel: the channel[null] has been removed from the channel table before
2023-07-31 11:55:52,777 INFO RocketmqRemoting - closeChannel: close the connection to remote address[172.16.0.93:10784] result: true
2023-07-31 11:55:52,777 WARN RocketmqClient - sendKernelImpl exception, resend at once, InvokeID: 3944832610831701411, RT: 3001ms, Broker: MessageQueue [topic=t2, brokerName=broker-a, queueId=0]
org.apache.rocketmq.remoting.exception.RemotingTimeoutException: wait response on the channel <127.0.0.1/172.16.0.93:10784> timeout, 2999(ms)
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract.invokeSyncImpl(NettyRemotingAbstract.java:437)
at org.apache.rocketmq.remoting.netty.NettyRemotingClient.invokeSync(NettyRemotingClient.java:377)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessageSync(MQClientAPIImpl.java:503)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessage(MQClientAPIImpl.java:487)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessage(MQClientAPIImpl.java:431)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendKernelImpl(DefaultMQProducerImpl.java:882)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendDefaultImpl(DefaultMQProducerImpl.java:611)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.send(DefaultMQProducerImpl.java:1403)
at org.apache.rocketmq.client.producer.DefaultMQProducer.send(DefaultMQProducer.java:349)
at org.example.App.main(App.java:42)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65)
2023-07-31 11:55:52,777 WARN RocketmqClient - Message{topic='t2', flag=0, properties={UNIQ_KEY=7F000001536B5910E4409D0E249001BB, WAIT=true, TAGS=tagA}, body=[72, 101, 108, 108, 111, 44, 32, 87, 111, 114, 108, 100, 33, 32, 52, 52, 51], transactionId='null'}
2023-07-31 11:55:52,777 WARN RocketmqClient - mq retry time: 1, cost time : 3001
2023-07-31 11:55:52,777 WARN RocketmqClient - mq cost time out : 3001
2023-07-31 11:55:52,777 WARN RocketmqClient - mq send not OK:
2023-07-31 11:55:52,777 WARN RocketmqClient - MessageQueue [topic=t2, brokerName=broker-b, queueId=0]
```
我想问一下这个是什么原因，有否解决方案，谢谢。
GitHub link: https://github.com/apache/rocketmq/discussions/7099
----
This is an automatically sent email for dev@rocketmq.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@rocketmq.apache.org
[GitHub] [rocketmq] pxd98 edited a discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
Posted by "pxd98 (via GitHub)" <gi...@apache.org>.
GitHub user pxd98 edited a discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
RocketMQ版本为4.9.1，生产者是同步发送，broker端为同步双写。在重启一个Broker主节点的时候发现在该节点刚重启完的时候出现了超时（sendDefaultImpl call timeout），生产者的超时时间设置为3s，使用mqadmin 查询该消息显示该消息已被成功投递。怀疑是刚重启完成后生产者准备往这个节点发送消息，但发送失败，此时已经判断与该节点无法连接的用时已经超过了3s，导致直接发送超时。即使是重启从节点，也有这个问题。在刚开始时会告诉我发送状态是slave not found，之后会有一瞬间的长等待，然后就报了上面这个错。
日志如下：
```
2023-07-31 11:55:49,776 WARN RocketmqClient - mq retry time: 0, cost time : 0
2023-07-31 11:55:49,776 INFO RocketmqRemoting - createChannel: begin to connect remote host[127.0.0.1:10784] asynchronously
2023-07-31 11:55:49,777 INFO RocketmqRemoting - NETTY CLIENT PIPELINE: CONNECT UNKNOWN => 127.0.0.1/172.16.0.93:10784
2023-07-31 11:55:49,777 INFO RocketmqRemoting - createChannel: connect remote host[127.0.0.1:10784] success, AbstractBootstrap$PendingRegistrationPromise@4e515669(success)
2023-07-31 11:55:52,163 WARN RocketmqClient - get Topic [TBW102] RouteInfoFromNameServer is not exist value
2023-07-31 11:55:52,163 WARN RocketmqClient - updateTopicRouteInfoFromNameServer Exception
org.apache.rocketmq.client.exception.MQClientException: CODE: 17 DESC: No topic route info in name server for the topic: TBW102
See http://rocketmq.apache.org/docs/faq/ for further details.
at org.apache.rocketmq.client.impl.MQClientAPIImpl.getTopicRouteInfoFromNameServer(MQClientAPIImpl.java:1385)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.getTopicRouteInfoFromNameServer(MQClientAPIImpl.java:1355)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:622)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:509)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:358)
at org.apache.rocketmq.client.impl.factory.MQClientInstance$3.run(MQClientInstance.java:275)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2023-07-31 11:55:52,776 INFO RocketmqRemoting - closeChannel: begin close the channel[127.0.0.1:10784] Found: true
2023-07-31 11:55:52,777 INFO RocketmqRemoting - closeChannel: the channel[127.0.0.1:10784] was removed from channel table
2023-07-31 11:55:52,777 WARN RocketmqRemoting - invokeSync: close socket because of timeout, 3000ms, 127.0.0.1:10784
2023-07-31 11:55:52,777 WARN RocketmqRemoting - invokeSync: wait response timeout exception, the channel[127.0.0.1:10784]
2023-07-31 11:55:52,777 INFO RocketmqRemoting - NETTY CLIENT PIPELINE: CLOSE 172.16.0.93:10784
2023-07-31 11:55:52,777 INFO RocketmqRemoting - eventCloseChannel: the channel[null] has been removed from the channel table before
2023-07-31 11:55:52,777 INFO RocketmqRemoting - closeChannel: close the connection to remote address[172.16.0.93:10784] result: true
2023-07-31 11:55:52,777 WARN RocketmqClient - sendKernelImpl exception, resend at once, InvokeID: 3944832610831701411, RT: 3001ms, Broker: MessageQueue [topic=t2, brokerName=broker-a, queueId=0]
org.apache.rocketmq.remoting.exception.RemotingTimeoutException: wait response on the channel <127.0.0.1/172.16.0.93:10784> timeout, 2999(ms)
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract.invokeSyncImpl(NettyRemotingAbstract.java:437)
at org.apache.rocketmq.remoting.netty.NettyRemotingClient.invokeSync(NettyRemotingClient.java:377)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessageSync(MQClientAPIImpl.java:503)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessage(MQClientAPIImpl.java:487)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessage(MQClientAPIImpl.java:431)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendKernelImpl(DefaultMQProducerImpl.java:882)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendDefaultImpl(DefaultMQProducerImpl.java:611)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.send(DefaultMQProducerImpl.java:1403)
at org.apache.rocketmq.client.producer.DefaultMQProducer.send(DefaultMQProducer.java:349)
at org.example.App.main(App.java:42)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65)
2023-07-31 11:55:52,777 WARN RocketmqClient - Message{topic='t2', flag=0, properties={UNIQ_KEY=7F000001536B5910E4409D0E249001BB, WAIT=true, TAGS=tagA}, body=[72, 101, 108, 108, 111, 44, 32, 87, 111, 114, 108, 100, 33, 32, 52, 52, 51], transactionId='null'}
2023-07-31 11:55:52,777 WARN RocketmqClient - mq retry time: 1, cost time : 3001
2023-07-31 11:55:52,777 WARN RocketmqClient - mq cost time out : 3001
2023-07-31 11:55:52,777 WARN RocketmqClient - mq send not OK:
2023-07-31 11:55:52,777 WARN RocketmqClient - MessageQueue [topic=t2, brokerName=broker-b, queueId=0]
```
我想问一下这个是什么原因，有否解决方案，谢谢。
GitHub link: https://github.com/apache/rocketmq/discussions/7099
----
This is an automatically sent email for dev@rocketmq.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@rocketmq.apache.org
[GitHub] [rocketmq] pxd98 added a comment to the discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
Posted by "pxd98 (via GitHub)" <gi...@apache.org>.
GitHub user pxd98 added a comment to the discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
我把同步双写改成异步双写后就没有这个问题了，由于该消息在mq中存在，是不是因为主从同步超时，从而导致生产者有这个报错？谢谢解答。
GitHub link: https://github.com/apache/rocketmq/discussions/7099#discussioncomment-6591587
----
This is an automatically sent email for dev@rocketmq.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@rocketmq.apache.org
[GitHub] [rocketmq] pxd98 edited a discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
Posted by "pxd98 (via GitHub)" <gi...@apache.org>.
GitHub user pxd98 edited a discussion: RocketMQ 在broker 重启时， 生产者显示消息发送超时，但该消息仍被mq接收
RocketMQ版本为4.9.1，生产者是同步发送，broker端为同步双写。在重启一个Broker主节点的时候发现在该节点刚重启完的时候出现了超时（sendDefaultImpl call timeout），生产者的超时时间设置为3s，使用mqadmin 查询该消息显示该消息已被成功投递。怀疑是刚重启完成后生产者准备往这个节点发送消息，但发送失败，此时已经判断与该节点无法连接的用时已经超过了3s，导致直接发送超时。日志如下：
```
2023-07-31 11:55:49,776 WARN RocketmqClient - mq retry time: 0, cost time : 0
2023-07-31 11:55:49,776 INFO RocketmqRemoting - createChannel: begin to connect remote host[127.0.0.1:10784] asynchronously
2023-07-31 11:55:49,777 INFO RocketmqRemoting - NETTY CLIENT PIPELINE: CONNECT UNKNOWN => 127.0.0.1/172.16.0.93:10784
2023-07-31 11:55:49,777 INFO RocketmqRemoting - createChannel: connect remote host[127.0.0.1:10784] success, AbstractBootstrap$PendingRegistrationPromise@4e515669(success)
2023-07-31 11:55:52,163 WARN RocketmqClient - get Topic [TBW102] RouteInfoFromNameServer is not exist value
2023-07-31 11:55:52,163 WARN RocketmqClient - updateTopicRouteInfoFromNameServer Exception
org.apache.rocketmq.client.exception.MQClientException: CODE: 17 DESC: No topic route info in name server for the topic: TBW102
See http://rocketmq.apache.org/docs/faq/ for further details.
at org.apache.rocketmq.client.impl.MQClientAPIImpl.getTopicRouteInfoFromNameServer(MQClientAPIImpl.java:1385)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.getTopicRouteInfoFromNameServer(MQClientAPIImpl.java:1355)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:622)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:509)
at org.apache.rocketmq.client.impl.factory.MQClientInstance.updateTopicRouteInfoFromNameServer(MQClientInstance.java:358)
at org.apache.rocketmq.client.impl.factory.MQClientInstance$3.run(MQClientInstance.java:275)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2023-07-31 11:55:52,776 INFO RocketmqRemoting - closeChannel: begin close the channel[127.0.0.1:10784] Found: true
2023-07-31 11:55:52,777 INFO RocketmqRemoting - closeChannel: the channel[127.0.0.1:10784] was removed from channel table
2023-07-31 11:55:52,777 WARN RocketmqRemoting - invokeSync: close socket because of timeout, 3000ms, 127.0.0.1:10784
2023-07-31 11:55:52,777 WARN RocketmqRemoting - invokeSync: wait response timeout exception, the channel[127.0.0.1:10784]
2023-07-31 11:55:52,777 INFO RocketmqRemoting - NETTY CLIENT PIPELINE: CLOSE 172.16.0.93:10784
2023-07-31 11:55:52,777 INFO RocketmqRemoting - eventCloseChannel: the channel[null] has been removed from the channel table before
2023-07-31 11:55:52,777 INFO RocketmqRemoting - closeChannel: close the connection to remote address[172.16.0.93:10784] result: true
2023-07-31 11:55:52,777 WARN RocketmqClient - sendKernelImpl exception, resend at once, InvokeID: 3944832610831701411, RT: 3001ms, Broker: MessageQueue [topic=t2, brokerName=broker-a, queueId=0]
org.apache.rocketmq.remoting.exception.RemotingTimeoutException: wait response on the channel <127.0.0.1/172.16.0.93:10784> timeout, 2999(ms)
at org.apache.rocketmq.remoting.netty.NettyRemotingAbstract.invokeSyncImpl(NettyRemotingAbstract.java:437)
at org.apache.rocketmq.remoting.netty.NettyRemotingClient.invokeSync(NettyRemotingClient.java:377)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessageSync(MQClientAPIImpl.java:503)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessage(MQClientAPIImpl.java:487)
at org.apache.rocketmq.client.impl.MQClientAPIImpl.sendMessage(MQClientAPIImpl.java:431)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendKernelImpl(DefaultMQProducerImpl.java:882)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.sendDefaultImpl(DefaultMQProducerImpl.java:611)
at org.apache.rocketmq.client.impl.producer.DefaultMQProducerImpl.send(DefaultMQProducerImpl.java:1403)
at org.apache.rocketmq.client.producer.DefaultMQProducer.send(DefaultMQProducer.java:349)
at org.example.App.main(App.java:42)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:108)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65)
2023-07-31 11:55:52,777 WARN RocketmqClient - Message{topic='t2', flag=0, properties={UNIQ_KEY=7F000001536B5910E4409D0E249001BB, WAIT=true, TAGS=tagA}, body=[72, 101, 108, 108, 111, 44, 32, 87, 111, 114, 108, 100, 33, 32, 52, 52, 51], transactionId='null'}
2023-07-31 11:55:52,777 WARN RocketmqClient - mq retry time: 1, cost time : 3001
2023-07-31 11:55:52,777 WARN RocketmqClient - mq cost time out : 3001
2023-07-31 11:55:52,777 WARN RocketmqClient - mq send not OK:
2023-07-31 11:55:52,777 WARN RocketmqClient - MessageQueue [topic=t2, brokerName=broker-b, queueId=0]
```
我想问一下这个是什么原因，有否解决方案，谢谢。
GitHub link: https://github.com/apache/rocketmq/discussions/7099
----
This is an automatically sent email for dev@rocketmq.apache.org.
To unsubscribe, please send an email to: dev-unsubscribe@rocketmq.apache.org