把一次线上 502 查到底:从网关日志到应用链路

终端窗口中滚动的服务日志

从网关返回的一个 502 开始,按时间戳、连接复用与应用侧日志逐层对齐,找到真正断开的环节。

线上告警只在下午的高峰时段出现:网关侧 502 比例从 0.1% 抬升到 1.4%,应用侧却没有对应的异常日志。这类不对称的故障,最容易在一开始就查错方向。下面是我当时的完整排查顺序,以及最后定位到的那个差异。

01先确认 502 是谁返回的

502 只说明网关没有从上游拿到合法响应,不说明上游发生了什么。第一步不是翻应用日志,而是确认这份响应出自哪一层:反向代理、服务网格边车,还是应用进程。

  • 在网关侧把 502 请求按 upstream 地址分组,看是否集中在一个实例或一个可用区
  • 对照同一时刻的上游连接数与排队时长,区分“拒绝连接”和“读超时”
  • 确认响应体中是否带有网关自己的错误页特征,避免把上游透传的错误也算进来

一个可直接使用的日志格式

默认日志缺少关键字段时,补上 upstream 状态与耗时,才能把网关时间与业务时间对上。

nginx
log_format upstream_trace '$time_iso8601 $request_id '
  '$status $upstream_addr $upstream_status '
  '$upstream_connect_time $upstream_header_time '
  '$upstream_response_time $request_time';

02把时间轴对齐到应用侧

拿到 request_id 之后,在应用侧按这个 id 反查。此时常见的两种结果是:应用侧完全无记录(请求没进到进程),或应用侧有记录但很快中断(进程内异常退出)。这两种情况的后续路径完全不同。

现象可能原因验证方式
应用无 request_id 记录连接在网关与上游之间被重置核对 upstream_connect_time 与内核连接计数
有记录但无结束日志进程被重启或线程阻塞查看同一分钟的容器重启与 GC 记录
上游返回 499 或空响应客户端提前断开对照前端埋点的请求取消时间

容易忽略的差异:连接复用

这次的答案在连接池。网关与上游之间开启了长连接复用,而应用侧在发布后把空闲连接的回收时间调短了。网关仍持有已失效的连接,于是在高峰时段反复命中被对端关闭的套接字。日志上表现为 upstream_connect_time 极短、upstream_status 为空。

ts
const agent = new http.Agent({
  keepAlive: true,
  keepAliveMsecs: 15_000,
  maxSockets: 64,
});

server.keepAliveTimeout = 65_000;
server.headersTimeout = 66_000;

结论不是把某一侧的时间改大,而是让两端的空闲回收顺序一致:网关的空闲时间必须小于上游的 keepAliveTimeout,否则一定会出现“网关认为连接还活着、上游已经关闭”的窗口。

03复现与验证

  1. 01在预发环境把上游 keepAliveTimeout 调到 5 秒,网关保持默认值
  2. 02用固定并发压测,观察 upstream_status 为空的比例是否随空闲时长上升
  3. 03改回一致的配置后重跑同一压测脚本,对比 502 比例

排查的价值不只是修好这一次,而是让下一次同类问题能在五分钟内被指认出来。

— 本次故障复盘记录

04事后补上什么

修复之后做了三件小事:网关日志默认输出 upstream_status 与连接耗时;为“上游空响应”单独建一个告警维度;把连接池与超时参数的对应关系写进发布检查清单。前两件让问题可见,第三件让问题不容易被重新引入。

502 本身很少是根因。它更像一个提示:链路上有一层的状态没有被观测到。顺着缺口补观测,比顺着错误码猜原因更快。

SYANG

后端工程师 / 技术写作者

写服务端,也写把问题说清楚的过程。这里记录我在接口、数据与稳定性上的具体做法,以及做错的判断。

去关于我 →

相关文章

Related
← 返回文章列表