Implementing logging with metadata | Pure DI in TypeScript Node.js

In the previous tutorial, I've shown how to implement a RequestId feature using AsyncLocalStorage.
Here, we will extend the functionality of our app by adding Logger with metadata.

I will use the repo as starting point.

Logger

Why not use console.* instead? The utilization of a custom logging mechanism, such as the implementation of a Logger interface, offers lots of advantages over relying solely on the use of console. These benefits include:

The ability to selectively log only certain levels of information (such as warnings and above)
The inclusion of additional metadata within the log output
The implementation of a logger name
The potential for future flexibility in terms of easily replacing the logging mechanism without necessitating extensive modifications to the underlying codebase.

Let's switch things up and start using a new logging tool instead of just sticking with console.log. This change will give us more control and options for handling our logs.

// logger.ts
export interface Logger {
  info(message: string, data?: any): void;
  error(message: string, data?: any): void;
}

export type CreateLogger = (name: string) => Logger;

This is the essential part I will use later.

Business logic

Let's replace console.log with our logger.

// stub-order-service.ts
class StubOrderService {
  constructor(
    private readonly getRequestId: GetRequestId,
    private readonly logger: Logger
  ) {}

  findOrderById: FindOrderById = (orderId) => {
    const requestId = this.getRequestId();

    this.logger.info(
      `calling findOrderById with orderId: ${orderId}, requestId: ${requestId}`
    );

    return Promise.resolve({
      id: orderId,
    });
  };
}

// registry/stub-order-service.ts
function stubOrderService() {
  return ({
    getRequestId,
    createLogger,
  }: {
    getRequestId: GetRequestId;
    createLogger: CreateLogger;
  }) => {
    const { findOrderById } = new StubOrderService(
      getRequestId,
      createLogger(StubOrderService.name)
    );

    return {
      findOrderById,
    };
  };
}

Here we made our stubOrderService require createLogger function.

Now we need to register createLogger implementation.

Console Logger

// console-logger.ts
class ConsoleLogger implements Logger {
  constructor(private readonly name: string) {}

  info(message: string, data: any): void {
    console.info(message, { ...data, logger: this.name });
  }

  error(message: string, data: any): void {
    console.error(message, { ...data, logger: this.name });
  }
}

// registry/console-logger.ts
export function consoleLogger() {
  return (): { createLogger: CreateLogger } => {
    return {
      createLogger: (name) => new ConsoleLogger(name),
    };
  };
}

And don't forget to register consoleLogger in our registry.

// create-app-registry.ts
export function createAppRegistry() {
  return (
    new RegistryComposer()
      .add(consoleLogger())
      // ...
      .compose()
  );
}

When we run our application now, we get a similar output as before:

Request:

GET /orders/123/receipt HTTP/1.1
Host: localhost:3000

Output:

INFO: calling findOrderById with orderId: 123, requestId: <random-guid> { logger: 'StubOrderService' }

RequestId Logger Metadata

The logger parent class is really helpful when trying to debug code. To make it even better, we could add some extra information automatically when we log something. For example, we could include the RequestId we implemented in the previous article every time we log a request.

// logger-metadata.ts
type LoggerMetadata = Record<string, any>;

type GetLoggerMetadata<T extends LoggerMetadata = LoggerMetadata> = () => T;

// console-logger.ts
class ConsoleLogger implements Logger {
  constructor(
    private readonly name: string,
    private readonly getLoggerMetadata: GetLoggerMetadata
  ) {}

  info(message: string, data: any): void {
    console.info(message, this.stitchData(data));
  }

  error(message: string, data: any): void {
    console.error(message, this.stitchData(data));
  }

  private stitchData(data: any): any {
    return {
      ...this.getLoggerMetadata(),
      ...data,
      logger: this.name,
    };
  }
}

// registry/console-logger.ts
export function consoleLogger() {
  return ({
    getLoggerMetadata,
  }: {
    getLoggerMetadata: GetLoggerMetadata;
  }): { createLogger: CreateLogger } => {
    return {
      createLogger: (name) => new ConsoleLogger(name, getLoggerMetadata),
    };
  };
}

// request-id-logger-metadata.ts
class RequestIdLoggerMetadataProvider {
  constructor(private readonly getRequestId: GetRequestId) {}

  getLoggerMetadata: GetLoggerMetadata = () => {
    return {
      requestId: this.getRequestId(),
    };
  };
}

// registry/request-id-logger-metadata.ts
interface RequestIdLoggerMetadata {
  requestId?: string;
}

class RequestIdLoggerMetadataProvider {
  constructor(private readonly getRequestId: GetRequestId) {}

  getLoggerMetadata: GetLoggerMetadata<RequestIdLoggerMetadata> = () => {
    return {
      requestId: this.getRequestId(),
    };
  };
}

// create-app-registry.ts
export function createAppRegistry() {
  return (
    new RegistryComposer()
      .add(requestIdStore())
      .add(requestIdLoggerMetadata())
      .add(consoleLogger())
      // ...
      .compose()
  );
}

Now when we have RequestId logged as part of metadata, we can remove it from the business logic:

// stub-order-service.ts
class StubOrderService {
  constructor(private readonly logger: Logger) {}

  findOrderById: FindOrderById = (orderId) => {
    this.logger.info(`calling findOrderById with orderId: ${orderId}`);

    return Promise.resolve({
      id: orderId,
    });
  };
}

// registry/stub-order-service.ts
function stubOrderService() {
  return ({ createLogger }: { createLogger: CreateLogger }) => {
    const { findOrderById } = new StubOrderService(
      createLogger(StubOrderService.name)
    );

    return {
      findOrderById,
    };
  };
}

Let's run our code, and check the output:

INFO: calling findOrderById with orderId: 123 { requestId: <random-id>, logger: 'StubOrderService' }

Chaining Logger Metadata

Works perfectly, but what if we have multiple GetLoggerMetadata? We can change the signature to chain the getLoggerMetadata. Let's add another metadata provider that will just add the environment name to our logs:

// registry/environment-logger-metadata.ts
export function environmentLoggerMetadata(name: string) {
  return ({ getLoggerMetadata }: { getLoggerMetadata?: GetLoggerMetadata }) => {
    return {
      getLoggerMetadata: () => ({
        ...getLoggerMetadata?.(),
        environment: name,
      }),
    };
  };
}

The interesting part here is environmentLoggerMetadata depends on optional getLoggerMetadata and registers getLoggerMetadata. If getLoggerMetadata exists, it will be extended with environment field, otherwise, just environment field will be added.

We should also update requestIdLoggerMetadata to make getLoggerMetadata chainable.

export function requestIdLoggerMetadata<TParent extends LoggerMetadata>() {
  return ({
    getRequestId,
    getLoggerMetadata,
  }: {
    getRequestId: GetRequestId;
    getLoggerMetadata?: GetLoggerMetadata<TParent>;
  }) => {
    const provider = new RequestIdLoggerMetadataProvider(getRequestId);

    return {
      getLoggerMetadata: () =>
        ({
          ...getLoggerMetadata?.(),
          ...provider.getLoggerMetadata(),
        } as Norm<TParent & RequestIdLoggerMetadata>),
    };
  };
}

We can also improve the code by using pipe pattern here. Feel free to left a comment with sample code (the code should be typesafe) :)

Let's update our registry code

// create-app-registry.ts
export function createAppRegistry() {
  return (
    new RegistryComposer()
      .add(environmentLoggerMetadata("local"))
      .add(requestIdStore())
      .add(requestIdLoggerMetadata())
      .add(consoleLogger())
      // ...
      .compose()
  );
}

Output:

INFO: calling findOrderById with orderId: 123, requestId: 79b6a17e-65dd-41ea-bc6e-e82a4b4143a5 {
  environment: 'local',
  requestId: '79b6a17e-65dd-41ea-bc6e-e82a4b4143a5',
  logger: 'StubOrderService'
}

The chaining is a very powerful tool here, which we can use to add, replace, or extend our Registry Services easily.

Full example source code can be found here

Conclusion

In this tutorial, we learned how to implement Logger with LoggerMetadata in fastify application.

In the next article, I'm going to implement a GraphQL server with dataloader using the tools we introduced.

Blog