Dubbo部署导致上游调用报错问题排查

最新推荐文章于 2022-03-17 10:30:02 发布

micro_hz

最新推荐文章于 2022-03-17 10:30:02 发布

阅读量710

点赞数

分类专栏：编程语言源码分析框架学习

本文链接：https://blog.csdn.net/micro_hz/article/details/102572669

版权

编程语言同时被 3 个专栏收录

179 篇文章 4 订阅

订阅专栏

框架学习

42 篇文章 1 订阅

订阅专栏

源码分析

21 篇文章 0 订阅

订阅专栏

现象

在部署的时候，总会有上游的部分调用请求出错。在流量小的时候这样的报错是能容忍的，但是库存作为核心服务，高并发的极小的流量，它占的绝对值的数量也不小，所以这个问题已经到了不得不解决的地步。开始抓取以下的日志进行分析。

原因分析

应用启动的日志:
在这里插入图片描述
启动的时间点为：16:48分，但是准确的服务提供的时间其实并非这个时间点。因为我们在应用层用AOP去拦截了所有请求，看请求日志如下：

也就是说27:32其实已经有请求过来了。
首先查看对应点的CPU
发现飙高的时间是高于接受请求之前的。
在这里插入图片描述

最开始一直怀疑是 JIT 问题，如果是JIT的问题，JIT在有一个执行阀值，会在调用达到一定次数才会根据情况进行c1和c2级别的编译，CPU这飙高位置应该在27:32，所以这个点的CPU飙高与JIT应该无关。

接下来我们来看调用方的日志：

[应用:group_xxx-center] [主机:item-center-12] [文件:error.log] ===> [2019-10-14 16:27:30] [ERROR] [] [parallel-query-sku2-thread-25]  c.g.p.g.f.UncheckedExceptionFilter.63    -  [DUBBO] Failed to invoke remote method: getXXX, provider: dubbo://192.168.8.26:20881/com.xxxx?anyhost=true&application=item-center&check=false&connections=4&default.chec........, cause: message can not send, because channel is closed . url:dubbo://192.168.8.26:20881/com.........monitor=dubbo%3A%2F%2F192.168.7.68%3A2181%2Fcom.alibaba.dubbo.registry.RegistryService%3Fapplication%3Ditem-center%26backup%3D192.168.7.69%3A2181%2C192.168.7.70%3A2181%26dubbo%3D2.6.2%26environment%3Dproduct%26owner%3Dlingyun%26pid%3D13053%26protocol%3Dregistry%26refer%3Ddubbo%253D2.6.2%2526interface%253Dcoxxxxx3053&register.ip=192.168.101.45&remote.timestamp=1571041648664&revision=1.0.9&side=consumer&timeout=500&timestamp=1571040797703
    at com.alibaba.dubbo.rpc.protocol.dubbo.DubboInvoker.doInvoke(DubboInvoker.java:100)
    at com.alibaba.dubbo.rpc.protocol.AbstractInvoker.invoke(AbstractInvoker.java:148)
    at com.xxxx.xxxxxx
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at cxxxx
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.xxxx
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter.invoke(FutureFilter.java:54)

因为平时由于网络抖动经常会有超时的情况，但是仔细分析这个日志，其实并不是超时，这也再次印证了这并非JIT的问题，其中可以看到关键的日志：cause: message can not send, because channel is closed.字面意思就是通道被关闭了。由于之前说到在应用层没有任何请求，27:30秒的这个调用就像白白被丢弃了一样，对于服务的提供者没有任何响应就关闭了通道。只能把问题的排查放到更底层的实现上。我们分析下ZK的服务注册与提供者的获取时间日志：

服务注册
已经开始建立netty连接，这些目标机器应该是公司的一些监控中间件的工具，在 ZK 注册之前进行了连接。

下面就是服务提供者注册ZK的日志:

消费者的机器拿到zk的通知：

27:28分这个时间点，对于消费者就可以调用最新的机器了。但是根据调用出错的日志:

失败之后重连

服务调用时序图：

也就是连接成功建立，但是Dubbo调用却出错了.再次回到出错的日志：because channel is closed在netty源码位置如下

根据dubbo的架构：

transport 网络传输层：抽象 mina 和 netty 为统一接口，以 Message 为中心，扩展接口为 Channel, Transporter, Client, Server, Codec。由于dubbo每层是单向依赖，这层是对TCP连接的封装，于是我开始看linux的tcp相关的日志：

看到这个关键字:在dubbo服务的端口存在SYNC flooding 。洪水攻击。就是linux监听到底层的端口发现可能是SYNC包过载，避免三次握手客户端不响应就存在占满服务端资源的情况，是一种DDos类型。
先贴出TCP三次握手的过程如下
为什么会触发这个日志，我查看我们服务器的内核版本为3.10.0，找到对应linux内核源码的对应日志打印的地方.

这已经是触发洪水攻击的内部处理逻辑了，看调用更上层.

这是处理SYNC ACK的逻辑.

也就是当前请求已经超过icsk_accept_queue队列.也就是tcp连接其实维护了两个队列：

我们看到的内核日志Possible SYN flooding on port其实就是SYNC 请求过来丢弃报文的日志。为什么丢弃呢，因为满了SYNC Queue. 其实这个连接数的backlog是可以配置的。我看我们系统是128。但是实际上我们的机器上的连接数已经超过这个量了。具体的backlog参数的处理逻辑如下：

处理SYNC请求

int tcp_conn_request(struct request_sock_ops *rsk_ops,
             const struct tcp_request_sock_ops *af_ops,
             struct sock *sk, struct sk_buff *skb)
 
    if ((net->ipv4.sysctl_tcp_syncookies == 2 ||
         inet_csk_reqsk_queue_is_full(sk)) && !isn) {   // 条件1: 半连接 >= backlog
        want_cookie = tcp_syn_flood_action(sk, skb, rsk_ops->slab_name);
        if (!want_cookie)
            goto drop;
    }
 
    if (sk_acceptq_is_full(sk) && inet_csk_reqsk_queue_young(sk) > 1) { // 条件2: 全连接 > backlog 并且 半连接 > 1
        NET_INC_STATS(sock_net(sk), LINUX_MIB_LISTENOVERFLOWS);
        goto drop;
    }

处理ACK

struct sock *tcp_v4_syn_recv_sock(const struct sock *sk, struct sk_buff *skb,
                  struct request_sock *req,
                  struct dst_entry *dst,
                  struct request_sock *req_unhash,
                  bool *own_req)
{
     // code omitted
     if (sk_acceptq_is_full(sk))           //  全连接 > backlog, 就丢弃
         goto exit_overflow;
 
     newsk = tcp_create_openreq_child(sk, req, skb); // 创建子套接字了
     // code omitted
}

从以上的现象和分析中,我认为内核存在以下问题

accept队列是否满的判断用>=比>更合适, 这样才能体现backlog的作用

accept队列满了,就应该拒绝半连接了,因为即使半连接握手完成,也无法加入accept队列,否则就会出现SYN_RECV–ESTABLISHED这样状态的连接对!这样的连接是不能进行数据传输的.

在这种情况下，对于客户端虽然建立了连接，但是对于服务端来说连接已经被丢弃，到Dubbo层真正调用的时候，其实通道已经关闭了。

解决方案

根据自身实际情况和并发量，修改内核的该参数。

sysctl -w net.ipv4.tcp_max_syn_backlog=1024
sysctl -w net.ipv4.tcp_synack_retries=2
sysctl -w net.ipv4.tcp_abort_on_overflow=1 （这个参数是在连接被丢弃的立即通知客户端，而不是等待数据传输再通知）

修改完发现通道关闭的问题依旧存在，后来发现Netty没指定backlog参数也没扩展的口子，底层直接使用JDK socket的默认值50：
在这里插入图片描述
所以修改 netty源码，修改之后多次部署再也没个问题了。

看了此篇文章是不是感觉收获蛮大

micro_hz

关注

0
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
Dubbo部署导致上游调用报错问题排查

现象在部署的时候，总会有上游的部分调用请求出错。在流量小的时候这样的报错是能容忍的，但是库存作为核心服务，高并发的极小的流量，它占的绝对值的数量也不小，所以这个问题已经到了不得不解决的地步。开始抓取以下的日志进行分析。原因分析应用启动的日志:启动的时间点为：16:48分，但是准确的服务提供的时间其实并非这个时间点。因为我们在应用层用AOP去拦截了所有请求，看请求日志如下：也就是说27...
复制链接

扫一扫