こんにちは、株式会社medibaでバックエンドエンジニアをしている @mdbr92 です。
この記事は mediba Advent Calendar 2022 の23日目です。
※記事の内容はあくまで個人の発信であり、会社を代表する意見や見解ではありません。

この記事では NestJS で API サーバを開発した際にちょっと実装に苦労した、
ログへのリクエストID の出力について書いてみたいと思います。

はじめに

NestJS で API サーバを開発した際、１リクエストに対して複数の箇所で出力されているログを、リクエスト毎に追跡しやすくするために、ログにリクエストID（リクエスト毎に一意なID）を含めるという設計にしました。
nestjs-pinoのような外部パッケージを追加導入すれば実現できそうでしたが、リクエストID の出力という一点に対してパッケージの追加とカスタマイズは大げさだったので、自前で実装することにしました。

前提知識

NestJS を使った実装の概要程度の知識を前提としています。
公式ドキュメントのOVERVIEWあたりを把握していれば大丈夫だと思います。

記事中のサンプルコードについて

以下のようなコマンドでプロジェクトを生成したものに、処理を追加していく形で記述しています。

npm install -g @nestjs/cli

nest new (プロジェクト名)

※サンプルコードは実際のプロダクトで使われているコードではなく、本記事用に簡潔に記述したものです。
※ファイルを配置するディレクトリ名やクラス名は任意に決められますので、お好みで読み替えてください。

NestJS でのログ出力と出力形式のカスタマイズ

公式ドキュメントで説明されているので、おさらいを兼ねてになります。

ログ出力

コントローラやサービスでログを出力させるにはLoggerクラスのインスタンスを生成し、ログを出力したい場所でログレベルに応じたメソッド(log,warn,error...)を呼び出します。

AppService のメソッド内でログ出力する例

src/app.service.ts

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

@Injectable()
export class AppService {
  private readonly logger = new Logger(AppService.name); // ②インスタンスを作成(引数がコンテキストとなる)

  getHello(): string {
    this.logger.log('Logging at service'); // ③logレベルのログを出力
    return 'Hello World!';
  }
}

AppController のメソッド内でログ出力する例

src/app.controller.ts

import { Controller, Get, Logger } from '@nestjs/common'; // ①

import { AppService } from './app.service';

@Controller()
export class AppController {
  private readonly logger = new Logger(AppController.name); // ②

  constructor(private readonly appService: AppService) {}

  @Get()
  getHello(): string {
    this.logger.log('Logging at controller'); // ③
    return this.appService.getHello();
  }
}

起動してアクセスすると、以下のようなNestJS初期設定のフォーマットでログが出力されます。

log

[Nest] 30660  - 2022/11/24 18:52:22     LOG [AppController] Logging at controller
[Nest] 30660  - 2022/11/24 18:52:22     LOG [AppService] Logging at service

出力形式のカスタマイズ

任意の項目やフォーマットでログを出力させるには、LoggerServiceインターフェイスに沿ったサービスを作成し、ログ整形・出力処理を実装し、アプリケーションに設定します。

ここでは、JSON形式で出力するようにしてみます。

カスタムログ出力サービスを実装

src/custom-logger/custom-logger.service.ts

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

@Injectable()
export class CustomLoggerService implements LoggerService {
  /** JSON形式に整形して標準出力に出力 */
  private write(level: LogLevel, ...args: unknown[]) {
    const time = new Date().toISOString();
    const context = args.pop(); // args の最後の要素にコンテキスト(ログを出力する処理の場所)が入る
    const message = args.shift(); // args の最初の要素をメッセージとする
    const params = args.length !== 0 ? args : undefined; // args の残りの要素をパラメータ(オプション)とする
    // JSON形式で標準出力に出力
    console.log(JSON.stringify({ time, level, context, message, params }));
  }

  log(...args: unknown[]) {
    this.write('log', ...args);
  }

  warn(...args: unknown[]) {
    this.write('warn', ...args);
  }

  error(...args: unknown[]) {
    this.write('error', ...args);
  }
}

モジュールを作成し、AppModule の imports に追加

src/custom-logger/custom-logger.module.ts

import { Module } from '@nestjs/common';

import { CustomLoggerService } from './custom-logger.service';

@Module({
  providers: [CustomLoggerService],
})
export class CustomLoggerModule {}

src/app.module.ts

import { Module } from '@nestjs/common';

import { AppController } from './app.controller';
import { AppService } from './app.service';
import { CustomLoggerModule } from './custom-logger/custom-logger.module';

@Module({
  imports: [CustomLoggerModule],
  controllers: [AppController],
  providers: [AppService],
})
export class AppModule {}

起動処理で app.useLogger() を呼び出し、実装したサービスを指定

src/main.ts

import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import { CustomLoggerService } from './custom-logger/custom-logger.service'; // ①

async function bootstrap() {
  const app = await NestFactory.create(AppModule, {
    bufferLogs: true, // ②
  });
  app.useLogger(app.get(CustomLoggerService)); // ③
  await app.listen(3000);
}
bootstrap();

これで、以下のような JSON 形式でログ出力できるようになりました。

log

{"time":"2022-11-25T09:44:26.333Z","level":"log","context":"AppController","message":"Logging at controller"}
{"time":"2022-11-25T09:44:26.333Z","level":"log","context":"AppService","message":"Logging at service"}

ログ出力項目にリクエストID を追加する

ここからが本題です。

リクエスト時にユニークな ID を払い出す

リクエスト毎にそれぞれユニークな ID を払い出す方法として、NodeJS 標準APIの crypto.randomUUID() を利用しました。
randomUUID() はランダムに UUID バージョン 4 形式の ID 文字列を生成してくれます。

ミドルウェアを実装して、リクエスト毎に払い出します。

リクエストID を生成するミドルウェアを追加

src/custom-logger/custom-logger.middleware.ts

import { randomUUID } from 'node:crypto';

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

@Injectable()
export class CustomLoggerMiddleware implements NestMiddleware {
  use(req: Request, _res: Response, next: NextFunction) {
    // ユニークなIDを生成
    const requestId = randomUUID();
    // とりあえず、リクエストヘッダに保存
    req.headers['request-id'] = requestId;
    next();
  }
}

追加したミドルウェアを適用する

src/custom-logger/custom-logger.module.ts

import { MiddlewareConsumer, Module, NestModule } from '@nestjs/common';

import { CustomLoggerMiddleware } from './custom-logger.middleware';
import { CustomLoggerService } from './custom-logger.service';

@Module({
  providers: [CustomLoggerService],
})
export class CustomLoggerModule implements NestModule {
  configure(consumer: MiddlewareConsumer) {
    consumer.apply(CustomLoggerMiddleware).forRoutes('*');
  }
}

動作確認

ためしにコントローラでリクエストヘッダから取得し、ログに出力してみます。

コントローラメソッドの引数に@Headersデコレータをつけることで、リクエストヘッダの値を受け取ることができます。

src/app.controller.ts

import { Controller, Get, Headers, Logger } from '@nestjs/common';

import { AppService } from './app.service';

@Controller()
export class AppController {
  private readonly logger = new Logger(AppController.name);

  constructor(private readonly appService: AppService) {}

  @Get()
  getHello(@Headers('request-id') requestId: string): string {
    this.logger.log('Logging at controller', { requestId });
    return this.appService.getHello();
  }
}

log

{"time":"2022-11-28T09:57:30.590Z","level":"log","context":"AppController","message":"Logging at controller","params":[{"requestId":"1f54b385-840c-4c4f-928b-4125f5a4a10c"}]}
{"time":"2022-11-28T09:57:30.590Z","level":"log","context":"AppService","message":"Logging at service"}
{"time":"2022-11-28T09:57:32.761Z","level":"log","context":"AppController","message":"Logging at controller","params":[{"requestId":"85ac3046-62b7-4620-b8dd-35975c525d4a"}]}
{"time":"2022-11-28T09:57:32.762Z","level":"log","context":"AppService","message":"Logging at service"}

リクエスト毎に異なる requestId が出力されました。

カスタムログ出力サービスの処理の中からリクエストID を取得する

コントローラであれば前項のようにリクエストヘッダなどから受け取ったリクエストID をログに出力することもできますが、
サービスのメソッドやログ出力処理の中から自発的に取得することはできません。
コントローラからサービスのメソッドを呼び出す際にリクエストID を引数としてバケツリレーするのも現実的ではないでしょう。

ミドルウェアで生成したリクエストID をログ出力処理内で参照する実現方法を探し、NodeJS 標準 API の AsyncLocalStorage というものが使えそうでした。

AsyncLocalStorage を使うことで、後続処理からは参照できるが、他の並列処理とは独立した、スレッドローカル変数のようなものが実現できます。

リクエストID 用の AsyncLocalStorage

src/custom-logger/storage.ts

import { AsyncLocalStorage } from 'node:async_hooks';

export const storage = new AsyncLocalStorage<string>();

ミドルウェアでリクエストID を保存

src/custom-logger/custom-logger.middleware.ts

import { randomUUID } from 'node:crypto';

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

import { storage } from './storage';

@Injectable()
export class CustomLoggerMiddleware implements NestMiddleware {
  use(req: Request, _res: Response, next: NextFunction) {
    // ユニークなIDを生成
    const requestId = randomUUID();

    // AsyncLocalStorage に リクエストID を保存
    storage.run(requestId, next, undefined);
  }
}

カスタムログ出力サービスでリクエストID を取得してログの項目に追加

src/custom-logger/custom-logger.service.ts

import { Injectable, LogLevel, LoggerService } from '@nestjs/common';
import { storage } from './storage';

@Injectable()
export class CustomLoggerService implements LoggerService {
  /** JSON形式に整形して標準出力に出力 */
  private write(level: LogLevel, ...args: unknown[]) {
    const time = new Date().toISOString();
    const context = args.pop();
    const message = args.shift();
    const params = args.length !== 0 ? args : undefined;
    // AsyncLocalStorage から リクエストID を取得
    const requestId = storage.getStore();
    console.log(JSON.stringify({ time, level, requestId, context, message, params }));
  }

(以下略)

動作確認

※AppController でリクエストヘッダからリクエストID を取得するようにした部分はもとに戻しています。

src/app.controller.ts

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

import { AppService } from './app.service';

@Controller()
export class AppController {
  private readonly logger = new Logger(AppController.name);

  constructor(private readonly appService: AppService) {}

  @Get()
  getHello(): string {
    this.logger.log('Logging at controller');
    return this.appService.getHello();
  }
}

起動時してアクセスしてみると

log

{"time":"2022-11-29T09:18:36.677Z","level":"log","requestId":"4f6c9a84-3896-41dd-9bb9-09f9c9e76b7d","context":"AppController","message":"Logging at controller"}
{"time":"2022-11-29T09:18:36.677Z","level":"log","requestId":"4f6c9a84-3896-41dd-9bb9-09f9c9e76b7d","context":"AppService","message":"Logging at service"}
{"time":"2022-11-29T09:18:37.301Z","level":"log","requestId":"5e668425-62a2-4706-8988-ad3ac36b3e14","context":"AppController","message":"Logging at controller"}
{"time":"2022-11-29T09:18:37.301Z","level":"log","requestId":"5e668425-62a2-4706-8988-ad3ac36b3e14","context":"AppService","message":"Logging at service"}

ログ出力時にリクエストID を出力できるようになりました。

サービスメソッド呼び出しの前に数秒待つ処理を入れて同時アクセスしてみても、
後発のリクエストで上書きされることもなく保持されています。

log

{"time":"2022-11-30T09:02:27.344Z","level":"log","requestId":"b2319e14-b399-46f9-8f91-616a0f3ad5b2","context":"AppController","message":"Logging at controller"}
{"time":"2022-11-30T09:02:27.832Z","level":"log","requestId":"0aab269a-a106-41bf-b49a-44fae2150309","context":"AppController","message":"Logging at controller"}
{"time":"2022-11-30T09:02:30.346Z","level":"log","requestId":"b2319e14-b399-46f9-8f91-616a0f3ad5b2","context":"AppService","message":"Logging at service"}
{"time":"2022-11-30T09:02:30.833Z","level":"log","requestId":"0aab269a-a106-41bf-b49a-44fae2150309","context":"AppService","message":"Logging at service"}

さいごに

この件で実装方法に迷っていた際に、同様の事例の記事を見つけることができなかったため、今回書いてみました。
この記事が少しでも似たような事例で実装方法に迷っている方の助けになれば幸いです。

株式会社mediba からのお知らせ

現在、medibaの募集求人ページから応募され入社が決定すると、お祝い金として30万円をプレゼントするキャンペーンを実施中です！！
リモート環境を充実するためディスプレイやマイクを買いそろえるも良し。スキル習熟のために自己研鑽に使うも良し。使途は完全自由です。
→　募集・応募ページ

いきなり応募だとちょっとハードルが高い・・でも興味がある方は、カジュアル面談も行っていますので、まずはお話してみませんか？
→　カジュアル面談

※お祝い金は、試用期間（3か月）を経て、雇用が継続した場合に支給させて頂きます。