快捷導(dǎo)航

如何用node優(yōu)雅地打印全鏈路日志

更新時(shí)間：2022年03月07日 16:33:36 作者：lemon在努力

這篇文章主要給大家介紹了關(guān)于如何用node優(yōu)雅地打印全鏈路日志的相關(guān)資料,文中通過實(shí)例代碼介紹的非常詳細(xì),對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值,需要的朋友可以參考下

前言

當(dāng)用戶報(bào)問題：線上某個(gè)功能使用報(bào)錯(cuò)時(shí)，如何快速準(zhǔn)確地定位？當(dāng)某個(gè)請(qǐng)求接口返回?cái)?shù)據(jù)緩慢時(shí)，如何有效地追蹤優(yōu)化？

一、原理和實(shí)踐

眾所周知，當(dāng)一個(gè)請(qǐng)求到來時(shí)，大概會(huì)有以下日志產(chǎn)生：

1、AceesLog：用戶訪問日志

2、Exception：代碼異常日志

3、SQL：sql查詢?nèi)罩?/p>

4、ThirdParty：第三方服務(wù)日志

該如何追蹤一條請(qǐng)求產(chǎn)生的所有日志？

一般做法是使用一個(gè)requestId來做唯一標(biāo)識(shí)，

然后寫一個(gè)中間件，把requestId注入到context上下文中，當(dāng)需要打日志時(shí)，再從context中取出打印，

在第三方服務(wù)和SQL日志中，還需要把requestId傳入到相應(yīng)的函數(shù)里面打印，這樣層層傳遞，實(shí)在太麻煩，代碼侵入性也比較強(qiáng)。

我們的目標(biāo)是降低代碼侵入性，一次注入，自動(dòng)跟蹤。

經(jīng)過調(diào)研，async_hooks可以追蹤異步行為的生命周期，在每個(gè)異步資源（每個(gè)請(qǐng)求都是一個(gè)異步資源）中，它都有2個(gè)ID，

分別是asyncId（異步資源當(dāng)前生命周期ID），trigerAsyncId（父級(jí)異步資源ID）。

async_hooks提供了以下生命周期鉤子來監(jiān)聽異步資源：

asyncHook = async_hook.createHook({
  // 監(jiān)聽異步資源的創(chuàng)建
  init(asyncId,type,triggerAsyncId,resource){},
  // 異步資源回調(diào)函數(shù)開始執(zhí)行之前
  before(asyncId){},
  // 異步資源回調(diào)函數(shù)開始執(zhí)行后
  after(asyncId){},
  // 監(jiān)聽異步資源的銷毀
  destroy(asyncId){}
})

那如果我們做一個(gè)映射，每個(gè)asyncId映射一個(gè)storage，storage里面再存儲(chǔ)對(duì)應(yīng)的requestId，那requestId就可以很容易獲取了。

正好cls-hooked這個(gè)庫已經(jīng)基于async_hooks做好了封裝，在同一份異步資源維護(hù)一份數(shù)據(jù)，以鍵值對(duì)的形式存儲(chǔ)。（注意：async_hooked需要在高版本node>=8.2.1使用）當(dāng)然社區(qū)中還有其他的實(shí)現(xiàn)，比如cls-session，node-continuation-local-storage等。

下面講下我把cls-hooked運(yùn)用在我項(xiàng)目中的實(shí)例：

/session.js 創(chuàng)建命名存儲(chǔ)空間

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調(diào)用logger打印日志

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

/app.js 設(shè)置requestId、設(shè)置requestId返回響應(yīng)頭、打印訪問日志

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)
// 設(shè)置requestId session.run(() => { session.set('requestId', requestId)
logger.info(`url:${ctx.request.path}；params:${params}`) next()
// 設(shè)置返回響應(yīng)頭
ctx.res.setHeader('X-Request-Id',requestId)
}) }

我們看下當(dāng)一條請(qǐng)求路徑是/home?a=1到來時(shí)的日志：

訪問日志：
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

可以看到同一條請(qǐng)求整個(gè)鏈路的日志requestId是一樣的。如果后面有告警發(fā)到告警平臺(tái)，那么我們根據(jù)requestId就可以找到這條請(qǐng)求執(zhí)行的整個(gè)鏈路了。

細(xì)心的同學(xué)可能會(huì)觀察到我在接口返回的響應(yīng)頭里面也設(shè)置了requestId,目的就是為了后續(xù)如果發(fā)現(xiàn)某條請(qǐng)求響應(yīng)緩慢或者有問題，那直接從瀏覽器就可以知道requestId，就可以做分析了。