Problem description

Due to the limitations of node.js’s single-threaded model, we cannot set global Traceid to aggregate requests, that is, bind output logs to requests. If logs and requests are not bound, it is difficult to determine the relationship between log output and user requests, which makes it difficult to troubleshoot online problems.

For example, when a user accesses the retrieveOne API, the retrieveOneSub function is called, which would be tedious if we wanted to output the student information corresponding to the current request in the retrieveOneSub function. Under the current implementation of course-se, our solution to this problem is as follows:

  • Scenario 1: In the callretrieveOneSubThe parent function of the function, i.eretrieveOneInside, theparamDatafordeconstruction, output student related information, but the programUnable to refine the log output granularity.
  • Solution 2: ModifyretrieveOneSubFunction signature, receiveparamDataFor its parameters, the programEnsures log output granularity, butIn the case of a long call chain, you need to change the function signature for each functionTo make it receiveparamData, a lot of work, not very feasible.
/** * returns a submitted function * @param {ParamData} ParamData * @param {Context} CTX * @param {string} id */
export async function retrieveOne(paramData, ctx, id) {
  const { subModel } = paramData.ce;
  const sub_asgn_id = Number(id);

  // Run the paramdata. user command to obtain user information, such as user_id.
  // But you cannot refine the log output granularity unless you change the signature of retrieveOneSub,
  // Add paramData as its parameter.
  const { user_id } = paramData.user;
  console.log(`${user_id} is trying to retreive one submission.`);
  // The retrieveOneSub function is invoked.
  const sub = await retrieveOneSub(sub_asgn_id, subModel);
  const submission = sub;
  assign(sub, { sub_asgn_id });
  assign(paramData, { submission, sub });
  return sub;
}

@param {number} sub_asgn_id * @param {SubModel} model */
async function retrieveOneSub(sub_asgn_id, model) {
  const [sub] = await model.findById(sub_asgn_id);
  if(! sub) {throw new ME.SoftError(ME.NOT_FOUND, 'The commit could not be found');
  }
  return sub;
}
Copy the code

Async Hooks

Node’s Async Hooks experimental API can also be used to solve this problem. After Node.js v8.x, there is official support for the Async Hooks API that can listen for asynchronous behavior.

Async Scope

Async Hooks Provide an Async Scope for each (synchronous or asynchronous) function. Call the executionAsyncId method to get the Async ID of the current function. Call triggerAsyncId to get the Async ID of the current function caller.

const asyncHooks = require("async_hooks");
const { executionAsyncId, triggerAsyncId } = asyncHooks;

console.log(`top level: ${executionAsyncId()} ${triggerAsyncId()}`);

const f = (a)= > {
  console.log(`f: ${executionAsyncId()} ${triggerAsyncId()}`);
};

f();

const g = (a)= > {
  console.log(`setTimeout: ${executionAsyncId()} ${triggerAsyncId()}`);
  setTimeout((a)= > {
    console.log(`inner setTimeout: ${executionAsyncId()} ${triggerAsyncId()}`);
  }, 0);
};

setTimeout(g, 0);
setTimeout(g, 0);
Copy the code

In the above code, we use setTimeout to simulate an asynchronous call process, and in this asynchronous process we call the handler synchronization function, and we output its corresponding Async ID and Trigger Async ID in each function. After executing the above code, the result is as follows.

top level: 1 0
f: 1 0
setTimeout: 7 1       
setTimeout: 9 1       
inner setTimeout: 11 7
inner setTimeout: 13 9
Copy the code

Through the above log output, we get the following information:

  • Calling a synchronous function does not change its Async ID, such as a functionfThe Async ID in is the same as the Async ID of its caller.
  • The same function that is called asynchronously at different times will be assigned different Async ids, as shown in the above codegFunction.

Tracing asynchronous resources

As we said earlier, Async Hooks can be used to trace asynchronous resources. To do this, we need to understand the relevant API for Async Hooks, as described in the comments in the code below.

const asyncHooks = require("async_hooks");

// Create an AsyncHooks instance.
const hooks = asyncHooks.createHook({
  // An init event is emitted when an object is constructed.
  init: function(asyncId, type, triggerId, resource) {},
  // Before events are emitted before the callback is executed.
  before: function(asyncId) {},
  // The after event is emitted after the callback is executed.
  after: function(asyncId) {},
  // The Destroy event is emitted after the object is destroyed.
  destroy: function(asyncId) {}});// Enable hooks for asynchronous functions in this instance.
hooks.enable();

// Turn off tracking for asynchronous resources.
hooks.disable();
Copy the code

When we call createHook, we inject init, before, After, and destroy functions to track the different life cycles of an asynchronous resource.

New solution

Based on the Async Hooks API, we can design the following solution to bind logs to request records, that is, global binding of Trace ids.

const asyncHooks = require("async_hooks");
const { executionAsyncId } = asyncHooks;

// Save the context of the asynchronous call.
const contexts = {};

const hooks = asyncHooks.createHook({
  // An init event is emitted when an object is constructed.
  init: function(asyncId, type, triggerId, resource) {
    // triggerId is the asyncId of the caller of the current function.
    if (contexts[triggerId]) {
      // Sets the asynchronous context of the current function to be the same as that of the caller.contexts[asyncId] = contexts[triggerId]; }},// The Destroy event is emitted after the object is destroyed.
  destroy: function(asyncId) {
    if(! contexts[asyncId])return;
    // Destroys the current asynchronous context.
    deletecontexts[asyncId]; }});/ / the key! Allow hooks to be enabled for asynchronous functions in this instance.
hooks.enable();

// Simulate business processing functions.
function handler(params) {
  // Set the context, which can be done in Middleware (e.g. Logger Middleware).
  contexts[executionAsyncId()] = params;
  
  // Here is the business logic.
  console.log(`handler The ${JSON.stringify(params)}`);
  f();
}

function f() {
  setTimeout((a)= > {
    // Outputs the params that belong to the asynchronous procedure.
    console.log(`setTimeout The ${JSON.stringify(contexts[executionAsyncId()])}`);
  });
}

// Simulate two asynchronous processes (two requests).
setTimeout(handler, 0, { id: 0 });
setTimeout(handler, 0, { id: 1 });
Copy the code

In the code above we said contexts are used to store context data (such as Trace ID) in each asynchronous procedure, then we created an instance of Async Hooks. When the asynchronous resource is initialized, the context data corresponding to the current Async ID is set to be the context data of the caller. When the asynchronous resource is destroyed, we delete its corresponding context data.

In this way, we solve the problem by simply setting the context data at the beginning and retrieving it in the various procedures (synchronous and asynchronous) that it raises.

Execute the above code and the result is as follows. According to the output log, our solution works.

handler {"id":0}
handler {"id":1}
setTimeout {"id":0}
setTimeout {"id":1}
Copy the code

Note, however, that Async Hooks are experimental apis with some performance costs, but Node officials are working to make them productively available. Therefore, with sufficient machine resources, use this solution to sacrifice some performance in exchange for development experience.