前言

写这篇博客之前，其实我们生产环境遇到了一个问题，算是特别大的事故，因为我之前的设计失误，导致了日志记录的信息不准确。

事情是这样的，某一天早上，因为业务后端的某个服务宕机了，导致BFF访问他们的服务超时，线上一下子报了很多错误日志。然后，我就配合服务端同事们排查错误，因为这件事儿反推导出了我们的BFF系统日志系统有问题。后端同事先于我找到了出问题的环节，然后告诉了我影响的范围，然后我根据这个影响范围去查看了一下日志，发现一个很奇怪的问题，为什么有的接口明明就好比是直接返回用户一个HelloWorld这样字符串的接口，怎么也记录上了那样一个错误信息，这种接口是100%不可能产生错误捕获的呀，完全是牛头不对马嘴啊。

此刻，我心目中大概已经意识到了一点儿问题的，容我卖个关子，一会儿再跟大家揭晓问题的答案。

错误的代码设计

项目中的代码不便于向大家展示，于是我将其简化，让大家明白这里面存在的问题。

首先，用一个全局的单例类来存储Request对象。

let request: Request = null;

export function setRequest(req) {
  request = req;
}

export function getRequest() {
  return request;
}

创建一个中间件，用来记录Request对象：

import { Injectable, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { setRequest } from './singleton';

@Injectable()
export class TraceMiddleware implements NestMiddleware {
  use(req: Request & { traceId: string }, res: Response, next: NextFunction) {
    setRequest(req);
    next();
  }
}

应用中间件：

import { TraceMiddleware } from './ctx.middleware';
import { MiddlewareConsumer, Module } from '@nestjs/common';
import { AppController } from './app.controller';

@Module({
  controllers: [AppController]
})
export class AppModule {
  configure(consumer: MiddlewareConsumer) {
    consumer.apply(TraceMiddleware).forRoutes('*');
  }
}

然后在一个Controller里面模拟日志：

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

@Controller('/app')
export class AppController {
  @Inject()
  private readonly appService: AppService;

  @Get('/index')
  getHello(): string {
    const req = getRequest();
    console.log(req.url, 'home');
    return this.appService.getHello();
  }
}

目前看起来，似乎还没有什么问题哈。

为什么要这样设计

有的同学可能不太理解我为什么要这样设计，因为，实际上，在NestJS中，我们在Controller里面是很容易的拿到Request对象的，比如：

import { Controller, Get, Inject } from '@nestjs/common';
import { AppService } from './app.service';
import { getRequest } from './singleton';
import { Request } from 'express';
import { REQUEST } from '@nestjs/core';

@Controller('/app')
export class AppController {
  @Inject(REQUEST)
  protected readonly request: Request;
  
  @Get('/index')
  getHello(): string {
     // 使用Request对象做一些操作
  }
}

给大家看一下我们的Logger类：

import * as dayjs from 'dayjs';
import { FormattedLog, RequestLogCommonStructure } from '@/common/types';
import { Request } from 'express';
import { APP_VERSION } from '@/common/constants';

export abstract class LoggerService {
  private version = APP_VERSION;

  /**
   * 子类返回Request上下文对象
   */
  protected abstract getRequest(): Request;

  /**
   * 获取请求上下文的公共数据
   * @returns
   */
  protected getRequestCommonBodyLog(): RequestLogCommonStructure {
    const req = this.getRequest() as Request & { traceId: string };
    if (!req) {
      return {
        userId: '',
        traceId: '',
        method: '',
        actKey: '',
        url: '',
        args: {
          body: '',
          params: '',
          query: '',
        },
      };
    }
    const userId = (req.query.curuserid ||
      req.query.userId ||
      req.headers['x-user-id']) as string;
    const actId = req.params.actKey as string;
    const traceId = req.traceId;
    return {
      userId,
      traceId,
      method: req.method,
      actKey: actId,
      url: req.route?.path,
      args: {
        body: req.body,
        params: req.params,
        query: req.query,
      },
    };
  }

  private getLogBody(level: string, logContext: Partial<FormattedLog>) {
    const { traceId, method, url, args, userId, actKey } =
      this.getRequestCommonBodyLog();
    return {
      _LEVEL_: level,
      _TS_: dayjs(new Date()).format('YYYY/MM/DD HH:mm:ss'),
      _CALLER_: logContext.caller || 'unknown',
      _MSG_: '',
      _VER_: `v${this.version}`,
      _DEPLOY_: process.env.NODE_ENV,
      _APP_: 'act-bff',
      _COMP_: 'server',
      _TYPE_: logContext.type || 'general',
      traceID: traceId,
      // TODO: 待定
      spanID: '',
      operation: '',
      method: method || 'unknown',
      uri: url || 'unknown',
      args: logContext.args || args || 'unknown',
      code: logContext.code || -1,
      message: logContext.message || 'unknown',
      userid: userId || logContext.userId || '',
      actKey: actKey || '',
      spend: logContext.spend || '',
    };
  }

  public log(message: Partial<FormattedLog>) {
    const formattedLog = this.getLogBody('log', message);
    console.log(JSON.stringify(formattedLog));
  }

  public error(message: Partial<FormattedLog>) {
    const formattedLog = this.getLogBody('error', message);
    console.error(JSON.stringify(formattedLog));
  }

  public warn(message: Partial<FormattedLog>) {
    const formattedLog = this.getLogBody('warn', message);
    console.warn(formattedLog);
  }

  public debug(message: Partial<FormattedLog>) {
    const formattedLog = this.getLogBody('debug', message);
    console.debug(formattedLog);
  }
}

但是，实际上，是因为我的Logger需要Request对象，Logger对象的调用是在任何地方，比如我们将代码分层，业务逻辑层和数据访问层，Logger就可能在这些层中调用。

此刻，就造成了每次使用Logger的时候，必须把上层的Request对象传进来，层层传递，这得把人累死啊，我是肯定不能忍受这样的设计的，有没有什么好办法呢？我思考了一周之后，想到了把Request对象用一个全局单例的对象保存下来不就好了吗，于是这就是上面给大家看到的代码中，为什么用那种方式把Request对象记录下来的目的，这样做的好处就是Logger类的内聚性高，使用起来十分方便。

import { Logger } from 'xxx'
class SomeBusiness {

    someAction() {
        Logger.getInstance().log("some error information");
    }
}

复现错误

好了，接下来就是给大家解密我的错误设计的时刻了。

因为业务需求增加，现在加了一个异步方法，Controller里面加了一个getDemo的方法。

import { Controller, Get, Inject } from '@nestjs/common';
import { AppService } from './app.service';
import { getRequest } from './singleton';
import { Request } from 'express';
import { REQUEST } from '@nestjs/core';

@Controller('/app')
export class AppController {
  @Inject(REQUEST)
  protected readonly request: Request;

  @Inject()
  private readonly appService: AppService;

  @Get('/index')
  getHello(): string {
    const req = getRequest();
    console.log(req.url, 'home');
    return this.appService.getHello();
  }

  @Get('/demo')
  getDemo() {
    return new Promise((resolve) => {
      setTimeout(() => {
        const req = getRequest();
        console.log(req.url, 'demo');
        resolve('hello demo');
      }, 5000);
    });
  }
}

此刻，我模拟一个用户的行为，我们先访问localhost:3000/app/demo，然后抓紧时间赶紧访问/index（5S以内），然后控制台打印的内容如下： 我们惊讶的发现，竟然都打印的是/index的请求地址，这不就导致Request对象已经串了。

如果把这个设计思路用SpringMVC写拿到Tomcat上跑，或者用ASP.NET MVC写在IIS上跑，是不会有问题的。

但是众所周知，Nodejs是单线程的应用程序，没有谁特别说明过服务器里面有多线程的概念呀，那这个问题就很简单就解释了。因为在这个异步等待的过程中，后来的请求把之前的Request对象覆盖掉了，导致在异步任务完成的时候拿到的是最新的Request对象，而实际上我们需要的是对应/app/demo那个请求的Request对象。

怎样理解Nodejs的单线程？

为了便于大家理解，先普及一下知识点。

进程和线程

我并不是计算机科班出身，所以解释并不一定专业。在大学的时候，学过2年的C#程序，因此对进程和线程有一点儿认识。 以下是Chatgpt4给出的它们的定义：

进程和线程是计算机中的两个基本概念，它们与程序的执行和资源管理密切相关：

1. 进程（Process） ：进程是程序的执行实例。在操作系统中，一个进程通常代表一个执行中的程序，包括其代码和所有相关的资源。它是系统资源分配和调度的基本单位，拥有独立的内存地址空间。每个进程至少包含一个线程（主线程）。
2. 线程（Thread） ：线程是进程中的一个执行流程，是操作系统能够进行运算调度的最小单位。它通常被用于执行程序中的一个任务，一个进程中可以包含多个线程。线程共享其父进程的内存空间和资源，但每个线程有自己的执行堆栈和程序计数器。

简而言之，进程是资源分配的单位，线程是执行的单位。线程在一个进程中运行，多个线程可以共享同一进程的资源。

如果说，你觉得对这个专业名词解释仍然看不懂的话，那就接着看我的理解吧。

首先，进程比较简单，进程就是一个程序，就比如大学第一课我们学C语言编写一个控制台程序，编译之后运行起来，它就是一个进程。

线程，就不太好理解了，不过我们可以用一个形象的例子来举例。

在西游记中讲述了西天取经的故事，孙悟空，拔下一把猴毛，变出许许多多的猴子参加与妖怪的战斗，这个时候，孙悟空西天取经其实就是进程（因为我们写一个程序总是为了完成什么事儿嘛），孙悟空护送唐僧取经，遇到妖怪，发生战斗，这个过程，孙悟空就是我们常听说的主线程（因为他得去开始西天取经这个事儿）。因为是他变出的猴子们，然后一个一个的猴子就跟妖怪战斗，这些猴子就是工作线程或者说是后台线程，工作线程是主线程创建的。

有的同学不太明白什么情况下会有这种创建线程的需求，就比如在Socket网络编程中，有一个操作是需要一直监听外部设备的连接，在这个操作里面就是一个while(true)的循环，直到有外部的设备连接，才中断循环。如果主线程来执行这个代码，一旦执行到这儿，我们的界面就卡死了。

所以这种活儿，主线程不能干，那么主线程就需要找一个人来帮它干，于是一个工作线程就接替了这个while(true)的工作，然后主线程接着干别的事儿。

这儿，就出现了另外一个问题，当工作线程需要汇报结果给主线程的时候，就牵扯到了两个线程之间的通信，我这里就不展开讲了，有兴趣的同学可以自行查阅相关的资料。

我对Nodejs单线程的理解

关于Nodejs的单线程，取决于你怎么理解它的。

我是这样来理解的：Nodejs的单线程体现在我们编写的代码跑在一个线程上，并且Nodejs没有提供我们去开启线程的能力，但是并不是说V8底层就只有一个线程在工作（如果真的只有一个线程工作，那怎么解释文件读写和网络I/O操作能够同时进行呢？）。

理解 Node.js 的单线程模型，关键在于区分“事件循环”（Event Loop）和“异步操作”。

Node.js 主要的操作（如执行代码、处理事件）在单个线程上进行。这意味着一次只能执行一个操作，从而避免了多线程编程中的复杂性，如线程同步问题。

虽然 Node.js 在主线程上运行是单线程的，但它支持异步操作，特别是输入/输出操作。当Node.js执行如文件读写、网络通信等操作时，这些操作是非阻塞的，Node.js不会在这些操作完成时挂起主线程。相反，这些操作在后台执行，一旦完成，就会将回调函数放入事件队列中，等待主线程空闲时执行。

通过这种方式，Node.js 可以高效处理大量并发的I/O操作，因为主线程不会因为I/O操作的等待而闲置。这使得Node.js特别适合构建高性能的网络应用。

Node.js的单线程模型不适合CPU密集型任务，因为长时间的计算会阻塞事件循环，影响整体性能。对于这类任务，可以使用工作线程或分布式计算等策略。

如果你觉得上面的内容看起来仍然觉得有点儿吃力，那我用直白的话术将其描述一遍。

就比如成都某家的火锅店生意非常好，然后大家去吃火锅就需要排队。我们把从进火锅店坐下到最终吃上火锅，类比成一个请求发送给Node服务器到前端收到响应结果。

假设现在服务员已经安排我们就坐了，服务员给我们菜单提交了点餐结果，这时服务员是不会在这儿傻傻的等待的，他就立马去安排下一桌客人。然后我们就等待服务员上菜，当后厨把我们点单的食材都准备好了，服务员就给我们上菜，这时候我们就可以吃上火锅了。

但是，事情肯定不是这么简单的，有些人他做事儿比较缓慢，他点菜需要花费很多的时间，总是在纠结吃什么好呢，此刻服务员又不能跑去照顾别的客人（假设服务员这时走了就会被投诉扣工资），于是服务员就只能在这儿傻傻的等着。

即便后厨已经把食材准备好了，让服务员给我们呈上来，但是因为另一桌的客人还在点菜，他只能等那桌客人点餐完成之后才能给我们上菜，我们就推迟了吃上火锅。

所以，通过这个例子，在Nodejs Web开发中，我们尽量少用sync操作，（比如readFileSync)。

Node Server和其它多线程Server的区别

我以Java Web举例。

在 Node.js（单线程）和 Java Web（多线程）的开发中，它们的优劣各有不同：

Node.js（单线程）优劣：

• 优点：
  • 高效的I/O处理：非阻塞I/O使得Node.js适合处理高并发请求，特别是I/O密集型任务。
  • 简化的共享状态：单线程避免了多线程中的线程同步问题，简化了状态共享的复杂性。
• 缺点：
  • 不适合CPU密集型任务：长时间的CPU密集型操作可能会阻塞事件循环，影响性能。
  • 错误处理：未捕获的异常可能导致整个应用崩溃。

Java Web（多线程）优劣：

• 优点：
  • 强大的处理能力：适合复杂的业务逻辑和CPU密集型任务，每个请求一个线程，可以并行处理。
  • 稳定的生态系统：成熟的框架和工具，适用于大型企业级应用。
• 缺点：
  • 资源消耗：每个线程都消耗内存和上下文切换开销，可能在高并发情况下影响性能。
  • 复杂的并发处理：需要处理线程安全问题，增加开发难度。

注意点：

• Node.js：
  • 用异步代码避免阻塞事件循环。
  • 对错误和异常进行妥善处理。
• Java Web：
  • 管理和优化线程使用，注意线程安全。
  • 合理利用Java的多线程和并发工具来提高性能。

正是因为Nodejs的这些特点，使得它特别适合面对高并发的业务场景，但是也因为这个特性，我们需要注意数据访问存在的一些问题。

利用"线程上下文"改善日志设计

之前说了那么多Nodejs是单线程的，那么哪儿来的什么"线程上下文"呢？

其实，这个“线程上下文”是我自己的叫法而已。

在Nodejs的高版本中，引入了一个async_hooks的模块，使用它提供的API，我们就能实现像Java Web开发中多线程的那种效果（简单理解即每个Request都是独立的）

在我的这个场景中，我用到的是AsyncLocalStorage👉async_hooks 异步钩子 | Node.js API 文档 (nodejs.com.cn)。

AsyncLocalStorage 是 Node.js 中的一个 API，它提供了一种在异步调用链中存储和访问数据的方式，类似于线程本地存储。这个 API 允许你在一个异步操作的整个生命周期中传递上下文信息，而无需显式地将这些信息在每个函数调用中传递。这在构建如Web服务器等需要在多个异步操作间共享状态的应用时非常有用。例如，在处理Web请求时，可以用它来存储和访问特定于请求的用户信息。

前置知识点已经向大家阐述清楚了，接下来就是编码了，基于最开始我们的那个例子进行改造。

改造Request对象的储存方式：

import { AsyncLocalStorage } from 'async_hooks';
import { Request } from 'express';

export const storageCtx = new AsyncLocalStorage<Request>();

export function getRequest() {
  return storageCtx.getStore();
}

改造中间件：

import { Injectable, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { storageCtx } from './singleton';

@Injectable()
export class TraceMiddleware implements NestMiddleware {
  use(req: Request & { traceId: string }, res: Response, next: NextFunction) {
    storageCtx.run(req, next as any);
  }
}

AsyncLocalStorage.prototype.run 方法的第二个回调函数是一个异步函数，它在创建的异步本地存储上下文中执行。这个回调函数是你希望在特定上下文中运行的代码块。当调用 run 方法时，会创建一个新的上下文环境，回调函数中的所有异步操作都将共享这个环境中的数据。

简单来说，这个回调函数就是你想要在隔离的异步上下文中执行的逻辑，这样你就可以在这个上下文中存取数据，而这些数据在异步调用链中是连续且独立的。

因为我们后面的操作就是在一个特定的上下文环境中执行，所以run方法的第二个参数指定为中间件的next回调函数就可以了（对NestJS的运行流程不太明白的，可以参考本系列之前的文章）

可以看到，不管怎么样请求，Request对象都已经变成独立的了。

总结

本文说起来仅仅只是给大家讲述一个API的实际应用却用了较大的篇幅来阐述一些基础知识点，希望对大家有用。

我是一个有代码洁癖的人，在项目的开发中，日志记录是困扰了我相当长的一个问题，因为它打破了我对高内聚低耦合的软件设计的认知，所以我觉得应该是有办法能够解决这个问题，因此不断的设计改进才写出了使用起来让人满意的Logger本文特此将这个经验与大家分享。

最后，各位同学在实际的开发中如果遇到关于NestJS的使用问题不会解决的，可以私信我~

如果大家喜欢我的文章，可以多多点赞收藏加关注，你们的认可是我最好的更新动力，😁。