sunnights
commented
8 years ago 你好，这是因为Client启动后首次调用超时导致的，如果首次调用影响比较大的话可以在Client配置中将timeout时间设置稍长一点 后续版本将对此问题进行修复
Closed zhbgs2000 closed 8 years ago
sunnights
commented
8 years ago 你好，这是因为Client启动后首次调用超时导致的，如果首次调用影响比较大的话可以在Client配置中将timeout时间设置稍长一点 后续版本将对此问题进行修复
rayzhang0603
commented
8 years ago 这个异常是在client端首次发起请求时出现，还是在多次请求中偶发出现？还是必先？ 这个异常从现象上是client在发起请求后262ms没有收到server的返回结果而取消了任务，通俗一点就是超时了。 如果是首次调用时的异常，一般跟类加载有关，后续会增加启动后预热功能缓解。 如果是多次请求中出现，可以看一下server端业务处理时间以及server端和client端是否有其他相关异常，在做进一步分析
zhbgs2000
commented
8 years ago 启动客户端几乎每次都会出现，偶尔也会正常，referer配置的超时如下： requestTimeout="10000" connectTimeout="5000" timeout="5000"
qdaxb
commented
8 years ago @zhbgs2000 能提供一下完整的配置文件吗？
zhbgs2000
commented
8 years ago 今天在办公环境出现的问题跟之前有点不一样，现在是请求超时的错误，一般是第一次客户端连接成功后关掉，重新打开客户端连接的时候出现：
com.weibo.api.motan.exception.MotanServiceException: error_message: NettyResponseFuture request timeout: serverPort=127.0.0.1:8002 requestId=146466761543200001 interface=com.bob.soa.api.SOAServiceI method=sendsms(java.lang.String,java.lang.String,java.lang.String,java.lang.String) cost=10001, status: 503, error_code: 10003,r=
at com.weibo.api.motan.transport.netty.NettyResponseFuture.timeoutSoCancel(NettyResponseFuture.java:234)
at com.weibo.api.motan.transport.netty.NettyResponseFuture.getValue(NettyResponseFuture.java:137)
at com.weibo.api.motan.rpc.DefaultResponse.
client端： <motan:referer id="SOAService" interface="com.bob.soa.api.SOAServiceI" directUrl="127.0.0.1:8002" requestTimeout="10000" connectTimeout="5000" timeout="5000"/> server端：
<bean id="SOAServiceImpl" class="com.bob.soa.soaserver.service.SOAServiceImpl"/><!-- 注册中心配置 使用不同注册中心需要依赖对应的jar包。如果不使用注册中心，可以把check属性改为false，忽略注册失败。-->
<!--<motan:registry regProtocol="local" name="registry" />-->
<!--<motan:registry regProtocol="consul" name="registry" address="127.0.0.1:8500"/>-->
<!-- <motan:registry regProtocol="zookeeper" name="zookeeper_registry" address="183.3.139.137:2181"/> -->
<!-- 协议配置。为防止多个业务配置冲突，推荐使用id表示具体协议。-->
<!-- <motan:protocol id="soaService" default="true" name="soaService"
maxServerConnection="80000" maxContentLength="1048576"
maxWorkerThread="800" minWorkerThread="20"/> -->
<!-- 通用配置，多个rpc服务使用相同的基础配置. group和module定义具体的服务池。export格式为“protocol id:提供服务的端口”-->
<!-- <motan:basicService export="soaService:8002"
group="group_soa" accessLog="false" shareChannel="true" module="group_soa"
application="rmip-motan" registry="zookeeper_registry" id="serviceBasicConfig"/>
-->
<!-- 具体rpc服务配置，声明实现的接口类。-->
<motan:service interface="com.bob.soa.api.SOAServiceI"
ref="SOAServiceImpl" export="8002" shareChannel="false" timeout="8000">
</motan:service>@zhbgs2000 这个错误看上去是请求超时了，但是具体是业务逻辑超时还是网络超时不能确定，建议：
com.bob.soa.soaserver.run.SOAClientRun.test_sendsms这个函数的执行时间是否超过了十秒；如果还是不能确认问题，可以试一下：
accessLog="true"在log4j.properties增加配置:
log4j.logger.accessLog=debug,accessfile
log4j.appender.accessfile=org.apache.log4j.DailyRollingFileAppender
log4j.appender.accessfile.file=./logs/client/access.log
log4j.appender.accessfile.DatePattern='.'yyyyMMdd
log4j.appender.accessfile.layout=org.apache.log4j.PatternLayout
log4j.appender.accessfile.layout.ConversionPattern=%-d{yyyy-MM-dd HH:mm:ss} [%p] %m%n1、test_sendsms只是测试服务端的一个RPC服务接口函数，服务端接口的实现基本是空的，只是打印收到的参数信息而已，不可能超过10秒的； 2、排除网络问题，本机测试该现象依旧存在，在办公环境内部局域网的情况下，更频繁，telnet地址端口均正常。本机一般第一次启动客户端测试进程是ok的，调用响应也比较快，终止进程后再重新启用测试，就会出现超时的现象。 客户端access.log 2016-06-02 22:06:38 [INFO] referer|motan|motan|192.168.24.2|com.bob.soa.api.SOAServiceI|sendsms|java.lang.String%2Cjava.lang.String%2Cjava.lang.String%2Cjava.lang.String|127.0.0.1|motan|motan|true|0|1094 2016-06-02 22:07:02 [INFO] referer|motan|motan|192.168.24.2|com.bob.soa.api.SOAServiceI|sendsms|java.lang.String%2Cjava.lang.String%2Cjava.lang.String%2Cjava.lang.String|127.0.0.1|motan|motan|false|0|10016
服务器端access.log 2016-06-02 22:06:38 [INFO] service|||192.168.24.2|com.bob.soa.api.SOAServiceI|sendsms|java.lang.String%2Cjava.lang.String%2Cjava.lang.String%2Cjava.lang.String|127.0.0.1|motan-client|motan-client|true|0|928 2016-06-02 22:07:23 [INFO] service|||192.168.24.2|com.bob.soa.api.SOAServiceI|sendsms|java.lang.String%2Cjava.lang.String%2Cjava.lang.String%2Cjava.lang.String|127.0.0.1|motan-client|motan-client|true|0|111
qdaxb
commented
8 years ago @zhbgs2000 从日志看motan框架本身没有占用很长时间，但是client调用的时间比较长，我们复现不了这个问题，我猜测可能和文件描述符限制或者防火墙有关，建议用tcpdump抓一下回环网卡的流量进一步分析。
tcpdump -i lo0 -w tcpdump.scp port 8002
服务端收可正常收到消息，客户端抛出异常，会是什么原因？
com.weibo.api.motan.exception.MotanServiceException: error_message: NettyResponseFuture task cancel: serverPort=127.0.0.1:8002 requestId=146453205192900001 interface=com.bob.soa.api.SOAServiceI method=sendsms(java.lang.String,java.lang.String,java.lang.String,java.lang.String) cost=262, status: 503, error_code: 10001,r= at com.weibo.api.motan.transport.netty.NettyResponseFuture.cancel(NettyResponseFuture.java:151) at com.weibo.api.motan.transport.netty.NettyClient$TimeoutMonitor.run(NettyClient.java:482) at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) at java.util.concurrent.FutureTask.runAndReset(Unknown Source) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source)