NestJS 日志记录最佳实践

最编程 2024-04-12 10:54:05

...

本文主要内容有

@nestjs 日志类的结构、基本概念、等级和输出格式
官方日志类的面相对象（类）的方式使用
日志类面相切面的使用方式

日志的意义

日志对于程序来说是一种非常重要的调试于监控的工具。在开发时(Development time)，日志是观察程序动态情况的窗口。在运行时(Run time)，日志可以实时反应被监控程序的各种指标，甚至包括硬件状况；也可以用于事后分析故障原因。可以说，用好日志工具，是管理和维护被开发系统的必要手段的途径。

nodejs内置的console，不需要安装依赖，就可以在应用程序中输出调试信息。但不推荐用console作为输出工具。如果只是简单快速地调试某个观测点，并且在这个临时工作结束之后就删除掉调试代码，倒也无伤大雅。如果需要系统地处理日志或调试信息，console就显得有些不方便。例如：

希望保留输出的代码，但是又不希望看到调试信息；
开发模式下要能看到调试信息，但是在程序发布上线后就不要再输出某些内容；
统一输出的格式；
使输出的内容醒目；
能够带有一些性能相关和程序上下文相关的信息；

其是上面提到的几点，也是 nestjs 内置的 logger 的特点。

深入 @nestjs 日志类

日常中用的比较多的（也确实比较方便的）方式是用console 直接 log 打印到终端的调试信息。在@nestjs中，有专门的工具类：Logger位于@nestjs/common。根据官方的介绍，Logger 主要有以下特性：

整个关闭日志

输出特定日志等级（例如只显示错误、警告等）

重写(override)其时间戳（例如使用 ISO8601 标准）

可以完全重写默认日志工具

以扩展（extend）方式定制化

利用依赖注入，简化组合和测试过程

在深入之前，先让我们了解@nestjs定义日志类的基本概念：

基本概念

日志等级

在@nestjs的源码中能够找到关于日志的等级定义，有底到高依次如下

// packages/common/services/utils/is-log-level-enabled.utils.ts
 const LOG_LEVEL_VALUES: Record<LogLevel, number> = {
  verbose: 0,
  debug: 1,
  log: 2,
  warn: 3,
  error: 4,
};

不难看出，作者根据信息的重要程度给日志类型加以区分，让用户可以根据程序所运行的环境不同，而输出信息价值不同的日志。例如在运行时，可能就不关注警告级别以下的内容，在测试时，则关注日志(log)级以上的的内容，而开发和调试阶段，也有不同的关注焦点。

日志格式

当我们用日志工具输出信息时，默认格式如下：

[AppName] [PID] [Timestamp] [LogLevel] [Context] Message [+ms]

AppName 应用程序名，被固定为[Nest]
PID：系统分配的进程编号
Timestamp：当前日志输出的系统时间，默认月/日/年, 时:分:秒[AP]M
LogLevel：日志等级文本
Context：上下文
Message：输出的消息，可以是对象类型(JSON.stringify)输出
+ms：两次输出信息的时间间隔，时间戳（后文提及的时间戳均指此）

类的结构

@nestjs 的日志类位于common 包中，关键要素的结构如下：

                  Interface
               ┌───────────────┐
       ┌──────►│ LoggerService │
       │       └──────▲────────┘
       │              │
       │              │ Implementation
       │       ┌──────┴────────┐
       │       │ ConsoleLogger │
       │       └──────▲────────┘
       │              │
       │              │ Dependance
       │       ┌──────┴────────┐
       └───────┤     Logger    │
 Implementation└───────────────┘

LoggerService 是接口标准，如果要替换掉内置的日志类，最低要求是得符合这个接口。
ConsoleLogger 日志主要业务类，主要负责处理格式化日志字符串输出。
Logger 更高层高层封装，加入了输出缓存，并统一管理日志等级。自身有一个ConsoleLogger的默认单例。

一般直接使用Logger 就可以，虽然可以直接用ConsoleLogger 但是这会造成日志等级难以统一的问题（某些情景下这不是问题而是特性）。

两种用法

从应用程序开发的思考逻辑上，可以将程序理解为：面向对象（类和对象）或者面向切面（或服务）。所以，围绕这两种不同的思考逻辑，日志也要有针对性的调整。主要不同表现在控制上下文字符和时间戳上。

手动实例化——面向对象

// src/app.controller.ts

import { Controller, Get, Logger } from '@nestjs/common';
import { AppService } from './app.service';

@Controller()
export class AppController {
  logger: Logger = new Logger(AppController.name,{timestamp:true});
  constructor(private readonly appService: AppService) {}

  @Get()
  getHello(): string {
    this.logger.log('hello world');
    return this.appService.getHello();
  }
}

此时，已经可以获得比较完善的日志输出信息：

[Nest] 32648  - 06/28/2023, 2:08:48 PM     LOG [NestFactory] Starting Nest application...
[Nest] 32648  - 06/28/2023, 2:08:48 PM     LOG [InstanceLoader] AppModule dependencies initialized +12ms
[Nest] 32648  - 06/28/2023, 2:08:48 PM     LOG [RoutesResolver] AppController {/}: +20ms
[Nest] 32648  - 06/28/2023, 2:08:48 PM     LOG [RouterExplorer] Mapped {/, GET} route +2ms
[Nest] 32648  - 06/28/2023, 2:08:48 PM     LOG [NestApplication] Nest application successfully started +2ms
[Nest] 32648  - 06/28/2023, 2:08:49 PM     LOG [AppController] hello world
[Nest] 32648  - 06/28/2023, 2:08:49 PM     LOG [AppService] getHello called

实例化过程比较简单，只需要2个参数，且均是可选参数。时间戳作为构造函数的第二个对象的属性（唯一）：

{string} 类型的上下文（在一个实例只有一种上下文）；
{boolean} 时间戳，显示两次日志的间隔；

上下文常用于表示调用者的识别文本。当然也可以根据不同的业务类型，以程序切面的方式来定义多个实例但相同的实例名称。

时间戳用来表示程序的执行时间，但是要注意，这个间隔的毫秒数是指两条日志的输出间隔，不论这两条信息是否属于同一个实例的操作，即便是其中之一并没有要求输出时间戳。也就说，每次输出日志都会更新到静态变量中保存。

另外，@nestjs有三处可以设置日志等级，分别是：

启动之初的Nest工厂方法创建应用根对象时加入日志等级参数；
设置Logger 的logLevels属性
上文提及的，直接使用ConsoleLogger 类来直接控制输出类，此时作为构造函数的第二个对象参数中的字段：{logLevels:LogLevel[]}；

日志等级虽然是一个数组，但是输入一个元素和一个以上元素其含义不同。如果参数是一个元素的数组，那么输出的权重大于等于这个元素。例如输入["log"]，那么除了verbose，其他都输出。如果输入两个及以上的日志等级，那么仅输出被指定等级的日志。例如输入["log","error"]，那么除此以外的其他类型都不会显示。

依赖注入——面向切面(AOP)

用上面的方式，如果要根据某个服务或者切面来统一日志的上下文，就会显得比较麻烦。在这里使用@nestjs托管的依赖注入就比较方便了。首先利用@Inject装饰器定义切面，然后在所在的模块中定义Provider，需要注意依赖关系，在最先要注入的地方定义Provider。

// src/app.controller.ts
import { AppService } from './app.service';

@Controller()
export class AppController {
  constructor(
    private readonly appService: AppService,
    @Inject('UsersLogger')
    private readonly logger: Logger,
  ) {}
  @Get()
  getHello(): string {
    this.logger.log('@Controller');
    return this.appService.getHello();
  }
}

// src/app.service.ts
@Injectable()
export class AppService {
  constructor(@Inject('UsersLogger') private readonly logger: Logger) {}
  getHello(): string {
    this.logger.log('@Service');
    return 'Hello World!';
  }
}

// src/app.module.ts
@Module({
  imports: [],
  controllers: [AppController],
  providers: [
    AppService,
    {
      provide: 'UsersLogger',
      useFactory: () => {
        return new Logger('Users');
      },
    },
  ],
})
export class AppModule {}

此时输出

[Nest] 45552  - 06/29/2023, 8:45:34 AM     LOG [NestFactory] Starting Nest application...
[Nest] 45552  - 06/29/2023, 8:45:34 AM     LOG [InstanceLoader] AppModule dependencies initialized +13ms
[Nest] 45552  - 06/29/2023, 8:45:34 AM     LOG [RoutesResolver] AppController {/}: +26ms
[Nest] 45552  - 06/29/2023, 8:45:34 AM     LOG [RouterExplorer] Mapped {/, GET} route +3ms
[Nest] 45552  - 06/29/2023, 8:45:34 AM     LOG [NestApplication] Nest application successfully started +2ms
[Nest] 45552  - 06/29/2023, 8:45:37 AM     LOG [Users] @Controller
[Nest] 45552  - 06/29/2023, 8:45:37 AM     LOG [Users] @Service

后期调整上下文

若用Logger，并且在构造时没有设置上下文，那么在每次输出日志时，第二个参数会作为上下文的文本。如果在构造时设置了上下文，后期无法调整。若用ConsoleLogger，可以随时用setContext方法调整。

日志缓存

Logger实现的缓存逻辑，通过调用attachBuffer()来开启缓存，并用flush()方法来输出被缓存的内容，同时关闭缓存。例如：

@Controller()
export class AppController {
  constructor(
    private readonly appService: AppService,
    @Inject('UsersLogger')
    private readonly logger: Logger,
  ) {
  }

  @Get()
  getHello(): string {
    Logger.attachBuffer();
    this.logger.log('@Controller');
    this.logger.error('...');
    return this.appService.getHello();
  }
  @Get('buffer')
  buffer(): string {
    Logger.attachBuffer();
    return 'ok';
  }

  @Get('log')
  log(): string {
    Logger.flush();
    return 'OK';
  }
}

因为采用静态方法控制了日志输出，所以进程中的所有日志都会被控制。所以在调用了buffer的API之后并在调用log之前，终端不会输出日志。

更换全局日志

默认@nestjs用的是ConsoleLogger类作为日志输出。开发者可以替换掉自己想要的日志类，有两种方式：

在应用程序工厂构造阶段用别的类替换掉：

// src/main.ts
async function bootstrap() {
  const app = await NestFactory.create(AppModule, {
    logger: console,
  });
  await app.listen(3000);
}
bootstrap();

调用静态的 Logger.overrideLogger

  Logger.overrideLogger(console);

此时需要留意，根据Logger的逻辑，替换了默认的日志类，那么应用程序将会采用单例(日志输出类)方式运行。

总结

@nestjs/common 的日志基本能够满足日志需求，可以配合如pm2，或者Docker的日志功能，将输出日志进一步扩展使用。通过配置日志输出级别来精准灵活地处理不同运行环境中的日志信息输出。合理地定义上下文，可以方便且快速地找到关注的信息。

尽量使用Logger，除非特殊需求，不要用ConsoleLogger，因为控制更复杂。

展望

经过上面的研究，还是可以找出Logger一些美中不足，例如控制日志写文件（如果采用一些进程管理工具或容器工具，这一点并不重要），再例如如何现实更醒目的文本信息……

上一篇： Dagre 算法简介及其在自动流程图布局中的应用

下一篇：如何绘制标准化 UML 用例图

NestJS 日志记录最佳实践

本文主要内容有

日志的意义

深入 @nestjs 日志类

基本概念

日志等级

日志格式

类的结构

两种用法

手动实例化——面向对象

依赖注入——面向切面(AOP)

后期调整上下文

日志缓存

更换全局日志

总结

展望

NestJS 学习优秀项目分析和最佳实践

NestJS 日志记录最佳实践

简单易懂的日志系统详解 - Logback的最佳实践指南