Zhao jian created ROCKETMQ-305:
----------------------------------
Summary: When using FilterServer consumption, the client reports a
timeout error
Key: ROCKETMQ-305
URL: https://issues.apache.org/jira/browse/ROCKETMQ-305
Project: Apache RocketMQ
Issue Type: Bug
Environment: version : 4.1
config:
2M/2S
SYNC_MASTER
SYNC_FLUSH
filterServerNums=1
CentOS Linux release 7.2.1511
Linux 10.13.13.49 3.10.0-327.el7.x86_64 #1 SMP Thu Nov 19 22:10:57 UTC 2015
x86_64 x86_64 x86_64 GNU/Linux
Reporter: Zhao jian
Assignee: vongosling
I used FilterServer in the deployment of the cluster, When the client consumes
messages frequently reported timeout errors when requesting FilterServer. The
client and server network latency is less than 2 milliseconds, and the time is
consistent.
*consumer log:*
2017-10-27 10:40:19.830 Thread-22 RocketmqClient [WARN] execute the pull
request exception
org.apache.rocketmq.client.exception.MQClientException: wait response from
10.15.224.214:44949 timeout :30000ms. Request: RemotingCommand [code=11,
language=JAVA, version=232, opaque=1184254, flag(B)=0, remark=null,
extFields={queueId=924, maxMsgNums=32, sysFlag=11, suspendTimeoutMillis=15000,
commitOffset=171, topic=BenchmarkTest, queueOffset=171,
subVersion=1509070444572, consumerGroup=zhaojian_test},
serializeTypeCurrentRPC=JSON]
For more information, please visit the url, http://rocketmq.apache.org/docs/faq/
at
org.apache.rocketmq.client.impl.MQClientAPIImpl$2.operationComplete(MQClientAPIImpl.java:603)
[rocketmq-client-4.1.0-incubating.jar:4.1.0-incubating]
at
org.apache.rocketmq.remoting.netty.ResponseFuture.executeInvokeCallback(ResponseFuture.java:51)
[rocketmq-remoting-4.1.0-incubating.jar:4.1.0-incubating]
at
org.apache.rocketmq.remoting.netty.NettyRemotingAbstract$2.run(NettyRemotingAbstract.java:275)
[rocketmq-remoting-4.1.0-incubating.jar:4.1.0-incubating]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[?:1.8.0_11]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_11]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[?:1.8.0_11]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[?:1.8.0_11]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_11]
2017-10-27 10:40:19.883 Thread-19 RocketmqRemoting [WARN] receive response, but
not matched any request, 10.15.224.214:44949
2017-10-27 10:40:19.883 Thread-19 RocketmqRemoting [WARN] RemotingCommand
[code=19, language=JAVA, version=232, opaque=714268, flag(B)=1, remark=null,
extFields={suggestWhichBrokerId=0, nextBeginOffset=171, maxOffset=171,
minOffset=0}, serializeTypeCurrentRPC=JSON]
2017-10-27 10:40:19.883 Thread-19 RocketmqRemoting [WARN] receive response, but
not matched any request, 10.15.224.214:44949
2017-10-27 10:40:19.883 Thread-19 RocketmqRemoting [WARN] RemotingCommand
[code=19, language=JAVA, version=232, opaque=714275, flag(B)=1, remark=null,
extFields={suggestWhichBrokerId=0, nextBeginOffset=170, maxOffset=170,
minOffset=0}, serializeTypeCurrentRPC=JSON]
2017-10-27 10:40:19.883 Thread-19 RocketmqRemoting [WARN] receive response, but
not matched any request, 10.15.224.214:44949
2017-10-27 10:40:19.883 Thread-19 RocketmqRemoting [WARN] RemotingCommand
[code=19, language=JAVA, version=232, opaque=714322, flag(B)=1, remark=null,
extFields={suggestWhichBrokerId=0, nextBeginOffset=171, maxOffset=171,
minOffset=0}, serializeTypeCurrentRPC=JSON]
*I added some log print on the client and FilterServer, found that the client
sends a request FilterServer more than 15 seconds to process the request, this
may be the reason for overtime, but I don't know how to troubleshoot and solve
the problem.
The following is the content of the log*
*consumer log*
2017-10-27 10:46:45.633 Thread-18 RocketmqRemoting [INFO] send request success,
code=11, opaque=1076871 [id: 0x8e5d2316, L:/10.15.244.244:44817 -
R:/10.13.13.49:45238]
2017-10-27 10:47:18.820 Thread-24 RocketmqRemoting [WARN] RemotingCommand
[code=19, language=JAVA, version=232, opaque=1076871, flag(B)=1, remark=null,
extFields={suggestWhichBrokerId=0, nextBeginOffset=168, maxOffset=168,
minOffset=0}, serializeTypeCurrentRPC=JSON]
*filtersrv.log*
2017-10-27 10:46:56 INFO RemotingExecutorThread_446 - receive request, 11
10.15.244.244:44817 RemotingCommand [code=11, language=JAVA, version=232,
opaque=1076871, flag(B)=0, remark=null, extFields={queueId=399, maxMsgNums=32,
sysFlag=11, suspendTimeoutMillis=15000, commitOffset=168, topic=BenchmarkTest,
queueOffset=168, subVersion=1509070444572, consumerGroup=zhaojian_test},
serializeTypeCurrentRPC=JSON]
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
