前回 ① では可観測性の3本柱のうち メトリクス と 外形監視 を学びました。
メトリクスは「数値の折れ線」で 異常に“気づく” ための柱でした。でも気づいた後、こう思いますよね。
「エラー率が25%に上がったのは分かった。で、誰の・どのリクエストで・何が起きたの？」
この「なぜ」を1件1件掘るための柱が、今回の ログ です。この記事では「ただ puts するだけ」から一歩進んで、後から機械的に検索・分析できるログ＝構造化ログを、Rails を例に図解で一から組み立てます。
🌑 おさらい：3本柱の役割分担
┌──────────┬──────────────────────────┐
│ 📊メトリクス │ 数値の折れ線。“異常に気づく” │
│ 📜ログ │ 1件1件の出来事。“なぜ?を掘る” ←今回│
│ 🧵トレース │ 処理の流れ全体を追う（次回③） │
└──────────┴──────────────────────────┘
気づく(📊) → 掘る(📜) → 流れを追う(🧵)
たとえ話で言うと：
📊メトリクス = 車のダッシュボード（速度・水温の“針”）→「今ヤバい」が分かる
📜ログ = ドライブレコーダー（何が起きたかの記録）→ 後から“なぜ”を再生
メトリクスで「ヤバい」に気づき、ログで「なぜ」を再生する。役割分担です。
1️⃣ なぜ「構造化」なのか
ログには大きく2つの書き方があります。まずダメな例から。
❌ 非構造化ログ（人間がなんとなく読む用・ベタ書き）
14:30:27 Request succeeded response_time=0.5s for user john from 192.168.1.100
一見読めます。でも「user=john のログだけ抜き出したい」と思った瞬間に地獄が始まります。
- 正規表現でこねくり回すしかない
-
User/userの表記揺れで壊れる - フォーマットを少し変えた瞬間、過去の抽出スクリプトが全部死ぬ
そこで 構造化ログ＝「1行1JSON」にします。
✅ 構造化ログ（機械が読む用）
{"time":"14:30:27","event":"request","status":"success",
"response_time":0.5,"user":"john","ip":"192.168.1.100"}
こうしておくと、「user=john かつ status=error」を フィールド指定で機械検索 できます。
非構造化 = 日記を文章でダラダラ書く → 「先月の雨の日」を探すのが地獄
構造化 = 日付・天気・出来事を“表の列”で記録 → 一発で絞り込める
設計の勘所：前回メトリクスで学んだ tags（{dependency, status} のような切り口）と、ログの フィールド は同じ発想です。「切り口で絞り込めるようにしておく」のが、メトリクスでもログでも探索性の肝。可観測性の本では「ディメンション（キーの数）とカーディナリティ（値の種類）が高いほど探索が精密になる」と表現されます。
2️⃣ ログはどこへ流れるのか（収集パイプライン）
「JSONで出す」の前に、出したログがどこへ行くのかを押さえます。実はメトリクスとそっくりな旅をします。
📊メトリクス: アプリ → /metrics → Prometheus(pull) → Grafana(PromQL)
📜ログ: アプリ → stdout → 収集役 → Loki → Grafana(LogQL)
▲ ▲ ▲
Promtail/fluentd ログDB 検索言語
図でじっくり：
┌─ アプリの Pod ───────────┐
│ logger │
│ {"time":..,"event":..} │ ← 1行1JSONを
│ │ │
│ ▼ 標準出力(stdout) │
└────────┼─────────────────┘
│ ① 収集役が「コンテナのstdout」を拾う
▼
┌─ Promtail / fluentd ─┐ ← 各ノードに常駐し、全Podのstdoutを集める“集荷係”
└────────┼──────────────┘
│ ② Loki へ転送
▼
┌─ Loki ──────────────┐ ← ログ版のPrometheus。ログを貯めて検索させるDB
└────────┼─────────────┘
│ ③ Grafana が LogQL で問い合わせ
▼
┌─ Grafana 🖥️ ────────┐ ← {namespace="myapp"} |= "error" で検索
└──────────────────────┘
用語が増えてきたので整理します。
| 用語 | ざっくり言うと |
|---|---|
| Loki | ログ版のPrometheus。ログを貯めて検索させるDB |
| Promtail | ログ版のscrape役。Podのstdoutを拾って Loki へ送る |
| fluentd | Promtail と同類の“集荷係”（環境によってどちらか） |
| LogQL | ログ版のPromQL。{label} |= "文字列" で絞り込む |
ここ超重要：ログは ファイルではなく標準出力（stdout）に出す。Kubernetes の世界では収集役（Promtail/fluentd）が「コンテナの stdout」を拾う仕組みなので、/var/log/myapp/app.log のようにファイルへ書くと収集されず Loki まで届きません。「ログがGrafanaに出ない」の典型原因No.1です。
そしてアプリ側から見ると、ログ収集は 「stdout に垂れ流すだけ（fire-and-forget）」。アプリは Loki の存在すら知りません。
アプリは「画面(stdout)に出すだけ」。送り先(Loki)を知らない＝疎結合
→ 収集基盤を入れ替えても、アプリのコードを書き直さなくていい
これは前回のメトリクス（pull型：アプリは送り先を知らない）と共通の思想です。アプリをインフラ構成から切り離しておくのがポイント。
「立てる」のは誰か：Prometheus と同じく、Loki / Promtail / fluentd / Grafana は監視基盤側に既設であることが多いです（Kubernetes なら共有のobservabilityスタックとして用意済み）。アプリ開発者がやるのは「stdout に 1行1JSON を出す」ところまで。そこから先は基盤に任せます。
3️⃣ JsonLogFormatter：全ログを統一JSONに変える心臓部
ここから実装です。Rails を例にします。
Rails 標準の logger は、こんな人間向けのベタテキストを吐きます。
Rails.logger.info("注文完了")
↓
I, [2026-06-15T14:30:27.123 #1] INFO -- : 注文完了
これを JSON に化けさせるのが、自作の Formatter です。
# config/initializers/logging.rb
class JsonLogFormatter < ActiveSupport::Logger::SimpleFormatter
def call(severity, time, _progname, message)
base = {
time: time.iso8601(3), # 共通フィールド
level: severity.downcase,
request_id: Current.request_id, # ← 縦串（後述）
user_id: Current.user_id,
app_version: ENV.fetch('APP_VERSION', 'unknown'),
}
case message
when Hash # ← Hashを渡すと「独立フィールド」に展開！
base.merge!(message)
when Exception # ← 例外を渡すと error 情報を自動展開
base[:event] = 'exception'
base[:error_class] = message.class.name
base[:error_message] = message.message
base[:backtrace] = message.backtrace&.first(10)
else # ← 普通の文字列は message フィールドへ（互換）
base[:message] = message.to_s
end
base.compact! # nil のフィールドは消す
"#{base.to_json}\n" # JSON 1行 + 改行
end
end
一番賢いのは message の「型」で振る舞いを変える ところ。
logger.info("注文完了")
→ {"time":..,"level":"info","message":"注文完了"} (文字列)
logger.info({event:"order.confirmed", order_id:999})
→ {"time":..,"level":"info","event":"order.confirmed","order_id":999}
↑ Hashを渡すと order_id が“独立した検索可能フィールド”になる！
logger.error(exception)
→ {"time":..,"level":"error","event":"exception",
"error_class":"Timeout::Error","backtrace":[...]}
開発者は「意味のある Hash を渡すだけ」で構造化フィールドが増やせて、従来の文字列ログも壊れない（互換）。1つの変換器が、文字列・Hash・例外を全部いい感じの JSON にしてくれます。
設計の勘所：base.compact! で nil フィールドを消しています。ログイン前のリクエストだと user_id は nil ですが、"user_id":null を毎行出すと Loki 側でノイズ・無駄なインデックスになります。値が無いキーは最初から出さないのがクリーン。
4️⃣ lograge：1リクエスト = ぐちゃ複数行 → 綺麗な1行
手動の logger.info は JSON 化できました。でも HTTP アクセスログ はどうでしょう。Rails 標準は1リクエストで何行も吐きます。
Started POST "/graphql" for 10.0.0.1 at 2026-06-15 14:30:27
Processing by GraphqlController#execute as JSON
Parameters: {...}
Completed 200 OK in 152ms (Views: 3ms | ActiveRecord: 40ms)
↑ 4行バラバラ。検索しづらい・量が膨らむ
これを「意味のある1行JSON」に集約してくれるのが lograge。
config.lograge.enabled = true
config.lograge.formatter = Lograge::Formatters::Json.new
# /healthz は秒単位で叩かれてノイズになるのでログから除外
config.lograge.ignore_actions = ['HealthController#show']
# リクエストごとに固定で詰める情報（縦串フィールドもここで足す）
config.lograge.custom_options = lambda do |event|
{
event: 'http.request',
request_id: Current.request_id,
user_id: Current.user_id,
duration_ms: event.duration, # ← 命名をプロジェクトで統一しておく
app_version: ENV.fetch('APP_VERSION', 'unknown'),
}.compact
end
結果はこうなります。
{"event":"http.request","method":"POST","path":"/graphql",
"status":200,"duration_ms":152,"request_id":"abc-123","user_id":42}
JsonLogFormatter (3️⃣) … “手動で書いたログ” を JSON化
lograge (4️⃣) … “HTTPアクセスログ” を1行JSON化
→ 2つで「手動ログ」と「アクセスログ」の両方を、同じフィールド名で揃える
設計の勘所：/healthz（ヘルスチェック）は外形監視や Kubernetes の probe が秒単位で叩きます。そのままだとログが healthz で埋まり、本物のエラーがノイズに沈み、Loki のストレージも食います。監視のための叩きが、ログを汚すという現場あるある。ignore_actions で先回りして除外しておきましょう。
5️⃣ 相関ID（request_id）：バラバラのログを「1本の糸」で束ねる
ここがログ柱の心臓です。1リクエストは内部で大量のログを撒き散らします。
ユーザー42が「購入」ボタン → 内部で連鎖的に処理:
{event:"http.request"} ← どこの？
{event:"external.call", ...} ← 誰の？
{event:"external.call", ...} ← 同じ購入の？
{event:"order.failed", ...} ← 別の人のかも？
↑ 何千リクエストのログが入り乱れる中、
「user42 のあの購入」だけを拾えない
解決策は 全ログに同じ request_id を埋める こと。
{"request_id":"abc-123","event":"http.request","user_id":42}
{"request_id":"abc-123","event":"external.call","dependency":"unleash"}
{"request_id":"abc-123","event":"external.call","dependency":"payment","duration_ms":3200}
{"request_id":"abc-123","event":"order.failed","error_class":"Timeout"}
Loki で {request_id="abc-123"} と1発検索すれば、1リクエストの物語が時系列で再生されます。
「user42 の購入は、payment が 3.2 秒かかって Timeout で失敗した」と即わかる ＼(^o^)／
どうやって全ログに同じIDを付ける？
毎回手で request_id: を渡すのは現実的じゃありません。そこで リクエストごとの“黒板” を使います。Rails なら ActiveSupport::CurrentAttributes。
# app/models/current.rb
class Current < ActiveSupport::CurrentAttributes
attribute :request_id, :user_id
end
# Rack middleware：リクエスト着信時に request_id を黒板へ書く
class CurrentRequestId
def initialize(app) = @app = app
def call(env)
Current.request_id = env['action_dispatch.request_id']
@app.call(env)
end
end
┌─ middleware ─────────────────────────────────┐
│ リクエスト着信時に request_id を Current に保存 │
└──────────────────────────────────────────────┘
│ 以降、処理中はどこからでも Current.request_id が読める
▼
JsonLogFormatter が全ログ行に request_id を自動で差し込む（3️⃣で見た通り）
開発者は普通にログを書くだけ。フォーマッタが毎行勝手に縦串を通してくれます。
設計の勘所（一番ハマる所）：Current の中身は スレッドローカル（そのスレッド専用の置き場）に保たれます。これは必須です。Web サーバ（Puma など）は複数スレッドが同時に別々のリクエストを処理するため、もし「グローバル変数1個」で持つと——
スレッド1(user42) ┐
スレッド2(user99) ├→ 同じ箱を奪い合い → IDが混線💥
スレッド3(user7) ┘ user42 のログに user99 の ID が付く
という個人情報の取り違え事故が起きます。CurrentAttributes はリクエスト境界で自動リセットされ、スレッド安全に設計されているので、自前のグローバル変数で代用しないこと。
6️⃣ イベント別ログ：出来事に「名前」を付ける
ログを撒く時は、出来事に 名詞.動詞 の名前を付けると探索性が上がります。
Rails.logger.info(
event: 'order.confirmed',
order_id: order.id,
amount: order.total_price,
)
order.confirmed / order.failed / order.stock_released
job.start / job.complete / job.failed
external.call / http.request
event を「名詞.動詞」で階層化すると…
{event=~"order\\..*"} で「注文系すべて」
{event="order.failed"} で「失敗だけ」
→ 出来事を“分類”できる＝探索性が上がる
ここで前回のメトリクスと相補的になるのが面白いところ。同じ「payment 呼び出し」を：
📊メトリクス: payment_duration{...} → 「payment全体、p95が3秒に悪化」(気づく)
📜ログ: {event:"external.call", dependency:"payment",
duration_ms:3200, request_id:"abc-123"} → 「user42のあの1回」(掘る)
📊メトリクスで「全体で遅い」と気づく
│ request_id で突合してドリルダウン
▼
📜ログで「user42 のこの注文のこの呼び出しが犯人」と特定
7️⃣ PII・機密マスキング：ログに残してはいけないものを潰す
ログは Loki に保存・検索される＝広く見られる。だからこそ、入れてはいけないものがあります。
❌ もしマスクしないと…
{"event":"login","password":"hunter2","email":"taro@example.com",
"card_number":"4111-1111-1111-1111","token":"secret-xyz"}
↑ パスワード・カード番号・個人情報が丸見え＝重大インシデント
Rails なら filter_parameters で該当キーを自動マスクできます。
config.filter_parameters += [
:password, :token, :access_token, :secret,
:card_number, :cvv, :email, :phone, :authorization, :cookie,
]
✅ 登録したキーは出力時に [FILTERED] へ
{"event":"login","password":"[FILTERED]","email":"[FILTERED]",
"card_number":"[FILTERED]"}
設計の勘所（穴を作らない）：filter_parameters が効くのは主に HTTP（コントローラ）経由のログです。非同期ジョブ（Sidekiq など）のログは別経路で、ここを通りません。「HTTP はマスクしたのに、ジョブの引数にカード番号が平文で残っていた」は典型的な事故。ログが生まれる経路すべてでマスクを掛ける必要があります。
なお email のような一見地味な項目も PII（個人を識別できる情報） なので保護対象です。「危険そうな物」だけでなく「個人を特定できる物すべて」を守りましょう。
8️⃣ 設計ガード：壊さない・後で困らないための配慮
最後に、目立たないけど大事な安全装置を3つ。
ガード①：テスト環境ではログ機能を“あえてOFF”
unless Rails.env.test? # ← test 以外でだけ有効化
Rails.application.config.log_formatter = JsonLogFormatter.new
config.lograge.enabled = true
end
アプリは 3つの環境（モード） で動きます。
| 環境 | 何の世界か |
|---|---|
| production（本番） | 実ユーザーが使う本物。ここでこそ観測したい |
| development（開発） | 自分のPCで作る世界。人間が読みやすいログがいい |
| test（テスト） | 自動テスト（RSpec 等）が走る世界。静かに素のまま動かしたい |
今 production → testじゃない → ✅ JSONログ ON（本物を観測したい）
今 test → testだ！ → 🚫 JSONログ OFF（既存テストを邪魔しない）
ログの“出方”を変えると、ログの形を前提にした既存テストが誤爆することがあります。「観測の追加が、既存テストの破壊を招かない」ように、テスト中だけは素の Rails に保ちます。観測を諦めているのではなく、テスト中だけ静かにしているだけ。本番ではちゃんとONです。
ガード②：app_version で「どのリリースで壊れた？」に答える
app_version: ENV.fetch('APP_VERSION', 'unknown') # CD でデプロイ時に Git SHA を注入
全ログに**コードの“製造ロット番号”（Git SHA）**を刻んでおくと——
{"event":"order.failed", "app_version":"a1b2c3d"}
{"event":"order.failed", "app_version":"a1b2c3d"}
↑ 失敗が全部「a1b2c3d のリリース」のもの！
「金曜にリリースしたら土曜からエラー急増」のとき、エラーログの app_version を見れば犯人リリースを即特定し、前の版に戻す（ロールバック）判断ができます。食品の製造ロット番号と同じ発想ですね。
ガード③：正直な「未検証」の明記
これは技術というより姿勢の話。「動作確認した」と嘘をつかず、検証できた所とできなかった所を分けて明記する（例：「構文チェックはOK、ただしテストはローカル環境制約で未実行、CI に委ねる」）。レビュアーが正しく判断できるようになります。観測の本質である**「事実を正直に出力する」**は、ログだけでなく PR 報告にも効く話です。
🏆 まとめ
┌─ ログ柱・全体マップ ───────────────────────────────────┐
│ 1️⃣ なぜ構造化 検索できる形＝1行1JSON。切り口で絞る │
│ 2️⃣ パイプライン stdout→収集役→Loki→Grafana(LogQL) ※基盤既設│
│ 3️⃣ Formatter 文字列/Hash/例外 を統一JSONに（心臓） │
│ 4️⃣ lograge 1リクエスト=1行のアクセスログ。/healthz除外 │
│ 5️⃣ 縦串request_id 1リクエストの物語を再生。スレッドローカル必須 │
│ 6️⃣ イベント別ログ 名詞.動詞 / メトリクスと相補（気づく→掘る） │
│ 7️⃣ マスキング PII/機密を[FILTERED]。全経路を塞ぐ │
│ 8️⃣ 設計ガード test無効化 / app_version / 正直な報告 │
└────────────────────────────────────────────────────────┘
メトリクス（前回）で 「ヤバい」に気づき、ログ（今回）で 「なぜ」を1件まで掘れる ようになりました。残るは最後の柱。
次回 ③ は 🧵 トレース。「1リクエストの中で DB に101回問い合わせてた！」のような N+1 問題を“滝グラフ”で一発で見つける 話、OpenTelemetry と Tempo を扱います。お楽しみに。