[NestJS] middleware を超えて ─ fastify hook でつくるリクエストロギング実装

「リクエストロギングなら、middleware でやればいいのでは？」

という声が聞こえてきそうですが、確かにそのとおりです。
NestJSでリクエストのロギングを実装するなら、 middleware を使うのがもっとも一般的な選択肢でしょう。

しかし、もしあなたがHTTPアダプターに fastify を採用しているなら、その middleware は裏側で fastify の hook を使って実行されていることをご存知でしょうか？

本記事では、

• middleware / hook と interceptor の役割の違い
• GraphQL専用だったロギングを、REST APIと共通化した経緯
• fastifyのhookを直接利用する実装方法

についてお話したいと思います。
フレームワークの裏側を理解することで、よりシンプルで責務に合ったロギング設計が可能となるでしょう。

🎯 背景：GraphQL と REST API のロギング共通化

スペースマーケットでは、元々 GraphQL API を中心に構築しており、リクエストのロギングはApollo Server の Plugin 機能を使って実装していました。
当時のブログにも当時の実装方法を紹介しています。

NestJS + Apollo Server でログ出力を行う

@Plugin()
export class LoggingPlugin implements ApolloServerPlugin {
 async requestDidStart(
   requestContext: GraphQLRequestContext
 ): Promise<GraphQLRequestListener> {
   console.log('Request started');
   const {
     request: { query, operationName, variables },
   } = requestContext;

   return {
     async didEncounterErrors({ errors }) {
       // errors は配列なので JSON 文字列に変換している
       const message = {
         errors: JSON.stringify(errors, null, 2),
       };
       console.error(message);
     },
     async willSendResponse() {
       const message = {
         operationName,
         query,
         variables,
       };
       console.log(message);
     },
   };
 }
}

これは GraphQL の実行コンテキストにアクセスでき非常に強力ですが、当然ながら REST API として公開しているエンドポイント（例: /users/1）に対しては適用できません。

前回の記事でお伝えしてした通り、わたしたちは Rails から NestJS へ移行を進めている最中です。
そんな中で REST API を移行する際に「既存のロギングでは GraphQL にしか対応していない」という課題がありました。
両APIをカバーする共通ロガーの実装が、今回の取り組みの出発点になります。

⚖️ 補足：選択肢としてのInterceptor（と、それを選ばなかった理由）

ここで共通化の選択肢として、NestJS の標準機能である interceptor を思い浮かべる方も多いでしょう。
interceptor はコントローラーのメソッドと GraphQL のリゾルバの両方に適用できるため、一見すると有力な候補です。

middleware や interceptor など、NestJS のライフサイクルにおいてどこで何が行われるかは Request Lifecycle に記載されています。

簡単に図にしたものがこちらです。

middleware / interceptor の違いをまとめると以下のようになります。

	middleware	interceptor
目的	リクエスト/レスポンスの逐次処理	メソッド実行の前後処理、結果の変換・監視
実行タイミング	リクエストがルートハンドラに到達する前	コントローラー処理の前後(詳細は図参照)
引数として受け取れるオブジェクト	Request, Response	ExecutionContext, CallHandler
用途	ロギング、認証、CORSなど	前後処理、整形

interceptor は便利な機能ですが、本質はアプリケーション側での機能です。
これを使ってリクエストロギングを実装するのは、責務が異なるレイヤーの仕事をさせることになり、意図しない副作用を生む可能性があります。

この思想に基づき、より責務に合った middleware / hook で実装する方針を固めました。

余談

interceptor と GraphQL の組み合わせは少し注意が必要です。
fieldResolverEnhancers: ['interceptors'] のオプションが設定されている場合、GraphQLの ResolveField に対しても適用されます。

そのため、リクエスト自体は1回にも関わらずログが複数回（ResolveFieldごとに）出力されることになります。
当初 interceptor で実装を試みていたのですが、スペースマーケットでは Sentry でのエラー通知を ResolveField に対しても通知するため fieldResolverEnhancers を元々設定されていたこともあり、ログが爆増する結果となりました。

この設定に気づかず interceptor の仕様かと勘ぐったりもしましたが、ちゃんと公式ドキュメントにも注意書きとして記載されていました…。
ドキュメント大事。

💡 Middlewareは、Hookの上で動いている

fastify には フック（hook） というライフサイクルイベントに処理を登録する仕組みが備わっています。
では、なぜ NestJS x fastifyで app.use() のような middleware が使えるのでしょうか？

答えは express との互換性を持たせるために、middleware の概念を提供しているからです。
(実際には fastify の hook を利用して実装されています)

これは express が持っているエコシステムを活用できるようにすることで、fastify への移行を容易にするための設計と考えられます。

そして fastify で middleware を実現するためのパッケージが @fastify/middie です。

https://fastify.dev/docs/latest/Reference/Middleware

NestJS においては、@nestjs/platform-fastify をインストールすることで @fastify/middie も依存パッケージとして入ってくるため、express 利用時と同様に app.use() で middleware を登録することができます。

なお、main.ts で @fastify/middie を app.register すると

FastifyError: The decorator 'use' has already been added!

のようにすでに登録済であるエラーが発生するため、middie の存在を開発者として意識する必要はありません。

つまるところ、NestJS の middleware は express の middleware のラッパー的な存在であり、fastify が express と互換性持っているからこそ 抽象化された middleware の機能として提供されている といえます。

fastify ネイティブの hook を使うか、middleware を使うかプロジェクトの要件やチームの好みによる部分が大きいでしょう。
express から fastify へ移行するケースを考えると、middleware を使うことで既存の express のコードを大きく変更せずに移行できるメリットがあります。
新規プロジェクトで fastify を選択する場合は、hook を直接利用してもよいでしょう。
（NestJS の middleware が抽象化してくれているとはいえ、実態は fastify が middleware の互換性を提供しているからこそ成り立っているものであり、このあたりの技術選定は議論の余地があります）

🛠️ 実装：fastify の hook を使ったリクエストロギング

わたしたちの実装では、main.tsで fastify のネイティブフックを直接登録する方法としました。
hook の種類はいくつか選ぶことができますが、リクエストの開始と終了を捉えるために onRequest と onResponse を利用します。
middleware でも同様のことはできますが、hook を使ったほうが種類が多くより細かい制御が可能になります。
また、middie による互換レイヤーの（僅かな）オーバーヘッドも無くすことができます。

main.ts

const httpLoggerHook = app.get(HttpLoggerHook)
httpLoggerHook.apply(app.getHttpAdapter().getInstance())

http-logger.hook.ts

declare module 'http' {
  interface ServerResponse {
    startTime: number
  }
}

@Injectable()
export class HttpLoggerHook {
  public apply(app: FastifyInstance): void {
    app.addHook('onRequest', async (_, reply) => {
      // reply はリクエストごとに生成されるため、ここで開始時間を設定しておく
      reply.raw.startTime = Date.now()
    })

    app.addHook('onResponse', (request, reply) => {
      const { statusCode } = reply
      const responseTime = reply.raw.startTime ? Date.now() - reply.raw.startTime : 0

      // 実際には graphql と rest でログフォーマットを変えています
      if (statusCode >= 500) {
        console.error(`HTTP ${statusCode} - ${request.method} ${request.url} - ${responseTime}ms`)
      } else {
        console.log(`HTTP ${statusCode} - ${request.method} ${request.url} - ${responseTime}ms`)
      }
    })
  }
}

middleware を使う場合は、以下のように実装できます。

logger.middleware.ts

import { FastifyReply, FastifyRequest } from 'fastify'

export function logger(request: FastifyRequest['raw'], response: FastifyReply['raw'], next: () => void) {
  const start = Date.now()

  response.on('finish', () => {
    const responseTime = Date.now() - start
    const statusCode = response.statusCode
    if (statusCode >= 500) {
      console.error(`HTTP ${statusCode} - ${request.method} ${request.url} - ${responseTime}ms`)
    } else {
      console.log(`HTTP ${statusCode} - ${request.method} ${request.url} - ${responseTime}ms`)
    }
  })
  next()
}

✅ まとめ

• ロギングは通信の責務であり、interceptor（アプリケーション層）より hook や middleware が適している
• fastify 環境の middleware は hook の上で動く互換機能である
• middleware を使うか hookを使うかは、プロジェクトの要件やチームの選択による

NestJS x fastify でリクエストロギングを実装するなら、middlewareを 使うのが一見すると標準的に見えます。
しかし、その実装は内部的に fastify の hook により実現されています。

フレームワークの裏側の仕組みを少し知ることで、世界がより面白く感じますし、シンプルで本質的な実装を選択できるチャンスにもなると思います。

今回の知見が、皆さんのNestJSライフの助けとなれば幸いです。