[Proposal] Refactor Logger implementation for better extensibility

[mayorandrew]

Feature Request

Is your feature request related to a problem? Please describe.

In Nest you can create a custom logger by implementing the LoggerService interface from here https://github.com/nestjs/nest/blob/master/packages/common/services/logger.service.ts#L11 and passing instance of a custom logger to app.useLogger function (as described in the docs).

app.useLogger sets Logger.instance property to the provided logger instance: https://github.com/nestjs/nest/blob/master/packages/common/services/logger.service.ts#L120.

If you use the Nest logger in your class like so:

import { Logger, Injectable } from '@nestjs/common';

@Injectable()
class MyService {
  logger = new Logger(MyService.name);
 
  doSomething() {
    this.logger.log('doSomething');
  }
}

const app = await NestFactory.create(AppModule, { logger: new MyLogger() });

The line this.logger.log eventually calls method log on MyLogger and passes three arguments: message, context and isTimestampEnabled. First two are described in the LoggerService interface while isTimestampEnabled is not.

I expect LoggerService interface to be on par with the actual usage of the logger.

Also, the way Logger class itself is organized is quite strange and in my opinion has some extension limitations.
For example, having isTimestampEnabled property passed to each log message is strange for me.

Here is the link to Codesandbox with an example: https://codesandbox.io/s/nestjs-custom-logger-fwrjl?file=/src/main.ts.
Note that there are some problems with displaying logs in the console of codesandbox (sometimes I see them and other times don't).

Describe the solution you'd like

I think the only good way out of this issue is to refactor the way Logger is implemented which will probably be a breaking change.

Here is the solution I can propose:

We could have current Logger class as an abstract implementation-agnostic logger which simply passes context to each instance call. Actual logging methods which are currently implemented as static methods of the Logger will be extracted into separate class, e.g. DefaultLogger, instance of which is set as Logger.instance by default. The logger parameters such as isTimestampEnabled will then be supplied to the DefaultLogger instead of the Logger since they may not be valid for every logger implementation. This way we can even leave current LoggerService interface untouched.

Code examples for the proposed solution (shortened for brevity):

// maybe this should not implement the LoggerService
class Logger {
  // actual logger implementing the LoggerService
  private static instance: LoggerService = new DefaultLogger();

  // saving current way of customizing the logger
  static overrideLogger(instance) {
    this.instance = instance;
  }

  // Context of this instance of the abstract logger
  private context: string;

  // Save context
  setContext(context: string) {
    this.context = context;
  }

  // Example log method with args added for the sake of extensibility
  log(message: any, context?: string, ...args) {
    this.constructor.callFunction('log', message, context || this.context, ...args);
  }

  // Passes the call to the concrete implementation of the logger
  // Made this static to reuse in static methods
  private static callFunction(
    name: 'log' | 'warn' | 'debug' | 'verbose',
    message: any,
    context?: string,
    ...args
  ) {
    // I have omitted some checks here for the sake of brevity
    this.instance[name].call(this.instance, message, context, ...args);
  }

  // If we need static methods like Logger.log, we can just proxy them to the same callFunction
  static log(message: any, context?: string, ...args) {
    this.callFunction('log', message, context, ..args);
  }
}

// Actual default logger implementation
class DefaultLogger implements LoggerService {
  private isTimestampEnabled = true;
  constructor({ isTimestampEnabled }) { 
    this.isTimestampEnabled = isTimestampEnabled;
  }

  printMessage(
    message: any,
    color: (message: string) => string,
    context = '',
  ) {
    // Same as current Logger.printMessage but uses this.isTimestampEnabled instead of taking it from the args
  }

  // Same as current static Logger.log but without accepting isTimeDiffEnabled through the argument 
  // since it is saved as the instance field and can be directly used in printMessage
  log(message: any, context = '') {
    this.printMessage(message, clc.green, context);
  }
}

// If you want to customize the default logger, you can call
const app = await NestFactory.create(AppModule, { logger: new DefaultLogger({ isTimestampEnabled: false }) });

Teachability, Documentation, Adoption, Migration Strategy

Most of the public API won't change, but we will have to emphasize the correct way of using and customizing the logger in the docs. I have started doing this in this PR to the docs: nestjs/docs.nestjs.com#1441. But if we to refactor the Logger as I described, some more docs changes would be required such as explaining how to configure the default logger and explaining how default Logger is just an abstract wrapper.

For some custom loggers this will probably be a breaking change, but since I have only tried nestjs-pino, I cannot predict consequences on a larger scale, so additional input from community is required. But in the end it should make the Nest API clearer and more extensible.

What is the motivation / use case for changing the behavior?

I mostly explained my motivation in the PR to the docs: nestjs/docs.nestjs.com#1441. Basically I found a good library called nestjs-pino which provides custom logger using pino. But the way it was supposed to be used was feeling strange to me. I wanted nest to somehow abstract the logger implementation. And through the source code digging I have found that it actually kinda does, but is not described anywhere. So I want this feature to be more fleshed out.

[kamilmysliwiec]

First two are described in the LoggerService interface while isTimestampEnabled is not.
I expect LoggerService interface to be on par with the actual usage of the logger.

The last argument is nonessential for custom loggers.

Also, the way Logger class itself is organized is quite strange and in my opinion has some extension limitations.
For example, having isTimestampEnabled property passed to each log message is strange for me.

Whether to show timestamp or not depends on where we call the .log() (and other) method(s). It cannot be represented as a class-level property.

We could have current Logger class as an abstract implementation-agnostic logger which simply passes context to each instance call. Actual logging methods which are currently implemented as static methods of the Logger will be extracted into separate class, e.g. DefaultLogger, instance of which is set as Logger.instance by default.

What would be the benefit of splitting this class into 2 separate classes?

[mayorandrew]

The last argument is nonessential for custom loggers.

The problem here that it is still passed, so custom logger needs to be aware of it, otherwise it could lead to bugs.

I experienced that issue with nestjs-pino. It correctly implemented the LoggerService interface, but allowed additional args to be passed to the log method (https://github.com/iamolegga/nestjs-pino/blob/master/src/Logger.ts#L33) (having additional args is not fobidden when implementing an interface in TS). These additional args were passed to the underlying pino library. Because of isTimestampEnabled, first additional argument args[0] was always false and that messed up behavior of the pino. Yes, this is actually an issue with the library, but it could have been caught early on, if Nest better expressed details of Logger customization (had isTimestampEnabled in the LoggerService interface for example) .

As I understand TypeScript interface semantics, having inteface with method signature with two arguments means that user of such interface should not pass any more than two arguments to it. Here is my small test showing that:

Hence, the problem here, that while there exists an abstraction called LoggerService, class Logger itself expects instance to adhere to the typeof Logger interface which is expressed via using type cast as typeof Logger here:

nest/packages/common/services/logger.service.ts

Line 108 in 01dfe29

const func = instance && (instance as typeof Logger)[name];

There should at least be some type check before doing such type cast.

Whether to show timestamp or not depends on where we call the .log() (and other) method(s). It cannot be represented as a class-level property.

Thanks for pointing that out. Yes, my proposal of moving it DefaultLogger changes its behavior, so more thoughts about that are required.

As I see from the sources, isTimestampEnabled can only be set during new Logger instantiation in the service, like here:

nest/packages/core/nest-factory.ts

Line 29 in f0e7597

private readonly logger = new Logger('NestFactory', true);

Therefore it is bound to the lifetime of transitent Logger instance.

Other way to use isTimestampEnabled is to supply as the third argument to the static Logger methods, which imho should be discouraged because it actually uses a specific implementation of the logger, and not the abstract one. There is no way for me as app developer to cleanly use custom logger, if code uses static Logger.log calls.

Overall, existance of such property of the Logger class makes it a part of the abstract Logger interface of Nest. So it raises a question, why can't other properties, which change the Logger behavior on the message level, exist there. Maybe there should be a more abstract options parameter so that custom loggers may also provide their own options which are used only if you use a particular logger. But this kinda breaks the abstraction of the logger I want Nest to have, so I am not sure this is a good idea.

What would be the benefit of splitting this class into 2 separate classes?

Currently Logger class contains both abstract and concrete implementations of the Logger. Therefore it contradicts the single resposibility principle and increases class complexity. Also, in the current state, if you call static Logger.log methods, it actually calls the concrete implementation which cannot be altered by using app.useLogger which is really not obvious if you do not look into the sources.

So splitting current Logger into two classes will more cleanly describe the intent of how it should be used for the application and library developers, and, as a bonus, make Logger.log static calls abstract as well (which may be useful in some rare edge cases).

[kamilmysliwiec]

Let's track this here #6221