Shulou(Shulou.com)06/01 Report--

This article is about how to print full-link logs in node. The editor thinks it is very practical, so share it with you as a reference and follow the editor to have a look.

When a user reports a problem: how to locate quickly and accurately when an online function is used to report an error? When a request interface returns data slowly, how to effectively track the optimization?

I. principle and practice

It is well known that when a request arrives, the following logs are generated:

1. AceesLog: user access log

2. Exception: code exception log

3. SQL:sql query log

4. ThirdParty: third-party service log

How do you track all logs generated by a request?

The general practice is to use a requestId as a unique identification

Then write a middleware, inject requestId into the context context, and when you need to log, take it out of the context and print it.

In third-party services and SQL logs, you also need to transfer requestId to the corresponding function to print, which is too troublesome and the code is more intrusive.

Our goal is to reduce code intrusiveness, one-time injection, automatic tracking.

After research, async_hooks can track the life cycle of asynchronous behavior, in each asynchronous resource (each request is an asynchronous resource), it has two ID

They are asyncId (current lifecycle ID of asynchronous resources) and trigerAsyncId (parent asynchronous resources ID).

Async_hooks provides the following lifecycle hooks to listen for asynchronous resources:

AsyncHook = async_hook.createHook ({/ / init (asyncId,type,triggerAsyncId,resource) {} for the creation of asynchronous resources, / / before (asyncId) {} before the asynchronous resource callback function starts execution, / / after (asyncId) {} after the asynchronous resource callback function starts execution, / / destroy destroy (asyncId) {}} for listening asynchronous resources)

So if we do a mapping, each asyncId mapping a storage,storage and then store the corresponding requestId, 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.

Here's an example of how I used 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 the log

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

/ app.js set requestId, set requestId return response header, print access log

Const session = require ('. / session') const logger = require ('. / logger') async function accessHandler (ctx, next) {const requestId = ctx.header ['xmurrequestlyid'] | | 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 response header ctx.res.setHeader (' XripRequesttel Idcast))})}

Let's take a 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 that requests the entire link is the same. If an alarm is sent to the alarm platform, then we can find the entire link executed by the request according to the requestId.

Careful students may notice that I have also set requestId in the response header returned by the API, so that if a request is found to be slow or problematic later, you can know the requestId directly from the browser and do analysis.

Second, performance overhead

I did a local stress test.

This is the memory footprint comparison:

About 10% more than not using async_hook.

It's okay for our qps level 100 system, but if it's a highly concurrent service, you may have to consider it carefully.

Thank you for reading! This is the end of the article on "how to print full-link logs in node". I hope the above content can be of some help to you, so that you can learn more knowledge. if you think the article is good, you can share it for more people to see!

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.