使用 requestId 标记全链路日志

标记全链路日志有助于更好的解决 bug 和分析接口性能，本篇文章使用 node 来作为示例

• 代码示例
• 本文地址
• github

当一个请求到来时，会产生哪些日志

• 本次请求报文
• 本次请求涉及到的数据库操作
• 本次请求涉及到的缓存操作
• 本次请求涉及到的服务请求
• 本次请求所遭遇的异常
• 本次请求执行的关键函数
• 本次请求所对应的响应体

如何查询本次从请求到响应全链路的所有日志

使用 requestId 唯一标识每个请求，有时它又被称为 sessionId 或者 transactionId。

1. 使用 requestId 标记每次请求全链路日志，所要标记的日志种类如上所示
2. 通过把 X-Request-Id (X-Session-Id) 标记在请求头中，在整个链路进行传递

async function context (ctx: KoaContext, next: any) {
  const requestId = ctx.header['x-request-id'] || uuid()
  ctx.res.setHeader('requestId', requestId)
  ctx.requestId = requestId
  await next()
}

app.use('/todos/:id', (ctx) => {
  User.findByPk(ctx.body.id, {
    logging () {
      // log ctx.requestId
    }
  })
})

如何以侵入性更小的方式来标记每次请求

如上，在每次数据库查询时手动对 requestId 进行标记过于繁琐。可以统一设计 logger 函数进行标记

具体代码可见我一个脚手架中的 logger.ts

这里使用了流行的日志库 winston (13582 Star)

import winston, { format } from 'winston'

const requestId = format((info) => {
  info.requestId = session.get('requestId')
  return info
})

const logger = winston.createLogger({
  format: format.combine(
    format.timestamp(),
    requestId(),
    format.json()
  )
})

如何在 logger.ts 中绑定 requestId

或者说如何在 logger.ts 如何获得整个请求响应生命周期中的 requestId

• 通过 async_hooks 可以追踪异步行为的生命周期
• 通过 cls-hooked 可以获得每次异步请求的 requestId

具体代码可见 session.ts

import { createNamespace } from 'cls-hooked'

const session = createNamespace('hello, world')

export { session }

如何从全链路日志中得益

1. 当 sentry (警报系统) 中收到一条异常警报时，通过 requestId 可以在 elk (日志系统) 中获取到关于该异常的所有关键日志 (sql, redis, 关键函数的输入输出)
2. 当客户端一条请求过慢时，通过请求头获取到的 requestId 可以在 elk 中分析该请求的所有数据库查询时间，请求响应时间，缓存是否命中等指标
3. 查找 API 对应执行的 SQL 语句以及条数，判断是否有冗余 SQL 语句的查询

另外可以通过 zipkin 来追踪全链路耗时。

<hr/>

欢迎关注我的公众号山月行，在这里记录着我的技术成长，欢迎交流