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

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

1. Principle 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 a request?

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

and then write a middleware to inject the requestId into the context. When logging needs to be done, take it out of the context for printing.

In third-party services and SQL logs, you also need to inject the requestId into

The requestId is passed into the corresponding function for printing. It is too troublesome to pass it layer by layer, and the code is also relatively intrusive.

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

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

namely asyncId (the current life cycle ID of the asynchronous resource), trigerAsyncId ( Parent asynchronous resource ID).

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

asyncHook = async_hook.createHook({
  //Listen to the creation of asynchronous resources init(asyncId,type,triggerAsyncId,resource){},
  // Before the asynchronous resource callback function starts executing before(asyncId){},
  //After the asynchronous resource callback function starts executing, after(asyncId){},
  // Monitor the destruction of asynchronous resources destroy(asyncId){}
})

Then if we make a mapping, each asyncId maps to a storage, and the corresponding requestId is stored in the storage, then the requestId 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 a higher version of node>=8.2.1) Of course, there are other implementations in the community, such as cls-session, node-continuation-local-storage, etc.

Let's talk about an example of using 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 logger to print logs

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

/app.js Set requestId, set requestId to return response header, and print 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)
//Set requestId session.run(() => { session.set('requestId', requestId)
logger.info(`url:${ctx.request.path}; params:${params}`) next()
//Set the return response header ctx.res.setHeader('X-Request-Id',requestId)
}) }

Let’s look at the log when a request path is /home?a=1:

Access log:
requestId:79f422a6-6151-4bfd-93ca-3c6f892fb9ac url:/home;params:{"a":"1"}

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

You can see that the log requestId of the entire link for the same request 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 notice that I also set the requestId in the response header returned by the interface. The purpose is that if a request is found to respond slowly or has problems, the requestId can be known directly from the browser and analyzed. .

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 100-level system, but if it is a highly concurrent service, we may need to consider it carefully.

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