手把手教你在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相关知识，请访问：nodejs 教程！

以上就是手把手教你在node中怎么优雅打印全链路日志的详细内容，更多请关注其它相关文章！

声明：本文内容由网友自发贡献，本站不承担相应法律责任。对本内容有异议或投诉，请联系2913721942#qq.com核实处理，我们将尽快回复您，谢谢合作！