필사 모드: 構造化ロギングの設計 — 障害が起きたときに実際に役立つログを作る

• はじめに — 障害の真っ只中でログをgrepできないなら
• 人が読むログと機械が読むログは別物である
• すべてのログ行に必ず必要なフィールド
• ログレベルを実際に区別するたったひとつの基準
• 相関関係IDをサービス境界の向こうへ伝播させる
• カーディナリティとコスト — 何を入れてはいけないのか
• ログとメトリクスとトレース、何をいつ見るのか
• おわりに — ログは読むものではなく、絞り込むものである

はじめに — 障害の真っ只中でログをgrepできないなら

深夜にアラートを受け取ってログを開きます。サービスを三つ通るリクエストなのに、各サービスのログフォーマットが違います。片方はローカル時刻、片方はUTCです。リクエストを識別する共通のキーがないので、タイムスタンプが近い行を目で突き合わせてみます。そのうち「user 8812 checkout failed after 4102ms」という行を見つけますが、このユーザーが何人いるのかを数えるには正規表現を新しく書かなければなりません。

この状況の原因はログが足りないからではありません。むしろログは一日に数億行ずつ積み上がっています。問題は、そのログが人間が一行ずつ読むことを前提に設計されているという点にあります。事故対応で必要なのは読むことではなく、フィルタリングと集計です。

この記事はその前提を変える設計を扱います。

人が読むログと機械が読むログは別物である

ローカル開発環境のログは人が読みます。色があり、文章であり、順にスクロールすれば物語になります。プロダクションのログは機械が読みます。フィルタされ、集計され、結合されます。二つの要求をひとつのフォーマットで満たそうとする試みが、ほとんどのログを台無しにします。

正解は同じログを違う形で出力することです。プロダクションはJSON一行、ローカルはpretty形式でレンダリングします。そして決定的なルールがひとつあります。

// 悪い例: 値がメッセージ文字列の中に溶け込んでいる
logger.info(`user ${userId} checkout failed after ${ms}ms: ${err.message}`)
// -> 同じ事象を数えるには正規表現が必要で、err.message が変わると正規表現が壊れる

// 良い例: メッセージは定数、変わる値はすべてフィールド
logger.error(
  {
    event: 'checkout.failed',
    user_id: userId,
    order_id: orderId,
    duration_ms: ms,
    payment_provider: 'tosspay',
    err: { type: err.name, code: err.code, message: err.message },
  },
  'checkout failed'
)

メッセージ文字列は定数として維持します。そうしてはじめて同じ事象をひとつのキーで数えられます。変わる値がメッセージの中に入った瞬間、そのログは文章になり、集計対象から脱落します。

このルールひとつを守るだけで、次の問いに即答できるようになります。この失敗は何分前から始まったのか、特定の決済プロバイダに偏っているのか、特定のテナントにだけ発生しているのか。文章として残したログでは、すべて新しくパースし直さなければならない問いです。

eventフィールドは別に強調する価値があります。ドットで区切ったドメインイベント名を安定した識別子として置いておけば、ログバックエンドでそのままカウンターになります。メッセージのテキストは人のためのもので、eventは機械のためのものです。

すべてのログ行に必ず必要なフィールド

フィールドが多い必要はありません。なければ調査が止まるフィールドは決まっています。

タイムスタンプは別に触れておきます。必ずオフセットを含むRFC 3339形式で、できればUTCで残します。オフセットのないローカル時刻は次のようなことを引き起こします。

# paymentサービスはオフセットなしのKST、checkoutサービスはUTCで残していた
grep 'payment accepted' payment.log | tail -1
# 2026-07-26T13:02:11.004 payment accepted order_id=A-99183

grep 'checkout completed' checkout.log | tail -1
# 2026-07-26T04:02:11.118Z checkout completed order_id=A-99183

# 同じ事象なのに9時間ずれて見える。二つのログを一画面で並べる方法がない。

pinoを例に取ると、基本設定でこう押さえます。

import pino from 'pino'

export const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  timestamp: pino.stdTimeFunctions.isoTime, // オフセットを含むISO 8601
  formatters: {
    level: (label) => ({ level: label }), // 30 ではなく "info" で残す
  },
  base: {
    'service.name': process.env.OTEL_SERVICE_NAME,
    'service.version': process.env.SERVICE_VERSION,
    'deployment.environment': process.env.APP_ENV,
  },
})

baseに入れた値はすべての行に自動で付きます。リソースレベルのフィールドは個別の呼び出し部で繰り返しません。繰り返した瞬間、抜け落ちる場所が生まれます。

ログレベルを実際に区別するたったひとつの基準

レベルの定義はどの文書にもありますが、チームごとに実際の使い方はばらばらです。判断基準をひとつに固定すれば議論は終わります。

基準はこれです。ERRORは我々のシステムが自分の責任を果たせなかったという意味です。ユーザーが間違えたか、想定された失敗か、リトライで復旧したなら、それはERRORではありません。

• ERROR: 我々側の欠陥でリクエストを処理できませんでした。積み上がればページにつながるべきです。例: 依存サービスのタイムアウト後にリトライを使い切った、デシリアライズ失敗、コネクションプール枯渇。
• WARN: 処理はできましたが劣化しています。今すぐ手を打つ必要はありませんが、傾向は見るべきです。例: リトライ後の成功、フォールバック応答の使用、キャッシュミス率の急上昇、まもなく期限切れになる証明書。
• INFO: 状態が変わった事象です。あとで再現するときに必要な事実だけを残します。例: 注文作成、デプロイ完了、設定リロード。
• DEBUG: 開発者のための叙述です。プロダクションの既定値はoffで、特定のリクエストや特定のテナントに限って動的にオンにできる必要があります。

ここでもっとも多く間違えるのが400番台の応答です。不正なリクエストボディ、期限切れのトークン、権限なしは、我々のシステムが正常に動作した結果です。これらをERRORで打った瞬間、ERRORログの大半が正常なトラフィックで埋まり、本当の欠陥がその中に埋もれます。クライアントエラーはINFOかWARNで残し、比率が急上昇することはメトリクスで監視します。

// エラーハンドラ: 責任の所在でレベルを分ける
app.use((err, req, res, next) => {
  const status = err.status ?? 500
  const fields = {
    event: 'http.request.failed',
    http_status: status,
    route: req.route?.path,
    err: { type: err.name, code: err.code, message: err.message },
  }

  if (status >= 500) {
    req.log.error(fields, 'request failed') // 我々の責任
  } else if (status === 429) {
    req.log.warn(fields, 'request throttled') // 劣化
  } else {
    req.log.info(fields, 'request rejected') // クライアントの責任
  }

  res.status(status).json({ error: err.publicMessage ?? 'request failed' })
})

レベルの方針が定着したかはひとつの指標で確認します。ERRORログが出るたびに誰かが確認してみる価値があるか。そうでないなら、そのログはERRORではありません。

相関関係IDをサービス境界の向こうへ伝播させる

ひとつのサービスの中でしか有効でないリクエストIDは半人前です。価値が出る地点は、サービス境界を越えるときです。

標準はW3C Trace Contextで、ヘッダーはtraceparentです。形式は四つの部分に固定されています。

curl -sD - -o /dev/null https://checkout.internal/v1/orders \
  -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' \
  -H 'tracestate: acme=t61rcWkgMzE'

# 00                                 バージョン
# 4bf92f3577b34da6a3ce929d0e0e4736   トレースID (16バイト、リクエスト全体で同一)
# 00f067aa0ba902b7                   親スパンID (8バイト、呼び出し段階ごとに変わる)
# 01                                 フラグ (最後のビットが1ならサンプリングされた)

最後のフラグに注目してください。01ならこのトレースは保存されます。00なら捨てられます。ログにこの値を一緒に残しておけば、あとで「トレースのリンクを押したのに何もない」という状況の原因がすぐに分かります。

アプリケーションでは、ロガーが自動でトレースコンテキストを付けるようにするのが肝心です。呼び出し部で毎回渡させると必ず漏れます。

import { context, trace } from '@opentelemetry/api'
import { AsyncLocalStorage } from 'node:async_hooks'

const requestStore = new AsyncLocalStorage()

// リクエストの入口で一度だけコンテキストを植える
export function requestContext(req, res, next) {
  const requestId = req.headers['x-request-id'] ?? crypto.randomUUID()
  res.setHeader('x-request-id', requestId)
  requestStore.run({ requestId, tenantId: req.auth?.tenantId }, () => next())
}

// すべてのログ呼び出しが通る薄いラッパー
export function ctx(fields = {}) {
  const store = requestStore.getStore() ?? {}
  const span = trace.getSpan(context.active())
  const sc = span?.spanContext()
  return {
    ...fields,
    request_id: store.requestId,
    tenant_id: store.tenantId,
    trace_id: sc?.traceId,
    span_id: sc?.spanId,
    trace_sampled: sc ? Boolean(sc.traceFlags & 1) : undefined,
  }
}

logger.error(ctx({ event: 'checkout.failed', order_id: orderId }), 'checkout failed')

伝播が実際に壊れる地点は三か所です。第一に、独自のHTTPクライアントを使うコード経路 — 自動計装が包めなければヘッダーは付きません。第二に、メッセージキュー — ヘッダーに直接注入しなければ、プロデューサーとコンシューマーのトレースが切れます。第三に、バッチ処理とcron — 入口で新しいトレースを開始しなければ、ログのtrace_idがまるごと空になります。

カーディナリティとコスト — 何を入れてはいけないのか

ログは無料ではありません。まず計算からしてみます。

# 一行あたり平均1.2KB、毎秒4,000行
python3 -c "print(f'{1.2*1024*4000*86400/1e9:.1f} GB/day')"
# 424.7 GB/day

# 30日保管、インデックス込みの単価をGBあたり2.5通貨単位と仮定すると
python3 -c "print(f'{424.7*30*2.5:,.0f} per month')"
# 31,853 per month

ここで削る対象は行数ではなく、一行あたりのサイズとインデックス対象のフィールドです。次のものはログに入れません。

• 個人情報: メールアドレス全体、電話番号、住所、生年月日、国民識別番号。必要な場合はハッシュや内部IDに置き換えます。
• シークレット: Authorizationヘッダー、クッキー、APIキー、カード番号、リフレッシュトークン。これらの値は一度ログに入ると、バックアップとインデックスとコールドストレージに同時に複製されます。
• 大容量ペイロード: リクエストとレスポンスのボディ全体、スタックトレースの繰り返し出力、シリアライズされたオブジェクトのダンプ。ボディはサイズとハッシュだけを残し、必要なら別のストレージに短いTTLで置きます。
• 意味のない一意値: ログバックエンドがインデックスするフィールドにUUIDを無制限に入れると、インデックスがデータより大きくなります。インデックスするフィールドと保存するだけのフィールドを区別します。

マスキングはアプリケーションの中で処理するのが原則です。収集パイプラインで消す方式は、すでにプロセスの外に出たあとなので漏洩経路が増えます。

export const logger = pino({
  redact: {
    paths: [
      'req.headers.authorization',
      'req.headers.cookie',
      'req.headers["x-api-key"]',
      'req.body.password',
      'req.body.card_number',
      '*.email',
      '*.phone',
      'user.ssn',
    ],
    censor: '[REDACTED]',
  },
})

サンプリングはボリュームを削る最後の手段ですが、やり方が重要です。よくある助言の「INFOログの10%だけ残す」を行単位のランダムで実装すると最悪の結果になります。ひとつのリクエストのログが断片的に残り、どのリクエストも完全な物語を持ちません。

サンプリングは行ではなくリクエスト単位で決めます。trace_idをハッシュして判定すれば、同じリクエストのすべてのログが一緒に残るか一緒に捨てられます。

const KEEP_RATIO = 0.05

// trace_id で決定的に判定 — ひとつのリクエストのログは全部残るか全部落ちる
function keepLowSeverity(traceId) {
  if (!traceId) return true
  const bucket = parseInt(traceId.slice(-4), 16) / 0xffff
  return bucket < KEEP_RATIO
}

export function emit(level, fields, msg) {
  const enriched = ctx(fields)
  const alwaysKeep = level === 'error' || level === 'warn' || enriched.trace_sampled
  if (!alwaysKeep && !keepLowSeverity(enriched.trace_id)) return
  logger[level](enriched, msg)
}

ERRORとWARNは絶対にサンプリングしません。そしてトレースがサンプリングされたリクエストのログは一緒に残します。そうしてはじめて、トレースからログに移ったときに空の画面を見ずに済みます。

ログとメトリクスとトレース、何をいつ見るのか

三つの信号は代替品ではなく調査の順序です。三つとも有効にしているのに調査が遅いチームは、たいてい順序がありません。

• メトリクスが先です。いつから何がおかしくなったのか、影響範囲はどれくらいかに答えます。安くて常時オンでカーディナリティが低いため、アラートの根拠になれる唯一の信号です。
• 次がトレースです。遅くなったリクエストをひとつ開いて、どのサービスのどの区間で時間が消えたのかに答えます。メトリクスが教えてくれた時間帯とルートで範囲を絞ってから入ります。
• ログが最後です。そのスパンの中で正確に何が起きたのか、どんな値が入ってきてどの分岐を通ったのかに答えます。trace_idでフィルタして入れば、読むべき行は数十行にまで減ります。

この順序が機能するには信号どうしのつなぎが必要です。メトリクスからトレースへの橋はエグゼンプラーです。ヒストグラムの観測にtrace_idを付けておけば、グラフの跳ねた点をクリックしてそのトレースをすぐ開けます。

# エグゼンプラーが付いていれば、このグラフの点からそのままトレースへ移動できる
histogram_quantile(
  0.99,
  sum by (le, route) (rate(http_request_duration_seconds_bucket{job="checkout-api"}[5m]))
)

トレースからログへの橋は、先ほど作ったtrace_idフィールドです。ログからメトリクスへの橋はeventフィールドです。三つの橋が全部架かっていれば、調査時間は数十分単位から数分単位に下がります。どれかひとつでも欠けると、その地点からまた目での突き合わせが始まります。

おわりに — ログは読むものではなく、絞り込むものである

覚えておくべきことは一文です。プロダクションログの目的は読まれることではなく、絞り込まれることです。

その目的からすべてのルールが導かれます。メッセージは定数にして値はフィールドに出します。すべての行にtrace_idとservice.nameとオフセットを含むタイムスタンプを入れます。ERRORは我々の責任のときだけ使います。機微な値はプロセスを離れる前に消します。サンプリングはリクエスト単位で行います。

今すぐひとつだけ直すなら、メッセージ文字列から変数を抜き出すことから始めてください。この変更ひとつが、正規表現でしか答えられなかった問いを即座に集計可能な問いへ変えます。

さらに掘り下げるための資料です。

• W3C Trace Context 仕様
• OpenTelemetry: Logs データモデル
• OpenTelemetry Semantic Conventions
• Google SRE Workbook: Alerting on SLOs