Correlating the logs for tracking In NestJs

The Problem

Imagine you’re at the helm of an e-commerce juggernaut—a complex system with multiple services orchestrating tasks like managing user carts, processing orders, handling payments, and tracking shipments. It’s a bustling digital marketplace, and transactions flow seamlessly between these services.
But here’s the catch: With so many moving parts, there’s bound to be a hiccup somewhere. Maybe an order fails to process, a payment gateway misbehaves, or a shipment mysteriously vanishes into the digital ether. When these glitches occur, you need to play detective and trace the breadcrumbs back to their source.

The Role of Logs

In this intricate dance of microservices, logs become our trusty companions. Each service diligently records its activities, creating a trail of events. But here’s the twist: In a distributed system, these logs converge into a single timeline—a grand mosaic of actions and reactions. It’s like assembling a jigsaw puzzle, where every piece matters.

The Quest for Unique Identifiers

When trouble strikes, we reach for our magnifying glass—the transaction ID or order ID. These unique identifiers are like cosmic coordinates, pinpointing the exact moment when things went awry. Armed with this information, we dive into the logs, hoping to unravel the mystery.
But what if the crucial identifier isn’t there? What if it’s missing from the log where the error occurred? Suddenly, we’re lost in a labyrinth, desperately seeking context. Perhaps the error log stares back at us, cryptic and unyielding. We know something’s amiss, but without that golden thread—the transaction ID—we’re left fumbling in the dark.

And so, we face the conundrum: How do we bridge the gap between logs and reality? How do we find the elusive context that ties it all together? It’s a challenge that haunts every distributed system engineer—the quest for clarity amidst chaos.

The Solution

The solution is to have a correlation ID. It’s like a golden thread woven through the fabric of your distributed system. Shared between all services involved in a request or transaction, this ID becomes our beacon. And here’s the magic: By embedding it in every log, we create a breadcrumb trail—a lifeline to the heart of the matter.

The Art of Sharing IDs

But how do we pass this mystical ID between services? Fear not; it’s simpler than deciphering ancient scrolls. Here’s the playbook:
Source Generation: The correlation ID starts at the source, which could be the frontend or a backend-for-frontend service. Think of it as a unique mark given to each transaction.

Header Travel: As the request travels, it carries an “x-correlation-id” header. This header is like a tiny parchment containing the secret—the essence of our journey.

Service Adoption: Every internal service receives this sacred header. They treat it like a valuable tool, recording it in their logs.

When an error occurs, we consult the logs. Armed with the correlation ID, we trace all related events through time and find out our culprit.

How to do this in Nestjs?

Async local storage

It is a powerful API that simplifies data storage and retrieval across asynchronous operations. Imagine it as a persistent context that spans multiple asynchronous calls, akin to a global variable tailored for a specific asynchronous execution context. With AsyncLocalStorage, you can seamlessly manage state and share data without the complexities of manual bookkeeping.

For example:

import { AsyncLocalStorage } from 'node:async_hooks';

// Create an instance of AsyncLocalStorage
const store = new AsyncLocalStorage();

// run an async operation with context
store.run({ isAdmin: true }, createUser(data));

In this scenario, createUser represents a sophisticated function that orchestrates multiple asynchronous tasks, such as checking for duplicate users in a database, creating the user, and triggering email verification. The beauty of AsyncLocalStorage lies in its ability to maintain the { isAdmin: true } context across these asynchronous steps. At any point during the user creation process, you can effortlessly retrieve the context value using store.getStore().

const { isAdmin } = store.getStore()

This approach ensures that critical information, like the correlationId, remains accessible throughout your Node.js application.

In Express or Nestjs application, you will find it suitable to add this context as a middleware

// with-context.middleware.ts
import { AsyncLocalStorage } from "node:async_hooks";
import { NextFunction, Request, Response } from "express";

interface ContextStore {
    correlationId: string;
}

export const globalStore = new AsyncLocalStorage<ContextStore>();

export const withCorrelationId = (
  request: Request,
  response: Response,
  next: NextFunction
) => {
    const context = globalStore.getContext();
    context.correlationId = request.headers['x-correlation-id'] ?? uuid.v4()
    response.setHeader('x-correlation-id', correlationId);
    globalStore.run({}, () => next());
};

Here we are adding a middleware withCorrelationId which will include the correlation id in a context and
run the next() middleware or route function within this context.

Now we need to add this middleware to our main application

// main.ts
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import { withCorrelationId } from './with-context.middleware';


async function bootstrap() {
    const app = await NestFactory.create(AppModule, {
        logger: ['error', 'warn', 'debug'],
        cors: true,
    });
    app.use(withCorrelationId);
    ... // other middlewares or initializers

    await app.listen(3000, () => {
        logger.info(`Listening on port: 3000`);
    });
}

To add this correlation id to any log, we can create a custom logger in winston with TRANSIENT scope.

// logging.service.ts
import { Injectable, Scope } from '@nestjs/common';
import { createLogger } from 'winston';
import { globalStore } from './with-context.middleware'


@Injectable({ scope: Scope.TRANSIENT })
export class LoggingService {
     private rootLogger = createLogger();

     private getLogger(){
         const { correlationId } = globalStore.getStore();
            const childLogger = rootLogger.child({
                correlationId,
            });
            return childLogger;
     }

    info(msg: string, meta?: unknown[]){
        this.getLogger().info(msg, ...meta)
    }

    ... // other log level implementations
}

And there we have our logger. Use it like a normal logger.

@Injectable()
export class YourService{
    constructor(private readonly logger: LoggingService){}

    someFunction(){
        try {
            someAsyncOp()
        } catch (error) {
            this.logger.error("some error", error);
        }
    }
}

This way we never needed to get the context in every service file. it gets auto logged.
You can also use the context to attach some additional ids or any kind of data to the logging in the middle of the process without passing the data directly to each next function.