NodeJs服务链路追踪日志

news2024/11/27 16:52:57

（逆境给人宝贵的磨炼机会。仅有经得起环境考验的人，才能算是真正的强者。自古以来的伟人，大多是抱着不屈不挠的精神，从逆境中挣扎奋斗过来的。——松下幸之助）

在这里插入图片描述

服务链路追踪

服务的链路追踪指我们可以通过一个标记，快速排查整个业务从开始到结束的过程。快速定位整个业务环节的信息，异常等。
常见的业务场景是前后端通信，后端服务间通信。
链路id业界通常称为TraceId

前后端通信

场景一

前端每次对后端请求前都先生成"request-id"，统一前后端的链路追踪id，前端可以用此id来做自己业务的链路追踪，后端也可以直接在请求头headers中取出使用。
优点

前后端链路追踪id统一，方便排查业务问题
不用后端生成链路id，减少业务性能损耗

缺点

链路id由前端产生，存在安全问题
前后端业务耦合度过高

场景二

前端不维护前端日志或没有日志的情况下，链路id通常由后端自己管理，在接收请求之前，利用多线程特性，将链路id存入线程上下文并在后续业务中获取。
优点

链路id由后端管理，与前端解耦

缺点

无法和前端统一链路id，增加前后端统一排查问题的难度

服务间通信

后端多服务通信或第三方通信时，为了快速定位问题，往往需要统一多服务间日志的链路id，假如A->B->C，A服务将生成的traceId放在请求头中交给B服务，B服务再获取请求头中的id进行业务处理，C服务也进行相同的处理，那么三个服务的日志id相同，就能够在日志排查中大大降低排查难度

NodeJs服务链路追踪的难点

对于java等多线程服务来说，每个线程有自己的上下文可以用来做链路追踪，但nodejs主线程是单线程，无法针对每个请求做多线程处理。
在过去，node服务的链路追踪通常会做类似koa框架的ctx上下文变量，通过每一层的传递来维护上下文，达到链路追踪的目的。但这样的做法有一些冗余，使代码不得不变得臃肿，难以维护。
所以在nodejs后续版本中提供了async_hooks异步函数钩子，可以在一个请求链路中保存上下文，让链路追踪成为可能

最佳实践

使用nestjs服务，通过三种不同的方式来演示链路追踪

async_hooks
NodeJs官方
cls-rtracer
cls-rtracer最佳实践
链路追踪性能
nestjs-cls
nestjs官方

async_hooks

async_hooks日志打印，使用懒加载的形式，提供静态方法打印

import { AsyncLocalStorage } from "async_hooks";
import * as dayjs from "dayjs";
let asyncLocalStorage: AsyncLocalStorage<unknown>;

export class LogAsyncLocalStorage {

  static init (next) {
    this.getInstance().run(Math.random(), () => next());
  }

  static getInstance () {
    if (!asyncLocalStorage) {
      asyncLocalStorage = new AsyncLocalStorage();
    }
    return asyncLocalStorage;
  }

  static info (message: string) {
    const nowTime = dayjs().format('YYYY-MM-DD HH:mm:ss');
    const requlestId = asyncLocalStorage.getStore();
    console.log(`requestId：${requlestId} time：${nowTime} info：${message}`);
  }

}

cls-rtracer

相比较原生的async_hooks，该组件更符合中间件加载模式，代码侵入性更小
提供了两种组件，TraceIdMiddleware使用了自动生成的uuid作为traceId，TraceIdRandomMiddleware使用自定义的随机数作为traceId。
这里为了演示使用了随机数，实际业务中通常是uuid等唯一的字符串或数字

import * as rTracer from 'cls-rtracer';
export const TraceIdMiddleware = rTracer.expressMiddleware({
  useHeader: true,
  headerName: 'traceId',
});
export const TraceIdRandomMiddleware = rTracer.expressMiddleware({
  requestIdFactory: () => Math.random(),
});

nestjs-cls

针对nestjs做了优化，在模块化的基础上，做了ts检查和其他定制化的api。其中userId是使用了自定义的traceId。在包引入时进行初始化，在下面会提到。

import { Injectable } from "@nestjs/common/decorators";
import * as dayjs from "dayjs";
import { ClsService } from "nestjs-cls/dist/src/lib/cls.service";

@Injectable()
export class LogNestCls {

  constructor(
    private readonly clsService: ClsService
  ) { }

  info (message: string) {
    const nowTime = dayjs().format('YYYY-MM-DD HH:mm:ss');
    const requlestId = this.clsService.get('userId');
    console.log(`requestId：${requlestId} time：${nowTime} info：${message}`);
  }

}

控制层

import { Controller, Get } from '@nestjs/common';
import { AppService } from './app.service';
import { LogAsyncLocalStorage } from './log.asyncLocalStorage';
import { LogNestCls } from './log.nest.cls';
import { LogRtracer } from './log.rTracer';

@Controller()
export class AppController {
  constructor(
    private readonly appService: AppService,
    private readonly LogNestCls: LogNestCls
  ) { }

  @Get('asyncLocalStorage')
  getHeeloAsyncLocalStorage () {
    LogAsyncLocalStorage.info('收到前端请求，即将进入service');
    return this.appService.getHeeloAsyncLocalStorage();
  }

  @Get('rTracer')
  getRTracer () {
    LogRtracer.info('收到前端请求，即将进入service');
    return this.appService.getRTracer();
  }

  @Get('nestCliId')
  getNestCli () {
    this.LogNestCls.info('收到前端请求，即将进入service');
    return this.appService.getNestCli();
  }

}

业务层

import { Injectable } from "@nestjs/common";
import { LogRtracer } from "./log.rTracer";
import { LogAsyncLocalStorage } from './log.asyncLocalStorage';
import { LogNestCls } from "./log.nest.cls";

@Injectable()
export class AppService {

  constructor(
    private readonly LogNestCls: LogNestCls
  ) { }

  getRTracer () {
    LogRtracer.info('getHello 进入service，即将处理业务');
  }
  getHeeloAsyncLocalStorage () {
    LogAsyncLocalStorage.info('getHeeloAsyncLocalStorage 进入service，即将处理业务');
  }
  getNestCli () {
    this.LogNestCls.info('getNestCli 进入service，即将处理业务');
  }
}

模块加载

async_hooks

import { MiddlewareConsumer, Module, NestModule } from "@nestjs/common";
import { AppController } from "./app.controller";
import { AppService } from "./app.service";
import { LogAsyncLocalStorage } from "./log.asyncLocalStorage";

@Module({
  imports: [],
  controllers: [AppController],
  providers: [AppService],
})

export class AppModule implements NestModule {
  configure (consumer: MiddlewareConsumer) {
  consumer
  .apply((req, res, next) => LogAsyncLocalStorage.init(next))
  .forRoutes('*')
  }
}

cls-rtracer

import { MiddlewareConsumer, Module, NestModule } from "@nestjs/common";
import { AppController } from "./app.controller";
import { AppService } from "./app.service";
import { TraceIdMiddleware } from "./rTracer";

@Module({
  imports: [],
  controllers: [AppController],
  providers: [AppService],
})

export class AppModule implements NestModule {
  configure (consumer: MiddlewareConsumer) {
  consumer
  .apply(TraceIdMiddleware)
  // .apply(TraceIdRandomMiddleware)
  .forRoutes('*')
  }
}

nestjs-cls

import {  Module } from "@nestjs/common";
import { AppController } from "./app.controller";
import { AppService } from "./app.service";
import { ClsModule } from "nestjs-cls";
import { LogNestCls } from "./log.nest.cls";

@Module({
  imports: [
    ClsModule.forRoot({
      global: true,
      middleware: {
        mount: true,
        setup: (cls, req) => {
          cls.set('userId', Math.random());
        }
      }
    })
  ],
  controllers: [AppController],
  providers: [AppService, LogNestCls],
})
export class AppModule { }

运行结果

async_hooks

requestId：0.8233251518769558 time：2023-05-27 22:40:27 info：收到前端
请求，即将进入service
requestId：0.8233251518769558 time：2023-05-27 22:40:27 info：getHeeloAsyncLocalStorage 进入service，即将处理业务

cls-rtracer

requestId：354b79f0-fc9c-11ed-beac-f57b0395da38 time：2023-05-27 22:38:55 info：收到前端请求，即将进入service
requestId：354b79f0-fc9c-11ed-beac-f57b0395da38 time：2023-05-27 22:38:55 info：getHello 进入service，即将处理业务

nestjs-cls

requestId：0.43237919752342924 time：2023-05-27 22:41:04 info：收到前端请求，即将进入service
requestId：0.43237919752342924 time：2023-05-27 22:41:04 info：getNestCli 进入service，即将处理业务