我是 LEE,老李,一个在 IT 行业摸爬滚打 16 年的技术老兵。
事件背景
最近得空,重新捡起 502 的事情。跟运维小伙伴沟通后,发现很多业务系统都存在一个“随机” 502 的问题,而且都定位不到问题所在。大团队为这个事情被核心业务组挑战了很长时间,我决定拦下这个事情,看看到底是什么原因,我也非常好奇是什么原因让这么多专家困扰,实际我也想破解下迷题。
现象获取
我们拉取了一个和业务核心网关的 traefik 的转发日志,过滤了下 502 的情况,数量非常少而且只有零星的几个,出现的时间点非常没有规律。
初步定位异常出现是随机行为,如此我们去检测后端业务的 Pod 状态,发现 Pod 的状态一直稳定,没有在异常时间内出现 Pod 的重启以及其他服务状态的异常的情况。随后再次检查应用 Pod 的日志内容,没有发现任何可疑的日志,甚至 502 出现的时候,应用日志都没有任何输出,证明流量没有到 Pod 内的服务上来,所以导致没有日志输出。
业务组和运维的小伙伴各持一词,都是觉得问题不会出现在自己的这边,最后大家陷入了“僵局”。我也陷入了沉思,为什么会出现这样的问题,都是觉得不是自己的问题,却都找不到强有力的证明方案,而且问题不能 100% 复现,也没有办法解决。
原理分析
在沉思片刻后,我觉得最复杂的问题导致的原因可能最简单,我决定换一个维度来思考这个问题。 既然是 502 的问题,那我们就从 http 协议上去找答案。翻找了一会,果不其然有了突破口。
状态码 | IP | 端口 | 响应 | 描述 |
---|---|---|---|---|
502 | × | × | × | Bad Gateway - 目标 ip 不可达 (可能是缺少网络、防火墙阻挡) |
503 | ✓ | × | × | Service Unavailable - 目标 ip 可达,但是 port 不可被连接 (可能是防火墙阻挡、服务监听端口没有正常启动) |
499 | ✓ | ✓ | × | Client has closed connection - 目标 ip,port 可达,但是没有回应(Response) (可能是防火墙阻挡、也可能是服务端处理的时间过长,客户端“不耐烦”了,先关闭连接) |
我们这次要解决的问题是 502 的问题,根据我上面总结的表格,就知道这个问题产生就需要知道几个重要的核心点:
- 确定 502 反馈回来的节点,一定是不是最末端的业务 Pod,一定是上层的转发层
- 定位断点后,要确认上下游之间的连接关系。因为 http 协议底层还是 tcp 协议,所以 tcp 那些让人烦心的事情还是要考虑起来(比如各种超时)
- 确定故障 Ip 为什么不可达的原因,以及触发场景,以及我们是否能够复现
然后与研发组小伙伴沟通,现在都是 HTTP 1.1 的 WebService,没有什么花头。 然后通过跟业务组和运维小伙伴反复确认架构,通过绘图,一步一步复盘可能出现异常的节点。通过结合表格,所有人发现,都是其中业务层的转发 Gateway 到其他的业务的 Pod 会存在这样问题。
既然缩小故障出现的范围,在这个小范围内,我继续归纳可能出现异常点,最后矛头全部指向了中间的 traefik,它极有可能是导致这个问题点。随后我们在对应的测试环境中部署了具备输出 502 异常原因的 traefik。 具体参看《traefik 诡异的 502 排除以及优化》这篇文章
正在大家争论的时候,我在 A4 纸上归总了下疑点:
- 业务 Pod 状态正常,没有出现任何异常,测试 Ip + Port 都是可达的
- Traefik 的日志中 "DownstreamStatus" 和 "OriginStatus" 都是 502,异常应该是后端 Pod 传入的
- 业务 Pod 在异常时,没有出现任何有效日志输出,流量存在可能到与没有到的可行性
其中 1 和 2 在网络层相悖,1 和 3 在业务层相悖
部署魔改的 traefik
通过更换原有业务的 Pod 的 traefik,我们开始监控出现 502 的真实报错原因。 经过一段时间的耐心等待,我们总算在日志检索的时候看到了 502 异常的原因。
我们看到图片中的 "cause by: EOF", EOF 这个错误表示 Socket 已经在 io 层面到了最后,另一意思是 Socket 已经关闭了。但是 traefik 还在继续使用这个 socket 转发流量,导致出现了 502 的异常。 通过对日志记录的 upstream 的 Ip 和业务 Pod 的 Ip 的对比,确实是同一个 Ip。至此我们确认了出现 502 的原因是 Socket 提前流量在转发情况下关闭了。
通过上面的图,我们总结下整个事情出现的过程。 Traefik 和 Pod 之间建立了 Tcp 连接 (Http 是基于 Tcp 协议),Traefik 和 Pod 之间使用的 HTTP 1.1 协议,自动被协商了长链接。在完成一轮数据包发送以后,Pod 因为某些原因(这些原因后面会提到)关闭了 Socket,然后在 Tcp 层面向 traefik 发送了 FIN,ACK 包,traefik 接收到了 FIN,ACK 包后, 向 Pod 发送 ACK 响应包,完成了 Socket 关闭动作。此时转发流程上层模块还没有及时更新状态,代转发的数据包继续往这个 Ip 发送。但是在发送的过程中,突然发现这个 Socket 已经关闭了,只能向客户端发送 502 的异常。
会导致 EOF 的可能原因:
- 后端服务器可能会突然发送 FIN,ACK 包,主动关闭了 Socket。
- 前、后端上配置的 http keepalive 的 idle timeout 时间不匹配,后端时间小于前端时间。
Tcpdump 抓包
为了得到最后的结论,我们在相关的环境中部署了 Tcpdump 抓包来验证整个过程是否正确。 在获得某次异常结果的时候抓包文件后,我看到了复合我判断证据。
在上面的 tcpdump 示例中,您可以看到以下内容:
- Packet 5992, 后端 Pod 收到一个 GET 请求
- Packet 6064, 响应是 200 OK.
- Packet 6084, 后端 Pod 收到另一个 GET 请求
- Packet 6154, 响应是 200 OK.
- Packet 6228, 后端 Pod 收到第三个 GET 请求
- 此时, 后端 Pod 返回了一个 FIN,ACK 且开始关闭连接
迷幻的转发链
假如我们在真实业务部署环境中存在这样一条类似的转发链,每一个节点往下转发都有一个 keepalive 的保持(idle timeout)时间(Tn)。
Client --T1--> L7 Proxy --T2--> L7 Proxy --T3--> .... L7 Proxy --Tn--> Pod
根据我们之前分析的内容和结论,我们可以得出这样一串时间表达式:T1 <= T2 <= T3 <= .... <= Tn
从而推到出一个治理理论:全网的转发链条在多层情况下,keepalive 的保持(idle timeout)时间需要全网规划,如果有一个环节出现异常,都会在某处触发 502 的异常出现。
有没有破局的办法呢? 有! 就是 Client 向 Pod 发送“心跳”包,刷新整个转发链中的 http keepalive 的 idle timeout 时间。
处理方法
通过一通复杂的分析与验证后,我这边对团队中小伙伴整体复盘异常,得到最后的结论:
- 修正链路上不合规的 http keepalive 的 idle timeout 时间,满足时间表达式
- 在代码中加入发送“心跳”包的功能
最终效果
最终拿出了转发中各个 L7 代理的 http keepalive 的 idle timeout 时间,然后逐一的修正,满足上面提到的“时间表达式”,业务组的 Pod 经过 48 小时的运行验证,随机 502 的情况在没有出现。当然还需要心跳”包的配合才能最终治本。