Node.js 服务端日志实践：从 console.log 到结构化日志

上个月线上出了个偶发 bug：用户支付回调偶发失败。翻日志发现三年前某师兄留下的 console.log('callback here!!!')，气得我当场决定把整个服务的日志体系重构一遍。

这篇总结重构中沉淀下来的实践。

console.log 的三宗罪

先明确为什么不能止步于 console.log：

没有级别：调试信息和致命错误混在一起，线上要么被刷屏要么关键信息被淹没
没有结构：console.log('user', userId, 'pay', amount) 打出来的文本没法被日志系统检索，想查"某用户的所有支付记录"只能靠肉眼
没有元信息：没有时间戳、没有请求 ID、没有进程标识，多实例部署时根本分不清日志来自哪台机器

结构化日志：一切皆为 JSON

核心思想：每条日志是一个 JSON 对象，字段固定、可检索：

{
  "time": "2021-05-15T10:23:45.123Z",
  "level": "info",
  "msg": "payment callback received",
  "requestId": "req-8f3a2b",
  "userId": 1024,
  "amount": 9900,
  "channel": "alipay",
  "pid": 23581,
  "hostname": "prod-node-03"
}

这样的日志被 ELK（Elasticsearch + Kibana）或 Loki 收集后，可以直接写查询：userId: 1024 AND amount > 5000。排查效率是文本日志的一百倍。

选型：pino 还是 winston

社区两大主流：

winston：老牌、插件多、功能全（多 transport、日志轮转、彩色输出）
pino：新生代，主打性能——官方 benchmark 比 winston 快 5 倍左右，API 极简

我选了 pino，理由：日志在高并发下是热路径，性能敏感；而且 pino 的设计哲学"日志就该是 JSON"和我的想法一致。

pino 落地

const pino = require('pino')

const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  // 生产环境输出 JSON；开发环境用 pino-pretty 美化
  transport:
    process.env.NODE_ENV !== 'production'
      ? { target: 'pino-pretty', options: { colorize: true } }
      : undefined,
})

logger.info({ userId: 1024, amount: 9900 }, 'payment callback received')
logger.error({ err: new Error('db timeout'), sql: 'UPDATE ...' }, 'update failed')

注意第二个参数才是消息，第一个参数是合并进日志对象的结构化字段。错误对象用 err 字段传，pino 会自动序列化堆栈。

关键实践一：请求 ID 贯穿全链路

单次请求里打的日志，必须能用同一个 requestId 串起来：

const { randomUUID } = require('crypto')

// Express 中间件：给每个请求生成 requestId，并创建带上下文的子 logger
app.use((req, res, next) => {
  req.id = randomUUID()
  req.log = logger.child({ requestId: req.id })
  res.setHeader('X-Request-Id', req.id)
  next()
})

// 业务代码里全部用 req.log
app.post('/pay/callback', async (req, res) => {
  req.log.info({ body: req.body }, 'callback received')
  // ...
  req.log.error({ err }, 'callback failed')
})

logger.child() 创建的子 logger 会自动带上 requestId 字段。出问题时让用户把响应头里的 X-Request-Id 发过来，一秒定位这次请求的全部日志。

关键实践二：级别规范

团队约定俗成：

级别	用途	例子
`error`	需要立即处理的故障	支付失败、DB 连接断开
`warn`	异常但可容忍	重试成功、配置项缺失用默认值
`info`	关键业务节点	订单创建、用户登录
`debug`	排查用的详细信息	请求参数、中间状态

线上 level: 'info'，debug 日志不进生产；排查问题时通过 LOG_LEVEL=debug 动态调整（配合 pino 的 logger.level = 'debug' 甚至可以不重启热更新）。

千万别用 info 级别打高频流水（比如每条心跳），存储费用会教你做人。

关键实践三：日志落盘与轮转

容器化部署推荐直接输出到 stdout，由容器平台收集（K8s 的 DaemonSet、docker logging driver），应用不操心文件。

传统虚拟机部署则用 pino.transport 配合轮转：

const logger = pino({
  transport: {
    target: 'pino/file',
    options: { destination: '/var/log/app/app.log' },
  },
})

轮转交给系统的 logrotate 或 pino 生态的 rotating-file-stream，别在应用进程里自己切文件——多进程写同一文件会出各种灵异问题。

小结

结构化日志 = 每条都是 JSON，字段固定可检索
pino 性能优先、winston 功能全家桶，高并发服务选 pino
requestId 用 child logger 贯穿单次请求，排查效率质变
级别规范 + 输出 stdout（容器）或 transport 落盘（虚拟机）

重构完的第二周，又出了一次支付问题。这次我在 Kibana 里输了个 requestId，三十秒定位到是第三方回调的签名字段变了。师兄的 callback here!!! 时代，正式终结。