使用 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/>

歡迎關注個人公衆號山月行，在這裏記錄着個人技術成長，歡迎交流