用 Node 的 AsyncLocalStorage 打请求日志,我踩了三个坑

服务跑在 Node 18.17,Koa 2 起的 HTTP 服务,日志用 pino。之前每个请求入口手动生成一个 traceId,一路当参数往下传,传到第五层 service 的时候就开始有人忘了带。后来换成 AsyncLocalStorage 存上下文,入口中间件里 run 一个 store,业务代码直接取,看起来能一劳永逸。

做法很简单,一个模块管上下文:

// ctx.js
import { AsyncLocalStorage } from 'node:async_hooks';
const als = new AsyncLocalStorage();
export const runWithCtx = (ctx, fn) => als.run(ctx, fn);
export const getCtx = () => als.getStore();

Koa 入口中间件:

app.use(async (ctx, next) => {
  const traceId = ctx.get('x-trace-id') || crypto.randomUUID();
  await runWithCtx({ traceId }, async () => {
    ctx.state.traceId = traceId;
    await next();
  });
});

pino 这边加个 mixin,每次打日志自动带上:

const logger = pino({
  mixin() {
    const c = getCtx();
    return c ? { traceId: c.traceId } : {};
  },
});

上线后日志里 traceId 基本都有了,但踩了三个坑。

第一个是定时任务。有个每分钟跑的 job 调了同一个 service,日志里 traceId 全是 undefined。原因很直白:AsyncLocalStorage 只在 run 的回调链里有效,定时器回调不在任何请求的链路里。后来在 job 外面也包一层 runWithCtx({ traceId: ‘job:xxx’ }),才统一。

第二个是连接池和缓存。我一开始把 store 塞得比较满,连 request 对象、用户信息都放进去,结果某个全局 Map 缓存里存了带 store 引用的对象,内存曲线慢慢往上走。AsyncLocalStorage 的 store 是跟着异步上下文活的,别把长生命周期的东西挂在上面,只放 traceId、userId 这种小字段,其他按需查。

第三个最隐蔽:用 Promise.all 并发发下游请求时,日志顺序和 traceId 都正常,但有一次某个第三方 SDK 内部用了 process.nextTick 加老式回调,回调里 getCtx() 拿到的是外层另一个请求的 store。排查了很久,最后确认是那个 SDK 自己缓存了回调函数。换掉 SDK 后就好了。所以第三方库如果大量用回调、事件订阅模型,上下文可能串。

代价也要说清楚:AsyncLocalStorage 有额外开销,官方文档也提过,高 QPS 下每个请求 run 一次不是零成本。我压测过本地简单接口,QPS 大概掉 5% 左右,业务能接受,但如果是对延迟极敏感的服务,得自己测。

边界大概是这样:纯 async/await 链路很稳;定时器、事件订阅、老回调、worker 线程之间不自动传递,worker_threads 里是另一个上下文,得手动把 traceId 传进去再 run。

现在想问的是:你们在生产里怎么处理跨 worker 或跨进程的 trace 传递?是只在消息体里带 traceId 重新建上下文,还是有更省事的做法?

0
赞同度 100% · 0 条评论 · 11 阅读

0 条评论

支持 Markdown · 回复会实时推送给对方

还没有评论,写下第一条。