Logger Injection & Scoped Logging

So far, we used general logging strategy.

Added log at the function call time using @LoggedFunction, added parameter to log using@Logged, and added returned value to log using @Returns.

From now on, we're gonna use special logger provided by NestLogged.

Logger Injection

NestLogged automatically initialize instance of Logger exported from @nestjs/common in the class (service, controller, etc).

If you want to print a log in the function, you need access to the Logger instance that NestLogged initialized.

For this, NestLogged provides @InjectLogger decorator.

The position of parameter @InjectLogger used will be filled with ScopedLogger instance, the special Logger wrapper of NestLogged.

This ScopedLogger is used like normal Logger, but there is some additional features.

Some of this additional features are for the Scoped Logging, so we will explain it later.

@Injectable()
class UserService {
  @LoggedFunction
  @Returns({ result: "http.result", userId: "body.user.id" })
  async getUser(
    @Logged("userId")
    userId: string,
    @InjectLogger logger?: ScopedLogger
  ) {
    logger.log(userId);
    return {
      http: {
        result: "success",
        code: 200,
      },
      body: {
        user: {
          id: userId,
          name: "tester",
        },
        secret: "supersecret",
      },
    };
  }
}

/*
example: userService.getUser("user-asdf")
... [UserService] (ID ...) | getUser: CALL getUser WITH userId=asdf
... [UserService] (ID ...) | getUser: asdf
... [UserService] (ID ...) | getUser: RETURNED getUser WITH userId=asdf
*/

Since we added @InjectLogger there is some change in the log, and you can print log in the middle of function with the ScopedLogger from @InjectLogger.

The ScopedLogger instance we received is the same instance with ScopedLogger used for the function call log and return log.

InjectLogger Changelog

1. Add ID.

2. Add scope.

ID is the way to identify every single unique function call. If there is no ScopedLogger instance in the place of parameter the @InjectLogger used, it will create new ScopedLogger instance and add random ID.

Scoped Logging

In most program, the function call flows like a drill. and it is same with NestJS.

Most of the time in NestJS, one route is processed through call of controller and service's methods. When HTTP request comes in, NestJS run the method in controller, and called method in controller calls methods in various services.

How can we know the who and how of one line of log?

For answer of this problem, NestLogged provides call trace and a unique ID for a ScopedLogger at a root of function call.

import { Controller, Get, Injectable } from "@nestjs/common"
import { LoggedRoute, LoggedFunction } from "../logged"
import { ScopedLogger } from "../logger"
import { Returns, Logged, InjectLogger, LoggedParam, LoggedQuery } from "../reflected"

@Injectable()
class UserService {
  private readonly fakeUserDB = {
    users: [
      {
        id: 'user-tester1',
        name: 'tester1',
        secret: 'supersecret'
      },
      {
        id: 'user-tester2',
        name: 'tester2',
        secret: 'supersecret2'
      }
    ]
  }

  @LoggedFunction
  @Returns({ ok: 'ok', foundUserId: 'user.id', reason: 'reason' })
  async getUserInfo(
    @Logged("userId")
    userId: string,
    @InjectLogger logger: ScopedLogger
  ) {
    const userIndex = this.fakeUserDB.users.findIndex(({ id }) => id === userId);
    if (userIndex === -1) {
      logger.warn(`User ${userId} not found.`)
      return {
        ok: false,
        reason: 'user_not_found'
      }
    }
    logger.log(`User ${userId} found at ${userIndex}`)
    return {
      ok: true,
      user: this.fakeUserDB.users[userIndex]
    }
  }
}

@Controller('users')
class UserController {
  constructor(
    private userService: UserService
  ) { }

  @LoggedRoute()
  @Get()
  @Returns({ result: "http.code", userId: "body.id", failReason: 'http.reason' })
  async getUser(
    @LoggedQuery("id")("userId")
    userId: string,
    @InjectLogger logger?: ScopedLogger
  ) {
    const userInfo = await this.userService.getUserInfo(userId, logger)
    if (!userInfo.ok) {
      return {
        http: {
          code: 400,
          reason: userInfo.reason
        }
      }
    }
    return {
      http: {
        code: 200,
      },
      body: userInfo.user
    }
  }
}

/*
example: GET /users?id=user-tester1
... [UserController] (ID ...) | getUser: HIT HTTP UserController::/[GET] (getUser) WITH userId=user-tester1
... [UserService] (ID ...) | getUser -> getUserInfo: CALL getUserInfo WITH userId=user-tester1
... [UserService] (ID ...) | getUser -> getUserInfo: User user-tester1 found at 0
... [UserService] (ID ...) | getUser -> getUserInfo: RETURNED getUserInfo WITH ok=true, foundUserId=user-tester1
... [UserController] (ID ...) | getUser: RETURNED HTTP UserController::/[GET] (getUser) WITH result=200, userId=user-tester1
*/
/*
example: GET /users?id=user-asdf
... [UserController] (ID ...) | getUser: HIT HTTP UserController::/[GET] (getUser) WITH userId=user-asdf
... [UserService] (ID ...) | getUser -> getUserInfo: CALL getUserInfo WITH userId=user-asdf
... [UserService] (ID ...) | getUser -> getUserInfo: User user-asdf not found.
... [UserService] (ID ...) | getUser -> getUserInfo: RETURNED getUserInfo WITH ok=false, reason=user_not_found
... [UserController] (ID ...) | getUser: RETURNED HTTP UserController::/[GET] (getUser) WITH result=400, failReason=user_not_found
*/