使用0.2.2-SNAPSHOT版本中的demo，发现通过zookeeper注册的服务，在客户端调用时调用成功了，但返回不了结果

anlogo commented 8 years ago

今天下载了0.2.2-SNAPSHOT版本，并尝试运行了其中的demo，但发现一个问题：运行的服务类是com.weibo.motan.demo.server.DemoRpcServer 配置了zookeeper注册中心，而且是内网的其它机器运行的client类是com.weibo.motan.demo.client.DemoRpcClient ，但发现在client类执行调用 service.hello("motan" + i) 时返回了 null, 而且只有前面2次这样，第3次调用开始返回的结果就对了，控制台输出如下： null null Hello motan3!

谢谢！

rayzhang0603 commented 8 years ago

看一下是否超时了。requestTimeout调到1000试试

anlogo commented 8 years ago

设置了timeout 为3000 还是一样的结果客户端日志： DEBUG 16/10/14 15:52:00 org.I0Itec.zkclient.ZkClient (638) - State is SyncConnected INFO 16/10/14 15:52:00 info (55) - CommandFailbackRegistry init. url: zookeeper://120.24.216.196:2181/com.weibo.api.motan.registry.RegistryService?group=default_rpc INFO 16/10/14 15:52:00 info (59) - [ZookeeperRegistry] Listener (com.weibo.api.motan.cluster.support.ClusterSupport@dd3b207) will subscribe to url (motan://192.168.56.1:0/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc) in Registry [zookeeper://120.24.216.196:2181/default_rpc/com.weibo.api.motan.registry.RegistryService/1.0/service] INFO 16/10/14 15:52:00 info (55) - CommandFailbackRegistry subscribe. url: motan://192.168.56.1:0/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc INFO 16/10/14 15:52:00 info (55) - CommandServiceManager init url:motan://192.168.56.1:0/com.weibo.motan.demo.service.MotanDemoService?singleton=true&haStrategy=failover&module=motan-demo-rpc&maxClientConnection=10&loadbalance=roundrobin&minClientConnection=1&check=true&nodeType=service&version=1.0&throwException=false&accessLog=false&retries=2&protocol=motan&isDefault=true&application=myMotanDemo&refreshTimestamp=1476431505052&id=motanDemoReferer1&requestTimeout=3000&group=motan-demo-rpc& DEBUG 16/10/14 15:52:00 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 1,3 replyHeader:: 1,1386,-101 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/client/192.168.56.1,F response::
DEBUG 16/10/14 15:52:00 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 2,3 replyHeader:: 2,1386,0 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/client,F response:: s{1358,1358,1476430445041,1476430445041,0,14,0,0,0,0,1379} DEBUG 16/10/14 15:52:00 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 3,1 replyHeader:: 3,1387,0 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/client/192.168.56.1,#ffffffacffffffed05741ffffffac6d6f74616e3a2f2f3139322e3136382e35362e313a302f636f6d2e776569626f2e6d6f74616e2e64656d6f2e736572766963652e4d6f74616e44656d6f536572766963653f73696e676c65746f6e3d7472756526686153747261746567793d6661696c6f766572266d6f64756c653d6d6f74616e2d64656d6f2d727063266d6178436c69656e74436f6e6e656374696f6e3d3130266c6f616462616c616e63653d726f756e64726f62696e266d696e436c69656e74436f6e6e656374696f6e3d3126636865636b3d74727565266e6f6465547970653d736572766963652676657273696f6e3d312e30267468726f77457863657074696f6e3d66616c7365266163636573734c6f673d66616c736526726574726965733d322670726f746f636f6c3d6d6f74616e26697344656661756c743d74727565266170706c69636174696f6e3d6d794d6f74616e44656d6f267265667265736854696d657374616d703d313437363433313530353035322669643d6d6f74616e44656d6f5265666572657231267265717565737454696d656f75743d333030302667726f75703d6d6f74616e2d64656d6f2d72706326,v{s{31,s{'world,'anyone}}},1 response:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/client/192.168.56.1 DEBUG 16/10/14 15:52:00 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 4,3 replyHeader:: 4,1387,0 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/server,T response:: s{1355,1355,1476430411728,1476430411728,0,3,0,0,0,1,1384} DEBUG 16/10/14 15:52:00 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 5,8 replyHeader:: 5,1387,0 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/server,T response:: v{'192.168.56.1:8001} INFO 16/10/14 15:52:00 info (55) - [ZookeeperRegistry] subscribe service: path=/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/server/192.168.56.1, info=motan://192.168.56.1:0/com.weibo.motan.demo.service.MotanDemoService?singleton=true&haStrategy=failover&module=motan-demo-rpc&maxClientConnection=10&loadbalance=roundrobin&minClientConnection=1&check=true&nodeType=service&version=1.0&throwException=false&accessLog=false&retries=2&protocol=motan&isDefault=true&application=myMotanDemo&refreshTimestamp=1476431505052&id=motanDemoReferer1&requestTimeout=3000&group=motan-demo-rpc& DEBUG 16/10/14 15:52:00 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 6,3 replyHeader:: 6,1387,-101 request:: '/motan/motan-demo-rpc/command,T response::
DEBUG 16/10/14 15:52:00 org.I0Itec.zkclient.ZkClient (137) - Subscribed data changes for /motan/motan-demo-rpc/command INFO 16/10/14 15:52:00 info (55) - [ZookeeperRegistry] subscribe command: path=/motan/motan-demo-rpc/command, info=motan://192.168.56.1:0/com.weibo.motan.demo.service.MotanDemoService?singleton=true&haStrategy=failover&module=motan-demo-rpc&maxClientConnection=10&loadbalance=roundrobin&minClientConnection=1&check=true&nodeType=service&version=1.0&throwException=false&accessLog=false&retries=2&protocol=motan&isDefault=true&application=myMotanDemo&refreshTimestamp=1476431505052&id=motanDemoReferer1&requestTimeout=3000&group=motan-demo-rpc& INFO 16/10/14 15:52:00 info (55) - CommandFailbackRegistry discover. url: motan://192.168.56.1:0/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc DEBUG 16/10/14 15:52:01 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 7,3 replyHeader:: 7,1387,-101 request:: '/motan/motan-demo-rpc/command,T response::
INFO 16/10/14 15:52:01 info (55) - CommandFailbackRegistry discover command. commandStr: , rpccommand is null. DEBUG 16/10/14 15:52:01 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 8,3 replyHeader:: 8,1387,0 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/server,T response:: s{1355,1355,1476430411728,1476430411728,0,3,0,0,0,1,1384} DEBUG 16/10/14 15:52:01 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 9,8 replyHeader:: 9,1387,0 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/server,T response:: v{'192.168.56.1:8001} DEBUG 16/10/14 15:52:01 org.apache.zookeeper.ClientCnxn (843) - Reading reply sessionid:0x157792e7f08001f, packet:: clientPath:null serverPath:null finished:false header:: 10,4 replyHeader:: 10,1387,0 request:: '/motan/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/server/192.168.56.1:8001,F response:: #ffffffacffffffed05741ffffffa96d6f74616e3a2f2f3139322e3136382e35362e313a383030312f636f6d2e776569626f2e6d6f74616e2e64656d6f2e736572766963652e4d6f74616e44656d6f536572766963653f6d6178436f6e74656e744c656e6774683d31303438353736266d6f64756c653d6d6f74616e2d64656d6f2d727063266e6f6465547970653d73657276696365266163636573734c6f673d66616c7365266d696e576f726b65725468726561643d32302670726f746f636f6c3d6d6f74616e26697344656661756c743d74727565266170706c69636174696f6e3d6d794d6f74616e44656d6f266d6178576f726b65725468726561643d3830302673686172654368616e6e656c3d74727565267265667265736854696d657374616d703d313437363433313437393237342669643d636f6d2e776569626f2e6170692e6d6f74616e2e636f6e6669672e737072696e67737570706f72742e53657276696365436f6e6669674265616e266578706f72743d64656d6f4d6f74616e3a38303031266d6178536572766572436f6e6e656374696f6e3d38303030302667726f75703d6d6f74616e2d64656d6f2d72706326,s{1384,1384,1476431495051,1476431495051,0,0,0,96679157618442270,432,0,1384} INFO 16/10/14 15:52:01 info (55) - CommandFailbackRegistry discover size: 1, result:[motan://192.168.56.1:8001/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc] INFO 16/10/14 15:52:01 info (59) - ClusterSupport config change notify: registry=zookeeper://120.24.216.196:2181/com.weibo.api.motan.registry.RegistryService service=motan://192.168.56.1:0/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/1.0/referer urls=[motan://192.168.56.1:8001/motan-demo-rpc/com.weibo.motan.demo.service.MotanDemoService/1.0/service] INFO 16/10/14 15:52:01 info (55) - refresh weight. weight= INFO 16/10/14 15:52:01 info (55) - ignore weightString: INFO 16/10/14 15:52:01 info (59) - NettyEndpointFactory create client: url=motan://192.168.56.1:8001/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc INFO 16/10/14 15:52:01 info (55) - init compress codec INFO 16/10/14 15:52:01 info (55) - init nettyclient. url:192.168.56.1-com.weibo.motan.demo.service.MotanDemoService, use codec:DefaultRpcCodec INFO 16/10/14 15:52:01 info (55) - NettyChannelHandler channelConnected: remote=/192.168.56.1:8001 local=/192.168.56.1:51199 event=UpstreamChannelStateEvent INFO 16/10/14 15:52:01 info (59) - NettyClient finish Open: url=motan://192.168.56.1:8001/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc INFO 16/10/14 15:52:01 info (55) - DefaultRpcReferer node init Success: [DefaultRpcReferer] url=motan://192.168.56.1:8001/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc INFO 16/10/14 15:52:01 info (55) - DefaultRpcProtocol refer Success: url=motan://192.168.56.1:8001/com.weibo.motan.demo.service.MotanDemoService?group=motan-demo-rpc --------start --------0 开始第一次调用远程服务 WARN 16/10/14 15:52:04 warn (67) - FailoverHaStrategy Call false for request:com.weibo.motan.demo.service.MotanDemoService.hello(java.lang.String) requestId=1548150658791636993 error=error_message: NettyResponseFuture request timeout: serverPort=192.168.56.1:8001 requestId=1548150658791636993 interface=com.weibo.motan.demo.service.MotanDemoService method=hello(java.lang.String) cost=3003, status: 503, error_code: 10003,r=null WARN 16/10/14 15:52:07 warn (67) - FailoverHaStrategy Call false for request:com.weibo.motan.demo.service.MotanDemoService.hello(java.lang.String) requestId=1548150658791636993 error=error_message: NettyResponseFuture request timeout: serverPort=192.168.56.1:8001 requestId=1548150658791636993 interface=com.weibo.motan.demo.service.MotanDemoService method=hello(java.lang.String) cost=3000, status: 503, error_code: 10003,r=null WARN 16/10/14 15:52:10 warn (75) - RefererInvocationHandler invoke false, so return default value: uri=motan://192.168.56.1:0/com.weibo.motan.demo.service.MotanDemoService requestId=1548150658791636993 interface=com.weibo.motan.demo.service.MotanDemoService method=hello(java.lang.String) com.weibo.api.motan.exception.MotanServiceException: error_message: NettyResponseFuture request timeout: serverPort=192.168.56.1:8001 requestId=1548150658791636993 interface=com.weibo.motan.demo.service.MotanDemoService method=hello(java.lang.String) cost=3001, status: 503, error_code: 10003,r=null at com.weibo.api.motan.transport.netty.NettyResponseFuture.timeoutSoCancel(NettyResponseFuture.java:236) at com.weibo.api.motan.transport.netty.NettyResponseFuture.getValue(NettyResponseFuture.java:137) at com.weibo.api.motan.rpc.DefaultResponse.(DefaultResponse.java:54) at com.weibo.api.motan.transport.netty.NettyClient.asyncResponse(NettyClient.java:204) at com.weibo.api.motan.transport.netty.NettyClient.request(NettyClient.java:187) at com.weibo.api.motan.transport.netty.NettyClient.request(NettyClient.java:116) at com.weibo.api.motan.protocol.rpc.DefaultRpcProtocol$DefaultRpcReferer.doCall(DefaultRpcProtocol.java:171) at com.weibo.api.motan.rpc.AbstractReferer.call(AbstractReferer.java:64) at com.weibo.api.motan.cluster.ha.FailoverHaStrategy.call(FailoverHaStrategy.java:72) at com.weibo.api.motan.cluster.support.ClusterSpi.call(ClusterSpi.java:73) at com.weibo.api.motan.proxy.RefererInvocationHandler.invoke(RefererInvocationHandler.java:108) at com.sun.proxy.$Proxy8.hello(Unknown Source) at com.weibo.motan.demo.client.DemoRpcClient.main(DemoRpcClient.java:37) null --------1 开始第二次调用远程服务 WARN 16/10/14 15:52:14 warn (67) - FailoverHaStrategy Call false for request:com.weibo.motan.demo.service.MotanDemoService.hello(java.lang.String) requestId=1548150669306757122 error=error_message: NettyResponseFuture request timeout: serverPort=192.168.56.1:8001 requestId=1548150669306757122 interface=com.weibo.motan.demo.service.MotanDemoService method=hello(java.lang.String) cost=3001, status: 503, error_code: 10003,r=null DEBUG 16/10/14 15:52:14 org.apache.zookeeper.ClientCnxn (742) - Got ping response for sessionid: 0x157792e7f08001f after 29ms WARN 16/10/14 15:52:16 warn (71) - NettyClient has response from server, but resonseFuture not exist, requestId=1548150658791636993 WARN 16/10/14 15:52:16 warn (71) - NettyClient has response from server, but resonseFuture not exist, requestId=1548150658791636993 WARN 16/10/14 15:52:16 warn (71) - NettyClient has response from server, but resonseFuture not exist, requestId=1548150658791636993 Hello motan1!

服务端日志： DEBUG 16/10/14 15:51:48 org.apache.zookeeper.ClientCnxn (742) - Got ping response for sessionid: 0x157792e7f08001e after 30ms INFO 16/10/14 15:51:49 serviceStatsLog (95) - [motan-totalAccessStatistic] app: motan module: motan total_count: 0 slow_count: 0 biz_excp: 0 other_excp: 0 avg_time: 0.00ms biz_time: 0.00ms avg_tps: 0 INFO 16/10/14 15:51:49 serviceStatsLog (99) - [motan-memoryStatistic] 28.19MB of 2702.50 MB (1.0%) used INFO 16/10/14 15:51:49 serviceStatsLog (99) - [motan-statisticCallback] identity: motan://192.168.56.1:8001/motan-demo-rpc//1.0/service connectionCount: 0 taskCount: 0 queueCount: 0 maxThreadCount: 800 maxTaskCount: 800 INFO 16/10/14 15:52:01 info (55) - NettyChannelHandler channelConnected: remote=/192.168.56.1:51199 local=/192.168.56.1:8001 event=UpstreamChannelStateEvent DEBUG 16/10/14 15:52:02 org.apache.zookeeper.ClientCnxn (742) - Got ping response for sessionid: 0x157792e7f08001e after 27ms DEBUG 16/10/14 15:52:15 org.apache.zookeeper.ClientCnxn (742) - Got ping response for sessionid: 0x157792e7f08001e after 24ms motan1

anlogo commented 8 years ago

服务端的日志贴的少了，现在再补充下:

DEBUG 16/10/14 15:51:48 org.apache.zookeeper.ClientCnxn (742) - Got ping response for sessionid: 0x157792e7f08001e after 30ms INFO 16/10/14 15:51:49 serviceStatsLog (95) - [motan-totalAccessStatistic] app: motan module: motan total_count: 0 slow_count: 0 biz_excp: 0 other_excp: 0 avg_time: 0.00ms biz_time: 0.00ms avg_tps: 0 INFO 16/10/14 15:51:49 serviceStatsLog (99) - [motan-memoryStatistic] 28.19MB of 2702.50 MB (1.0%) used INFO 16/10/14 15:51:49 serviceStatsLog (99) - [motan-statisticCallback] identity: motan://192.168.56.1:8001/motan-demo-rpc//1.0/service connectionCount: 0 taskCount: 0 queueCount: 0 maxThreadCount: 800 maxTaskCount: 800 INFO 16/10/14 15:52:01 info (55) - NettyChannelHandler channelConnected: remote=/192.168.56.1:51199 local=/192.168.56.1:8001 event=UpstreamChannelStateEvent DEBUG 16/10/14 15:52:02 org.apache.zookeeper.ClientCnxn (742) - Got ping response for sessionid: 0x157792e7f08001e after 27ms DEBUG 16/10/14 15:52:15 org.apache.zookeeper.ClientCnxn (742) - Got ping response for sessionid: 0x157792e7f08001e after 24ms motan1 motan0 motan1 motan0 motan0 motan2 motan3 INFO 16/10/14 15:52:19 serviceStatsLog (95) - [motan-totalAccessStatistic] app: motan module: motan total_count: 0 slow_count: 0 biz_excp: 0 other_excp: 0 avg_time: 0.00ms biz_time: 0.00ms avg_tps: 0 INFO 16/10/14 15:52:19 serviceStatsLog (99) - [motan-memoryStatistic] 32.04MB of 2702.50 MB (1.2%) used INFO 16/10/14 15:52:19 serviceStatsLog (99) - [motan-statisticCallback] identity: motan://192.168.56.1:8001/motan-demo-rpc//1.0/service connectionCount: 1 taskCount: 0 queueCount: 0 maxThreadCount: 800 maxTaskCount: 800 motan4 motan5 motan6 motan7 motan8 motan9

anlogo commented 8 years ago

这个问题非常奇怪：客户端第一次调用时间是 15:52:04，结果出来了3次重试都是timeout 但服务端却是在 15:52:15后收到并处理了客户端的第一次调用请求

rayzhang0603 commented 8 years ago

估计跟网络配置有关，可以看看参考这个是否相同问题https://github.com/weibocom/motan/issues/219 可以用直连方式直接调用试试

anlogo commented 8 years ago

估计是，不纠结这问题了，谢谢解答哈哈！

weibocom / motan

使用0.2.2-SNAPSHOT版本中的demo，发现通过zookeeper注册的服务，在客户端调用时调用成功了，但返回不了结果 #230