golang 服务大量 CLOSE_WAIT 故障排查

• 事故通过
• 排查
• 总结

事故通过

【2019-12-27 18:00 周五】
业务方忽然找来讲调用咱们程序大量提示“触发限流”，可是咱们没有收到任何监控报警。紧急查看了下 ServiceMesh sidecar 代理监控发现流量持续在减小，可是监控中没有任何触发限流的 http code 429 占比，若是有触发限流咱们会收到报警。

后来经过排查是程序中有一个历史限流逻辑触发了，可是程序中触发限流返回的 http code 是 200，这就彻底避开了 sidecar http code 非200 异常指标监控报警。把代码中的限流阈值调了很是大的一个值，统一走 sidecar 限流为准。

猜想本次触发限流可能跟网路抖动有关系，网络抖动致使链接持续被占用，最终 qps 超过限流阈值。由于这个程序最近都没有发布过，再加上业务上也没有突发流量，一切都很常态化。

【2019-12-28 15:30 周六】
相同的问题次日悄无声息的又出现了，仍是业务请求量持续下掉，上游业务方仍是提示“触发限流”，同时业务监控环比也在逐步下掉。

以恢复线上问题为第一原则快速重启了程序，线上恢复。

修改了代码，去掉了限流逻辑，就算触发限流也应该第一时间告警出来，这段代码返回 http 200 就很坑了，咱们彻底无感知。虽然咱们知道触发限流是“果”，“因”咱们并不知道，可是故障要在第一时间暴露出来才是最重要的。

咱们知道这个问题确定还会出现，要让隐藏的问题尽量的所有暴露出来，用最快最小的代价发现和解决掉才是正确的方式。

恢复线上问题以后，开始排查相关系统指标，首先排查程序依赖的 DB、redis 等中间件，各项指标都很正常，DB 链接池也很正常，活动链接数个位数，redis 也是。故障期间相关中间件、网络流量均出现 _qps_降低的状况。

当时开始排查网络抖动状况，可是仔细排查以后也没有出现丢包等状况。（仔细思考下，其实网络问题有点不合逻辑，由于相邻两天不可能同时触发同一条链路上的网络故障，并且其余系统都很正常。）

【2019-12-28 22:48 周六】
此次触发了 sidecar http code 非200占比 告警，咱们第一时间恢复了，整个告警到恢复只用了几分钟不到，将业务方的影响减小到最低。

可是因为缺乏请求链路中间环节日志，很难定位究竟是哪里出现问题。此次咱们打开了 sidecar 的请求日志，观察请求的日志，等待下次触发。(因为 qps 较高，默认是不打开 sidecar 请求日志)

同时请运维、基础架构、DBA、云专家等开始仔细排查整个链路。查看机器监控，发现故障期间 socket fd 升高到了3w多，随着fd升高内存也在持续占用，可是远没有到系统瓶颈，DB、redis 仍是出现故障窗口期间 qps 同步下掉的状况。

这个程序是两台机器，出故障只有一台机器，周五和周六分别是两台机器交替出现 hang 住的状况。可是因为没有保留现场，没法仔细分析。（之因此不能直接下掉一台机器保留现场，是由于有些业务调用并不彻底走 sidecar，有些仍是走的域名进行调用。因此没法干净的下掉一台机器排查。）

socket fd 升高暂不肯定是什么缘由形成的。此次已经作好准备，下次故障当即 dump 网路链接，步步逼近问题。

【2019-12-29 18:34 周日】
就在咱们排查的此时两台机器先后炸了一遍，迅速 netstat 下链接信息，而后重启程序，如今终于有了一些线索。

回顾整个故障过程，因为咱们没法短期内定位到，可是咱们必须转被动为主动。从原来被动接受通知，到主动发现，让问题第一时间暴露出来，快速无感知恢复线上，而后逐步经过各类方式方法慢慢定位。

不少时候，咱们排查问题会陷入细节，忽视了线上故障时间，应该以先恢复为第一原则。（故障等级和时间是正比的）

排查

【netstat 文件分析】
到目前为止发现问题没有那么简单，咱们开始有备而来，主动揪出这个问题的时候了。作好相应的策略抓取更多的现场信息分析。分析了 netstat 导出来的链接信息。

tcp6       0      0 localhost:synapse-nhttp localhost:56696         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:60666         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:39570         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:55682         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:36812         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:58454         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:43694         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:32928         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:60710         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:33418         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:36980         CLOSE_WAIT

一时蒙蔽，synapse-nhttp 这个是什么程序，当时不肯定全是 tcp 网络链接的 fd，情急之下只顾着导出最全的网络信息执行了 netstat -a ，没有带上 -n -p 转换端口为数字同时输出执行程序。~_~

这个 synapse-nhttp 很是可疑，同时查看了其余 go 程序机器都没有这个链接，为了排查是否程序自己问题，查看了 pre、qa 机器的链接，均都是 synapse-nhttp 这个端口名字。

判断下来 synapse-nhttp 确实是咱们本身的程序，可是为何端口名字会是 synapse-nhttp，后来查询下来发现咱们程序使用的 8280 端口就是 synapse-nhttp 默认端口，因此被 netstat 自动人性化解析了。~_~

因为请求链路通过 sidecar 进来，大量的 CLOSE_WAIT 被动关闭状态，开始怀疑 sidecar 问题，保险起见咱们采用排除法先将一个机器的量切到走域名作灰度测试，看是 sidecar 问题仍是程序自己问题。

咱们发现一个有意思的现象，CLOSE_WAIT 是被动关闭链接的状态，主动关闭链接的状态应该是 FIN_WAIT1。比较了两种状态链接数不是一个数量级，CLOSE_WAIT 将近1w个，而 FIN_WAIT1 只有几个，同时 FIN_WAIT2 只有几十个，TIME_WAIT一个没有。

合理状况下，sidecar 链接的 FIN_WAIT1 状态和本机程序链接的 CLOSE_WAIT 状态应该是一个数量级才对。可是如今明显被动关闭并无成功完成，要么是上游 sidecar 主动断开了链接，本机程序迟迟未能发送 fin ack，sidecar 端的链接被 tcp keepalive 保活关闭释放了。或者本机程序已经发出 fin ack 可是 sidecar 没有收到，还有一种可能就是，sidecar 端链接在收到 fin ack 前被回收了。

固然，这些只是猜想，为了搞清楚具体什么缘由致使只能抓包看 tcp 交互才能得出最终结论。

【tcpdump 包分析】
咱们准备好 tcpdump 脚本，按期抓取 tcp 包，如今就在等故障出现了，由于故障必定还会出现。果真在30号下午又出现了，咱们一阵激动准备分析dump文件，可是端口抓错了，sidecar 和程序都是本机调用走的是本地环回 lo 虚拟网卡接口，调整脚本在耐心的等待。~_~

问题又如期而至，咱们开始分析包。

能够很清楚看到 HTTP 请求有进来没有返回的。第一个红框是请求超时，上游主动关闭链接，超时时间大概是1s，服务器正常返回了 fin ack。第二个红框大概是间隔了一分半钟，主动关闭链接，可是直接返回 RST 重置标志，原先的链接其实已经不存在了。

为了验证这个请求为何没有返回，咱们提取 tcpdump 中的 HTTP 请求到后端日志查看发现到了服务器，咱们再从 Mysql 服务器请求 sql 中查看发现没有这个请求没有进来，同时咱们发现一个规律，故障期间 DB 非活动链接数都有持续跑高现象，很是规律。

基本上判定是 DB 链接池泄漏，开始排查代码。

发现代码中有一个方法有问题，这个方法以前一直没有业务规则命中，故障前一天26号有一个业务方开始走到这个方法。这个方法有一个隐藏bug，会致使 go 链接没法关闭。

这个bug其实也有go.sql原生库的一半责任。

var r *sql.Rows
    if r, err = core.GetDB().NewSession(nil).SelectBySql(query).Rows(); err != nil {
        return
    }

    for r.Next() {
        if err = r.Scan(&sum); err != nil {
            applog.Logger.Error(fmt.Sprint("xxx", err))
            r.Close() // 因为没有主动close链接致使泄漏
            return
        }
    }

sql.Rows 的Scan方法内部因为没有判断查询DB返回的空，就直接转换致使 converting panic 。在加上咱们这个方法没有处理 panic 状况，因此命中隐藏bug就会泄漏。

这个方法为何不主动关闭链接是由于 sql.Rows 扫描到最后会作关闭动做，因此一直以来都很好。

因此真正的问题是因为 链接池泄漏，致使全部的请求 goroutine block 在获取链接地方的地方，这一类问题排查起来很是困难。

总结

1.回顾这整个排查过程，我以为让系统运行的健康状态透明化才是发现问题的最有效手段，代码不出问题不现实。

2._go.sql_ 库还谈不上企业级应用，整个链接消耗、空闲和工做时长都是没有监控的，这也是致使这个case没法快速定位的缘由。包括go的其余方面都存在不少不完善的地方，尤为是企业级应用套件都很弱，包括_go_原生 dump 内存以后分析的套件。

3.整个排查仍是受到了一些噪音干扰，没能坚决核心逻辑和理论。DB 链接跑高为何没注意到，这一点实际上是由于咱们通常只看当时故障先后半小时后指标，没有拉长看最近一段时间规律是否有异样，包括 sidecar 流量持续下掉是由于都是存量请求，请求逐渐被 _hang_住，致使量持续下掉，因此看上去感受请求变少了，由于并无多出流量。

4.其实线上故障一旦被定位以后，问题自己都很简单，一行不起眼的代码而已。因此咱们必须敬畏每一行代码。

做者：王清培（趣头条 Tech Leader）