Node uses async_hooks module for request tracking

The async_hooks module is an experimental API officially added to Node.js in version v8.0.0. We also put it into production environment under version v8.xx.

So what are async_hooks?

async_hooks provides an API for tracking asynchronous resources, which are objects with associated callbacks.

In short, the async_hooks module can be used to track asynchronous callbacks. So how do you use this tracking capability and what problems may arise during its use?

Understanding async_hooks

async_hooks under v8.xx version mainly consists of two parts, one is createHook for tracking life cycle, and the other is AsyncResource for creating asynchronous resources.

const { createHook, AsyncResource, executionAsyncId } = require('async_hooks')

const hook = createHook({
 init (asyncId, type, triggerAsyncId, resource) {},
 before (asyncId) {},
 after (asyncId) {},
 destroy (asyncId) {}
})
hook.enable()

function fn () {
 console.log(executionAsyncId())
}

const asyncResource = new AsyncResource('demo')
asyncResource.run(fn)
asyncResource.run(fn)
asyncResource.emitDestroy()

The meaning and execution result of the above code are:

1. Creates a hooks instance containing hook functions that are executed during the init, before, after, and destroy cycles of each asynchronous operation.
2. Enable this hooks instance.
3. Manually create an asynchronous resource of type demo. At this time, the init hook is triggered, the asynchronous resource id is asyncId, the type is type (ie demo), the creation context id of the asynchronous resource is triggerAsyncId, and the asynchronous resource is resource.
4. Use this asynchronous resource to execute the fn function twice. This will trigger before twice and after twice. The asynchronous resource id is asyncId, which is the same as the value obtained through executionAsyncId in the fn function.
5. Manually trigger the destroy lifecycle hook.

Behind the asynchronous operations such as async, await, promise syntax or requests that we commonly use are asynchronous resources, which will also trigger these lifecycle hook functions.

Then, in the init hook function, we can create a pointing relationship from the asynchronous resource creation context triggerAsyncId (parent) to the current asynchronous resource asyncId (child), connect the asynchronous calls in series, get a complete call tree, and obtain the asyncId of the asynchronous resource that executes the current callback through executionAsyncId() in the callback function (i.e. fn in the above code), and trace the source of the call from the call chain.

At the same time, we also need to note that init is a hook for asynchronous resource creation, not a hook for asynchronous callback function creation. It will only be executed once when asynchronous resources are created. What problems will this bring in actual use?

Request Tracking

For the purpose of exception troubleshooting and data analysis, we hope to automatically add the request-id in the request header of the request sent by the client to the request header of each request sent to the mid- and back-end services in our Ada architecture Node.js service.

The simple design of the function implementation is as follows:

1. The init hook allows asynchronous resources on the same call chain to share a storage object.
2. Parse the request-id in the request header and add it to the storage corresponding to the current asynchronous call chain.
3. Rewrite the request method of http and https modules to obtain the request-id stored in the current call chain when the request is executed.

The sample code is as follows:

const http = require('http')
const { createHook, executionAsyncId } = require('async_hooks')
const fs = require('fs')

// Track the call chain and create a call chain storage object const cache = {}
const hook = createHook({
 init (asyncId, type, triggerAsyncId, resource) {
  if (type === 'TickObject') return
  // Since console.log is also an asynchronous behavior in Node.js, it will trigger the init hook, so we can only record logs through synchronous methods fs.appendFileSync('log.out', `init ${type}(${asyncId}: trigger: ${triggerAsyncId})\n`);
  // Determine whether the call chain storage object has been initialized if (!cache[triggerAsyncId]) {
   cache[triggerAsyncId] = {}
  }
  // Share the parent node's storage with the current asynchronous resource by reference cache[asyncId] = cache[triggerAsyncId]
 }
})
hook.enable()

// Rewrite http
const httpRequest = http.request
http.request = (options, callback) => {
 const client = httpRequest(options, callback)
 // Get the request-id stored in the asynchronous resource corresponding to the current request and write it to the header
 const requestId = cache[executionAsyncId()].requestId
 console.log('cache', cache[executionAsyncId()])
 client.setHeader('request-id', requestId)

 return client
}

function timeout () {
 return new Promise((resolve, reject) => {
  setTimeout(resolve, Math.random() * 1000)
 })
}
// Create service http
 .createServer(async (req, res) => {
  // Get the request-id of the current request and write it to the storage cache[executionAsyncId()].requestId = req.headers['request-id']
  //Simulate some other time-consuming operations await timeout()
  // Send a request http.request('http://www.baidu.com', (res) => {})
  res.write('hello\n')
  res.end()
 })
 .listen(3000)

Execute the code and perform a send test, and you will find that the request-id can be obtained correctly.

trap

At the same time, we also need to note that init is a hook for asynchronous resource creation, not a hook for asynchronous callback function creation, and it will only be executed once when asynchronous resources are created.

However, the above code is problematic. As demonstrated in the code of the async_hooks module introduced earlier, an asynchronous resource can continuously execute different functions, that is, asynchronous resources can be reused. Especially for asynchronous resources like TCP that are created by the C/C++ part, multiple requests may use the same TCP asynchronous resource. As a result, in this case, the initial init hook function will only be executed once when multiple requests arrive at the server, causing the call chain tracing of multiple requests to track the same triggerAsyncId, thereby referencing the same storage.

We modify the previous code as follows to perform a verification. The storage initialization part saves triggerAsyncId to facilitate the observation of the tracking relationship of asynchronous calls:

  if (!cache[triggerAsyncId]) {
   cache[triggerAsyncId] = {
    id: triggerAsyncId
   }
  }

The timeout function is changed to perform a long-time operation first and then a short-time operation:

function timeout () {
 return new Promise((resolve, reject) => {
  setTimeout(resolve, [1000, 5000].pop())
 })
}

After restarting the service, use postman (not curl because curl will close the connection after each request, which makes it impossible to reproduce) to send two consecutive requests. You can observe the following output:

{ id: 1, requestId: 'The id of the second request' }
{ id: 1, requestId: 'The id of the second request' }

It can be found that in the case of multiple concurrent operations with other operations that take varying amounts of time between write and read storage, the value stored in the request that arrives at the server first will be overwritten by the request that arrives at the server later, causing the previous request to read the wrong value. Of course, you can ensure that no other time-consuming operations are inserted between writing and reading, but in complex services, this kind of mental maintenance method is obviously unreliable. At this point, we need to make JS enter a new asynchronous resource context before each reading and writing, that is, obtain a new asyncId to avoid this reuse. The following modifications need to be made to the call chain storage part:

const http = require('http')
const { createHook, executionAsyncId } = require('async_hooks')
const fs = require('fs')
const cache = {}

const httpRequest = http.request
http.request = (options, callback) => {
 const client = httpRequest(options, callback)
 const requestId = cache[executionAsyncId()].requestId
 console.log('cache', cache[executionAsyncId()])
 client.setHeader('request-id', requestId)

 return client
}

// Extract storage initialization into an independent method async function cacheInit (callback) {
 // Use the await operation to make the code after await enter a new asynchronous context await Promise.resolve()
 cache[executionAsyncId()] = {}
 // Use callback execution so that subsequent operations belong to this new asynchronous context return callback()
}

const hook = createHook({
 init (asyncId, type, triggerAsyncId, resource) {
  if (!cache[triggerAsyncId]) {
   // init hook no longer initializes return fs.appendFileSync('log.out', `Not initialized using cacheInit method`)
  }
  cache[asyncId] = cache[triggerAsyncId]
 }
})
hook.enable()

function timeout () {
 return new Promise((resolve, reject) => {
  setTimeout(resolve, [1000, 5000].pop())
 })
}

http
.createServer(async (req, res) => {
 // Pass subsequent operations as callbacks to cacheInit
 await cacheInit(async function fn() {
  cache[executionAsyncId()].requestId = req.headers['request-id']
  await timeout()
  http.request('http://www.baidu.com', (res) => {})
  res.write('hello\n')
  res.end()
 })
})
.listen(3000)

It is worth mentioning that this organizational method using callbacks is very consistent with the koajs middleware model.

async function middleware (ctx, next) {
 await Promise.resolve()
 cache[executionAsyncId()] = {}
 return next()
}

NodeJs v14

This way of creating a new asynchronous context using await Promise.resolve() always seems a bit "heretical". Fortunately, NodeJs v9.xx provides an official implementation of creating an asynchronous context, asyncResource.runInAsyncScope. Even better, NodeJs v14.xx directly provides the official implementation of asynchronous call chain data storage, which will directly help you complete the three tasks of asynchronous call relationship tracking, creating new asynchronous launch documents, and managing data! The API will not be introduced in detail. We will directly use the new API to transform the previous implementation

const { AsyncLocalStorage } = require('async_hooks')
// Create an asyncLocalStorage storage instance directly, no longer need to manage async lifecycle hooks const asyncLocalStorage = new AsyncLocalStorage()
const storage = {
 enable (callback) {
  // Use the run method to create a new storage, and subsequent operations need to be executed as callbacks of the run method to use a new asynchronous resource context asyncLocalStorage.run({}, callback)
 },
 get (key) {
  return asyncLocalStorage.getStore()[key]
 },
 set (key, value) {
  asyncLocalStorage.getStore()[key] = value
 }
}

// Rewrite http
const httpRequest = http.request
http.request = (options, callback) => {
 const client = httpRequest(options, callback)
 // Get the request-id of the asynchronous resource storage and write it to the header
 client.setHeader('request-id', storage.get('requestId'))

 return client
}

// Using http
 .createServer((req, res) => {
  storage.enable(async function () {
   // Get the request-id of the current request and write it to storage storage.set('requestId', req.headers['request-id'])
   http.request('http://www.baidu.com', (res) => {})
   res.write('hello\n')
   res.end()
  })
 })
 .listen(3000)

As you can see, the official implementation of asyncLocalStorage.run API is also consistent in structure with our second version implementation.

Therefore, in Node.js v14.xx, the request tracking function can be easily implemented using the async_hooks module.

This is the end of this article about using the async_hooks module for node request tracking. For more information about node async_hooks request tracking, please search for previous articles on 123WORDPRESS.COM or continue to browse the following related articles. I hope you will support 123WORDPRESS.COM in the future!