Teach you step by step how to elegantly print full-link logs in node

How does node print full link logs elegantly? The following article will introduce to you how to elegantly print full-link logs in node. I hope it will be helpful to you!

When a user reports a problem: When an error occurs when using a certain online function, how can you quickly and accurately locate it? How to effectively track optimization when a certain request interface returns data slowly?

1. Principles and Practice

As we all know, when a request comes, the following logs will probably be generated:

1. AceesLog: User access Log

2. Exception: Code exception log

3. SQL: sql query log

4. ThirdParty: Third-party service log

How to track All logs generated by one request?

The general approach is to use a requestId as a unique identifier.

Then write a middleware and inject the requestId into the context. When logging is required, print it out from the context.

In third-party services and SQL logs, the requestId also needs to be passed into the corresponding function for printing. This layer-by-layer transfer is really too troublesome and the code is relatively intrusive.

Our goal is to reduce the intrusiveness of the code, inject it once and track it automatically.

After investigation, async_hooks can track the life cycle of asynchronous behavior. In each asynchronous resource (each request is an asynchronous resource), it has 2 IDs,

are asyncId (current life cycle ID of asynchronous resource), trigerAsyncId (parent asynchronous resource ID).

async_hooks provides the following life cycle hooks to monitor asynchronous resources:

asyncHook = async_hook.createHook({
  // 监听异步资源的创建
  init(asyncId,type,triggerAsyncId,resource){},
  // 异步资源回调函数开始执行之前
  before(asyncId){},
  // 异步资源回调函数开始执行后
  after(asyncId){},
  // 监听异步资源的销毁
  destroy(asyncId){}
})

If we make a mapping, each asyncId maps to a storage, and the corresponding requestId is stored in the storage, then the requestId is Can be easily obtained.

It just so happens that the cls-hooked library has been encapsulated based on async_hooks, maintaining a copy of data in the same asynchronous resource and storing it in the form of key-value pairs. (Note: async_hooked needs to be used in the higher version node>=8.2.1) Of course, there are other implementations in the community, such as cls-session, node-continuation-local-storage, etc.

The following is an example of how I applied cls-hooked in my project:

/session.js Create a named storage space

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

/logger.js Print log

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 calls the logger to print the log

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

/app.js Set the requestId, set the requestId to return the response header, and print the access log

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)
}) }

Let’s take a look at the next one The log when the request path is /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

You can see that the requestId of the log of the same request for the entire link is the same. If there is an alarm later sent to the alarm platform, then we can find the entire link executed by this request based on the requestId.

Careful students may observe that I also set the requestId in the response header returned by the interface. The purpose is to know the requestId directly from the browser if a certain request is found to respond slowly or has problems. , you can do analysis.

2. Performance overhead

I did a stress test locally,

This is the memory usage comparison:

About 10% more than not using async_hook.

It’s okay for our QPS system with level 100, but if it is a high-concurrency service, we may need to consider it carefully.

ps: If there are any errors, please point them out. If you don’t like them, please don’t comment.

For more node-related knowledge, please visit: nodejs tutorial!

The above is the detailed content of Teach you step by step how to elegantly print full-link logs in node. For more information, please follow other related articles on the PHP Chinese website!