线上告警只在下午的高峰时段出现:网关侧 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复现与验证
- 在预发环境把上游 keepAliveTimeout 调到 5 秒,网关保持默认值
- 用固定并发压测,观察 upstream_status 为空的比例是否随空闲时长上升
- 改回一致的配置后重跑同一压测脚本,对比 502 比例
排查的价值不只是修好这一次,而是让下一次同类问题能在五分钟内被指认出来。
04事后补上什么
修复之后做了三件小事:网关日志默认输出 upstream_status 与连接耗时;为“上游空响应”单独建一个告警维度;把连接池与超时参数的对应关系写进发布检查清单。前两件让问题可见,第三件让问题不容易被重新引入。
502 本身很少是根因。它更像一个提示:链路上有一层的状态没有被观测到。顺着缺口补观测,比顺着错误码猜原因更快。
