Enhance Logger Using Inversify Context, Decorators, and Reflect-metadata

Generally, Log is a footprint of a system, it tells us about the state of the service at a moment. With it, in case there is an issue on the server, we can trace the root cause.

Nowadays, the logger is an important feature for any service, either small or big. However, we shouldn't write too much or too few records, that will lead to overwhelming or not enough information. Besides, those records need to follow the same format within a codebase.

In this post, we will discuss how to enhance them by using inversify context and Decorators. The logger package used is winston, and the below code I used to create log group

export const logger = LoggerWrapper();

export const createChildLogger = (messagePrefix: string): Logger =>
  Object.create(logger, {
    write: {
      value(info) {
        info.message = `[${messagePrefix}] ${info.message}`;
        logger.write(info);
      },
    },
  });

Inversify and Its Context

A powerful and lightweight inversion of control (IoC) container
for JavaScript & Node.js apps powered by TypeScript

We already talk about how to break the dependencies by IoC in this post, the Inversify are made in order to help us follow IoC rule.

We can create a Logger component bind to our container, and use toDynamicValue API to create a logger instance for each other components. The input argument for the API is context, it represents the called component and all its dependencies.

const getClassNameFromRequest = (context: interfaces.Context) =>
  (context.currentRequest.parentRequest &&
    context.currentRequest.parentRequest.bindings.length &&
    context.currentRequest.parentRequest.bindings[0].implementationType &&
    (context.currentRequest.parentRequest.bindings[0].implementationType as any)
      .name) ||
  'Undefined';

container
    .bind<Logger>(types.Logger)
    .toDynamicValue((context: interfaces.Context) => {
      const namedMetadata = getClassNameFromRequest(context);
      return createChildLogger(namedMetadata);
    });

When we are here, let say we have a below service to get service info. Then whenever we call the request, a logger instance will be created for ServiceInfoServiceImpl, and the className will be added to the logger message.

Decorators

Decorators are a stage 2 proposal for JavaScript and are >available as an experimental feature of TypeScript.

Decorator is farmiliar concept for Java, C++, and so on. But it is just a experiment feature of Typescript. According to TS documentation, we must to endable experimentalDecorators compiler option to use Decorator.

The goal of using decorator is the same with Inversify, which is creating and customizing logger property for each class. Because the logger is a property of a class so we need to use class decorator.

export function classDecorator<T extends { new (...args: any[]): {} }>(constructor: T) {
  return class extends constructor {
    logger = createChildLogger(constructor.name);
  };
}

The class decorator will overide the class constructor, so we need to define a logger property, and be careful with other constructor params.

Dive Deeper

what if we also need called method?

It will look like [className] [methodName] message ...

I already tried method and property decorators, but it didn't work well. The reason for this is that the decorators just run at the runtime, while the logger instance is still not created yet.

After a lot of googling, I found this post. That is a wonderful idea, I take that then modify logger property, so I have what I need.

However, because the solution change the original definition of the called method, I wonder about that, although I haven't faced any issue while using it.

Ok, so how does it work??! The first thing we do is define const originalMethod = descriptor.value;, the originalMethod now belongs to the closure of our brand new descriptor.value. Yes, it will work as its definition

export const createChildLogger = (messagePrefix: string,subPrefix?: string): Logger =>
  Object.create(logger, {
    write: {
      value(info) {
        info.message = `[${messagePrefix}]${subPrefix ? ` [${subPrefix}]` : ''} ${info.message}`;
        logger.write(info);
      },
    },
  });

export function logGroup() {
  return (target: any) => {
    for (const propertyName of Object.getOwnPropertyNames(target.prototype)) {
      const descriptor = Object.getOwnPropertyDescriptor(
        target.prototype,
        propertyName,
      );
      if (!descriptor) {
        continue;
      }

      const originalMethod = descriptor.value;
      const isMethod = originalMethod instanceof Function;
      if (!isMethod) {
        continue;
      }

      descriptor.value = function (...args: any[]) {
        (this as any).logger = createChildLogger(target.name, propertyName);
        return originalMethod.apply(this, args);
      };

      Object.defineProperty(target.prototype, propertyName, descriptor);
    }
  };
}

Note: this class decorator doesn't work on the controller layer of Inversify

So, What if we need a prefix for a function outside of a class?

The solution below just work on service that process one request at a time
Because the decorators just can work with class, whenever a method from a class calls a util function, the function will lose the context.

When we install inversify, we always need a package called reflect-metadata. Generally, it is like a global variable, but it just is applied to a specific target scope. you can take a look at this repository.

The general idea is that we will store the caller className, methodName to the metadata of the logger property, then whenever we call an outside function, we structure the logger message using the context from metadata.

First of all, we need a customLogger as below and use it as the default logger. Then, we modify a few lines in our class decorator logGroup, and container config. When an outside function calls logger.debug or something, the new logger will check for the context then structure the message.

Inversify context

As mentioned above, the Inversify Context show us the connection between the called component with its dependencies. we can use the code below to get it.

export const getContextName = (node : interfaces.Request | null):string => 
  (node?.bindings[0].implementationType as any).name

export const getContextTree = (context:interfaces.Context): string[] => {
  let node = context.currentRequest.parentRequest
  const listNode = [];

  while(node){
    listNode.unshift(getContextName(node));
    node = node.parentRequest;
  }

  return [... new Set(listNode)];
}

Then call it in api onACtivation or in creating logger instance when initilize container

  container
    .bind<Logger>(types.Logger)
    .toDynamicValue((context: interfaces.Context) => {
      const namedMetadata = getClassNameFromRequest(context);
      const listNode = getContextTree(context);
      console.log(listNode);
      return createChildLogger(namedMetadata);
    });

Or

  container
    .bind<ServiceInfoService>(types.Service.SERVICE_INFO)
    .to(ServiceInfoServiceImpl)
    .onActivation((context: interfaces.Context, service: ServiceInfoService) => {
      const listNode = getContextTree(context);
      console.log(listNode)
      return service
    });

To be honest, I still don't have any idea for that listTree, just collect them then be proud of myself 🤣.

Play Around

We can use this npm package to init inversify project with build in the logger above, just install it then run the command below

typescript-maker init -ioc test-repo

Paypal.

I am really happy to receive your feedback on this article. Hope you have fun with it. Thanks for your precious time reading this.