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と組み合わせることで、あらゆるリクエストをエンドツーエンドでトレースできます。初日から機密データをログから除外すれば、アプリケーションとともにスケールする可観測性の基盤が得られます。

よくある質問

Gain Debugging Superpowers

Unleash the power of session replay to reproduce bugs, track slowdowns and uncover frustrations in your app. Get complete visibility into your frontend with OpenReplay — the most advanced open-source session replay tool for developers. Check our GitHub repo and join the thousands of developers in our community.