Node.js 向けの構造化ログ

Monitoring a SaaS in Production では、チームが問題発生から数分以内に気づけるよう、メトリクスとアラートを接続しました。メトリクスはスパイクの存在を教えてくれますが、その理由を教えてくれることはほとんどありません。それがロギングの問題であり、ここで解決しようとしているものです。

これは Full Stack SaaS Masterclass の一部で、マルチテナント SaaS を空のフォルダーから本番環境まで実際に構築するシリーズです。Module 4 では、デモとチームが実際に運用できる製品を分ける運用上の懸念事項を扱います。ロギングはそのスタックの基盤に位置づけられます。インシデント対応、サポートチケット、監査証跡は、最終的に「ログに何が書かれているか」に行き着くからです。

ほとんどの Node.js アプリは console.log で始まり、必要以上に長く使い続けます。なぜなら、1 回に 1 リクエストずつ処理するラップトップ上では問題なく動作するからです。しかし、2 つのリクエストが同時に処理され、ログ行が共有ターミナル上で混在したり、カスタマーサポートのチケットで回答が必要なのに利用可能なツールが非構造化テキストの壁に対する grep しかなかったりすると、途端に機能しなくなります。構造化ロギングはこれを解決し、早期に導入するコストが低いため、後回しにする理由はほとんどありません。

プレーンテキストログが機能しなくなる理由

console.log の呼び出しは文字列を生成します。文字列はターミナルを眺める人間にとっては問題ありませんが、ログを大規模にクエリしようとするシステムにとっては積極的に敵対的です。ログが CloudWatch、Datadog、または任意のアグリゲーターに移動すると、下流のすべてのツールは実際に必要とするフィールド（リクエスト ID、ユーザー ID、ステータスコード、処理時間）を正規表現で文字列から抽出することになります。正規表現ベースのパースは脆弱です。ログメッセージの 1 語が変わるだけで、それに基づいて構築されたすべての保存済み検索とアラートが壊れます。

構造化ロギングはアプローチを逆転させます。後で誰かがパースできることを期待して文章を書くのではなく、最初から名前付きフィールドを持つ JSON オブジェクトを書くのです。

{
  "level": "error",
  "time": "2023-09-14T10:22:31.482Z",
  "requestId": "8f14e45f-ceea-467e-add1-a889b9f6bfaa",
  "organizationId": "org_9f2c1a",
  "userId": "usr_71b30d",
  "route": "POST /invoices",
  "statusCode": 500,
  "durationMs": 812,
  "msg": "Failed to create invoice: unique constraint violation"
}

Enter fullscreen mode Exit fullscreen mode

ここにあるすべてのフィールドはパースなしでクエリ可能です。「過去 1 時間に organization org_9f2c1a で発生したすべての 500 エラーを表示せよ」は正規表現ではなくフィルターです。この違いが価値提案のすべてであり、システムが成長するにつれて複雑化します。10 人目のエンジニアがインシデントをデバッグする際も、最初のエンジニアが設定した同じ構造化フィールドの恩恵を受けられます。

ロギングライブラリの選択と NestJS への接続

Node.js にはいくつかの優れた構造化ロギングライブラリがあります。NestJS バックエンドの妥当なデフォルトは pino です。コールごとのオーバーヘッドを最小限に抑えるよう設計されており（汎用的な JSON.stringify ではなく高速パスによる JSON シリアライズ）、nestjs-pino を通じて NestJS とクリーンに統合できます。

// main.ts
import { NestFactory } from '@nestjs/core';
import { Logger } from 'nestjs-pino';
import { AppModule } from './app.module';

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

Enter fullscreen mode Exit fullscreen mode

// logger.module.ts
import { Module } from '@nestjs/common';
import { LoggerModule } from 'nestjs-pino';

@Module({
  imports: [
    LoggerModule.forRoot({
      pinoHttp: {
        level: process.env.LOG_LEVEL ?? 'info',
        redact: ['req.headers.authorization', 'req.headers.cookie', '*.password', '*.token'],
        serializers: {
          req: (req) => ({ method: req.method, url: req.url }),
          res: (res) => ({ statusCode: res.statusCode }),
        },
        transport:
          process.env.NODE_ENV === 'development'
            ? { target: 'pino-pretty', options: { singleLine: true } }
            : undefined,
      },
    }),
  ],
})
export class AppLoggerModule {}

Enter fullscreen mode Exit fullscreen mode

この設定で明らかなこと以外に重要な点が 2 つあります。まず、redact は後回しではなく、ログ行と漏洩した認証情報の違いであり、セキュリティレビューで問題が指摘された後のフォローアップチケットではなく、初期設定に含めるべきです。次に、pino-pretty トランスポートは開発環境に限定されています。本番環境では生の JSON を stdout に出力する必要があります。ログアグリゲーターがそれを期待しているためで、先に pretty-print すると、誰も読まない CPU 作業が増えるだけです。

これを設定すれば、サービスにロガーを注入するのは簡単です。

import { Injectable } from '@nestjs/common';
import { InjectPinoLogger, PinoLogger } from 'nestjs-pino';

@Injectable()
export class InvoiceService {
  constructor(@InjectPinoLogger(InvoiceService.name) private readonly logger: PinoLogger) {}

  async createInvoice(organizationId: string, amount: number): Promise<void> {
    this.logger.info({ organizationId, amount }, 'Creating invoice');

    try {
      // ... invoice creation logic
    } catch (error) {
      this.logger.error({ organizationId, err: error }, 'Invoice creation failed');
      throw error;
    }
  }
}

Enter fullscreen mode Exit fullscreen mode

ここで重要なのは err フィールドです。pino のデフォルトのエラーシリアライザは Error オブジェクトをそのメッセージとスタックトレースに別々の JSON フィールドとして展開します。console.log(error) で得られる文字列補間とは異なります。これにより、個々のログ行を開くことなく、すべてのサービスで特定の例外タイプを検索できます。

すべてのログ行に相関 ID を通す

インシデント発生時、単一のログ行だけでは役に立ちません。実際に必要なのは、1 つのリクエストに属するすべてのログ行を、それが触れたすべてのサービスにわたって取得することです。構造化フィールドだけでは、それらの行がすべて共通の ID を共有していない限り実現できません。それが相関 ID（リクエスト ID またはトレース ID と呼ばれることが多い）の役割です。

すべての関数呼び出しにパラメータとして渡すことなく NestJS アプリを通じて伝播する最もクリーンな方法は、Node の AsyncLocalStorage です。これは各リクエストに独自の分離コンテキストを与え、await の境界を越えて存続します。

// request-context.ts
import { AsyncLocalStorage } from 'async_hooks';
import { randomUUID } from 'crypto';

interface RequestContext {
  requestId: string;
  organizationId?: string;
}

export const requestContext = new AsyncLocalStorage<RequestContext>();

export function getRequestId(): string {
  return requestContext.getStore()?.requestId ?? 'no-context';
}

Enter fullscreen mode Exit fullscreen mode

// request-context.middleware.ts
import { Injectable, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { randomUUID } from 'crypto';
import { requestContext } from './request-context';

@Injectable()
export class RequestContextMiddleware implements NestMiddleware {
  use(req: Request, res: Response, next: NextFunction): void {
    const requestId = (req.headers['x-request-id'] as string) ?? randomUUID();
    res.setHeader('x-request-id', requestId);

    requestContext.run({ requestId }, () => next());
  }
}

Enter fullscreen mode Exit fullscreen mode

そのリクエストのコールスタックのどこからでも（ID がジョブペイロードに転送されている場合、キュージョブ内も含む）、ロガー呼び出しは getRequestId() を取得して自動的にアタッチできます。pino 設定の mixin オプションに接続すれば、エンジニアが明示的に渡すことを覚えておく必要がなくなります。

LoggerModule.forRoot({
  pinoHttp: {
    mixin() {
      return { requestId: getRequestId() };
    },
  },
});

Enter fullscreen mode Exit fullscreen mode

これは構造化自体に次ぐ、ロギング設定への単一の最高レバレッジ追加です。これがなければ、「この 1 つの失敗したチェックアウトの間に起こったすべてのこと」を再構築するには、タイムスタンプを推測し、他に何も同時に起こっていなかったことを期待するしかありません。これがあれば、1 つのクエリで済みます。

トレードオフ：構造化ロギングのコスト

これらはすべて無料ではなく、明らかな勝利として扱う前に、正直にコストを検討する価値があります。

構造化ログはローカル開発中にターミナルで直接読むのがやや不便です。そのため、上記の pino-pretty トランスポートが存在し、ローカル作業を柔軟にしつつ、本番出力は生 JSON のままに保つことができます。シリアライズにはログ呼び出しごとに実際の（ただし小さい）CPU コストがあり、ホットパスがリクエストごとに 1 回ではなくループの反復ごとにログを記録する場合に問題になります。また、redaction 設定はメンテナンスが必要です。認証情報、パスワード、API キー、セッショントークンを運ぶ可能性のある新しいフィールドはすべて redact リストに追加する必要があり、初期設定が完了するとこのリストは忘れられがちです。

これらのコストは、初期プロトタイプ段階を過ぎたほぼすべての SaaS バックエンドにとってメリットが上回りますが、メンテナンスサーフェスがない純粋なアップグレードであるかのように装うのではなく、これらを明示する価値があります。

本番環境で計画すべき落とし穴

非構造化フィールドへの PII のログ記録。 構造化は、顧客のメールアドレスを自由形式の msg 文字列や、誰もレビューしていない properties オブジェクトに入れることを防ぎません。Redaction ルールは名前で知っているフィールドしかキャッチしません。ログ呼び出しに追加される新しいフィールドは、API レスポンスに適用するのと同じ scrutiny で扱ってください。

ログ量が支払い意欲を上回る。 構造化 JSON ログは簡潔なテキストメッセージよりも 1 行あたりのサイズが大きく、本番環境で debug レベルの冗長なログを残すと、さらに増幅されます。環境ごとに LOG_LEVEL を設定し、本番では info をデフォルトにし、debug は永続的な設定ではなく、意図的で時間制限のある調査のために予約してください。

グレースフルシャットダウン時のログ喪失。 トランスポートがバッファされたログ行のフラッシュを完了する前にプロセスが終了した場合、クラッシュの原因となる情報がまさにアグリゲーターから欠落します。特にログがボックス外に送信される前にバッチ処理される場合は、シャットダウンフックがロガーのフラッシュを待ってからプロセスを終了させるようにしてください。

HTTP 境界で停止する相関 ID。 API プロセス内でのみ存在するリクエスト ID は、エンキューする BullMQ ジョブ、サードパーティ API へのアウトバウンド HTTP 呼び出し、別のサービスに公開されるメッセージなど、すべての下流呼び出しに転送される場合よりもはるかに役に立ちません。すべての境界で意図的に転送してください。そうしないと、インシデントが通常興味深い場所でトレイルが途切れます。

主要なポイント

• 構造化ログは文章ではなく、名前付きフィールドを持つ JSON オブジェクトであり、アグリゲーターによるクエリを可能にし、脆弱な正規表現パースを不要にします。
• Pino は NestJS バックエンドの堅実なデフォルトです。高速な JSON シリアライズ、nestjs-pino を通じた一流の NestJS 統合、組み込みの redaction とエラーシリアライズを備えています。
• 認証情報とトークンの redaction ルールは、セキュリティレビュー後のフォローアップチケットではなく、初期設定に含めるべきです。
• AsyncLocalStorage を使用すると、リクエストスコープの相関 ID をすべてのログ行に自動的にアタッチでき、タイムスタンプを推測するのではなく、1 つのクエリでインシデントを再構築できる違いを生みます。
• 本番のログレベルはデフォルトで info に保ち、debug は意図的で時間制限のある調査のために予約してください。冗長なログはアグリゲーターに送信されると実際のコストが発生するためです。
• 相関 ID を HTTP 呼び出し、キュージョブ、Webhook などすべての境界で転送してください。そうしないと、インシデントのデバッグが困難になるまさにその場所でトレイルが途切れます。

FAQ

構造化ロギングとは何ですか？
構造化ロギングとは、自由形式のテキスト文章ではなく、名前付き・型付きフィールド（requestId、statusCode、organizationId など）を持つオブジェクトとしてログエントリを書くことを意味します。これにより、ログアグリゲーターとクエリツールは正規表現でメッセージ文字列をパースするのではなく、これらのフィールドを直接フィルタリング・検索できます。

Node.js バックエンドでは pino が winston より優れていますか？
どちらも有能な構造化ロギングライブラリです。Pino は一般的に JSON シリアライズが高速で、nestjs-pino を通じて NestJS に直接統合できるため、新しい NestJS プロジェクトの一般的なデフォルトとなっています。Winston はより長い実績とより大きなプラグインエコシステムを持っており、すでにサポートされている特定のトランスポートが必要な場合に重要になることがあります。

複数のサービスにまたがるリクエストのログを相関させるにはどうすればよいですか？
システムのエッジで相関 ID（リクエスト ID またはトレース ID と呼ばれることが多い）を生成または転送し、リクエストの期間中 AsyncLocalStorage コンテキストに保存し、キュージョブやアウトバウンド HTTP リクエストを含むすべての下流呼び出しに明示的に転送します。そのコンテキストから読み取るすべてのログ行は、同じ ID を自動的にアタッチできます。

ログラインに絶対に含めてはいけないものは何ですか？
パスワード、セッショントークン、API キー、認証ヘッダー、完全なクレジットカード情報は平文でログに記録すべきではありません。既知の機密フィールド名に対してロガーレベルで redaction ルールを設定し、ログ呼び出しに追加される新しいフィールドは、API レスポンスに適用するのと同じレビュー scrutiny で扱ってください。

本番環境で debug レベルでログを記録すべきですか？
一般的にすべきではありません。本番のログレベルはデフォルトで info にし、debug は意図的で時間制限のある調査のために予約してください。debug レベルのログは、ほとんどの場合対応するメリットなしにすべてのリクエストでボリュームとコストを増大させるためです。

構造化ロギングはメトリクスやトレーシングシステムの必要性を置き換えますか？
いいえ。メトリクスは何か問題があることを素早く知らせ、トレーシングはリクエストがサービスをどのように移動したかを示し、ログは特定のリクエストが失敗した具体的な理由を説明します。これらは補完的であり、ここで説明する相関 ID は、インシデント中にコンテキストを失うことなく 3 つすべてを移動できるようにするものです。

参考文献

• 前へ: Monitoring a SaaS in Production
• 次へ: Audit Logs You Can Trust
• シリーズの開始: Choosing the Right Tech Stack for Your SaaS

---

著者について

こんにちは、Aman Singh です。スケーラブルな SaaS 製品、分散システム、クラウドアーキテクチャ、AI を活用したアプリケーションを専門とするシニアフルスタックエンジニアです。

System Design、Full Stack Engineering、Distributed Systems、Redis、PostgreSQL、AWS、Node.js、NestJS について執筆しています。

• ポートフォリオ: https://amanksingh.com
• GitHub: https://github.com/amansingh1501
• プロダクト: https://vowerole.com
• メール: [email protected]