总结
事故经过【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 导出来的连接信息。