手把手教你在node中怎麼優雅列印全鏈路紀錄檔

當使用者報問題：線上某個功能使用報錯時，如何快速準確地定位？當某個請求介面返回資料緩慢時，如何有效地追蹤優化？

一、原理和實踐

眾所周知，當一個請求到來時，大概會有以下紀錄檔產生：

1、AceesLog：使用者存取紀錄檔

2、Exception：程式碼異常紀錄檔

3、SQL：sql查詢紀錄檔

4、ThirdParty：第三方服務紀錄檔

該如何追蹤一條請求產生的所有紀錄檔？

一般做法是使用一個requestId來做唯一標識，

然後寫一箇中介軟體，把requestId注入到context上下文中，當需要打紀錄檔時，再從context中取出列印，

在第三方服務和SQL紀錄檔中，還需要把requestId傳入到相應的函數裡面列印，這樣層層傳遞，實在太麻煩，程式碼侵入性也比較強。

我們的目標是降低程式碼侵入性，一次注入，自動跟蹤。

經過調研，async_hooks可以追蹤非同步行為的生命週期，在每個非同步資源（每個請求都是一個非同步資源）中，它都有2個ID，

分別是asyncId（非同步資源當前生命週期ID），trigerAsyncId（父級非同步資源ID）。

async_hooks提供了以下生命週期勾點來監聽非同步資源：

asyncHook = async_hook.createHook({
  // 監聽非同步資源的建立
  init(asyncId,type,triggerAsyncId,resource){},
  // 非同步資源回撥函數開始執行之前
  before(asyncId){},
  // 非同步資源回撥函數開始執行後
  after(asyncId){},
  // 監聽非同步資源的銷燬
  destroy(asyncId){}
})

那如果我們做一個對映，每個asyncId對映一個storage，storage裡面再儲存對應的requestId，那requestId就可以很容易獲取了。

正好cls-hooked這個庫已經基於async_hooks做好了封裝，在同一份非同步資源維護一份資料，以鍵值對的形式儲存。（注意：async_hooked需要在高版本node>=8.2.1使用）當然社群中還有其他的實現，比如cls-session，node-continuation-local-storage等。

下面講下我把cls-hooked運用在我專案中的範例：

/session.js 建立命名儲存空間

const createNamespace = require('cls-hooked').createNamespace 
const session = createNamespace('requestId-store') 
module.exports = session

/logger.js 列印紀錄檔

const session = require('./session') 
module.exports = { 
info: (message) => 
{ 
const requestId = session.get('requestId')
console.log(`requestId:${requestId}`, message) 
}, 
error: (message) => 
{ 
const requestId = session.get('requestId') 
console.error(`requestId:${requestId}`, message) 
} 
}

/sequelize.js sql呼叫logger列印紀錄檔

const logger = require("./logger") 
new Sequelize( 
logging: function (sql, costtime) { 
logger.error( `sql exe : ${sql} | costtime ${costtime} ms` ); 
} )

/app.js 設定requestId、設定requestId返回響應頭、列印存取紀錄檔

const session = require('./session') 
const logger = require('./logger') 
async function accessHandler(ctx, next) 
{ 
const requestId = ctx.header['x-request-id'] || uuid()
const params = ctx.request.body ? JSON.stringify(ctx.request.body) : JSON.stringify(ctx.request.query)
// 設定requestId session.run(() => { session.set('requestId', requestId)
logger.info(`url:${ctx.request.path}；params:${params}`) next()
// 設定返回響應頭
ctx.res.setHeader('X-Request-Id',requestId)
}) }

我們看下當一條請求路徑是/home?a=1到來時的紀錄檔：

存取紀錄檔：
requestId:79f422a6-6151-4bfd-93ca-3c6f892fb9ac url:/home；params:{"a":"1"}

Sql紀錄檔：
requestId:79f422a6-6151-4bfd-93ca-3c6f892fb9ac sql exe :
Executed (default): SELECT `id` FROM t_user

可以看到同一條請求整個鏈路的紀錄檔requestId是一樣的。如果後面有告警發到告警平臺，那麼我們根據requestId就可以找到這條請求執行的整個鏈路了。

細心的同學可能會觀察到我在介面返回的響應頭裡面也設定了requestId,目的就是為了後續如果發現某條請求響應緩慢或者有問題，那直接從瀏覽器就可以知道requestId，就可以做分析了。

二、效能開銷

我本地做了一下壓測，

這是記憶體的佔用對比：

比未使用async_hook多了約10%。

對於我們qps是百級別的系統還好，但是如果是高並行的服務，可能要慎重考慮下了。

ps：有錯誤歡迎指出，不喜勿噴

更多node相關知識，請存取：！

以上就是手把手教你在node中怎麼優雅列印全鏈路紀錄檔的詳細內容，更多請關注TW511.COM其它相關文章！