Open xiaoxiaojx opened 1 year ago
业务方反馈自己负责的服务端渲染项目出现了少量的 404 告警, 约 0.0677% 的量。听到这个问题描述还是比较惊讶, 印象中 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 中间件却没有上报渲染出错的记录)
// 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 连接进行验证
// 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, 那么完整的事故过程就是
这里我们也可以把 Node.js Server Demo 的 render 时间从 100ms 改为 3s, 然后使用浏览器作为 Client 模拟用户打开 http://localhost:3000, 最后在 3s 内关闭网页 Tab 也能复现该过程 ✅
本次请求 success: false, statusCode: 404
on-finished 函数很实用, 但是不要忽略了 aborted 的情况。后续可以优化为 aborted 后单独上报一条记录, 监控 aborted 的量在一定预值即可
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 的定义与行为应该会少走一些弯路。一开始就下意识的认为 on-finished 只监听了 response 的 finish 事件, 仔细一瞧它的定义, 还包括了 close(aborted 是触发了该行为导致的连接提前关闭)以及 error 事件, on-finished 监听的所有事件见如下代码
问题简述
业务方反馈自己负责的服务端渲染项目出现了少量的 404 告警, 约 0.0677% 的量。听到这个问题描述还是比较惊讶, 印象中 404 可能是唯一不会出现的状态码, 原因如下
问题排查
难道是 Node Server 代码在某种条件下主动设置了 statusCode 为 404 ?
答案是否定的 ❌, 类似如下模拟的 Node Server 最简实现, 从代码初步判断只可能出现 render 正常渲染设置的 200 或者渲染错误 error 设置的 500 状态码
onFinished 回调函数中为本次 404 告警上报处 ⚠️(链路追踪中发现此时 error 中间件却没有上报渲染出错的记录)
当然实际 Node Server 代码远比 Demo 复杂得多, 所以 k同学先在可能会抛错的代码与可能存在逻辑漏洞的代码处追加了日志, 反复上线了几次也没有找到比较有价值的线索
此时都在想是不是可以放弃排查了, 0.0677% 的量也不是很多, 但是对这种诡异的现象又充满了好奇
于是我陷入了一阵沉思与回想, 在 k同学严密的日志中问题应该会无所遁形才对, 那么 假设追加的日志所监控的代码就是一切正常没有抛错, 那么可能发生的情况就是错误在日志覆盖不到的地方或者是客户端的异常导致?
根据这个假设前提我就想到了一种可能, 比如用 Node 作为 Client 并且使用 AbortController 来提前终止 tcp 连接进行验证
按照如上作为验证的 Client Demo, 那么完整的事故过程就是
这里我们也可以把 Node.js Server Demo 的 render 时间从 100ms 改为 3s, 然后使用浏览器作为 Client 模拟用户打开 http://localhost:3000, 最后在 3s 内关闭网页 Tab 也能复现该过程 ✅
问题结论
on-finished 函数很实用, 但是不要忽略了 aborted 的情况。后续可以优化为 aborted 后单独上报一条记录, 监控 aborted 的量在一定预值即可
其实回头想想, 如果能先彻底理解 on-finished 的定义与行为应该会少走一些弯路。一开始就下意识的认为 on-finished 只监听了 response 的 finish 事件, 仔细一瞧它的定义, 还包括了 close(aborted 是触发了该行为导致的连接提前关闭)以及 error 事件, on-finished 监听的所有事件见如下代码