Contextual Logging in Node.js with AsyncHooks

Context is crucial for logs, traces, and other monitoring data. Without it, identifying which endpoint or request triggered an error can be challenging, even if your logs indicate an issue. In languages like Java, context is provided through thread-local storage, as each request is handled in a separate thread. However, Node.js operates in a single thread and uses an event-driven model, which makes this approach less effective.

To address this, Node.js introduced async hooks, which enables you to create a persistent execution context. Async hooks allow you to store request-specific data, such as request IDs, session data, and user context (e.g., user ID, roles, permissions), and propagate this state through callbacks and promise chains. This data remains available throughout the lifetime of a web request, allowing you to consistently retrieve it without relying on global variables or other inefficient methods.

Implementing async hooks effectively enhances your application's observability. Attaching relevant metadata to logs, traces, and monitoring outputs creates a more transparent and traceable system, aiding in debugging, performance monitoring, and understanding user behavior.

In this article, we will explore how to use async hooks in Node.js to add context to your logs, making it easier to trace and debug issues.

Prerequisites

To follow this tutorial, you should have:

• The latest version of Node.js installed.
• Experience in building web applications using Node.js.
• Basic knowledge of logging. If you need a refresher, check out our logging guides, which cover logging with Pino and Winston in Node.js.

Download the demo project

In this section, you'll download a demo project containing a Fastify application. This application provides an endpoint for user registration via a query parameter, logs the entire registration process using the default Fastify logger, validates input, stores user data in simple in-memory storage, and sends a confirmation message upon successful registration.

Start by cloning the remote repository to your machine:

git clone https://github.com/betterstack-community/async-hooks-demo.git

Navigate into the project directory:

cd async-hooks-demo

Install the dependencies, which include Fastify (a web framework similar to Express) and Nodemon (which automatically restarts the server upon saving changes):

npm install

Open the index.js file. It should include the following code:

import Fastify from "fastify";

const fastify = Fastify({ logger: true });
const logger = fastify.log;
const users = new Map(); // Simple in-memory storage for user data

fastify.get("/register", (request, reply) => {
  const userName = request.query.username; // Get username from query parameter
  logger.info("Received registration request");
  reply.send(registerUser(userName));
});

function registerUser(userName) {
  logger.info("Registering user");
  if (validateInput(userName)) {
    return saveUserData(userName);
  } else {
    logger.warn("Invalid input for username");
    return "Invalid input for username";
  }
}

function validateInput(userName) {
  const isValid = typeof userName === "string" && userName.trim() !== "";
  logger.info(`Validating input. IsValid: ${isValid}`);
  return isValid;
}

function saveUserData(userName) {
  users.set(userName, { userName });
  logger.info("User data saved");
  return sendConfirmation();
}

function sendConfirmation() {
  logger.info("Sending confirmation");
  return "User registered successfully! Confirmation sent.";
}

fastify.listen({ port: 3000 }, (err, address) => {
  if (err) {
    logger.error(err);
    process.exit(1);
  }
  logger.info(`Server is listening on ${address}`);
});

The index.js file sets up a Fastify server, which uses Pino by default for logging and includes in-memory storage for user data. It defines a GET endpoint /register that handles user registration by accepting a username as a query parameter. When a registration request is received, the server logs the request and calls the registerUser function to process the registration.

The registerUser function logs the registration attempt, validates the input using the validateInput function, and saves the user data if the input is valid. The validateInput function checks if the username is a non-empty string and logs the validation result. If the input is valid, the saveUserData function stores the username in the Map, logs the saving action, and calls the sendConfirmation function. The sendConfirmation function logs the sending of confirmation and returns a success message.

Finally, the server is set to listen on port 3000. It logs the server address upon successful startup or logs any errors that occur during the startup process.

After that, launch the development server:

npm run dev

You should see output similar to the following, confirming that the server is up and running:

> async-hooks-demo@1.0.0 dev
> nodemon

[nodemon] 3.1.4
[nodemon] to restart at any time, enter `rs`
[nodemon] watching path(s): *.*
[nodemon] watching extensions: js,mjs,cjs,json
[nodemon] starting `node index.js`
{"level":30,"time":1719568192978,"pid":377131,"hostname":"test-server","msg":"Server listening at http://[::1]:3000"}
{"level":30,"time":1719568192980,"pid":377131,"hostname":"test-server","msg":"Server listening at http://127.0.0.1:3000"}
{"level":30,"time":1719568192980,"pid":377131,"hostname":"test-server","msg":"Server is listening on http://[::1]:3000"}

Open a separate terminal window and use curl to send a GET request to the registration endpoint, specifying your desired username:

curl -X GET "http://localhost:3000/register?username=jane"

If the registration is successful, you'll see the following output:

User registered successfully! Confirmation sent.

In the terminal where the server is running, you will see logs for the actions taken by the application to process the request:

"level":30,"time":1719568243712,"pid":377131,"hostname":"test-server","reqId":"req-1","req":{"method":"GET","url":"/register?username=jane","hostname":"localhost:3000","remoteAddress":"::1","remotePort":53672},"msg":"incoming request"}
{"level":30,"time":1719568243714,"pid":377131,"hostname":"test-server","msg":"Received registration request"}
{"level":30,"time":1719568243714,"pid":377131,"hostname":"test-server","msg":"Registering user"}
{"level":30,"time":1719568243714,"pid":377131,"hostname":"test-server","msg":"Validating input. IsValid: true"}
{"level":30,"time":1719568243714,"pid":377131,"hostname":"test-server","msg":"User data saved"}
{"level":30,"time":1719568243714,"pid":377131,"hostname":"test-server","msg":"Sending confirmation"}
{"level":30,"time":1719568243722,"pid":377131,"hostname":"test-server","reqId":"req-1","res":{"statusCode":200},"responseTime":9.472754001617432,"msg":"request completed"}

Now that the application is working as intended, you can proceed to the next section.

Understanding why logs need context

Logs are crucial for monitoring and debugging applications,. However, logs can become difficult to interpret and correlate without proper context, especially with multiple simultaneous requests. This lack of context can lead to confusion, making it challenging to trace the flow of a specific request or pinpoint the source of an error.

To understand why logs need context, visit the /register endpoint with invalid input:

curl -X GET "http://localhost:3000/register?username="

Invalid input for username

Now, if you check the logs in the terminal where the server is running, you'll see the following:

...
{"level":30,"time":1719568406951,"pid":377131,"hostname":"test-server","reqId":"req-2","req":{"method":"GET","url":"/register?username=","hostname":"localhost:3000","remoteAddress":"::1","remotePort":46326},"msg":"incoming request"}
{"level":30,"time":1719568406952,"pid":377131,"hostname":"test-server","msg":"Received registration request"}
{"level":30,"time":1719568406952,"pid":377131,"hostname":"test-server","msg":"Registering user"}
{"level":30,"time":1719568406952,"pid":377131,"hostname":"test-server","msg":"Validating input. IsValid: false"}
{"level":40,"time":1719568406952,"pid":377131,"hostname":"test-server","msg":"Invalid input for username"}
{"level":30,"time":1719568406953,"pid":377131,"hostname":"test-server","reqId":"req-2","res":{"statusCode":200},"responseTime":0.9300403594970703,"msg":"request completed"}

Reading logs without a request ID makes it difficult to trace and correlate log entries for the same request. Distinguishing between log messages from different requests is challenging, especially when multiple requests are processed simultaneously. For example, seeing multiple "Registering user" or "Validating input" messages without knowing which request they belong to creates confusion.

This issue is even more pronounced when dealing with failures. Without a unique request identifier, tracing the origin and flow of errors becomes nearly impossible. If an error occurs during user registration, log entries like "Validating input" followed by "Invalid input for username" lack context without a request ID, making it hard to reproduce issues or understand their impact.

When multiple errors occur simultaneously, logs become a mix of messages from different requests, further complicating diagnosis and resolution. This ambiguity hinders root cause analysis, slows down debugging, and can lead to prolonged system downtimes. Without request IDs, developers cannot efficiently track and resolve issues tied to specific user interactions, negatively affecting the system's reliability and maintainability.

Adding sensitive data like usernames or emails to logs might seem helpful, but it poses significant security risks. In the event of a data breach, such as the Equifax breach, exposing sensitive user data can have severe consequences. Logging sensitive information increases the risk of exposing a lot of users' data in a breach, making the system more vulnerable.

Compare with logs that include request IDs:

{"level":30,"time":1719569490839,"pid":377486,"hostname":"test-server","reqId":"req-2","req":{"method":"GET","url":"/register?username=","hostname":"localhost:3000","remoteAddress":"::1","remotePort":34046},"msg":"incoming request"}
{"level":30,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","msg":"Received registration request"}
{"level":30,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","msg":"Registering user"}
{"level":30,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","isValid":false,"msg":"Validating input"}
{"level":40,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","msg":"Invalid input for username"}
{"level":30,"time":1719569490841,"pid":377486,"hostname":"test-server","reqId":"req-2","res":{"statusCode":200},"responseTime":0.7647571563720703,"msg":"request completed"}

Using a request ID in logs significantly improves the ability to trace and correlate log entries for a single request. Each log entry includes the requestId, ensuring clarity and continuity throughout the request's lifecycle. This makes it easier to follow the actions for that specific request and identify issues.

For example, in the log output, the request ID f878fb79-84a0-4944-a5dd-3c11d4f2b76b consistently appears for receiving the registration request, registering the user, validating input, and identifying invalid input. This allows you to correlate all log entries related to this specific request quickly.

Logs with request IDs enable precise issue tracking, facilitating quicker and more accurate debuggin

Adding context without using async hooks

Now that you understand the importance of adding context to your logs, you might be tempted to use global variables to store context information like request IDs. However, this approach is problematic because another request could overwrite the global variable before the first request is fully processed, leading to data corruption and unreliable concurrency handling.

Attaching context data directly to the request object is a slightly better approach but has drawbacks. The default framework updates might overwrite the values, or collaborators might unintentionally overwrite the data.

Passing context data, such as a request ID, as parameters to each function in the call chain avoids global variables but introduces other problems. Function signatures become cluttered with passed but only sometimes used parameters, making the code harder to read and maintain. Tracking these parameters across multiple functions is complex and error-prone, and functions become tightly coupled with context, reducing their reusability.

To understand how passing context through parameters can become problematic, add the highlighted code to the index.js file:

import Fastify from "fastify";
import { v4 as uuidv4 } from "uuid";

const fastify = Fastify({ logger: true });
const logger = fastify.log;
const users = new Map(); // Simple in-memory storage for user data

fastify.get("/register", async (request, reply) => {
  const requestId = uuidv4(); // Generate a unique UUID
  const userName = request.query.username;
  logger.info({ requestId }, "Received registration request");
  reply.send(registerUser(requestId, userName));
});

function registerUser(requestId, userName) {
  logger.info({ requestId }, "Registering user");
  if (validateInput(requestId, userName)) {
    return saveUserData(requestId, userName);
  } else {
    logger.warn({ requestId }, "Invalid input for username");
    return `Invalid input for username.`;
  }
}

function validateInput(requestId, userName) {
  const isValid = typeof userName === "string" && userName.trim() !== "";
  logger.info({ requestId, isValid }, "Validating input");
  return isValid;
}

function saveUserData(requestId, userName) {
  users.set(userName, { userName });
  logger.info({ requestId }, "User data saved");
  return sendConfirmation(requestId);
}

function sendConfirmation(requestId) {
  logger.info({ requestId }, "Sending confirmation");
  return "User registered successfully! Confirmation sent.";
}
...

In the above example, a unique request ID (requestId) is generated using uuidv4() and passed through each function call in the registration process. This request ID is logged at various stages, ensuring each function logs information related to the same request.

Now save your file, and the server will automatically restart. Open a second terminal and register with a valid user again:

curl -X GET "http://localhost:3000/register?username=john"

Then try to register with an invalid user:

curl -X GET "http://localhost:3000/register?username="

Return to the terminal where the server is running, and you will see log messages similar to this:

{"level":30,"time":1719569490839,"pid":377486,"hostname":"test-server","reqId":"req-2","req":{"method":"GET","url":"/register?username=","hostname":"localhost:3000","remoteAddress":"::1","remotePort":34046},"msg":"incoming request"}
{"level":30,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","msg":"Received registration request"}
{"level":30,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","msg":"Registering user"}
{"level":30,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","isValid":false,"msg":"Validating input"}
{"level":40,"time":1719569490840,"pid":377486,"hostname":"test-server","requestId":"f878fb79-84a0-4944-a5dd-3c11d4f2b76b","msg":"Invalid input for username"}
{"level":30,"time":1719569490841,"pid":377486,"hostname":"test-server","reqId":"req-2","res":{"statusCode":200},"responseTime":0.7647571563720703,"msg":"request completed"}

You will notice that the logs now have requestId, making it easy to correlate log entries for a single request and understand continuity throughout the request's lifecycle. This approach, however, comes with the cost of passing a parameter like requestId to every function, leading to code clutter, reduced readability, and maintenance difficulties.

Function signatures become unnecessarily bloated, and you have to propagate parameters through functions that don't directly need them, making the code harder to manage and more prone to bugs. Additionally, this reduces function reusability and violates the principle of separation of concerns by mixing business logic with contextual details.

To solve this problem, Node.js offers async hooks, which you will explore in detail in the next section.

Using AsyncHooks in Node.js

Node.js offers async hooks, which contain APIs for storing data in a context that maintains its state through asynchronous operations involving callbacks, timers, and promise chains. By storing data in the AsyncLocalStorage, you can retrieve it at any point in the async flow without explicitly passing it through function parameters.

You've already encountered async hooks if you've used continuation-local-storage or cls-hooked libraries. These hooks are valuable for request-level caching, enhancing stack traces or logs, and measuring performance.

To implement async hooks, open your index.js file and remove all the requestId parameters:

fastify.get("/register", async (request, reply) => {
  const requestId = uuidv4(); // Generate a unique UUID
  ...
  reply.send(registerUser(requestId, userName));
});

function registerUser(requestId, userName) {
  logger.info({ requestId }, "Registering user");
  if (validateInput(requestId, userName)) {
    return saveUserData(requestId, userName);
  } else {
    ...
  }
}

function validateInput(requestId, userName) {
  ...
  return isValid;
}

function saveUserData(requestId, userName) {
  ...
  return sendConfirmation(requestId);
}

function sendConfirmation(requestId) {
  logger.info({ requestId }, "Sending confirmation");
  return `User registered successfully! Confirmation sent.`;
}
...

Now, add AsyncLocalStorage to store and manage the request data: :

import Fastify from "fastify";
import { v4 as uuidv4 } from "uuid";
import { AsyncLocalStorage } from "async_hooks";

const fastify = Fastify({ logger: true });
const logger = fastify.log;
const asyncLocalStorage = new AsyncLocalStorage();
...

fastify.get("/register", (request, reply) => {
  const requestId = uuidv4();

  asyncLocalStorage.run(new Map(), () => {
    asyncLocalStorage.getStore().set("requestId", requestId);
    const userName = request.query.username;
    logger.info({ requestId }, "Received registration request");
    reply.send(registerUser(userName));
  });
});

function getRequestId() {
  const store = asyncLocalStorage.getStore();
  return store ? store.get("requestId") : undefined;
}

function registerUser(userName) {
  const requestId = getRequestId();
  logger.info({ requestId }, "Registering user");
  if (validateInput(userName)) {
    ...
  } else {
    ...
  }
}

function validateInput(userName) {
  const requestId = getRequestId();
  const isValid = typeof userName === "string" && userName.trim() !== "";
  logger.info({ requestId, isValid }, "Validating input");
  return isValid;
}

function saveUserData(userName) {
  const requestId = getRequestId();
  users.set(userName, { userName });
  logger.info({ requestId }, "User data saved");
  return sendConfirmation();
}

function sendConfirmation() {
  const requestId = getRequestId();
  logger.info({ requestId }, "Sending confirmation");
  return `User registered successfully! Confirmation sent for RequestId: ${requestId}`;
}
...

The AsyncLocalStorage manages and retrieves a requestId within asynchronous operations. You start by importing and initializing AsyncLocalStorage. Within the /register route, AsyncLocalStorage runs with a new map to store the requestId. The getRequestId function retrieves the requestId from storage, ensuring it is consistently available across the different asynchronous function calls such as registerUser, validateInput, saveUserData, and sendConfirmation.

This approach ensures that the requestId is automatically available for logging and tracing without explicitly passing it through function parameters.

Save your changes, and the server will automatically restart.

Now, send a request with a valid user:

curl -X GET "http://localhost:3000/register?username=john"

Make another request with an invalid user:

curl -X GET "http://localhost:3000/register?username="

You will see the logs with the request IDs:

{"level":30,"time":1719571279221,"pid":378139,"hostname":"test-server","requestId":"1137837b-0e89-4ea8-abf1-095a7e27890c","msg":"Received registration request"}
....
{"level":30,"time":1719571289649,"pid":378139,"hostname":"test-server","requestId":"775f4b35-2441-4439-a721-22dd985a4092","msg":"Received registration request"}
{"level":30,"time":1719571289649,"pid":378139,"hostname":"test-server","requestId":"775f4b35-2441-4439-a721-22dd985a4092","msg":"Registering user"}
{"level":30,"time":1719571289649,"pid":378139,"hostname":"test-server","requestId":"775f4b35-2441-4439-a721-22dd985a4092","isValid":false,"msg":"Validating input"}
{"level":40,"time":1719571289649,"pid":378139,"hostname":"test-server","requestId":"775f4b35-2441-4439-a721-22dd985a4092","msg":"Invalid input for username"}
{"level":30,"time":1719571289650,"pid":378139,"hostname":"test-server","reqId":"req-2","res":{"statusCode":200},"responseTime":1.1139988899230957,"msg":"request completed"}

The logs now include request IDs, making it easy to correlate log entries for a single request and maintain continuity throughout its lifecycle. This has been achieved without explicitly passing the request ID as a parameter through multiple function calls.

Final thoughts

This tutorial has guided you through the importance of context logging and how to implement it effectively using the AsyncHooks module in Node.js. By using AsyncLocalStorage, you've learned how to maintain context across asynchronous operations, significantly enhancing your application's observability and debugging capabilities.

To deepen your understanding of AsyncHooks, explore the official Node.js documentation. While AsyncHooks offers additional APIs like createHook, AsyncHook, and executionAsyncResource, it's worth noting that the documentation advises caution due to potential usability and performance concerns with these more advanced features.

For further enhancing your logging practices, explore our comprehensive logging guides for valuable insights and best practices.

Article by

Stanley Ulili

Stanley is a freelance web developer and researcher from Malawi. He loves learning new things and writing about them to understand and solidify concepts. He hopes that by sharing his experience, others can learn something from them too!

Got an article suggestion? Let us know

This work is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License.