使用 Node.js 中间件记录请求日志

当你的 API 在凌晨 2 点出现故障时,你首先会去查看日志。如果日志缺失、不完整或淹没在噪音中,调试就变成了猜谜游戏。Node.js 中的 HTTP 请求日志记录是那些容易出错且代价高昂的基础功能之一。

本文介绍了 Express 中请求日志中间件的工作原理、何时使用 Morgan 或 Pino 等成熟库,以及生产级日志记录的实际样貌。

日志中间件在 Express 请求生命周期中的位置

在 Express 中,中间件是一个签名为 (req, res, next) 的函数。它在请求到达路由处理器之前拦截每个请求。日志中间件位于该链的顶部,记录进来的内容和出去的内容。

[客户端] → [日志中间件] → [认证中间件] → [路由处理器] → [响应]

关键点在于:你无法记录完整的响应——状态码、持续时间——直到响应完成。这就是为什么日志中间件监听 res 的 finish 事件,而不是立即记录。

import crypto from 'node:crypto'

// Express 请求日志中间件
const logRequests = (req, res, next) => {
  const start = Date.now()

  res.on('finish', () => {
    logger.info({
      method: req.method,
      url: req.url,
      status: res.statusCode,
      duration: Date.now() - start,
      requestId: req.headers['x-request-id'] ?? crypto.randomUUID(),
    })
  })

  next()
}

app.use(logRequests)

注意 crypto.randomUUID() 需要导入 node:crypto 模块(或使用 Node.js 19+ 中可用的全局 crypto)。此外,这里的 logger 对象是一个占位符——你需要将其替换为实际的日志库实例(如 Pino 或 console)。

这种模式适用于任何 Node.js HTTP 服务器,不仅仅是 Express。

使用 Morgan 进行传统访问日志记录

Morgan 是经典的 Express 请求日志中间件。两行代码就能获得 Apache 风格的访问日志:

import morgan from 'morgan'

app.use(morgan('combined'))
// 输出示例:
// ::1 - - [01/Jan/2025:00:00:00 +0000] "GET /api/users HTTP/1.1" 200 1234

Morgan 适合开发和简单部署。它的输出是人类可读的,但不易于机器解析——当你将日志发送到 Datadog、Loki 或任何结构化日志系统时,这就成了问题。

使用 Pino 在 Node.js 中进行结构化日志记录

对于生产环境,结构化日志记录意味着输出 JSON。每条日志行都成为可查询的记录。Pino 是这里的标准选择——它比 Winston 或 Bunyan 快得多,开销最小。

pino-http 包可作为 Express 中间件直接使用:

import express from 'express'
import pinoHttp from 'pino-http'

const app = express()

app.use(pinoHttp({
  level: process.env.LOG_LEVEL ?? 'info',
  redact: ['req.headers.authorization', 'req.headers.cookie'],
}))

app.get('/', (req, res) => {
  req.log.info('handling root request')
  res.send('ok')
})

Pino 写入 stdout。你的基础设施(Docker、systemd、日志转发器)负责将这些日志行路由到需要的地方。

关联 ID 和请求上下文

当你需要跨多个异步操作追踪请求时,需要在每条日志行上附加一个一致的请求 ID。在现代 Node.js 中,使用 AsyncLocalStorage 来实现——而不是已弃用的 domain 模块或低级异步钩子。

import { AsyncLocalStorage } from 'node:async_hooks'
import crypto from 'node:crypto'

export const requestContext = new AsyncLocalStorage()

app.use((req, res, next) => {
  const requestId = req.headers['x-request-id'] ?? crypto.randomUUID()
  requestContext.run({ requestId }, next)
})

该请求异步上下文中的任何日志调用现在都可以获取 requestId,无需手动在每个函数中传递它。以下是如何检索它:

// 在任何下游模块中
import { requestContext } from './context.js'

function doWork() {
  const { requestId } = requestContext.getStore()
  logger.info({ requestId, msg: 'doing work' })
}

负责任地记录日志

在生产环境中需要注意的几条规则:

• 永远不要记录 Authorization 头、cookies 或 API 令牌。 使用 Pino 的 redact 选项或在写入前手动清理。
• 小心处理代理后面的客户端 IP。 req.socket.remoteAddress 会给你代理的 IP。如果你的应用在反向代理后面,正确配置 Express 的 trust proxy 设置,并谨慎处理 X-Forwarded-For 头。
• 默认不要记录请求体。 它们可能很大、是二进制的或包含个人身份信息(PII)。有选择性地记录它们,并设置大小限制。

在 Morgan 和 Pino 之间选择

如果你喜欢可读的输出,可以在本地开发中使用 Morgan。对于任何要发布到生产环境的应用,使用 Pino。

结论

好的日志中间件在你需要它之前是不可见的——但当你需要时,它就是一切。从 pino-http 开始,将结构化 JSON 输出到 stdout,让你的基础设施处理路由和存储。通过 AsyncLocalStorage 配合关联 ID,这样你就可以端到端追踪任何请求。从第一天起就将敏感数据排除在日志之外,你将拥有一个随应用扩展的可观测性基础。

常见问题

我可以在同一个 Express 应用中同时使用 Morgan 和 Pino 吗?

可以,你可以同时运行两者。一个常见的模式是在开发环境中使用 Morgan 以获得可读的控制台输出,在生产环境中使用 Pino 以获得结构化 JSON 日志。使用环境变量有条件地应用其中一个,这样你就可以避免在任何单一环境中出现重复的日志条目。

如何将 Pino 日志发送到 Datadog 或 Elasticsearch 等外部服务?

Pino 按设计将 JSON 写入 stdout。使用 Fluent Bit、Filebeat 或 Datadog Agent 等日志转发器从容器或进程中收集 stdout 输出,并将其转发到你的日志平台。这使你的应用代码与任何特定的日志目标解耦。

为什么我应该使用 AsyncLocalStorage 而不是通过函数参数传递请求 ID?

AsyncLocalStorage 会自动在整个异步调用链中传播上下文,无需修改函数签名。手动通过每个函数传递请求 ID 容易出错且会使代码混乱。AsyncLocalStorage 在 Node.js 16 及以上版本中是稳定的,是请求范围上下文的推荐方法。

日志中间件会给我的 API 响应增加明显的延迟吗?

使用 Pino 时,开销通常可以忽略不计,因为它使用快速序列化并高效地将日志写入 stdout。Morgan 对于大多数工作负载也是轻量级的。`finish` 事件监听器模式意味着日志记录在响应已交给操作系统后运行,因此通常不会影响客户端延迟。避免在日志路径中进行同步文件写入或繁重的序列化。