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`のメソッドがあったので、こちらを拡張します。

```typescript: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] `がありますが、それは以下のメソッドを上書きすれば変更できるはず（今回はやってないので・・・）

```typescript:ConsoleLoggerより抜粋
  protected formatPid(pid: number) {
    return `[Nest] ${pid}  - `;
  }
```

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

## ソースコード

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

`CustomLogger`クラスの追加

```typescript: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`クラスを利用するように`main.ts`で設定
※ここは公式にも記載されてそうなので大幅に記載を省略・・・

```javascript:main.ts
import { NestFactory } from '@nestjs/core'
import { AppModule } from './app.module'
import { CustomLogger } from './custom-logger' // ★ここを追加

async function bootstrap() {
  const app = await NestFactory.create(AppModule)
  app.useLogger(new CustomLogger()) // ★ここを追加
  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`クラスにミドルウェアとして最初に処理されるように追加

```typescript: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`クラスを変更します。

```typescript: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を利用

Lambdaのログをよく見ている人は気がついているかもしれませんが、Lambdaの方でもリクエストIDを発行しています。

そのため、Lambda上で動かす場合には、そっちを使います。

[serverless-expressのドキュメント](https://github.com/CodeGenieApp/serverless-express?tab=readme-ov-file#accessing-the-event-and-context-objects)を見る限り、リクエストIDを保持しているcontextにアクセスするには`getCurrentInvoke`を利用するので、こちらを使って取得します。

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

```typescript: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

https://qiita.com/mdbr92/items/5390e4a2fdcc53362e42

https://docs.nestjs.com/techniques/logger#extend-built-in-logger

https://docs.nestjs.com/recipes/async-local-storage