ロギングはひどい

 (loggingsucks.com)
37 ポイント 投稿者 GN⁺ 2025-12-22 | 1件のコメント | WhatsAppで共有
  • 現代の分散システムでは、従来のログ方式は真実を伝えられない構造的限界を抱えている
  • ログは依然として2005年式の単一サーバー環境を前提に設計されており、複数のサービス・データベース・キャッシュをまたぐリクエストのコンテキストを失ってしまう
  • 単純な文字列検索では構造・関係・相関性を理解できず、問題の原因を見つけにくくする
  • 解決策は、各リクエストごとに**あらゆる文脈を含んだ単一の「Wide Event（または Canonical Log Line）」**を残すこと
  • これにより、ログは単なるテキストではなく分析可能なデータ資産へと変わる

ロギングの根本的な問題

  • 従来のログはモノリシックサーバー時代を前提に作られており、現代の分散サービス構造を反映できていない
    • 1つのリクエストが複数のサービス・DB・キャッシュ・キューを通過するのに、ログは依然として単一サーバー基準で記録される
  • 例のログでは1リクエストあたり13行が生成され、同時ユーザー10,000人なら毎秒130,000行が流れ込むが、その大半は無意味な情報である
  • 問題発生時に必要なのは**コンテキスト（context）**だが、現在のログにはそれが欠けている

文字列検索の限界

  • ユーザーが「決済できない」と報告したとき、メールアドレスや user_id でログを検索しても一貫した構造がないため有効な結果を得にくい
    • 同じユーザー ID でも user-123、user_id=user-123、{"userId":"user-123"} のように数十種類の形式で記録される
  • サービス間でログフォーマットが異なるため、関連イベントの追跡が不可能
  • 核心的な問題は、ログが**書き込み（write）**中心に設計されており、**検索（query）**には最適化されていないこと

重要概念の定義

  • Structured Logging: 文字列の代わりに**キー・バリュー（JSON）**形式で記録する方式
  • Cardinality（カーディナリティ）: フィールドの一意な値の数。たとえば user_id は非常に高い
  • Dimensionality（次元数）: ログイベント内のフィールド数。多いほど分析可能性が高い
  • Wide Event / Canonical Log Line: リクエストごとに1つの文脈が豊富な単一ログイベント
  • ほとんどのロギングシステムは高カーディナリティデータをコストの問題で制限するが、実際にはそれこそがデバッグに最も有用である

OpenTelemetry の限界

  • OpenTelemetry（OTel）はプロトコルと SDK のセットであり、データ収集・転送の標準だけを提供する
  • しかし OTel は次のことを行わない
    1. 何をログに記録するかを決めない
    2. ビジネスコンテキスト（例: サブスクリプション等級、カート金額など）を自動で追加しない
    3. 開発者のロギングに対する考え方を変えない
  • 同じライブラリを使っていても、コンテキストを意図的に追加した計測と単純な計測とでは、デバッグ体験に大きな差が出る
  • OTel は単なる**伝送手段（plumbing）**であり、何を流すかは開発者が決める必要がある

Wide Event / Canonical Log Line 方式

  • 従来の「コードが何をするか」中心のロギングから離れ、「リクエストに何が起きたか」を記録すべきである
  • 各リクエストごとに、サービス単位で1つの広範なイベントを生成する
    • リクエスト・ユーザー・決済・エラー・環境など50以上のフィールドを含められる
  • 例の JSON には user_id、subscription_tier、service_version、error_code などあらゆるデバッグ用コンテキストが含まれる
  • これにより、単一の検索で「プレミアムユーザーの決済失敗原因」のような即時分析が可能になる

Wide Event のクエリ活用

  • Wide Event は単純なテキスト検索ではなく、構造化データのクエリとして扱う
  • 高カーディナリティ・高次元データを基盤に、リアルタイム分析レベルのデバッグが可能
  • 例: 「過去1時間のプレミアムユーザーの決済失敗率を、エラーコード別に集計する」といったクエリを即座に実行できる

実装パターン

  • リクエストのライフサイクル全体を通じてイベントを構築し、最後に一度だけ出力する
    • ミドルウェアで request_id、timestamp、method、path などの基本フィールドを初期化
    • ハンドラーでユーザー・カート・決済・エラー情報を段階的に追加
  • 最終的に logger.info(event) で単一の JSON イベントを記録する

サンプリングによるコスト制御

  • 1リクエストあたり50フィールド以上を記録するとコストが急増するため、サンプリングが必要
  • 単純なランダムサンプリングではエラーを見逃す危険がある
  • Tail Sampling 戦略を提示
    1. エラー（500 など）は常に保存
    2. 遅いリクエスト（p99 以上）は常に保存
    3. VIP ユーザー・特定フラグのセッションは常に保存
    4. それ以外は 1〜5% だけランダムサンプリング
  • これにより、コスト削減と重要イベントの保持を同時に達成できる

よくある誤解の整理

  • Structured Logging ≠ Wide Event: JSON フォーマットだけでは不十分で、コンテキストこそが重要
  • OpenTelemetry を使うこと ≠ 完全な可観測性の確保: 収集が標準化されるだけで、何を記録するかは開発者次第
  • Tracing と同じではない: トレーシングはサービス間の流れを扱い、Wide Event はサービス内部のコンテキストを提供する
  • ログはデバッグ用、メトリクスはダッシュボード用という区別は不要 — Wide Event は両方の用途を満たす
  • 高カーディナリティデータは高価だという認識は古く、ClickHouse・BigQuery などの現代的な DB はこれを効率的に処理できる

Wide Event 導入の効果

  • デバッグが**発掘作業（archaeology）から分析（analytics）**へと変わる
  • 「ユーザーの決済失敗」を見つけるために50個のサービスログを grep していた方法から、
    「プレミアムユーザーの決済失敗率をエラーコード別に照会する」単一クエリベースの分析へと変化する
  • 結果として、ログは嘘をついていた道具から、真実を語るデータ資産へと転換される

関連記事

1件のコメント

 
GN⁺ 2025-12-22
Hacker Newsの意見

  • 文章が読みにくく、AIが手伝ったような印象があった。それでもメッセージには価値があり、もう少し簡潔ならよかったと思う。
    最近考えていたことは次のとおり。

    • スタック全体に認証があるので、すべてのログ行に user id を含めるようにし始めた。そのおかげで、ユーザーがたどった体験を全体として見やすくなった
    • エラーをリクエストログとは別の行として記録するのは面倒。trace でフィルタできるとはいえ、「5xx リクエストに関連するエラーだけを見せて」のようなクエリは作りにくい
    • こうしたコンテキストを追加するだけでは不十分で、同僚にも新しいフィールドができたことを 周知 しなければならない。知らずに自分で苦労している人をよく見た
    • より良い tracing ツール に投資すると、単純なログでは不可能なレベルのデバッグができるようになる。user id を trace に使うという考え方を拡張したものだ
    • コードベースに request ID という概念があるなら、それでもユーザーの行動をより具体的に追跡できる
    • TID をサービス全体で強制すれば、どのチームでも TID ひとつでトランザクション全体を追跡できる
    • こういう「AIくさい」というタイプのコメントは、いずれ 批判される文化 になりそうだ

  • この話題なら Charity Majors に触れないわけにはいかない。彼女は「wide events」と「observability」という概念を10年以上広めてきて、Honeycomb.io をその哲学の上に築いた。
    今ではさまざまなツールでこの方式を実装できる。structured logs や traces を使って wide event を捉え、時系列・ヒストグラムなど可視化が豊富なツールを使うことが重要だ

    • ただし「observability」という用語自体を彼女が作ったわけではない。すでに複数の分野で数十年前から使われていた概念だ。彼女は影響力のある実務家だが、用語の創始者ではない
    • 彼女のブログと Honeycomb の背景にある話は、業界の人ならぜひ読んでおく価値がある。このアプローチの価値を最初に認識したチームだった
    • 文章が彼女の文体にあまりに似ていて、最後に Honeycomb の広告が出るのかと思ったが、そうではなくて驚いた
    • .NET エコシステムでは Nick Blumhardt がかなり前から「structured logging」を扱っていて、Seq と Serilog がそれを支えていた
    • 彼女のコンテンツは良いが、「observability」をブランド化した人物はいない。敬意は払いつつも、誇張した主張は避けるべきだ

  • この記事の主張には一部同意するが、単一の wide event だけを残す方式には落とし穴がある。リクエストの途中で例外やタイムアウトが起きると、何も残らない。
    言語の標準ロギングフレームワークや依存関係のログも取りこぼすことになる。
    だからこれは既存ログの上に重ねる 追加レイヤー として使うのがよい。request/session 単位の ID を置き、ClickHouse のようなところで集計すればよい

    • 中間層の可視性が問題なら、イベントが十分に wide ではない ということだ。log.error(data) でも wide_event.attach(error, data) でも本質は同じ
    • 「connection X:Y accepted at Z ns」と「closed at Z ns」のようなログは、遅いシステムのデバッグに非常に役立つ
    • 私は PHP フレームワークで LoggerInterface を作って解決した。例外をグローバルハンドラで捕まえ、DB に wide な形で保存する。多少のボイラープレートはあるが、あまりにうまく動くので今ではないと困る

  • プレゼンテーションと インタラクティブな例 は素晴らしかった。だが結局は「ログに構造化タグを追加しろ」という話に要約される。
    wide log は複雑さと 可読性の低下 のわりに、得られる利点が大きくないと感じる。
    単に grep "uid=user-123" application.log で十分なのに、わざわざユーザーの配送方法まで付ける必要があるのかと思う。
    （ちなみに Android の Brave ブラウザではチェックボックスが動作しなかった）

    • JSON ログなら依然として grep '"uid": "user-123"' で検索できる。--context オプションで前後の行も見られる

  • 半導体製造の環境で、数千のメッセージバス参加者 がいるシステムを扱っていた。1時間あたり 300〜400MB のログが出ていたが、grep と CLI ツールだけでも十分に管理 できていた。
    ログは単なるイベントの時系列であり、詳細な分析は Oracle クエリで処理していた。ログは事象の因果関係を把握するための道具だ

    • ログは タイムライン把握用 であって、リクエスト・レスポンスのすべてのデータを入れるためのものではない。情報を入れすぎるとかえって理解しづらくなる。
      ログは「いつ、何が起きたか」を語り、「なぜ」はコードとデータとイベントの組み合わせから探すものだ
      個人的には ELK スタック のようなインターフェースは直感的な探索に不向きだと思う。ログは直感的に追いながら読むことが重要だ
    • 1時間あたり 400MB のログは実際それほど多くない。だから単純な grep でも十分に処理できる

  • 記事の最後にある「すべてのエラー・例外・遅いリクエストをログしろ」という助言は、危険な発想 だ。
    たとえば依存先が遅くなると、ログ量が100倍に爆発する可能性がある。
    障害時にはサービスはより少ない仕事をしたほうが復旧しやすいのに、ログの爆増はむしろ 連鎖障害 を引き起こす

    • Cloudflare では 適応的サンプリング を使っている。ログのバッチをフィールドごとにバケット化し、各バケットでは入力ログ数の平方根あるいは対数分だけを残す。
      ログ量が多いほどサンプリング比率が自動調整され、システムが過負荷にならない
    • こういう マジック閾値 は危険だ。P(99) のような値は動的に更新されるべきだ。OTEL provider で定期的に実測値を取れば安全だ
    • 本番サービスではログ収集を 需要に応じてスケール するよう設計すべきだ。ローカルディスクへのバッファリングだけでも大きな助けになる
    • 高トラフィックなサービスなら、trace_id mod 100 == 0 のような方式で 健全なリクエストだけをサンプリング すればよい
    • ログがボトルネックになるなら、システム設計が間違っている。効率的なロギングなら 毎秒数億件 でも処理可能だ

  • 現代のソフトウェアでは、単一のログだけで「何が起きたのか」を完全に説明するのは難しい。
    だから 垂直相関(Vertical correlation) と 水平相関(Horizontal correlation) が必要になる。
    スタック内の上下層のあいだでは同じ correlation 値を共有すべきで、システム間通信ではピア間の correlation が必要だ。
    こうした値を API やプロトコルに追加するのは難しいが、トランザクション ID をあらかじめ設計しておけば全体追跡が可能になる

  • 単一の記事のために ドメインを別に登録 するのは持続性が低いと思う。
    毎年更新費用がかかるので、個人ブログや サブドメイン を使うほうがよい。
    たとえば logging-sucks.boristane.com のような形がよい

    • 実際、このドメインと記事は著者の observability SaaS の宣伝用 だ。Cloudflare アカウントが必要だが無料なので、長期的なマーケティング戦略なのだろう。それでも有益だったし、私も CF アカウントがあるので使ってみようと思う
    • この記事は Simon Willison の「Give people something to link to」 と似た文脈にある
    • これはブログ記事というより デジタルマーケティング用のリード獲得ページ に近い。サービス宣伝であることが明確だ

  • 「ログはモノリシック時代の遺物だ」という主張については、私は ローカルログは依然として有効 だと思う。
    ローカルプロセスのやり取りを記録するのが本来の役割であり、別サーバーの状況を把握するには トランザクショントレーシング が必要だ。
    適切な場所のログだけ見ても根本原因にたどり着ける

    • ただしログは単なる原因分析用ではなく、誰が影響を受けたのか、性能と入力の相関、セキュリティ脆弱性の影響 などのビジネスインサイトを与えることもある。
      豊かなコンテキストを持つログは分析エンジンと組み合わせることで、製品改善にも活用できる
    • 「リクエストが15個のサービスと3個の DB を通る」という話に対して、そうした複雑さは避けるべきだという反応もあった
    • 私は APN/Kibana だけでもログ分析には十分だと感じる

  • 「コードが何をするかではなく、リクエストに何が起きたかをログしろ」という言葉には同意するが、著者は経験不足に見えた。
    私はこれを 「bug parts logging」 と呼んでいて、処理経路・回数・時間といった 前兆シグナル を含めるべきだと考える。
    ロギングはメトリクスや監査(audit)とは異なる。ロギングに失敗しても処理は継続されるべきだが、監査の失敗は致命的だ。
    SCADA システムの「historian」という概念のように、観測(observables) と 評価(evaluatives) を区別すべきだ。
    たとえば燃料センサーの細かなイベントは診断には有用だが、「目的地まで行けるか」という問いには不要だ。
    結局重要なのは、何を観測し、何を評価するのか を明確にすることだ

    • 私は「観測性の統一理論」を支持する。ログ・メトリクス・監査はすべてビットストリームにすぎず、損失なく変換可能だ。
      保存・変換・照会の方法は異なっても、消費地点とメカニズム は同じように設計できる。
      こうすればシステム設計が単純になり、長期保存されたログを後から再処理することもできる