在 Monitoring a SaaS in Production 中，我们接入了指标和告警，让团队能在问题发生后几分钟内知晓。指标能告诉你存在峰值，但很少告诉你原因。这是一个日志问题，也是我们在此解决的问题。

这是 Full Stack SaaS Masterclass 的一部分，这是一个从空文件夹构建多租户 SaaS 直至生产环境的真实系列课程。模块 4 涵盖了将演示转为团队可实际运行产品所需的运维关注点。日志是该技术栈的基础：事件响应、支持工单和审计跟踪最终都会回到“日志说了什么”。

大多数 Node.js 应用都从 console.log 开始，且持续使用的时间远超预期，因为它在单次请求的笔记本电脑上运行良好。当两个请求同时进行且其日志行在共享终端中交错，或客户支持工单需要答案而唯一可用工具是针对非结构化文本墙的 grep 时，它就不再适用。结构化日志解决了这个问题，且其设置成本低到可以尽早完成，几乎没有理由推迟。

为什么纯文本日志不再适用

console.log 调用会生成一个字符串。对于盯着终端的人类来说，字符串没问题，但对任何试图大规模查询日志的系统来说却是敌对的。一旦日志移动到 CloudWatch、Datadog 或任何聚合器，每个下游工具最终都会用正则表达式重新解析该字符串，以提取它实际需要的字段：请求 ID、用户 ID、状态码、持续时间。基于正则的解析是脆弱的。对日志消息的一个词的更改会破坏所有基于它的已保存搜索和告警。

结构化日志反转了这种方法：你不是写一个句子并希望有人稍后可以解析它，而是从一开始就写一个带有命名字段的 JSON 对象。

{
  "level": "error",
  "time": "2023-09-14T10:22:31.482Z",
  "requestId": "8f14e45f-ceea-467e-add1-a889b9f6bfaa",
  "organizationId": "org_9f2c1a",
  "userId": "usr_71b30d",
  "route": "POST /invoices",
  "statusCode": 500,
  "durationMs": 812,
  "msg": "Failed to create invoice: unique constraint violation"
}

Enter fullscreen mode Exit fullscreen mode

这里的每个字段都无需解析即可查询。“给我看过去一小时内 org_9f2c1a 组织的所有 500 错误”是一个过滤器，而不是正则表达式。这种差异是整个价值主张，且随着系统增长而叠加：第十个调试事件的工程师受益于与第一个设置它的工程师相同的结构化字段。

选择日志库并将其连接到 NestJS

Node.js 有几个可靠的结构化日志库。pino 是 NestJS 后端的合理默认选择。它旨在最小化每次调用的开销（使用快速路径的 JSON 序列化，而不是大多数日志记录器依赖的通用 JSON.stringify），并且通过 nestjs-pino 与 NestJS 干净集成。

// main.ts
import { NestFactory } from '@nestjs/core';
import { Logger } from 'nestjs-pino';
import { AppModule } from './app.module';

async function bootstrap() {
  const app = await NestFactory.create(AppModule, { bufferLogs: true });
  app.useLogger(app.get(Logger));
  await app.listen(3000);
}
bootstrap();

Enter fullscreen mode Exit fullscreen mode 

// logger.module.ts
import { Module } from '@nestjs/common';
import { LoggerModule } from 'nestjs-pino';

@Module({
  imports: [
    LoggerModule.forRoot({
      pinoHttp: {
        level: process.env.LOG_LEVEL ?? 'info',
        redact: ['req.headers.authorization', 'req.headers.cookie', '*.password', '*.token'],
        serializers: {
          req: (req) => ({ method: req.method, url: req.url }),
          res: (res) => ({ statusCode: res.statusCode }),
        },
        transport:
          process.env.NODE_ENV === 'development'
            ? { target: 'pino-pretty', options: { singleLine: true } }
            : undefined,
      },
    }),
  ],
})
export class AppLoggerModule {}

Enter fullscreen mode Exit fullscreen mode

该配置中除了显而易见的内容外，有两件事很重要。首先，redact 不是事后想法；它是日志行与泄露凭证之间的区别，它属于初始设置，而不是安全审查标记后的后续工单。其次，pino-pretty 传输仅限于开发环境。在生产环境中，你希望原始 JSON 直接输出到 stdout，因为这是你的日志聚合器所期望的，而先对其进行美化打印只会增加没有人阅读的 CPU 工作。

有了这个，就可以直接将日志记录器注入到服务中：

import { Injectable } from '@nestjs/common';
import { InjectPinoLogger, PinoLogger } from 'nestjs-pino';

@Injectable()
export class InvoiceService {
  constructor(@InjectPinoLogger(InvoiceService.name) private readonly logger: PinoLogger) {}

  async createInvoice(organizationId: string, amount: number): Promise<void> {
    this.logger.info({ organizationId, amount }, 'Creating invoice');

    try {
      // ... invoice creation logic
    } catch (error) {
      this.logger.error({ organizationId, err: error }, 'Invoice creation failed');
      throw error;
    }
  }
}

Enter fullscreen mode Exit fullscreen mode

这里的 err 字段很重要：pino 的默认错误序列化器会将 Error 对象扩展为其消息和堆栈跟踪作为单独的 JSON 字段，而不是从 console.log(error) 获得的字符串插值。这使得你可以跨每个服务搜索特定的异常类型，而无需打开单个日志行。

将关联 ID 贯穿每个日志行

在事件期间，单个日志行本身很少有用。你真正想要的是属于一个请求的每个日志行，跨越它所触及的每个服务，而仅靠结构化字段无法实现这一点，除非这些行中的每一行都共享一个共同的 ID。这就是关联 ID（通常称为请求 ID 或跟踪 ID）的用途。

通过 NestJS 应用传播它而无需将其作为参数贯穿每个函数调用的最干净方法是 Node 的 AsyncLocalStorage，它为每个请求提供自己的隔离上下文，该上下文在 await 边界上保持不变。

// request-context.ts
import { AsyncLocalStorage } from 'async_hooks';
import { randomUUID } from 'crypto';

interface RequestContext {
  requestId: string;
  organizationId?: string;
}

export const requestContext = new AsyncLocalStorage<RequestContext>();

export function getRequestId(): string {
  return requestContext.getStore()?.requestId ?? 'no-context';
}

Enter fullscreen mode Exit fullscreen mode 

// request-context.middleware.ts
import { Injectable, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { randomUUID } from 'crypto';
import { requestContext } from './request-context';

@Injectable()
export class RequestContextMiddleware implements NestMiddleware {
  use(req: Request, res: Response, next: NextFunction): void {
    const requestId = (req.headers['x-request-id'] as string) ?? randomUUID();
    res.setHeader('x-request-id', requestId);

    requestContext.run({ requestId }, () => next());
  }
}

Enter fullscreen mode Exit fullscreen mode

现在，该请求调用栈中任何地方（包括由其触发的队列作业，如果 ID 被转发到作业负载中）的任何日志调用都可以拉取 getRequestId() 并自动附加它。将其连接到 pino 配置的 mixin 选项中，这样它就永远不是工程师必须显式传递的东西：

LoggerModule.forRoot({
  pinoHttp: {
    mixin() {
      return { requestId: getRequestId() };
    },
  },
});

Enter fullscreen mode Exit fullscreen mode

这是结构化本身之后对日志设置的最高杠杆补充。没有它，重建“这个失败结账期间发生的一切”意味着猜测时间戳并希望没有其他事情同时发生。有了它，只需一个查询。

权衡：结构化日志的成本

这一切都不是免费的，在将其视为显而易见的胜利之前，这些成本值得诚实地审视。

结构化日志在本地开发期间直接在终端中阅读不太愉快，这就是为什么上面的 pino-pretty 传输专门存在，以在本地工作时缓解这种情况，同时保持生产输出为原始 JSON。序列化每次日志调用都有一个真实（尽管很小）的 CPU 成本，如果热路径在循环的每次迭代中记录而不是每个请求记录一次，这就很重要了。并且需要维护脱敏配置。每个可能携带凭证、密码、API 密钥、会话令牌的新字段都需要添加到脱敏列表中，而一旦初始设置完成，这个列表很容易被遗忘。

对于几乎任何超过最早原型阶段的 SaaS 后端，好处都超过了这些成本，但值得指出它们，而不是假装结构化日志是纯升级而没有维护面。

值得规划的生产陷阱

将 PII 记录到非结构化字段中。 结构并不能阻止有人将客户的电子邮件地址放入自由格式的 msg 字符串或无人审查的 properties 对象中。脱敏规则只捕获它们按名称知道的字段；对待添加到日志调用的任何新字段，应与应用于 API 响应的审查相同。

日志量超出你愿意支付的费用。 结构化 JSON 日志每行比简洁的文本消息大，而在生产中保留冗长的 debug 级别日志会成倍增加这一点。按环境设置 LOG_LEVEL，在生产中默认为 info，并将 debug 保留用于有意的、时间限制的调查，而不是永久设置。

在优雅关闭期间丢失日志。 如果进程在传输完成刷新缓冲的日志行之前退出，那么解释崩溃的任何内容正是聚合器中缺失的内容。确保你的关闭钩子等待日志记录器在进程退出前刷新，特别是如果日志在发送到外部之前是分批的。

关联 ID 在 HTTP 边界处停止。 仅存在于 API 进程内的请求 ID 远不如转发到每个下游调用的有用：它排队的 BullMQ 作业、对第三方 API 的出站 HTTP 调用、发布到另一个服务的消息。在每个边界处都有意转发它，否则跟踪会在事件通常变得有趣的地方中断。

要点总结

  • 结构化日志是带有命名字段的 JSON 对象，而不是句子，这使得它们可以通过聚合器查询，而不是需要脆弱的正则解析。
  • Pino 是 NestJS 后端的可靠默认选择：快速 JSON 序列化，通过 nestjs-pino 的一流 NestJS 集成，以及内置的脱敏和错误序列化。
  • 凭证和令牌的脱敏规则属于初始设置，而不是安全审查后的后续工单。
  • AsyncLocalStorage 允许你自动将请求范围的关联 ID 附加到每个日志行，这是通过一个查询重建事件与猜测时间戳之间的区别。
  • 默认将生产日志级别保持在 info，并将 debug 保留用于有意的、时间限制的调查，因为详细日志一旦发送到聚合器就会产生实际成本。
  • 跨每个边界转发关联 ID，HTTP 调用、队列作业、Webhook，否则跟踪会在事件变得难以调试的地方中断。

常见问题

什么是结构化日志？
结构化日志意味着将日志条目编写为带有命名、类型化字段（如 requestId、statusCode、organizationId）的对象，而不是自由格式的文本句子。它允许日志聚合器和查询工具直接在这些字段上过滤和搜索，而不是用正则解析消息字符串。

对于 Node.js 后端，pino 比 winston 好吗？
两者都是有能力的结构化日志库。Pino 通常是 JSON 序列化的更快选择，并且通过 nestjs-pino 与 NestJS 直接集成，这就是为什么它是新 NestJS 项目的常见默认选择。Winston 有更长的记录和更大的插件生态系统，如果你需要它已经支持的特定传输，这可能很重要。

如何跨多个服务关联请求的日志？
在系统边缘生成或转发关联 ID（通常称为请求 ID 或跟踪 ID），在请求期间将其存储在 AsyncLocalStorage 上下文中，并在每个下游调用（包括队列作业和出站 HTTP 请求）上显式转发它。从该上下文读取的每个日志行然后可以自动附加相同的 ID。

日志行中永远不应该出现什么？
密码、会话令牌、API 密钥、授权头和完整的支付卡详细信息永远不应以明文形式记录。在日志记录器级别为已知敏感字段名配置脱敏规则，并对待添加到日志调用的任何新字段，应与应用于 API 响应的审查相同。

我应该在生产中以 debug 级别记录吗？
通常不应该。默认将生产日志级别设置为 info，并将 debug 保留用于有意的、时间限制的调查，因为 debug 级别日志会成倍增加每个请求的量和成本，而大多数时候没有相应的好处。

结构化日志是否取代了对指标或跟踪系统的需求？
不是。指标能快速告诉你出了问题，跟踪显示请求如何跨服务移动，日志解释特定请求失败的具体原因。它们是互补的，这里描述的关联 ID 是让你在事件期间在三者之间移动而不丢失上下文的关键。

延伸阅读

关于作者

你好，我是 Aman Singh —— 专注于可扩展 SaaS 产品、分布式系统、云架构和 AI 驱动应用的资深全栈工程师。

我撰写关于系统设计、全栈工程、分布式系统、Redis、PostgreSQL、AWS、Node.js 和 NestJS 的文章。