如何用node優(yōu)雅地打印全鏈路日志
前言
當(dāng)用戶報問題:線上某個功能使用報錯時,如何快速準(zhǔn)確地定位?當(dāng)某個請求接口返回數(shù)據(jù)緩慢時,如何有效地追蹤優(yōu)化?
一、原理和實踐
眾所周知,當(dāng)一個請求到來時,大概會有以下日志產(chǎn)生:
1、AceesLog:用戶訪問日志
2、Exception:代碼異常日志
3、SQL:sql查詢?nèi)罩?/p>
4、ThirdParty:第三方服務(wù)日志
該如何追蹤一條請求產(chǎn)生的所有日志?
一般做法是使用一個requestId來做唯一標(biāo)識,
然后寫一個中間件,把requestId注入到context上下文中,當(dāng)需要打日志時,再從context中取出打印,
在第三方服務(wù)和SQL日志中,還需要把requestId傳入到相應(yīng)的函數(shù)里面打印,這樣層層傳遞,實在太麻煩,代碼侵入性也比較強。
我們的目標(biāo)是降低代碼侵入性,一次注入,自動跟蹤。
經(jīng)過調(diào)研,async_hooks可以追蹤異步行為的生命周期,在每個異步資源(每個請求都是一個異步資源)中,它都有2個ID,
分別是asyncId(異步資源當(dāng)前生命周期ID),trigerAsyncId(父級異步資源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){} })
那如果我們做一個映射,每個asyncId映射一個storage,storage里面再存儲對應(yīng)的requestId,那requestId就可以很容易獲取了。
正好cls-hooked這個庫已經(jīng)基于async_hooks做好了封裝,在同一份異步資源維護一份數(shù)據(jù),以鍵值對的形式存儲。(注意:async_hooked需要在高版本node>=8.2.1使用)當(dāng)然社區(qū)中還有其他的實現(xiàn),比如cls-session,node-continuation-local-storage等。
下面講下我把cls-hooked運用在我項目中的實例:
/session.js 創(chuàng)建命名存儲空間
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)一條請求路徑是/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是一樣的。如果后面有告警發(fā)到告警平臺,那么我們根據(jù)requestId就可以找到這條請求執(zhí)行的整個鏈路了。
細心的同學(xué)可能會觀察到我在接口返回的響應(yīng)頭里面也設(shè)置了requestId,目的就是為了后續(xù)如果發(fā)現(xiàn)某條請求響應(yīng)緩慢或者有問題,那直接從瀏覽器就可以知道requestId,就可以做分析了。
二、性能開銷
我本地做了一下壓測,
這是內(nèi)存的占用對比:
比未使用async_hook多了約10%。
對于我們qps是百級別的系統(tǒng)還好,但是如果是高并發(fā)的服務(wù),可能要慎重考慮下了。
總結(jié)
到此這篇關(guān)于如何用node優(yōu)雅地打印全鏈路日志的文章就介紹到這了,更多相關(guān)node打印全鏈路日志內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家!
相關(guān)文章
nodejs中使用HTTP分塊響應(yīng)和定時器示例代碼
本文通過示例將要創(chuàng)建一個輸出純文本的HTTP服務(wù)器,輸出的純文本每隔一秒會新增100個用換行符分隔的時間戳。實例代碼非常不錯,具有參考借鑒價值,需要的朋友參考下2017-03-03Node Puppeteer圖像識別實現(xiàn)百度指數(shù)爬蟲的示例
本篇文章主要介紹了Node Puppeteer圖像識別實現(xiàn)百度指數(shù)爬蟲的示例,小編覺得挺不錯的,現(xiàn)在分享給大家,也給大家做個參考。一起跟隨小編過來看看吧2018-02-02