生产日志要带上下文:只打印错误不够

0阅读9分钟

日志要能回答问题

线上问题发生时,日志如果只有 error 和一段堆栈,我能做的事情非常有限——我知道「哪里挂了」,但不知道「用户做了什么才挂的」「系统当时处在什么状态」「这个问题影响了多大范围」。这三类信息恰恰是排障时最花时间的部分。

有用日志应该服务排障问题,而不是只证明代码报错了。我判断一组日志好不好的标准很简单:假设我现在不知道 bug 是什么,只看日志能不能还原出事情经过。如果能,这日志就及格了。

这篇文章讨论的是「日志上下文」——每条日志除了消息本身,还应该带哪些结构化信息,让排障从「猜」变成「查」。

为什么堆栈不够:从「出错」到「理解出错」的差距

堆栈告诉你崩溃发生在哪一行,但它不告诉你以下这些事情:

  • 请求是谁发起的:是所有用户都受影响,还是某个特定租户的数据触发了边界条件?
  • 请求经过了什么路径:用户先做了 A 再做 B,还是直接调了 C?不同路径可能走不同的代码分支。
  • 外部依赖当时的状态:第三方接口超时了还是正常返回了错误码?这两种情况的处理方式完全不同。
  • 业务实体的关键属性:订单金额是 100 还是 100000?用户角色是普通用户还是管理员?这些属性往往是触发 bug 的关键条件。

缺少上下文的日志就像交通事故报告只写了「车停了」,没写车速、路况、信号灯状态。事后复盘的人只能对着报告发呆。

我见过不少团队在出了生产事故之后,花大量时间「还原现场」——翻代码、看 git log、问当事人、查数据库快照。如果日志本身就能回答大部分还原问题,这些时间可以省下来直接修 bug。

关键上下文:每条日志应该回答什么

日志上下文不是越多越好,而是要覆盖排障时会问到的关键问题。我把这些上下文分成六个层次:

请求标识(Request / Trace ID)

这是串起一条请求全链路日志的线索。在单体应用里,一个请求 ID 就够了;在微服务架构下,还需要 trace ID 来关联跨服务的调用链。

生成时机很关键——必须在系统边界(网关、入口中间件)生成,然后向下透传。如果每个服务各自生成,就失去了关联的意义。

// ❌ 每个 handler 内部生成,无法跨服务关联
function handleOrderCreate(req: Request) {
  const localId = crypto.randomUUID()
  logger.info({ localId }, 'creating order')
}
 
// ✅ 在入口中间件生成,注入到请求上下文
app.use((req, res, next) => {
  const requestId = req.headers['x-request-id'] ?? crypto.randomUUID()
  req.context = { requestId }
  next()
})

模块与操作名称

光有请求 ID 还不够。一条请求可能经过多个模块、多次数据库查询、多次外部调用。每条日志需要说明自己属于哪个模块、在做哪个操作,才能在大量日志里快速定位到出错的那一步。

// ❌ 看不出在做什么
{"level":"error","msg":"query failed","requestId":"abc-123"}
 
// ✅ 模块和操作清晰
{"level":"error","msg":"query failed","requestId":"abc-123","module":"order-service","operation":"createOrder","step":"validateInventory"}

用户 / 租户标识

知道「哪个用户遇到了问题」对于判断影响范围至关重要。但这里有个前提:标识要安全。记录用户 ID、租户 ID 这类内部标识没问题,但不能记录能直接定位到个人的敏感信息(手机号、身份证号等)。

关键参数摘要

触发 bug 的往往是某些特定参数值。日志里应该记录影响业务逻辑的关键参数,但要做摘要而不是完整复制。比如,记录「订单包含 3 个 SKU,总金额 299」比记录整个订单 JSON 有用得多,而且安全得多。

外部依赖状态

现代应用几乎都依赖外部服务——支付、短信、存储、AI 接口。当这些依赖出问题时,日志需要记录:调了哪个接口、返回了什么状态码、耗时多久。区分「对方返回了 500」和「对方超时 30 秒」对排障方向的影响完全不同。

业务状态变化

有些 bug 不是单次请求的问题,而是状态机出了问题。比如订单从「已支付」变成了「待发货」,但库存没有扣减。这类问题需要在状态变化时记录日志:变更前状态、变更后状态、变化的触发条件。

案例:三个真实场景的日志对比

案例一:支付回调处理失败

用户在 App 里完成支付,但订单状态一直卡在「支付中」。客服反馈到开发,开发需要查为什么支付回调没生效。

// ❌ 只有错误,没有上下文
logger.error('payment callback processing failed', error)
// 输出:
// {"level":"error","msg":"payment callback processing failed","error":"TypeError: Cannot read property 'amount' of undefined"}
 
// ✅ 带完整上下文
logger.error({
  requestId: ctx.requestId,
  module: 'payment',
  operation: 'handlePaymentCallback',
  provider: 'stripe',
  orderId: order.id,
  userId: order.userId,
  callbackStatus: req.body.status,
  orderStatusBefore: order.status,
  error: error.message,
  stack: error.stack,
}, 'payment callback processing failed')
// 输出:
// {"level":"error","msg":"payment callback processing failed","requestId":"req-7f3a","module":"payment","operation":"handlePaymentCallback","provider":"stripe","orderId":"ord-8821","userId":"usr-4412","callbackStatus":"succeeded","orderStatusBefore":"pending_payment","error":"Cannot read property 'amount' of undefined","stack":"..."}

有了上下文,排障路径很清晰:requestId 可以拉出这个请求的全部日志;orderIduserId 可以直接查数据库看订单状态;callbackStatus: "succeeded" 说明 Stripe 那边确实支付成功了;orderStatusBefore: "pending_payment" 确认了订单确实还没更新。接下来只需要看为什么 amountundefined——很可能是订单查询那边的数据加载逻辑有 bug。

案例二:定时任务批量失败

一个每日执行的同步任务突然大面积失败,运维在凌晨收到了告警。

// ❌ 只知道失败了
logger.error('sync job failed', error)
 
// ✅ 带业务上下文
logger.error({
  module: 'sync-service',
  operation: 'dailyProductSync',
  jobRunId: 'run-20260625-001',
  totalItems: 15000,
  successCount: 23,
  failedCount: 14977,
  firstError: errors[0]?.message,
  firstErrorSku: errors[0]?.sku,
  externalApiStatus: lastApiResponse?.status,
  externalApiLatencyMs: lastApiResponse?.latencyMs,
  durationMs: Date.now() - startTime,
}, 'daily product sync job failed')

运维拿到这条日志就能判断:successCount: 23 说明不是全部失败,开头几条成功了;externalApiStatus 会告诉他是外部 API 从第 24 条开始返回错误,还是超时;firstErrorSku 可以直接拿去做 API 复现。不用叫醒开发就能做初步定位。

案例三:权限校验偶发失败

某个用户反馈偶尔无法访问自己创建的资源,但其他用户没问题。

// ❌ 只有结果
logger.warn('permission denied', { userId, resourceId })
 
// ✅ 带权限上下文
logger.warn({
  requestId: ctx.requestId,
  module: 'auth',
  operation: 'checkResourceAccess',
  userId: user.id,
  userRole: user.role,
  userTenantId: user.tenantId,
  resourceId: resource.id,
  resourceOwnerId: resource.ownerId,
  resourceTenantId: resource.tenantId,
  permissionRule: 'owner-or-admin',
  matchedRule: 'none',
  crossTenantAccess: user.tenantId !== resource.tenantId,
}, 'permission denied for resource access')

看到 crossTenantAccess: true,问题就清楚了——这个用户的租户和资源的租户不一样,权限规则没有考虑跨租户场景。没有这个上下文,光看 userIdresourceId 根本查不出原因。

日志上下文注入的完整流程

下面是一个典型的请求生命周期里,日志上下文如何在各层逐步丰富:

流程图画布 · 115%
Mermaid 流程图加载中...

这个流程的关键点有三个:

  1. Request ID 在入口生成,不在业务层生成。如果每个服务自己生成,日志就没法关联。
  2. 上下文逐层丰富,不是在一处塞所有字段。认证中间件加用户信息,业务层加操作信息,依赖调用加响应状态。
  3. Canonical Log 在请求结束时记录,把整条请求的关键信息汇总成一条宽事件。这条日志是排障时最先看的那条。

日志上下文的质量对比

下表对比了「没有上下文」「基础上下文」「高质量上下文」三种日志在排障能力上的差异:

维度无上下文日志基础上下文日志高质量上下文日志
单条日志信息量只有错误消息和堆栈加上请求 ID 和时间戳包含请求 ID、模块、操作、用户、参数摘要、依赖状态
跨服务关联不可能通过 trace ID 关联trace ID + 每层模块/操作标注
影响范围判断靠猜通过用户 ID 聚合直接按 userId/tenantId 查询
问题复现需要翻数据库参数摘要提供部分线索关键参数直接可用于复现
状态回溯不知道变更前状态知道当前状态记录变更前后的状态和触发条件
排障平均时间小时级,可能无法定位分钟级到小时级分钟级,大部分问题可直接定位
告警价值只知道出错了知道哪个服务出错了知道什么操作在什么条件下出错

日志级别:不是所有失败都是 error

日志级别滥用是另一个常见问题。infowarnerror 不是随便选的,每个级别应该有明确的语义定义:

级别语义定义典型场景是否触发告警
debug开发排障信息,生产环境默认关闭函数入参出参、中间计算值
info正常业务流程的关键节点请求开始/结束、状态变更、任务完成否(但可聚合为指标)
warn预期内的异常或降级参数校验失败、重试成功、功能降级、限流条件告警(频率超阈值时)
error影响用户体验或数据一致性的异常数据库写入失败、支付回调处理异常、关键依赖不可用
fatal系统无法继续运行数据库连接池耗尽、核心配置缺失是,立即通知

常见的错误做法:

// ❌ 参数校验失败打 error,告警风暴
if (!input.email) {
  logger.error('missing email', { input })
  return res.status(400).json({ error: 'email required' })
}
 
// ✅ 参数校验是预期内的失败,用 warn
if (!input.email) {
  logger.warn('validation failed: missing email', {
    requestId: ctx.requestId,
    module: 'user-service',
    operation: 'createUser',
    validationField: 'email',
  })
  return res.status(400).json({ error: 'email required' })
}
 
// ❌ 外部超时和内部 bug 混在一起
catch (error) {
  logger.error('failed to fetch user profile', error)
}
 
// ✅ 区分外部依赖问题与内部异常
catch (error) {
  if (error instanceof TimeoutError) {
    logger.warn({
      module: 'user-service',
      operation: 'fetchProfile',
      dependency: 'profile-api',
      timeoutMs: 5000,
      retryAttempt: attempt,
    }, 'profile api timeout, will retry')
  } else {
    logger.error({
      requestId: ctx.requestId,
      module: 'user-service',
      operation: 'fetchProfile',
      error: error.message,
      stack: error.stack,
    }, 'unexpected error fetching profile')
  }
}

敏感信息控制:排障需要上下文,不需要密码

日志上下文不是原始数据的搬运工。以下字段必须脱敏或摘要:

数据类型正确做法错误做法
密码 / 密钥永不记录记录明文或 base64
Token / API Key只记录前 6 位 + ***完整记录
手机号138****123413812341234
邮箱a***[email protected]完整记录
身份证只记录是否通过校验完整记录
请求 body只记录影响业务逻辑的关键字段摘要JSON.stringify(req.body)
响应 body只记录状态码和关键字段完整记录
// ❌ 原始 body 全量记录
logger.info('creating order', { body: req.body })
 
// ✅ 摘要记录关键字段
logger.info({
  requestId: ctx.requestId,
  module: 'order-service',
  operation: 'createOrder',
  itemCount: req.body.items?.length ?? 0,
  totalAmount: req.body.totalAmount,
  currency: req.body.currency,
  // 不记录:收货地址、手机号、支付 token
}, 'creating order')
 
// Token 脱敏工具函数
function maskToken(token: string): string {
  if (!token || token.length < 8) return '***'
  return token.slice(0, 6) + '***'
}

结构化日志格式:让日志可查询

文本日志人眼能读,但机器难处理。生产日志应该输出结构化的 JSON 格式,这样日志平台(ELK、Loki、Datadog)才能高效索引和查询。

// ❌ 文本格式,难以查询
logger.info(`Order ${orderId} created by user ${userId}, total: ${total}, items: ${itemCount}`)
// 要查某个用户的订单,需要正则匹配,慢且易错
 
// ✅ JSON 结构化,字段可索引
logger.info({
  requestId: ctx.requestId,
  module: 'order-service',
  operation: 'createOrder',
  orderId,
  userId,
  total,
  itemCount,
  durationMs: Date.now() - startTime,
}, 'order created')
// 直接查询:userId="usr-4412" AND operation="createOrder"

推荐使用成熟的日志库(如 pinowinstonzerolog)而不是自己拼 JSON。这些库自带上下文注入、序列化安全和性能优化。

检查清单:上线前审查你的日志

每次提交涉及日志改动的代码前,我会逐项过一遍这个清单:

  • 请求 ID 透传:入口中间件是否生成了 Request ID?是否注入到了所有下游调用?
  • 模块标注:每条日志是否包含 moduleoperation 字段?
  • 用户标识:涉及用户操作的日志是否记录了 userIdtenantId
  • 参数摘要:关键业务参数是否记录?是否做了摘要而非全量?
  • 敏感信息脱敏:密码、Token、手机号、邮箱等是否已脱敏?
  • 外部依赖状态:调用外部服务的日志是否记录了状态码和耗时?
  • 状态变化记录:业务状态变更前后的值是否都记录了?
  • 日志级别语义error 是否只用于真正影响用户的异常?warninfo 的边界是否清晰?
  • 结构化输出:日志是否输出为 JSON 格式?字段命名是否与团队规范一致?
  • Canonical Log:请求结束时是否有一条汇总日志包含完整上下文?
  • 日志量控制:高频路径是否避免了 debug 级别的日志?循环内部是否避免了逐条打印?
  • 错误分类:外部超时和内部异常是否用了不同的日志级别和处理方式?
  • 可查询性:在日志平台上,能否通过 requestIduserIdorderId 等关键字段在 10 秒内定位到相关日志?

总结

日志是系统在生产环境里唯一留下的「证据」。证据质量直接决定了排障效率。

堆栈告诉你在哪一行挂的,上下文告诉你为什么挂、挂了影响谁、怎么复现。前者是调试的起点,后者才是排障的终点。

把日志当成产品来做:想清楚读者是谁(未来的自己和值班的同事),他们要回答什么问题(发生了什么、影响多大、怎么修),然后为这些问题提供足够的数据。

不要等出了事故才想起来加日志。上线前就把上下文准备好,排障时才不会对着空日志发呆。

参考资料

评论 0

0 / 1000