NestJSでログフォーマットを変更してリクエスト単位のIDを共通でログに記録する方法

はじめに

NestJSをLambda上で起動してみたけど、標準ログだと運用が困りそうなのでカスタマイズしてみました。

ログの標準フォーマット

NestJSの標準で出力されるログは以下のような感じです

[Nest] 227  - 10/09/2024, 2:47:17 PM     LOG [NestFactory] Starting Nest application...

ただ、運用を考えると以下の点を変更できるようにしたく思いました。

• プロセスIDの前にある[Nest]がいらない
• プロセスIDよりリクエスト単位のIDが欲しい
  • AWS Lambda上で実行するならAWSが割り振ったリクエストIDを使いたい
• 余計なスペースは削除したい
• 時間はミリ秒まで出して欲しい
• ログレベルのみでログ監視できるようにしたい

NestJSのログ拡張方法について

Loggerは一からLoggerServiceで定義されたインターフェースを実装する方法もありますが、基本的な動きは変更せずに処理を少し変更したいような場合は、ConsoleLoggerクラスを継承して、変更したいメソッドをオーバーライドすることで対応が可能です。

外部ロガーを使用する方法もありますが、ライブラリは増やしたくないので上記で対応できそうなので調べてはいないです。

オーバーライドすれば良いかの判断方法

公式サイトには、具体的なことは書いて無いのでソースコードを実際に確認して、オーバーライドすれば良さそうか判断する必要があります。
フォーマットをしてそうな箇所を探したところformatMessageのメソッドがあったので、こちらを拡張します。

ConsoleLoggerより抜粋

  protected formatMessage(
    logLevel: LogLevel,
    message: unknown,
    pidMessage: string,
    formattedLogLevel: string,
    contextMessage: string,
    timestampDiff: string,
  ) {
    const output = this.stringifyMessage(message, logLevel);
    pidMessage = this.colorize(pidMessage, logLevel);
    formattedLogLevel = this.colorize(formattedLogLevel, logLevel);
    return `${pidMessage}${this.getTimestamp()} ${formattedLogLevel} ${contextMessage}${output}${timestampDiff}\n`;
  }

ちなみにプロセスIDに余計な[Nest] がありますが、それは以下のメソッドを上書きすれば変更できるはず（今回はやってないので・・・）

ConsoleLoggerより抜粋

  protected formatPid(pid: number) {
    return `[Nest] ${pid}  - `;
  }

該当のソースコードはこちら
https://github.com/nestjs/nest/blob/master/packages/common/services/console-logger.service.ts

ソースコード

ステップ１：フォーマットの変更

CustomLoggerクラスの追加

custom-logger.ts

import { ConsoleLogger } from '@nestjs/common'

const dateTimeFormatter = new Intl.DateTimeFormat('ja-JP', {
  year: 'numeric',
  month: '2-digit',
  day: '2-digit',
  hour: '2-digit',
  minute: '2-digit',
  second: '2-digit',
  fractionalSecondDigits: 3,
  hour12: false
})

export class CustomLogger extends ConsoleLogger {

  constructor() {
    super()
  }

  /**
   * Customize log format
   * @override
   */
  formatMessage(logLevel, message, pidMessage, formattedLogLevel, contextMessage, timestampDiff) {
    const output = this.stringifyMessage(message, logLevel)
    const dateTime = dateTimeFormatter.format(Date.now()).replace(/\//g, '/').replace(', ', ' ')
    return `[${dateTime}][${formattedLogLevel.trim()}]${contextMessage}${output}${timestampDiff}\n`
  }
}

CustomLoggerクラスを利用するようにAppModuleクラスに設定
※ここは公式にも記載されてそうなので大幅に記載を省略・・・

main.ts

import { NestFactory } from '@nestjs/core'
import { AppModule } from './app.module'
import { ConsoleLogger } from './custom-logger' // ★ここを追加

async function bootstrap() {
  const app = await NestFactory.create(AppModule)
  app.useLogger(new ConsoleLogger()) // ★ここを追加
  await app.listen(3000)
}
bootstrap();

ステップ２：リクエストIDの追加

node標準のAsyncLocalStorageを利用してリクエスト単位での情報の保持をするようにします。
※ここではザックリとRequestオブジェクトの内容を丸っと持ってますが、リクエストスコープで使うものを整理して型を定義して管理するのが良いかも

storage.ts

import { AsyncLocalStorage } from 'node:async_hooks'
import type { Request } from 'express'

export const storage = new AsyncLocalStorage<Request>()

AppModuleクラスにミドルウェアとして最初に処理されるように追加

app.module.ts

import { Module, MiddlewareConsumer } from '@nestjs/common'// ★MiddlewareConsumerを追加
import type { Request, Response } from 'express'// ★ここを追加
import { randomUUID } from 'crypto'// ★ここを追加
import { storage } from './storage'// ★ここを追加

@Module({ /* 省略 */ })
export class AppModule {
  // ★↓ここを追加
  configure(consumer: MiddlewareConsumer) {
    consumer
      .apply((req: Request, res: Response, next: () => void) => {
        // リクエストIDの追加
        req.requestId = randomUUID()
        // リクエストオブジェクトを保持＆次の処理へ
        storage.run(req, () => next())
      })
      .forRoutes('*');
  }
  // ★↑ここまで追加
}

先ほどのCustomLoggerクラスを変更します。

custom-logger.ts

import { ConsoleLogger } from '@nestjs/common'
import { storage } from './storage'  // ★追加

// （省略）

export class CustomLogger extends ConsoleLogger {

  constructor() {
    super()
  }

  /**
   * Customize log format
   * @override
   */
  formatMessage(logLevel, message, pidMessage, formattedLogLevel, contextMessage, timestampDiff) {
    const output = this.stringifyMessage(message, logLevel)
    const dateTime = dateTimeFormatter.format(Date.now()).replace(/\//g, '/').replace(', ', ' ')

    // リクエスト情報取得 ★ここ追加★
    const request = storage.getStore()
    const requestId = request?.requestId ? request.requestId : '-'

    // ★requestIdを追加
    return `[${dateTime}][${formattedLogLevel.trim()}][${requestId}]${contextMessage}${output}${timestampDiff}\n`
  }
}

ステップ３：AWS LambdaのリクエストIDを利用

serverless-expressのドキュメントを見る限り、contextにアクセスするにはgetCurrentInvokeを利用するので、こちらを使って取得します。

既存のリクエストIDは、取得できなかった場合のみ生成に修正しています。

app.module.ts

import { Module, MiddlewareConsumer } from '@nestjs/common'
import type { Request, Response } from 'express'
import { randomUUID } from 'crypto'
import { storage } from './storage'
+ import { getCurrentInvoke } from '@vendia/serverless-express' // ★追加

@Module({ /* 省略 */ })
export class AppModule {
  configure(consumer: MiddlewareConsumer) {
    consumer
      .apply((req: Request, res: Response, next: () => void) => {
      
        // リクエストIDの追加
        const { event, context } = getCurrentInvoke() // ★追加
        req.requestId = context?.awsRequestId ? context.awsRequestId : randomUUID() // ★変更

        // リクエストオブジェクトを保持＆次の処理へ
        storage.run(req, () => next())
      })
      .forRoutes('*');
  }
}

参考URL