接口间断性 504 分析 (一)

刚进新公司就遇到一个很棘手的问题：线上一个接口每天 0.5% 左右的概率会出现 504，出现的时机也是随机的，每天大概有一到两个时间点会触发，非常诡异。

API 请求路径如下图所示，haproxy 做为网关，后端接两个 server，client 通过 haproxy 来访问 server 端的服务：

首先开始去查 haproxy 的日志，如下图所示，注意到第 1 行中的 504，以及前面的 12000ms，说明 server 端返回超时了，haproxy 超时时间为 2 分钟：

再看 server 端的日志，没有发现 504 对应的请求，最长的响应时间也不超过 15 秒，为什么 haproxy 会超时 120 秒呢？再去查 haproxy 的日志发现存在 504 的接口不止一个。

于是怀疑是不是 haproxy 主动断掉，再仔细检查日志，发现存在 sH 的标识，以下是对应的解释：

sH   
#服务器可以返回其响应头之前的“超时服务器”冲突。 
#这是最常见的异常，表示太长的事务，可能是由服务器或数据库饱和引起的。 
#立即的解决方法是增加“超时服务器”设置，但请务必记住，用户体验将遭受这些长时间的响应。 
#唯一的长期解决方案是修复应用程序。  
#参考：https://blog.csdn.net/chengfei112233/article/details/78983041

这就否定了 haproxy 本身的问题，haproxy 确实是等了 120 秒，server 没有响应。

那是不是 server 端出现了什么问题，导致不能返回给 haproxy 正确的响应呢？server 的应用日志里没有现象，接下来就可以充分怀疑 tcp 本身的机制导致的响应丢弃，网上搜索了下，发现这个参数 tcp_tw_recycle 与 tcp_timestamps 这两个参数同时开启时，在 NAT 环境会出现连接失败的情况。
(60 秒内，连接两个相同的请求（四元组一致:源 IP/端口 + 目标 IP/端口），后一个时间戳的请求，会被忽略。缓存每个连接最新的时间戳，后续请求中如果时间戳小于缓存的时间戳，即视为无效，相应的数据包会被丢弃。)

那我们是不是也是这样的原因呢？查了下参数确实都配置了，并且也 netstat 存在 reject 的日志，确实跟这个问题很像。与领导沟通了下，觉得这个问题最好还是抓包确认下，不能盲目参照别人经验。于是接下来开始了抓包之旅。

抓包下来，分析却发现 TCP 连接是没问题的，TCP 包序列并没有发现参数导致的大量异常序列（TCP Retransmission），但是应用就是没有返回，真的是非常诡异。

再去分析应用截取日志，通过 IP 与端口对应到请求：

从上面两张图可以清楚的看到：haproxy 断开连接后，应用才收到请求，非常诡异。

从以上对网络层面的分析，能推断出 centos 在 TCP 握手后，没有将后续的请求推送到应用。但是接下来怎么排查，真的是一点思路都没有。但是问题仍然存在，分析不能停止，于是向运维申请了一些服务器监控的权限，试图从 zabbix 上再找到些蛛丝马迹。结果仍然没有收获。

这时候怀疑是不是服务器性能比较差，压力抗不住，因为只有其中一台配置比较差的 504 的情况很多，而且每天可能就一到两个时间点会爆发。于是将 haproxy 的负载又做了调整，调整成了 8：2，将 504 的那台服务器的比例调整低了。

观察了一周时间，并没有发现 504 有任何明显的降低，这充分说明并非负载导致的 504。而且发现一个现象，当问题出现后，明显发现 linux 的剩余内存少了非常多，只有大概几十 M。

初步怀疑存在内存泄露，但是 JVM 并没有错误迹象，并且检查 gc 日志都是正常的，非常奇怪。最终，向运维申请加了一台服务器，三台服务器的比例调整成 6：2：2，观察了一周，发现 504 仍然存在，但是只会出现在那台一直报 504 的机器上。再观察一段时间，会把 504 多的那台设备下掉。

下面是三台机器的内存情况：

明显发现最上面一台可用内存很少，504 到此为止算是解决了。

总结一下，针对间断性 504 的异常问题，分别从网络、日志、监控、参数、命令等多个途径寻找异常点，来确定问题产生原因。最终结论是系统剩余内存太小，导致网络请求一直停留在系统层面，没有到达应用，超过了 haproxy 的超时限制。

其实还是走了一些弯路的，一开始就怀疑过内存，但是这个结论难以令人信服，所以先排除应用本身的问题后，才推动资源去通过替换服务器的方式解决该问题。

2018-12-25 续：
真的解决了么？其实并没有，真正的原因在下一篇总结。