241行のログのうち239行が同じ警告だった|構造化とリクエストID

241行のログのうち239行が同じ警告だった|構造化とリクエストID

手元の開発環境のPHPエラーログを開いてみました。5か月分で241行。そのうち239行が、まったく同じ1つの警告でした。

$ wc -l error.log
241

$ sed -E 's/^\[[^]]+\] //' error.log | sort | uniq -c | sort -rn | head -3
 239 PHP Warning: PHP Startup: Unable to load dynamic library 'php_imagick.dll'
   1 PHP Warning: rename(...\ja-XXXX.tmp, ...\wordpress-6.9.1-ja.zip): アクセスが拒否されました。
   1 PHP Warning: unlink(...\wordpress-6.9.1-ja.zip): Resource temporarily unavailable

本当に見たかったのは下の2行です。WordPressの自動更新が権限エラーで失敗していた記録で、これは実際に対処が必要な事象でした。それが、環境構築のときから毎回出ているだけの警告239行に埋もれていました。

ログ設計の話は「何を出すか」から始まりがちですが、実際に困るのは出したものを後から取り出せるかのほうです。この記事は、そこを中心にまとめます。

目次

ノイズはログを死なせる

239行の警告は、一度も対処されないまま5か月出続けていました。誰も困らなかったからです。しかしこの状態が続くと、ログを見る習慣そのものが失われます。「どうせ同じ警告だろう」と思うようになるからです。

対処は2つに1つです。

  • 直す
    この場合は拡張を入れるか、読み込み設定から外す
  • 黙らせる
    対処しないと決めたなら、出力しない

「とりあえず出しておく」がいちばん良くありません。ログに残っているのに誰も見ていない状態は、記録がないのとほぼ同じで、それでいてディスクと検索時間だけを消費します。

テキストログでは答えられない質問がある

同じ内容を2つの形式で出したログを用意して、実際に質問を投げてみます。206行ずつです。

# テキスト形式
[2026-09-09T03:00:00.000Z] INFO handled /api/orders in 163ms
[2026-09-09T03:00:00.000Z] ERROR failed to charge card

# 構造化(JSON Lines)形式
{"ts":"2026-09-09T03:00:00.000Z","level":"info","msg":"request handled",
 "request_id":"f233c65d","user_id":101,"path":"/api/orders","duration_ms":163,"status":500}
{"ts":"2026-09-09T03:00:00.000Z","level":"error","msg":"failed to charge card",
 "request_id":"f233c65d","user_id":101,"path":"/api/orders","error_code":"card_declined","attempt":1}
机の上に少しずれて積み上がった同じ紙の束が、自重で傾いている写真
同じものが並んでいるとき、量は情報ではない

「エラーは何件で、どのユーザーに起きたか」

# テキスト: 件数までは分かる
$ grep -c ERROR app.log
6
$ grep ERROR app.log | head -2
[2026-09-09T03:00:00.000Z] ERROR failed to charge card
[2026-09-09T03:00:37.000Z] ERROR failed to charge card
   → 誰に起きたかは書かれていない。ここで詰まる
# 構造化: そのまま集計できる
件数: 6
ユーザー別: { '101': 2, '102': 2, '103': 2 }
エラーコード別: { card_declined: 6 }

テキストログのほうは、「特定のユーザーに偏っているのか、全体に起きているのか」が判断できません。この違いは対応方針を変えます。1人だけなら個別対応、全体ならシステム側の問題です。

「遅かったリクエストの上位3件」

# 構造化: 並べ替えるだけ
305ms  /api/users/me   request_id=9af1b4a7
304ms  /api/orders     request_id=44da6126
304ms  /api/orders     request_id=5bda3ba9

テキストログでも in 163ms という文字列から正規表現で数値を抜き出せば不可能ではありません。ただ、その正規表現を書いている時点で、それは「ログの形式を後からパースする作業」です。出す側で構造化しておけば要りません。

ログのメッセージ文言を変えると壊れる、という点も重要です。テキストログの文面は、いつのまにか誰かの解析スクリプトの入力仕様になっています。

リクエストIDで1本につなぐ

構造化ログのいちばんの価値は、集計よりも追跡のほうにあると思います。

# エラーが起きたリクエストの全ログを見る
request_id = f233c65d
  info  request handled (status 500)
  error failed to charge card
API受付・アプリ・ジョブ投入・ワーカーの4段階のログに同じrequest_idが出力され、1つのIDで全体を追える様子を示した図
サービスをまたいでも同じIDを持ち回すのがポイント

入口で1つIDを振り、そのリクエストから派生する処理すべてに持ち回します。ジョブキューに積むときはメッセージにIDを入れ、ワーカー側でも同じIDでログを出します。

これがないと、非同期処理のデバッグは非常につらくなります。「ワーカーでエラーが出ている」までは分かっても、それがどのリクエスト由来なのかを突き合わせる手段がありません。時刻で推測することになりますが、同時実行されていれば当たりません。

実装上のポイントは「毎回引数で渡さなくていい仕組みにする」ことです。関数の引数に requestId を足していく方式は、必ずどこかで渡し忘れます。言語ごとに、実行コンテキストに紐づけて自動的にログへ付与する仕組みがあります。

  • Node.js:AsyncLocalStorage
  • Go:context.Context に入れてロガーを取り出す
  • Java:MDC(Mapped Diagnostic Context)
  • PHP:リクエスト単位のコンテナにロガーを1つ持たせる

外部から X-Request-Id ヘッダーが来ていればそれを引き継ぎ、なければ生成する、という作りにしておくと、ロードバランサーやCDNが振ったIDとも繋がります。

ログレベルの決め方

レベルは「深刻さ」で決めると人によってぶれます。「それを見た人が何をすべきか」で決めると揃います。

レベル意味見た人がすること
error処理が失敗し、対応が必要いま調べる
warn処理は続いたが、想定外のことが起きたあとで確認する
info正常系の重要な出来事何もしない。追跡時に読む
debug開発時の詳細本番では出さない

この基準で見ると、「対応する気がないもの」を error で出さないことになります。冒頭の239行の警告は、対応しないと決めた時点で error でも warn でもなくなります。

逆に、ユーザーの入力ミスを error で出すのもよくある間違いです。バリデーションエラーは想定内の正常な動作なので、info で十分です。これを error にしていると、本物の障害がその中に埋もれます。

ログに出してはいけないもの

ログは長期間保存され、検索でき、多くの人がアクセスできます。本番データベースより権限が緩いことも珍しくありません。

  • パスワード、APIキー、トークン、セッションID
  • クレジットカード番号
  • メールアドレス、電話番号、氏名、住所
  • リクエストボディやヘッダーの丸ごと出力(上のすべてが入りうる)

特に危ないのが最後です。「デバッグのために全部出しておこう」がそのまま本番に残るパターンで、Authorization ヘッダーがログに平文で残ります。

対策は、出す側でマスクするのではなく、ロガー側で除外することです。個々の呼び出しで気をつける方式は必ず漏れます。

// ロガーに除外キーを設定しておく(イメージ)
const REDACT = ["password", "token", "authorization", "credit_card"];
// → どこから渡されても、これらのキーは "[REDACTED]" に置き換わる

ユーザーを特定したい場合は、氏名やメールアドレスではなくIDだけを出します。今回の例で user_id: 101 としているのはそのためです。IDがあれば、必要になったときにデータベースを引けます。ログ側に個人情報を持たせる必要はありません。

まとめ

  • ノイズを放置しない
    241行中239行が同じ警告では、残りの2行は読まれない
  • 対応しないものはログに出さない
    「とりあえず出す」がログを死なせる
  • 構造化して出す
    後からパースする正規表現を書いている時点で設計を間違えている
  • リクエストIDを最初に振って持ち回す
    非同期処理では、これがないと追跡できない
  • レベルは「見た人が何をすべきか」で決める
    入力ミスは error ではない
  • 秘密情報はロガー側で除外する
    呼び出し側で気をつける方式は漏れる

ログは、書いているときではなく障害が起きた深夜に読まれます。そのときに欲しい情報が入っているか、という基準で設計するのが結局いちばん確実だと思います。

次に読む記事

よかったらシェアしてね!
  • URLをコピーしました!
  • URLをコピーしました!

この記事を書いた人

わどこんのアバター わどこん

実務12年のバックエンド・インフラエンジニア。バックエンド開発からクラウド・インフラの設計・構築・運用まで担当しています。主要言語は Java・Kotlin・PHP・Python。運用の現場で拾った知見を、再現できる手順に落として残すのがこのブログのテーマです。

目次