Enhance Logger Using Inversify Context, Decorators, and Reflect-metadata
Tags: inversify, decorator, logger, reflectmetada
Published: 2022-02-19 11:15:08

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](https://www.npmjs.com/package/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](https://dev.to/maithanhdanh/applying-domain-driven-design-in-developing-software-4ld0), 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. 
![controller-layer](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/w2ci2dm9ubnghv8ux6iw.png)
![application-layer](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/377xd78674o1rcykjuo6.png)
![log-result](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/gve2jkzklkwhnuo22tup.png) 

##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](https://www.typescriptlang.org/docs/handbook/decorators.html), we must to endable **experimentalDecorators** compiler option to use Decorator.
![enable-option](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/tkskyv560fr9lze1cx77.png)

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.
![class-decorator](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/pzm1i3yc5f6pc6l6dif2.png)
![log-result](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/s9p4u1r1dw6uj26n28x9.png)

##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](https://shusson.info/post/generic-logging-on-a-class-using-decorators-in-typescript). 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](https://github.com/rbuckton/reflect-metadata).

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.

![custom-logger](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/giscwykdz1929ds9hfwo.png)
![modified-logGroup](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/ufaovmmkmyswaq6txu5t.png)
![modified-container](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/5ycc2k9rw94m7a34fip2.png) 

###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](https://www.npmjs.com/package/typescript-maker) 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](https://paypal.me/DantisMai).

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