Arthur CARLI's journal

Implementing a simple Typescript decorator to easily log input, outputs and time elapsed of methods

Implementing a simple Typescript decorator to easily log input, outputs and time elapsed of methods

Arthur CARLI's photo
Arthur CARLI
·

4 min read

Why this article?

In some specific parts of our application, it can be useful to log the start and the end of methods with some useful information as the inputs, output, the time elapsed, etc... Thanks to typescript decorators, it can be done with a one liner

class SomeClass {
  @LogStartEnd(logger) // This will add logging before and after the method execution
  public aMethodWithArgs(arg1: boolean, arg2: string) : string {
    logger.info('Executing my function')
    // ...
    //  some processing taking time
    // ...
    return 'this is a result'
  }
}

Which would result into the following log during execution with inputs false, string

[Test][exec][Start] with args {"0":false,"1":"string"}
Executing my fonction
[Test][exec][End] with result "this is result"
[Test][exec][End] processing time: 0.2s

In this article, I will talk about what is a decorator and how to implement such decorator.

Definition

A Decorator in typescript is a special kind of declaration that can be attached to a class declaration, method, accessor, property, or parameter. Decorators use the form @expression, where expression must evaluate to a function that will be called at runtime with information about the decorated declaration. ref

It allows to annotate your code with function that will be called at runtime before the execution of the code being annotated.

Implementation

As we plan to annotate a method, we will use a method decorator. To be able to have a parametrized decorator, we will use a factory decorator . For our LogStartEnd decorator, this will lead to an implementation looking like this :

function LogStartEnd(logger: Logger, options?: {...}) {
  return (
    target: any,
    propertyKey: string,
    propertyDescriptor: PropertyDescriptor
  ) => {
  // do something
  }
}

As this is a decorator applied on a method, we take advantage of two of the three provided parameters:

  • propertyKey: which will contain the name of the function being decorated
  • propertyDescriptor: which will contain the javascript property decorator object, whose value property contains the implementation of the function

We can continue the implementation to override the original function with a new one that will append logs before and after the execution of the function.

export function LogStartEnd(logger: Logger, options?: {...}) {
  return (
    target: any,
    propertyKey: string,
    propertyDescriptor: PropertyDescriptor
  ) => {
    ...
    const originalFunction = propertyDescriptor.value // saving the original function of the method
    propertyDescriptor.value = function () { // creating a new function for the method ...
     ... 
     logStart({...}) // ...that logs something...
      const result = originalFunction.apply(this, arguments) // ... before calling the original function...
      if (result.then !== undefined) { // managing async and non async functions
        return result.then((r: any) => logEndWithParamsAndReturn({result, ...})) // ...and logging something after its execution while 
      } else {
        return logEndWithParamsAndReturn({result, ...}) // ...and logging something after its execution
      }
    }
    return propertyDescriptor
  }

Usage

The decorator should have parameters that will allow us to customize the way the decorator logs information. We want 2 parameters:

  • The first parameter is the logger object that will be used to log the info. It is an object that possess some methods like debug, info, etc. to log info.
  • The other parameter is an options object that allow to change the way message are logged:
    • withArgs: Log the input arguments of the function (default: true)
    • withResult: Log the result of the function (default: true)
    • withPrefix: Should prefix the log message with the name of the function (default: true)
    • withTime: Log the time taken by the function execution (default: true)
    • level: the level used for logging the message (default: info)

From this spec, we can declare the following parameters for the decorator: 

export type LogLevel = 'debug' | 'perf' | 'info' | 'warn' | 'error' | string
export type Logger = { [K in LogLevel]: (msg: string) => void }

export function LogStartEnd(logger: Logger, options?: {
  withArgs?: boolean,
  withResult?: boolean,
  withPrefix?: boolean,
  withTime?: boolean,
  level?: LogLevel
}) {
...

Conclusion

To keep the length of this article bearable, I will not go in the implementation details of this decorator here, but you can have a look the full implementation of the decorator here on my repo : https://gitlab.com/ArthurCrl/ts-berlingos/-/blob/master/src/logDecorator.ts

I hope you enjoyed this article if please like this article or follow me on twitter here: @RthrCrl

TypeScriptcoding