Fastify ベストプラクティス #6: グローバルログ出力

どのサーバーサイドアプリケーションにおいても、ロギングは極めて重要な役割を果たします。それはバグをデバッグするための重要な手がかりであるだけでなく、システムの状態を監視し、ユーザーの行動を分析するための基盤でもあります。理想的なロギングシステムは、以下の条件を満たすべきです：

1. 追跡可能性：各ログエントリは、それが属する元のリクエストに関連付けられるべきです。
2. 豊富な情報：ログの内容には、リクエストされたAPI名やユーザー情報など、十分なコンテキストが含まれるべきです。
3. 使いやすさ：プロジェクトのどの場所からでも、シンプルで統一された方法でログを記録できるべきです。

Fastifyのデフォルトのロギング機能はすでに非常に強力ですが、いくつかのベストプラクティスを適用することで、真にエンタープライズレベルのロギングシステムを構築することができます。この記事では、その目標を達成するための一歩一歩を解説します。

ステップ1：一意なリクエスト追跡IDのカスタマイズ

膨大なログの中から特定のリクエストの全プロセスを正確に特定するためには、一意の追跡ID（トレースIDまたはリクエストID）が必要です。Fastifyでは genReqId オプションを使用して、IDの生成ルールをカスタマイズすることが可能です。

デフォルトのID（例：req-1, req-2）は、現在のプロセスのライフサイクル内でのみ一意であり、サービスが再起動されたり、複数インスタンスでデプロイされたりすると重複します。より堅牢な一意の文字列を使用することが望ましいです。

// main.ts
import fastify from 'fastify';

const server = fastify({
  // リクエスト受信時にこの関数を呼び出してリクエストIDを生成
  genReqId(_req) {
    // ランダムな文字列を使用し、高い一意性を確保
    return Math.random().toString(36).substring(2, 12);
  },
  // ... その他の設定
});

これで、request.log を介して出力される各ログエントリには、{"level":30,"time":167... ,"pid":...,"hostname":"...","reqId":"a1b2c3d4e5",...} のような reqId フィールドが自動的に含まれるようになります。

ステップ2：ログにより多くのコンテキスト（API名など）を注入する

reqId があれば、リクエストを追跡できます。しかし、ログで直接「これは’ユーザー情報取得’APIから生成されたログだ」と分かれば、問題の調査がより効率的になります。

これを実現するために、Fastifyのフック（Hook）とルート定義（Route Schema）を利用できます。Fastify ベストプラクティス #5：Swaggerドキュメント生成では、各APIにインターフェースの目的を記述するための summary フィールドを設定しました。これをログのコンテキストとして活用できます。

各リクエストがルートハンドラに入る前に実行される onRequest フックを作成します。

// hooks/request.hook.ts
import { FastifyPluginAsync } from 'fastify';
import fp from 'fastify-plugin';

const requestHook: FastifyPluginAsync = fp(async (fastify) => {
  fastify.addHook('onRequest', (request, _reply, done) => {
    // 1. ルート定義からAPIのsummaryを取得
    const summary = request.routeOptions.schema?.summary || '';

    // 2. 現在のリクエストのloggerを基に子loggerを作成し、追加情報を付与
    const childLogger = request.log.child({ api: summary });

    // 3. 新しく作成した子loggerを現在のリクエストに上書き
    request.log = childLogger;

    done();
  });
});

export default requestHook;

このステップにより、request.log.info('...') を使用して出力されるログには、自動的に reqId と api フィールドが含まれるようになります。

ステップ3：中心的な課題と究極の解決策 AsyncLocalStorage

現状でもかなり良い状態ですが、まだ一つのペインポイントがあります：ログメソッド（request.log.info(...)）を呼び出すためには、request オブジェクトが必要であるという点です。

これは、深くネストされたService関数や独立したユーティリティ関数でログを記録したい場合、request オブジェクトまたは request.log を延々と引き回す必要があることを意味します。これは非常に煩雑であるだけでなく、コードの清潔さとカプセル化を著しく損ないます。

私たちが目指す理想的な状態は次のとおりです：どこからでもグローバルな logger をインポートし、logger.info() を直接呼び出すだけで、それが現在処理中のリクエストのコンテキストに自動的に関連付けられること。

これは魔法のように聞こえるかもしれませんが、この魔法を実現するツールが、Node.js v13.10+ に組み込まれている async_hooks モジュールの AsyncLocalStorage です。

解説：AsyncLocalStorage とは何か？

AsyncLocalStorage は、「リクエスト専用の透明なバックパック」のようなものだと想像してください。

1. バックパックの作成：まず、アプリケーション内で AsyncLocalStorage のグローバルインスタンスを一つ作成します。これはバックパックをデザインするようなものです。
2. バックパックの配布：HTTPリクエストが来ると、als.run(store, callback) を呼び出します。このアクションは、現在のリクエストの後続の操作チェーン全体（すべての await, .then(), コールバック関数など）に新しいバックパックを「背負わせる」ことになります。store はバックパックに入れたいもので、ここでは reqId と api を含む logger インスタンスがそれに当たります。
3. いつでも取り出し：このリクエストの処理中、コードがどれだけ深く実行されても、それが最初のリクエストからトリガーされた非同期チェーンの一部である限り、als.getStore() を使っていつでもこのリクエスト専用のバックパックを取得し、中身を取り出すことができます。
4. リクエストの分離：異なるリクエストは異なるバックパックを持ち、それらの間のデータは完全に隔離されています。リクエストAがリクエストBのバックパックの中身を取得することは決してありません。これは、並行リクエストを処理する上で極めて重要です。

簡単に言うと、AsyncLocalStorage はNode.jsの非同期操作に対して「スレッドローカルストレージ（Thread-Local Storage）」のようなメカニズムを提供し、非同期フローでコンテキストデータを安全に渡すという長年の課題を完璧に解決します。

ステップ4：AsyncLocalStorageを統合し、グローバルロガーを構築する

それでは、AsyncLocalStorage を使って私たちのロギングシステムを改造しましょう。

1. AsyncLocalStorage ユーティリティの作成

// utils/als.util.ts
import { AsyncLocalStorage } from 'async_hooks';
import { FastifyBaseLogger } from 'fastify';

// 「バックパック」に保存するデータ構造を定義
export type IAsyncStore = {
  logger: FastifyBaseLogger;
};

// グローバルで一意な AsyncLocalStorage インスタンスを作成
const asyncStore = new AsyncLocalStorage<IAsyncStore>();

// logger を安全に取得するための関数を提供
const getLogger = (): FastifyBaseLogger => {
  const store = asyncStore.getStore();
  // getStore() が undefined を返した場合、現在の実行コンテキストが als.run() の中にないことを意味します。
  // これは通常、サービス起動時などに業務ロジックのログを呼び出すといった論理エラーを示唆します。
  if (!store) {
    throw new Error('Logger could not be found in the current async context.');
  }
  return store.logger;
};

export const ALS = {
  asyncStore,
  getLogger,
};

2. onRequest フックの改造

以前のフックを修正し、als.run でリクエストのライフサイクル全体をラップします。

// hooks/request.hook.ts
import { ALS } from '@/utils/als.util';
import { FastifyPluginAsync } from 'fastify';
import fp from 'fastify-plugin';

const requestHook: FastifyPluginAsync = fp(async (fastify) => {
  fastify.addHook('onRequest', (request, _reply, done) => {
    const summary = request.routeOptions.schema?.summary || '';
    const childLogger = request.log.child({ api: summary });
    request.log = childLogger;

    // 重要：後続のすべての操作を run メソッドでラップする
    // コンテキストを含む logger インスタンスを store に保存する
    ALS.asyncStore.run({ logger: childLogger }, () => {
      // run のコールバック関数が実行完了すると、コンテキストは自動的に破棄される
      done();
    });
  });
});

export default requestHook;

3. グローバル logger ユーティリティの作成

これが最後の、そして最も巧妙なステップです。プロジェクト内のどのファイルからでもインポートできる logger オブジェクトを作成します。

// utils/logger.util.ts
import { ALS } from './als.util';
import { FastifyBaseLogger } from 'fastify';

// 必要なログレベルのメソッドのみを公開する
export const logger: Pick<FastifyBaseLogger, 'info' | 'error' | 'warn' | 'debug'> = {
  // ここではgetterの使用が重要です！
  // これにより、ALS.getLogger() はモジュールが初めてロードされた時ではなく、
  // logger.info() が実際に呼び出された瞬間に実行されることが保証されます。
  get info() {
    const log = ALS.getLogger();
    return log.info.bind(log);
  },
  get error() {
    const log = ALS.getLogger();
    return log.error.bind(log);
  },
  get warn() {
    const log = ALS.getLogger();
    return log.warn.bind(log);
  },
  get debug() {
    const log = ALS.getLogger();
    return log.debug.bind(log);
  },
};

最終的な効果：いつでもどこでも、手軽にロギング

これで、ControllerやService、その他のどのモジュールであっても、ログを記録したいときの使い方は非常にシンプルになります：

// services/user.service.ts
import { logger } from '@/utils/logger.util';

export class UserService {
  async findUser(userId: string) {
    logger.info({ userId }, 'Starting to find user...'); // このログには自動的にreqIdとapiが付与されます

    // ... ビジネスロジック ...
    if (!user) {
      logger.warn({ userId }, 'User not found.'); // このログも同様です
      return null;
    }

    logger.info({ userId, username: user.name }, 'User found successfully.');
    return user;
  }
}

もはや request オブジェクトがどこにあるかを気にする必要はありません。グローバルな logger をインポートするだけで、それは自動的に「透明なバックパック」(AsyncLocalStorage) から現在のリクエストに対応する logger インスタンスを見つけ出し、あなたのログ情報をすべてのコンテキストと共に出力します。

まとめ

以下の4つのステップを通じて、私たちは強力でエレガント、そして保守しやすいFastifyロギングシステムを構築しました：

1. genReqId: ログの追跡可能性を確保。
2. onRequest Hook: ログコンテキストを動的に拡充。
3. AsyncLocalStorage: 非同期フローにおけるコンテキスト伝搬という長年の課題を解決。
4. グローバル Logger ユーティリティ: 究極にシンプルな開発者体験を提供。

このアプローチはロギングだけでなく、ユーザー情報やテナントIDなど、リクエストのライフサイクルに紐づくあらゆるデータの管理にも応用でき、現代のNode.jsバックエンドアーキテクチャにおける必須ツールです。