NestJS 日志中间件与 TraceId 链路追踪实战

排查问题到深夜是后端开发常有的事尤其是服务一多、日志一杂的时候。日志文件里你能看到一堆“用户下单失败”“支付回调超时”但偏偏不知道这些日志来自哪个请求、先经过了谁、再到哪儿去。要解决这个问题最朴素有效的一招就是给每个请求发一张唯一的身份证——TraceId。这篇文章就把我在生产环境里落地的 NestJS 日志中间件与 TraceId 链路追踪方案完整拆开讲一遍从中间件的设计思路、AsyncLocalStorage 的上下文传递到业务代码里怎么无感地给日志加上 TraceId再到下游服务怎么把 ID 往后传。中大型后端项目、或者正准备做可观测性的开发同学都可以直接参考。1. 为什么每个请求都该有一张“身份证”1.1 没有 TraceId 时的日志混乱现场先还原一个非常常见的场景你的接口服务在一台实例上同时处理几十个请求每个请求内部会打十几条日志包括缓存查询、数据库访问、外部接口调用等等。没有 TraceId 的时候日志输出大概是这样的[Nest] LOG [OrderService] 查询订单 10086 成功 [Nest] LOG [PaymentService] 微信支付回调解析失败 [Nest] ERROR [UserService] 用户积分更新异常 [Nest] LOG [OrderService] 订单 10086 状态变更为已支付这几条日志看起来都发生在同一秒但你根本分不清它们是不是同一个请求产生的。如果“订单状态变更”和“支付回调失败”来自两个不同用户那排查问题的方向就完全不一样了。更麻烦的是当你按关键字去日志平台里筛比如筛“订单 10086”你可能会捞出来一堆历史请求的记录因为它们都操作过这个订单号。这时候你只能靠时间戳、线程名去猜效率非常低。微服务场景下这个问题更严重——请求会跨服务流转日志分散在 A 服务的文件、B 服务的容器、C 服务的队列里你需要在多个系统间来回切换手动拼凑整个调用链。没有 TraceId日志本质上就是“一堆文字”而不是“一条条有归属的执行轨迹”。这种状态下做线上问题定位靠的是经验和运气而不是系统和工具。1.2 TraceId 的价值不止是日志TraceId 的核心作用是让同一次请求产生的所有日志拥有同一个唯一标识。比如上面那个场景加了 TraceId 之后日志长这样[Nest] LOG [OrderService] [TraceId: 7a9c2f3e...] 查询订单 10086 成功 [Nest] LOG [PaymentService] [TraceId: 7a9c2f3e...] 微信支付回调解析失败只要在日志平台里按TraceId: 7a9c2f3e搜索整个请求链路的所有日志就能一次性捞出来按时间排序马上能看出问题出在哪一步。除此之外TraceId 还有一个容易被忽略的价值它是对外沟通的“凭证”。当用户在前端操作遇到异常你把响应头里的x-trace-id给到客服后端人员直接拿这个 ID 去日志平台检索就能快速定位用户当时请求到底发生了什么。这比让用户口头描述“我点了按钮没反应”要高效得多。从一个合格 TraceId 的角度看它至少需要满足几个底线全局唯一、生成成本低、不能包含敏感信息。我通常直接用 Node.js 内置的randomUUID()生成格式统一、无需引入额外依赖完全够用。1.3 有了 TraceId距离全链路追踪还差什么TraceId 只是第一步。现实中的请求不可能只停留在一个服务内部它一定会调用下游接口、写消息队列、触发定时任务。这时候 TraceId 必须能跨服务、跨异步边界传递——上游服务把 ID 塞进 HTTP Header下游服务读取并用它作为自己日志的 TraceId这样整条链路才能串起来。这也是为什么很多团队一开始觉得“加个日志 ID 很简单”但做深之后发现水很深。TraceId 的生成和写入本身不难难的是上下文传递的可靠性。你在 Controller 里能轻松打印出 TraceId但业务代码里的一个setTimeout、一个Promise.all、一个消息队列消费者可能就把上下文弄丢了。所以方案选型比实现本身更重要。2. 整体方案选型与设计思路2.1 中间件、拦截器、守卫到底该选谁在 NestJS 里要在请求进入业务逻辑之前统一处理日志有几个选择中间件Middleware、守卫Guard、拦截器Interceptor。很多新手会纠结用哪个我直接说结论日志和 TraceId 这种最通用的横切关注点优先用中间件。中间件在 NestJS 请求管线里是执行最早的环节比守卫和拦截器都靠前。它天然适合做以下这类事情解析请求头、生成上下文、记录访问日志、打印请求耗时。而且中间件是基于 Express 底层的能力注册方式简单想要匹配哪些路由可以精确控制。守卫适合做权限校验因为它能拿到ExecutionContext可以方便地读取Roles()这类装饰器元数据拦截器适合做响应映射、缓存、事务包裹因为它可以操作Observable流。如果你把 TraceId 生成逻辑放在拦截器里虽然也能用但链路中所有比拦截器更早执行的代码比如全局中间件里的日志就拿不到 TraceId 了。方案执行时机适合场景TraceId 适用性中间件 Middleware最早路由匹配前日志、请求头解析、通用上下文最合适覆盖范围最大守卫 Guard中间件之后路由处理前权限认证、角色校验可以做但时机偏晚拦截器 Interceptor路由处理前后均可响应转换、日志、事务可以做但拿不到更早的日志上下文所以我的方案是TraceId 中间件负责生成和注入自定义 Logger 负责读取和输出两边配合各司其职。2.2 请求上下文该存哪AsyncLocalStorage 是正解有了中间件下一个关键问题是怎么把 TraceId 安全地传给后面的所有业务代码。很多人第一反应是“直接把 TraceId 挂到req上不就行了”比如req.traceId xxx。这种做法在简单的同步链路里确实能用但有一个隐患你的业务代码并不是所有地方都能拿到req。举几个例子你在 Service 里发起了一个异步任务回调函数里不是总能拿到req你写了一个定时任务它根本没有req你在消息队列消费者里反序列化业务对象里面也不会带着req。要解决这个问题靠显式传参是最笨的——你会在每个函数签名里加一个traceId参数改起来非常痛苦。这里我的选择是 Node.js 自带的AsyncLocalStorageALS。你可以把它理解成一个“线程局部变量”不过在 Node.js 的异步模型里它更强大在run回调里创建的 Promise、定时器、事件监听器都能自动继承这个上下文。也就是说你在中间件里用als.run({ traceId }, () next())包住整个请求链路后面无论异步怎么嵌套只要在同一个请求的异步资源里都能通过als.getStore()拿到同一个 TraceId。用生活化的类比来解释传统传参就像每个人手里拿一张纸条走到哪都要主动递给下一个人很容易丢而 AsyncLocalStorage 就像在请求头上戴了一个看不见的光环同一个请求产生的所有异步任务都会自动带上这个光环。你不需要显式传递随时读一下光环就能拿到 TraceId。2.3 日志底层用内置 Logger 还是引入 pinoNestJS 自带了一个Logger开箱即用控制台输出带颜色、带时间戳中小型项目完全够用。但在生产环境我通常建议把日志输出成 JSON 结构化格式方便日志平台采集和查询。这时候可以考虑两类方案方案优点缺点适用场景NestJS 内置 Logger无额外依赖、接入简单默认非结构化性能一般中小项目、快速验证pino pino-http性能极高、原生 JSON 输出需要额外配置和 Nest 集成稍复杂中大型项目、日志采集winston生态成熟、输出格式丰富体积较大性能略逊于 pino已有 winston 技术栈的团队这篇文章的主体实现用 NestJS 内置 Logger 做演示因为它的思路可以平移到任何日志框架上。后面第 4 部分我会补一段怎么把getCurrentTraceId()塞进 pino 的结构化字段里方便你迁移到生产级方案。3. 核心实现TraceId 中间件与日志封装3.1 先搭一个 Trace 上下文模块我习惯把 TraceId 相关的逻辑独立成一个模块不污染业务代码。目录结构大致这样src/ ├── common/ │ ├── middleware/ │ │ └── trace-id.middleware.ts │ └── logger/ │ ├── trace-logger.service.ts │ └── logger.module.ts先在trace-id.middleware.ts里定义全局唯一的AsyncLocalStorage实例和工具函数// src/common/middleware/trace-id.middleware.ts import { AsyncLocalStorage } from async_hooks; import { randomUUID } from crypto; import { Injectable, Logger, NestMiddleware } from nestjs/common; import { NextFunction, Request, Response } from express; export interface TraceContext { traceId: string; } export const traceContext new AsyncLocalStorageTraceContext(); export function generateTraceId(): string { return randomUUID(); } export function getCurrentTraceId(): string | undefined { return traceContext.getStore()?.traceId; }这里有一个很重要的细节AsyncLocalStorage实例必须在模块级别导出成单例。如果你在多个文件里各自new AsyncLocalStorage()那不同模块之间就看不到同一个上下文了。3.2 实现 TraceId 中间件中间件是整个方案的入口。它需要做三件事从上游请求头里读取已有的 TraceId没读到就自己生成一个把最终生效的 TraceId 写进响应头用ALS.run包住next()让后续所有异步任务都能拿到上下文。// src/common/middleware/trace-id.middleware.ts Injectable() export class TraceIdMiddleware implements NestMiddleware { private readonly logger new Logger(TraceIdMiddleware.name); use(req: Request, res: Response, next: NextFunction) { const headerTraceId req.headers[x-trace-id]; const traceId Array.isArray(headerTraceId) ? headerTraceId[0] : headerTraceId ?? generateTraceId(); // 响应头总是带上当前生效的 TraceId方便调用方直接获取 res.setHeader(x-trace-id, traceId); const startAt process.hrtime.bigint(); const { method, originalUrl, ip } req; res.on(finish, () { const durationMs Number(process.hrtime.bigint() - startAt) / 1e6; const statusCode res.statusCode; this.logger.log( [HTTP] ${method} ${originalUrl} ${statusCode} ${durationMs.toFixed(2)}ms ip${ip} ); }); traceContext.run({ traceId }, () { next(); }); } }这个中间件有几个值得注意的细节第一优先沿用上游的x-trace-id。在企业级架构里流量往往先经过网关网关会生成全局唯一的 TraceId。如果业务服务忽略它、自己重新生成那网关和后端服务的日志就接不上了。记住一个原则上游有 ID就复用上游没有才生成。第二要用res.on(finish)而不是直接写在next()后面。因为next()之后业务代码是异步的如果你在中间件里立即记录访问日志拿到的响应状态码和耗时都是不对的。finish事件会在响应真正发送给客户端时触发这时候状态码、耗时都是准确的。第三IP 字段我直接取了req.ip。如果线上服务有反向代理需要确认 Express 的trust proxy配置是否正确否则拿到的可能是代理的 IP 而不是真实客户端 IP。这个坑后面还会提到。再啰嗦一句为什么要在ALS.run里调用next()如果你把next()放在run外面中间件自己是有 TraceId 的但后续所有业务异步任务就都拿不到上下文了。这一点是整篇文章最重要的细节之一。3.3 封装自动携带 TraceId 的 LoggerService中间件生成了 TraceId第三步是让日志输出自动带上它。我选择包装 NestJS 内置的Logger这样业务代码不需要改成this.logger.log(traceId, msg)只要按平时的写法输出日志TraceId 就会自动拼进去。// src/common/logger/trace-logger.service.ts import { Injectable, Logger } from nestjs/common; import { getCurrentTraceId } from ../middleware/trace-id.middleware; Injectable() export class TraceLoggerService extends Logger { log(message: any, context?: string, overrideTraceId?: string) { super.log(this.formatMessage(message, overrideTraceId), context); } error(message: any, stackOrContext?: string, context?: string) { super.error(this.formatMessage(message), stackOrContext, context); } warn(message: any, context?: string, overrideTraceId?: string) { super.warn(this.formatMessage(message, overrideTraceId), context); } debug(message: any, context?: string, overrideTraceId?: string) { super.debug(this.formatMessage(message, overrideTraceId), context); } verbose(message: any, context?: string, overrideTraceId?: string) { super.verbose(this.formatMessage(message, overrideTraceId), context); } private formatMessage(message: any, overrideTraceId?: string): string { const traceId overrideTraceId ?? getCurrentTraceId() ?? -; return [TraceId: ${traceId}] ${message}; } }这段代码的核心在formatMessage方法里先尝试拿当前异步上下文里的 TraceId拿不到就显示-。这保证了即使在一些非请求触发的场景里比如 NestJS 启动时的日志也不会因为缺 TraceId 而报错。细心的你可能会发现error方法里我没有处理overrideTraceId因为 NestJS 内置Logger.error(message, stack?, context?)的参数语义本身就有点绕第二参数在传了第三参数时表示“堆栈”在只传两个参数时又常常被当成“上下文”用。为了演示代码尽量简洁这里保持原参数结构你已经能通过formatMessage自动拿 TraceId 了。实际生产中可以按团队约定进一步封装重载。有了这个类接下来要把它注册成 NestJS 的依赖注入替身覆盖原来的Loggertoken// src/common/logger/logger.module.ts import { Global, Module } from nestjs/common; import { Logger } from nestjs/common; import { TraceLoggerService } from ./trace-logger.service; Global() Module({ providers: [ { provide: Logger, useClass: TraceLoggerService, }, ], exports: [Logger], }) export class LoggerModule {}这里用了Global()让所有模块都不需要显式导入LoggerModule就能注入增强后的 Logger。{ provide: Logger, useClass: TraceLoggerService }的意思是凡是注入Loggertoken 的地方实际拿到的都是TraceLoggerService实例。业务代码不需要改任何东西只要用构造器注入Logger日志就会自动带 TraceId。3.4 请求级访问日志与业务日志联动中间件里的访问日志和业务代码里的业务日志现在都能自动带上 TraceId 了但有一个问题中间件里的访问日志是在res.on(finish)回调里打的异步上下文是否还能读到答案是“能”。AsyncLocalStorage的上下文会传播到事件监听器的回调里这恰好就是它比手动传参更省心的原因之一。所以上面中间件代码里this.logger.log([HTTP] ...)是可以正确输出 TraceId 的。如果你实在担心某个特殊环境里事件回调读不到上下文也可以把 TraceId 存到闭包变量里手动拼进消息。两种方式都能跑但用 ALS 的方式更统一业务代码里隐式获取上下文才是它的价值所在。在业务 Controller 里的使用非常简单// src/app.controller.ts import { Controller, Get, Logger } from nestjs/common; Controller() export class AppController { constructor(private readonly logger: Logger) {} Get() getHello(): string { this.logger.log(这个日志会自动携带 TraceId, AppController.name); return Hello NestJS; } }运行时控制台输出类似[Nest] LOG [AppController] [TraceId: 7a9c2f3e-8b1d-4a5e-9c2f-3e8b1d4a5e9c] 这个日志会自动携带 TraceId 0ms如果调用方传了x-trace-id: abc-123输出的 TraceId 就会变成abc-123因为中间件优先沿用上游 ID。这为后面的跨服务传递打下了基础。3.5 全局注册中间件最后一步在根模块里注册中间件。需要注意的是中间件的注册必须在实现NestModule接口的模块里通过configure()方法完成通常是AppModule// src/app.module.ts import { MiddlewareConsumer, Module, NestModule } from nestjs/common; import { TraceIdMiddleware } from ./common/middleware/trace-id.middleware; import { LoggerModule } from ./common/logger/logger.module; Module({ imports: [LoggerModule], }) export class AppModule implements NestModule { configure(consumer: MiddlewareConsumer) { consumer .apply(TraceIdMiddleware) .forRoutes(*); } }forRoutes(*)表示对所有路由生效。如果你希望某些路径不走 TraceId比如健康检查可以用.exclude()方法排除但我的建议是一开始先用*把全量请求都纳入追踪等日志量确实大到需要裁剪时再按路径优化。到这里最核心的闭环已经完成了请求进来 → 中间件生成/读取 TraceId → ALS 注入上下文 → Logger 自动读取并打印 → 响应头返回 TraceId 给调用方。这套流程跑通之后再去处理跨服务和异步场景会从容很多。4. TraceId 的跨边界传递实战4.1 向下游 HTTP 服务透传 TraceId实际业务很少只有一个服务。订单服务要调库存服务库存服务要调商品服务每一个环节都要保持同一个 TraceId 才能在日志平台里做全链路检索。核心思路就是当前服务从 ALS 里取出 TraceId放进请求下游的 HTTP Header 里下游的 TraceId 中间件会优先读取并沿用。如果你用的是 Node.js 原生fetch可以这样写import { getCurrentTraceId } from ../common/middleware/trace-id.middleware; async function callDownstream() { const traceId getCurrentTraceId(); const res await fetch(http://service-b/api/stock, { headers: traceId ? { x-trace-id: traceId } : {}, }); return res.json(); }如果你用的是nestjs/axios最好在 Axios 实例上注册一个请求拦截器这样所有下游请求都会自动带上 TraceId不用每个方法手动加。// http.trace.interceptor.ts import { AxiosInterceptor, InternalAxiosRequestConfig } from axios; import { getCurrentTraceId } from ../common/middleware/trace-id.middleware; export const traceIdAxiosInterceptor: AxiosInterceptor ( config: InternalAxiosRequestConfig ) { const traceId getCurrentTraceId(); if (traceId) { config.headers.set(x-trace-id, traceId); } return config; };然后在模块初始化时注册到 Axios 实例上。这样只要是在当前请求上下文里发起的 HTTP 调用下游就能收到同一个 TraceId。下游服务只要也部署了同样的 TraceId 中间件整条调用的日志就能无缝串起来。这里要特别注意一定要在请求上下文中调用下游接口。如果你在一个没有经过中间件的异步任务里调下游getCurrentTraceId()返回的是undefined那就不会带 ID 了。解决方案可以参考下面的定时任务场景。4.2 定时任务与消息队列场景的上下文注入定时任务和消息队列监听器没有 HTTP 请求自然不会有 TraceId。但这类任务往往也是排查问题的重点。我的做法是在任务开始的地方手动创建 TraceId 并run一个上下文。import { Cron, CronExpression } from nestjs/schedule; import { randomUUID } from crypto; import { traceContext } from ../common/middleware/trace-id.middleware; Injectable() export class ReportTask { Cron(CronExpression.EVERY_HOUR) async generateReport() { const traceId randomUUID(); await traceContext.run({ traceId }, async () { // 这里面的所有日志都会带上同一个 TraceId this.logger.log(开始生成报表); const data await this.fetchData(); this.logger.log(生成报表完成共 ${data.length} 条); }); } }这样处理的好处是定时任务里的执行链路也拥有了可追踪的 ID。一旦某个报表任务生成的数据异常你就能根据任务日志里的 TraceId 把整个执行过程捞出来。消息队列消费者也可以套用同样的思路在rabbitmq或kafka的 message consumer 回调里优先从消息头里读取 TraceId没有则生成然后用traceContext.run包裹处理逻辑。只要做到“每个业务入口都有上下文兜底”TraceId 的覆盖范围就会非常完整。4.3 接入结构化日志走向生产如果你准备把日志接入 ELK 或云日志平台内置 Logger 的纯文本格式就不太方便了。结构化的 JSON 日志才是生产环境的主流。这时可以考虑引入 pino并把 TraceId 作为 JSON 字段输出。以nestjs-pino为例核心配置思路是给 pino 加一个 mixin把当前 ALS 里的 TraceId 注入到每一条日志记录里import { LoggerModule as PinoLoggerModule } from nestjs-pino; import { getCurrentTraceId } from ./common/middleware/trace-id.middleware; PinoLoggerModule.forRoot({ pinoHttp: { mixin() { return { traceId: getCurrentTraceId() ?? - }; }, }, })这样最终输出到日志平台的每一条记录都会带traceId字段查询的时候直接按字段过滤比全文搜索高效得多。中间件的生成逻辑完全不用改跨服务透传逻辑也不需要改只是日志的“展示形态”升级了。如果你已经用上了 APM 工具比如 SkyWalking、JaegerTraceId 还可以和 APM 中的 Trace 对应起来。当然这不是这篇文章的重点但有了基础 TraceId 之后再往上报链路数据会非常顺滑。5. 常见问题与避坑指南5.1 日志里的 TraceId 变成“-”最常见的排查结论就是中间件没有生效或者业务日志没走注入的 Logger。先确认中间件是否注册成功。如果你在AppModule里实现了NestModule.configure()但配置中间件的模块本身没有加载到应用里那forRoutes(*)自然不会执行。打印一下进入中间件的标志日志是最快的验证方式。再确认业务代码里注入的 Logger 是否被覆盖过。如果你在业务类里直接import { Logger }然后Logger.log(xxx)那走的是静态方法永远不会经过TraceLoggerService。正确姿势是通过构造函数注入private readonly logger: Logger让 NestJS 把TraceLoggerService实例交给你。还有一种情况是异步上下文真的丢了。如果你看到同一个请求的前半段有 TraceId、后半段变成-大概率是某个异步操作绕过了 ALS 的传播。常见的坑包括你手动new AsyncLocalStorage()脱离了模块单例、你在run外部启动了 Promise、或者你把next()放到了run外面。5.2 响应内容里有 TraceId但前端读不到TraceId 放在响应头里但浏览器端的 JavaScript 默认是读不到跨域响应头的。如果你用了 CORS 中间件需要在配置里显式暴露这个响应头app.enableCors({ exposedHeaders: [x-trace-id], });如果不加这一行页面里的fetch或axios只能拿到响应体拿不到x-trace-id这个 Header。这个问题很容易被忽略但影响的是“让前端能拿到排查凭证”这一整条链路。5.3 访问日志耗时不准我在中间件里用process.hrtime.bigint()来统计耗时而不是Date.now()差值。原因有两个Date.now()的毫秒精度在高并发下不够看而且系统时钟如果发生调整NTP 同步、手动改时间差值可能出现负数。process.hrtime.bigint()是单调时钟专门用来计算时间间隔结果稳定可靠。另外要注意res.on(finish)只表示响应已经交给操作系统并不代表客户端已经完整收到数据。对访问日志来说这个精度已经完全够用。5.4 健康检查、探针日志把追踪列表刷爆如果系统里有/health、/metrics这类高频探针接口不排队它们产生大量访问日志的话日志平台的检索体验会变差。我通常会在中间件里加一个过滤判断对这类路径不打印访问日志或者单独降低日志级别const SKIP_LOG_PATHS [/health, /metrics]; if (SKIP_LOG_PATHS.some((path) originalUrl.startsWith(path))) { traceContext.run({ traceId }, () next()); return; }注意即使不打印访问日志TraceId 中间件仍然要执行因为探针请求背后的异步任务也需要有上下文兜底。只是少打一条噪音日志而已。5.5 上下游 TraceId 对不上最常见的对不上有两种原因一是下游服务没做 TraceId 读取逻辑只知道自己生成那就永远和上游不一致二是跨服务调用时当前上下文丢失导致请求头没带上x-trace-id。排查这一类问题我一般会在两个服务里都打印上下游调用时的 TraceId 和请求头。先在 A 服务打印“准备调用 Bheader.x-trace-idxxx”再到 B 服务中间件打印“收到 x-trace-idyyy”。如果两个值不一致问题一定出在 A 服务发起调用时上下文丢失或 header 设置错误。最后说一点实战体会这套日志中间件与 TraceId 方案我实际用下来最大的体会是技术实现其实半小时就能写完难的是让整个团队把“TraceId 能够贯穿全链路”当做一个默认约定。比如下游服务没做读取逻辑、比如异步任务忘记注入上下文、再比如业务代码用了静态 Logger 方法每一个小疏漏都会让 TraceId 出现断层。我给你的建议是先单独抽出一个部门级的公共服务把 TraceId 中间件、Logger 封装、跨服务透传的问题全部解决掉再推广到各个业务线。同时一定要把响应头的x-trace-id用起来哪怕只是让前端在统一错误弹窗里展示一个 ID这对线上问题沟通效率的提升都是立竿见影的。最后再分享一个小技巧如果你的团队有多个 NestJS 服务这套 TraceId 代码基本可以原样复制唯一要改的只是下游服务的地址列表。把它沉淀成内部脚手架的一部分后续所有新服务都能自动获得这个能力。