Node.jsミドルウェアによるリクエストのログ記録

深夜2時にAPIで障害が発生したとき、最初に手を伸ばすのはログです。ログが欠落していたり、不完全だったり、ノイズに埋もれていたりすると、デバッグは当て推量になってしまいます。Node.jsにおけるHTTPリクエストのログ記録は、間違えやすく、無視すると高くつく基本事項の一つです。

この記事では、Expressにおけるリクエストログミドルウェアの仕組み、MorganやPinoといった確立されたライブラリをいつ使用すべきか、そして本番環境に対応したログ記録が実際にどのようなものかについて説明します。

Expressリクエストライフサイクルにおけるログミドルウェアの位置づけ

Expressでは、ミドルウェアは(req, res, next)というシグネチャを持つ関数です。ルートハンドラに到達する前に、すべてのリクエストをインターセプトします。ログミドルウェアはそのチェーンの最上部に位置し、入ってきたものと出ていったものを記録します。

[クライアント] → [ログミドルウェア] → [認証ミドルウェア] → [ルートハンドラ] → [レスポンス]

重要な洞察:レスポンス全体(ステータスコード、処理時間)をログに記録できるのは、レスポンスが完了してからです。そのため、ログミドルウェアは即座にログを記録するのではなく、resのfinishイベントをリッスンします。

import crypto from 'node:crypto'

// リクエストログ記録用のExpressミドルウェア
const logRequests = (req, res, next) => {
  const start = Date.now()

  res.on('finish', () => {
    logger.info({
      method: req.method,
      url: req.url,
      status: res.statusCode,
      duration: Date.now() - start,
      requestId: req.headers['x-request-id'] ?? crypto.randomUUID(),
    })
  })

  next()
}

app.use(logRequests)

crypto.randomUUID()を使用するには、node:cryptoモジュールをインポートする必要があります(またはNode.js 19以降で利用可能なグローバルcryptoを使用)。また、ここでのloggerオブジェクトはプレースホルダーです。実際のログライブラリインスタンス(PinoやConsoleなど)に置き換えてください。

このパターンは、Expressだけでなく、あらゆるNode.js HTTPサーバーで機能します。

Morganによる従来のアクセスログ記録

Morganは、古典的なExpressリクエストログミドルウェアです。2行のコードでApache形式のアクセスログが得られます:

import morgan from 'morgan'

app.use(morgan('combined'))
// 出力例:
// ::1 - - [01/Jan/2025:00:00:00 +0000] "GET /api/users HTTP/1.1" 200 1234

Morganは開発やシンプルなデプロイメントには問題ありません。出力は人間が読みやすいですが、機械的に解析しやすいものではありません。これは、Datadog、Loki、またはあらゆる構造化ログシステムにログを送信する際に問題となります。

Pinoによる構造化ログ記録

本番環境では、構造化ログ記録はJSONを出力することを意味します。すべてのログ行がクエリ可能なレコードになります。Pinoはここでの標準的な選択肢で、WinstonやBunyanよりも大幅に高速で、オーバーヘッドが最小限です。

pino-httpパッケージは、Expressミドルウェアとして簡単に組み込めます:

import express from 'express'
import pinoHttp from 'pino-http'

const app = express()

app.use(pinoHttp({
  level: process.env.LOG_LEVEL ?? 'info',
  redact: ['req.headers.authorization', 'req.headers.cookie'],
}))

app.get('/', (req, res) => {
  req.log.info('handling root request')
  res.send('ok')
})

Pinoはstdoutに書き込みます。インフラストラクチャ(Docker、systemd、ログシッパー)が、それらの行を必要な場所にルーティングします。

相関IDとリクエストコンテキスト

複数の非同期操作にわたってリクエストをトレースする場合、すべてのログ行に一貫したリクエストIDを付ける必要があります。最新のNode.jsでは、この目的のためにAsyncLocalStorageを使用してください。非推奨のdomainモジュールや低レベルの非同期フックは使用しないでください。

import { AsyncLocalStorage } from 'node:async_hooks'
import crypto from 'node:crypto'

export const requestContext = new AsyncLocalStorage()

app.use((req, res, next) => {
  const requestId = req.headers['x-request-id'] ?? crypto.randomUUID()
  requestContext.run({ requestId }, next)
})

そのリクエストの非同期コンテキスト内のログ呼び出しは、すべての関数に手動で渡すことなく、requestIdを取得できるようになります。以下は取得方法です:

// 任意の下流モジュール内で
import { requestContext } from './context.js'

function doWork() {
  const { requestId } = requestContext.getStore()
  logger.info({ requestId, msg: 'doing work' })
}

責任あるログ記録

本番環境で重要ないくつかのルール:

• Authorizationヘッダー、Cookie、APIトークンは絶対にログに記録しないでください。 Pinoのredactオプションを使用するか、書き込み前に手動でサニタイズしてください。
• プロキシ背後のクライアントIPには注意してください。 req.socket.remoteAddressはプロキシのIPを返します。アプリがリバースプロキシの背後にある場合は、Expressのtrust proxy設定を正しく構成し、X-Forwarded-Forヘッダーを慎重に扱ってください。
• リクエストボディをデフォルトでログに記録しないでください。 サイズが大きかったり、バイナリだったり、個人情報が含まれている可能性があります。サイズ制限を設けて選択的にログに記録してください。

MorganとPinoの選択

読みやすい出力を好む場合は、ローカル開発にMorganを使用してください。本番環境に出荷するものには、Pinoを使用してください。

まとめ

優れたログミドルウェアは、必要になるまで目に見えません。しかし、必要になったときにはすべてです。pino-httpから始めて、構造化されたJSONをstdoutに出力し、インフラストラクチャにルーティングとストレージを処理させてください。AsyncLocalStorageを介して相関IDと組み合わせることで、あらゆるリクエストをエンドツーエンドでトレースできます。初日から機密データをログから除外すれば、アプリケーションとともにスケールする可観測性の基盤が得られます。

よくある質問

同じExpressアプリケーションでMorganとPinoを一緒に使用できますか?

はい、両方を並行して実行できます。一般的なパターンは、開発環境では読みやすいコンソール出力のためにMorganを使用し、本番環境では構造化されたJSONログのためにPinoを使用することです。環境変数を使用してどちらか一方を条件付きで適用することで、単一環境内での重複ログエントリを回避できます。

PinoログをDatadogやElasticsearchなどの外部サービスに送信するにはどうすればよいですか?

Pinoは設計上、JSONをstdoutに書き込みます。Fluent Bit、Filebeat、またはDatadog Agentなどのログシッパーを使用して、コンテナまたはプロセスからstdout出力を収集し、ログプラットフォームに転送してください。これにより、アプリケーションコードを特定のログ送信先から切り離すことができます。

関数引数を通じてリクエストIDを渡す代わりに、AsyncLocalStorageを使用すべき理由は何ですか?

AsyncLocalStorageは、関数シグネチャを変更することなく、非同期呼び出しチェーン全体でコンテキストを自動的に伝播させます。すべての関数に手動でリクエストIDを渡すのはエラーが発生しやすく、コードが煩雑になります。AsyncLocalStorageはNode.js 16以降で安定しており、リクエストスコープのコンテキストに推奨されるアプローチです。

ログミドルウェアはAPIレスポンスに顕著なレイテンシを追加しますか?

Pinoを使用すると、高速なシリアライゼーションを使用し、stdoutに効率的にログを書き込むため、オーバーヘッドは通常無視できる程度です。Morganもほとんどのワークロードで軽量です。`finish`イベントリスナーパターンは、レスポンスがオペレーティングシステムに引き渡された後にログ記録が実行されることを意味するため、通常クライアントのレイテンシには影響しません。ログパスでの同期ファイル書き込みや重いシリアライゼーションは避けてください。