Node.js Server 偶发的神秘 404 告警排查

image

问题简述

业务方反馈自己负责的服务端渲染项目出现了少量的 404 告警, 约 0.0677% 的量。听到这个问题描述还是比较惊讶, 印象中 404 可能是唯一不会出现的状态码, 原因如下

  1. 进入 Node 服务的请求都是事先注册好了的路由, 没有注册的路由到网关就会被拦截, 流量到不了 Node 就谈不上 404
  2. 告警详情中发现出现 404 的路由在线上稳定运行已久，已知肯定存在的路由为何会 404 ?

问题排查

难道是 Node Server 代码在某种条件下主动设置了 statusCode 为 404 ?

答案是否定的 ❌, 类似如下模拟的 Node Server 最简实现, 从代码初步判断只可能出现 render 正常渲染设置的 200 或者渲染错误 error 设置的 500 状态码

on-finished: Execute a callback when a HTTP request closes, finishes, or errors.

onFinished 回调函数中为本次 404 告警上报处 ⚠️（链路追踪中发现此时 error 中间件却没有上报渲染出错的记录）

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
// Node Server Demo

const Koa = require("koa");
const onFinished = require("on-finished")

function report(msg) {
    console.log(msg)
}
async function error(ctx, next) {
    try {
        await next()
    } catch (err) {
        ctx.status = 500
        report(`本次渲染出错: errorMsg: ${err.message}`)
    }
}
async function render(ctx, next) {
    await new Promise(res => {
        setTimeout(() => {
            ctx.body = "ok"
            ctx.status = 200;
            res()
        }, 100) // 模拟服务端渲染等待 100ms
    })
    await next()
}
async function monitor(ctx, next) {
    onFinished(ctx.res, (err, res) => {
    	// >>> 本次 404 告警处 <<<
        report(`本次请求 success: ${!err && res.statusCode >= 200 && res.statusCode < 400}, statusCode: ${res.statusCode}`)
    })
    await next()
}

const app = new Koa();
app.use(error)
app.use(monitor)
app.use(render)
app.listen(3000)

当然实际 Node Server 代码远比 Demo 复杂得多, 所以 k同学先在可能会抛错的代码与可能存在逻辑漏洞的代码处追加了日志, 反复上线了几次也没有找到比较有价值的线索

此时都在想是不是可以放弃排查了, 0.0677% 的量也不是很多, 但是对这种诡异的现象又充满了好奇

于是我陷入了一阵沉思与回想, 在 k同学严密的日志中问题应该会无所遁形才对, 那么 假设追加的日志所监控的代码就是一切正常没有抛错, 那么可能发生的情况就是错误在日志覆盖不到的地方或者是客户端的异常导致?

根据这个假设前提我就想到了一种可能, 比如用 Node 作为 Client 并且使用 AbortController 来提前终止 tcp 连接进行验证

1
2
3
4
5
6
7
8
9
10
11
12
13
14
// Node Client Demo

const fetch = require('node-fetch')
let controller = new AbortController()
const signal = controller.signal

setTimeout(() => {
  controller.abort()
}, 50) // 小于 render 的 100ms 即可

fetch('http://localhost:3000', {
  signal,
  method: 'GET',
})

按照如上作为验证的 Client Demo, 那么完整的事故过程就是

  1. Client 发起请求（如浏览器新开 Tab 输入网页地址）
  2. Server 收到请求开始进行 render 等处理流程
  3. Client abort 了请求（如浏览器关闭了网页 Tab）
  4. Server 收到 abort -> tcp 连接即将断开 -> onFinished 回调被调用, 上报了此时的状态码为 Koa 初始状态的 404 -> tcp 连接断开
  5. Server 渲染结束, 设置响应 body 与状态码为 200, 由于 tcp 连接已经断开, 此时的设置没有了意义

这里我们也可以把 Node.js Server Demo 的 render 时间从 100ms 改为 3s, 然后使用浏览器作为 Client 模拟用户打开 http://localhost:3000, 最后在 3s 内关闭网页 Tab 也能复现该过程 ✅

1
本次请求 success: false, statusCode: 404

问题结论

on-finished 函数很实用, 但是不要忽略了 aborted 的情况。后续可以优化为 aborted 后单独上报一条记录, 监控 aborted 的量在一定预值即可

1
2
3
4
5
6
7
8
async function monitor(ctx, next) {
    onFinished(ctx.res, (err, res) => {
+        ctx.req.aborted && report("client aborted!")
+        report(`本次请求 success: ${ctx.req.aborted || (!err && res.statusCode >= 200 && res.statusCode < 400)}, statusCode: ${res.statusCode}`)
-        report(`本次请求 success: ${!err && res.statusCode >= 200 && res.statusCode < 400}, statusCode: ${res.statusCode}`)
    })
    await next()
}

on-finished: Execute a callback when a HTTP request closes, finishes, or errors.

其实回头想想, 如果能先彻底理解 on-finished 的定义与行为应该会少走一些弯路。一开始就下意识的认为 on-finished 只监听了 response 的 finish 事件, 仔细一瞧它的定义, 还包括了 close（aborted 是触发了该行为导致的连接提前关闭）以及 error 事件, on-finished 监听的所有事件见如下代码
image