一次dubbo超时问题的排查记录

现场问题阐述：

某个采集器启动一段时间后,在执行周期任务采集时会失败，报错Caused by: com.alibaba.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2019-10-08 11:18:00.219, end
 time: 2019-10-08 11:19:00.239, client elapsed: 1 ms, server elapsed: 60019 ms, timeout: 60000 ms, request: Request [id=1890720, version=2.0.0, twow
ay=true, event=false, broken=false, data=RpcInvocation [methodName=runTask, parameterTypes=[class com.merce.woven.rpc.dto.task.Task], arguments=[com
.merce.woven.rpc.dto.task.SyncDataTask@1e49507a], attachments={callback.service.instid=1958836898, path=com.merce.woven.rpc.CallbackListener, timeou
t=60000}]], channel: /192.166.151.53:20880 -> /192.166.151.53:20880
        at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.returnFromResponse(DefaultFuture.java:188)
        at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:110)
        at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:84)
        at com.alibaba.dubbo.rpc.protocol.dubbo.ChannelWrappedInvoker.doInvoke(ChannelWrappedInvoker.java:71)
        ... 9 more[2019-10-08 11:19:00.256]  ERROR [DefaultQuartzScheduler_Worker-6] --- ErrorLogger: Job (DEFAULT.624f33fb-ab0e-4509-8064-ec6d5847d
164 threw an exception.

后测试发现执行单次任务也会失败，错误一致。采集器重启后执行任务正常。

 

问题排查和分析：

首先在现场的测试环境中复现了上述报错场景，以下是排查过程大体记录：

1. 首先我们严重怀疑dubbo服务有问题, 因为这里明显的consumer的端口和provider的端口是相同的，所以我们怀疑是不是@Autowired注解的有问题，导致woven-app里本来就是内部调用方法却走了rpc远程调用，经过反复测试(通过修改bean name，及另外添加dubbo:reference), 证明woven-app对BrideServiceImpl实现类的调用就是本地调用，而不是走的rpc， 而如果想本地走rcp调用，必须借助dubbo:reference的配置，然后@Autowired必须注解这个类型，或者借助@Qualifer注解reference的id名称。所以至此我们知道应该不是woven-app内部方法调用的问题。

2. 通过对比其他采集器，发现以下两点：

    a. netstat 查看与logService 20881的连接一直存在(长连接理应保持)  ， 而失败采集器中没有此连接存在,只有和zk的4189端口保持的连接

    b. 通过采集器日志查看，大约每隔2个小时, logService的dubbo服务会断开连接(disconnect),并重新连接(reconnect)， 而执行任务失败的采集器没有相同的日志输出。

    c. 通过进一步的详细添加debug日志，也是发现logService写日志的时候迟迟没有返回

至此应该可以确认是logService服务获取不到(刚刚重启是可以获取到的)，或者是长连接总是断开还不会重连(采集器启动一段时间后)。

     后经分析正常的采集器上tcp.keepalive_time=7200(秒)，正常连接的服务器会每隔2小时发送keepalive消息来探测连接； 而执行任务失败的collector client端应该是和provider logserver断开了连接，而没有发送类似的探测消息。

至此可以判断失败任务的采集器大概率网络肯定是存在某种问题，总是和logsevice等server轻易断开，但是解决方案不可能从网络上去着手，当务之急考虑logService和collector断开后能不能让他自动去重连，就类似keep_alive机制。

   很遗憾这台采集器设备上修改了keep-alivetime=200s也自始至终没有收到disconnet和reconnect的消息；这是考虑到提供logservice服务的dubbo长连接是否能自动重连，结合dubbo服务的心跳机制，考虑是不是配置该consumer logservice的心跳时长小于调用的整体服务runTask的timeout时长，就能保证在runTask的rpc调用中一直保证logService服务的可用。 

下面是dubbo的心跳机制相关代码：

心跳机制HeartBeatTask的实现 ：

 // 最后读的时间，超过心跳超时时间

                    if (lastRead != null && now - lastRead > heartbeatTimeout) {

                        logger.warn("Close channel " + channel

                                + ", because heartbeat read idle time out: " + heartbeatTimeout + "ms");

                        // 客户端侧，重新连接服务端

                        if (channel instanceof Client) {

                            try {

                                ((Client) channel).reconnect();

                            } catch (Exception e) {

                                //do nothing

                            }

                        // 服务端侧，关闭客户端连接

                        } else {

                            channel.close();

                        }

                    }

因此，结合以上现象和分析, 对collector的consumer.xml中关于logService服务的引用做了如下修改：

<dubbo:reference id="loggingService" interface="com.merce.woven.rpc.LoggingService">

      <dubbo:parameter key="heartbeat" value="30000"/>        //单位是毫秒，这个时间必须小于设置的timeout，目前默认的timeout都是在provider.xml中配置的，均为60s

</dubbo:reference>

 

 现场测试环境经过以上修改，重启采集器, 至今所有采集任务均正常执行。 解决方案基本确定，但是这台采集器为什么总是断开dubbo的长连接的症结, 还需继续排查两个server之间的网络, 及硬件，防火墙等方面。