Implementing logging with metadata | Pure DI in TypeScript Node.js
Tags: programming, node, typescript, tutorial
Published: 2023-01-26 04:37:24

In the [previous tutorial](https://dev.to/vad3x/step-by-step-guide-of-implementing-scoped-like-dependencies-using-asynclocalstorage-within-fastify-3cg9), 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](https://github.com/vad3x/typesafe-dependency-injection-in-typescript-samples/tree/main/samples/part2-request-id) 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.

```ts
// 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.

```ts
// 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

```ts
// 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.

```ts
// 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.

```ts
// 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:

```ts
// 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:

```ts
// 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.

```ts
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

```ts
// 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](https://github.com/vad3x/typesafe-dependency-injection-in-typescript-samples/blob/main/samples/part3-logger)

## 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](https://github.com/graphql/dataloader) using the tools we introduced.