丁度ええ! ロギング

ロギングにまつわる問題の構造

ロギングにまつわる現場でよく見られる問題には以下のようなものがあります。

ロギングガイドラインを定義して、開発者に周知し実装してもらったが、実際運用してみると、役に立たないログが多すぎる。

担当者が異なると、ログ出力する粒度が微妙に異なり、解析に時間がかかる。

ログの形式や内容が統一されておらず、分析ツールでの活用が難しい。

ロギングベストプラクティスは探すといくつか見つかります。

これはこれで有用なのですが、実際の現場で各開発者にうまいことログを仕込ませるには、抽象度が高すぎるので、別途開発ガイドラインを定める必要があります。

では、公開されている開発ガイドラインでロギングに関して言及されているものを見てみます。

どちらも、ログの種類がちゃんと定義されていて、良さそうな感じなのですが、どう出力するかは書かれているものの、どう使うのか? の観点が足りないように思えます。実際、これらを使った開発の結果、運用時に役にたつログが出力できていないシステムは珍しくありません。

これは「ロギング」が実装しなくても、アプリケーションは仕様通り動いてしまう。そのためルールが守られないまま、開発が進んでしまうことがある。という性質があるためです。つまりロギングは非機能要求から出てくる仕様なので、機能要求と同じレベルで目的や意義をハッキリさせ、仕様に落とし込まないと、開発者によるバラツキが出てきてしまうのです。

では、非機能要求をきちんと定義して、出力内容を仕様として落とし込もう！ …としても非機能要求からロギング(技法)までの距離が遠いので、

① 多くの戦術がロギングという技法を使う構造になるため、ロギングだけでやるべきことを語るのが難しい。

さらにロギングの技法自体も、分解すると

https://gyazo.com/90eba93048b8b24aa5c6cea6dced6354

② サブ戦術と技法を内包するフラクタル構造を持つので、ロギング単体で語ることが多く、技法やツールの使い方にフォーカスがいきやすい

という構造的性質も持ちます。

これら①と②の性質から、以下のような事態に陥りやすいのです。

目的不明瞭による判断困難

非機能要求とログ技法の距離が遠いため、開発者は「何のために」「どこを」「どのように」ログすべきか判断しづらい。

実装ムラとカバレッジ不足

仕様として落とし込まれていない項目は抜け漏れや重複が生じ、運用時に必要な情報が取得できない場面が発生する。

標準化困難による運用負荷

ログ形式・粒度の統一が進まず、解析ツールへの取り込みやアラート設定の工数が増大する。

戦術からログを分類してみよう

そこで、ロギングにつながる戦術および品質特性からログの種類を分類してみます。

table:ログの分類

種類 戦術 品質特性

トレースログ システムイベントを記録する 可観測性、性能

モニタリングログ 指標を出力する 可観測性、可用性

リモート呼び出しログ 問題特定を支援する 診断容易性

監査ログ 攻撃から回復する セキュリティ

業務イベントログ 業務イベントを記録する (これは機能要求から出てくる)

システム利用状況の統計 利用状況を収集する ユーザビリティ

障害追跡ログ 問題特定を支援する 診断容易性

障害検知ログ 異常を検知する 可用性

プログレスログ システムイベントを記録する 可観測性

問題が起きた時に役に立つログとは?

「なんかトラブルが起こった時にログが出てないと対処のしようがないから、とにかく出力しておけ」

みたいな解像度の低いログ設計では、実際の運用で役にたつログを出力できることはまずできません。

トラブルが起きた時の対応を予測して設計しておかないと、いくらたくさんのログを出力していても、実際のトラブル時には役に立たないのです。

障害検知には、偽陰性と偽陽性が含まれるとその信頼が損なわれます。

偽陽性

本来は異常ではない(開発側が対応することがない)にもかかわらず、出力されているログのせいで、異常検知モニタリングに引っかかる。

偽陰性

本来は対応が必要なのに、例外が握りつぶされていて、ログが出力されない。

偽陰性は通常の開発ルールと静的検査によって対策できる。

偽陽性の発生率が高いと、Alert Stormingと呼ばれるアンチパターンに陥ります。

障害検知ログにより、大量のアラートが発生するが、ほどんどは対応不要なもの(静観)である。

なので、アラートに対する人間の慣れが発生し、本当の重要なアラートの時の初動が遅れてしまう(オオカミ少年現象)。

偽陽性によるAlert Stormingの代表的シナリオ

通常の画面遷移では必須となる値が、空になってリクエストされた

フロントエンド側でセッションが切れたリクエストや、ツール使ってリクエストされたりしたもので発生する可能性がある

→ なので、開発サイドとしては何もすることはないので静観する。

→ 開発者には、必須パラメータの欠落によるアラート ＝ 静観 という観念が広まる

偽陽性のための対策

対応する必要のない予期しない例外をいかに減らすか? がポイントです。

「予期しない例外」は、設計時に予測しない(できない)ということではありません。発生することはあることは分かっているが、それが起きた時にはシステムの利用者や運用者では対応できず、開発者が調査・対応しなくてはならないもの、という意味合いです。　

https://gyazo.com/ff3b827d86e9c373eb77b26ac9ae5285

特にユーザの入力内容によって、予期しない例外を発生させないように設計・実装することが重要です。

※ ネットワーク断は微妙なところで、完全に「予期しない例外」扱いしてしまうと、これまたAlert Stormingの原因になります。なので、サーキットブレイカーを使って断続的にエラーが発生する場合にだけ予期しない例外になるように設計した方が良いかもしれません。

スタックトレースだけで原因特定できるとは限らない

また、障害追跡ログのための例外設計においては、解析のための十分なコンテキストを例外に持たせることが重要です。

特に「業務例外」用の共通の例外を作るような場合、messageに何を書くかは、各開発者に委ねられてしまうため、解析のためのコンテキストが不十分なものが出力されてしまいがちです。

code:java

public class BusinessException extends ResultMessagesNotificationException {

public BusinessException(String message) {

super(ResultMessages.error().add(ResultMessage.fromText(message)));

}

public BusinessException(ResultMessages messages) {

super(messages);

}

public BusinessException(ResultMessages messages, Throwable cause) {

super(messages, cause);

}

}

これが業務的に予期する例外で、大域脱出するためにExceptionという機構を使っている、のだとしたら、異常状態を表現するデータ型をそれぞれ設計した方が良い。

で、これを記録する必要があれば「業務イベントログ」として出力する。

起こりうるトラブルをある程度予測(予期するものも、予期しないものも)して、例外・ログ設計しなければ、結局トラブル時には役に立たないのです。

戦術ごとのログ出し分けの実践

戦術ごとにログを出し分けるには、多くのロガーライブラリが持っている

ログレベル

ログカテゴリ

では、機能不十分なところがあります。

(本来はログカテゴリがログを分類するためのものだった、のかもしれませんが、現代では出力するプログラム名、クラス名をログカテゴリとして出力する慣例があります。)

そのため、ログレベルやログカテゴリで戦術ごとのログ出し分けを考えるのはやめて、別のメカニズムを使うことを考えましょう。

JavaのデファクトスタンダートなログファサードであるSLF4Jには、この用途のためのMarkerがあります。

以下に実装例を示します。

code:MarkerUsage.java

private static final Marker MARKER = MarkerFactory.getMarker("TRACE");

//...

LOG.info(MARKER, "message");

Markerごとに"type"を設定し、構造化ログで出力するSpring BootのLoggingFormatterを書くと、

以下のように出力されます。

code:出力

{"time":"2025-04-28T06:35:24.706646Z","traceId":"680f21ac0972f093aa4ab5f1024a4b46","level":"INFO","logger":"com.example.web.controller.PaymentController","thread":"http-nio-8080-exec-1","message":"Enter PaymentController.payment","type":"TRACE"}

{"time":"2025-04-28T06:35:24.992551Z","traceId":"680f21ac0972f093aa4ab5f1024a4b46","level":"INFO","logger":"com.example.web.controller.PaymentController","thread":"http-nio-8080-exec-1","message":"Exit PaymentController.payment","type":"TRACE"}

ファイルを種別ごとに分けたい場合は、以下のようにAppenderをMarkerごとに振り分けます。

code:logback.xml

<configuration>

<appender name="TRACE_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">

<file>logs/trace.log</file>

<filter class="ch.qos.logback.classic.filter.MarkerFilter">

<marker>TRACE</marker>

<OnMatch>ACCEPT</OnMatch>

<OnMismatch>DENY</OnMismatch>

</filter>

</appender>

<appender name="EXCEPTION_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">

<file>logs/exception.log</file>

<filter class="ch.qos.logback.classic.filter.MarkerFilter">

<marker>EXCEPTION</marker>

<OnMatch>DENY</OnMatch>

<OnMismatch>ACCEPT</OnMismatch>

</filter>

</appender>

<root level="INFO">

<appender-ref ref="TRACE_FILE"/>

<appender-ref ref="EXCEPTION_FILE"/>

</root>

</configuration>

「業務ロジックにロギングのコードを書くべきではない」は本当か?

前述のサンプルコードをみても、まずロギングのコードがControllerやドメインのコードにはありません。が、ここまでの整理に基づく戦術ごとのログは出力されています。

たいていは、AOPや上位レイヤーの予期しない例外ハンドラーで共通の処理ができるため、

業務のコードでログ出力を明示的に書くのは、

監査ログ

業務イベントログ

(場合によっては) モニタリングログ

くらいなものなので、ほとんど「業務ロジックにロギングのコードを書く」必要は、戦術ごとに整理してみると確かになさそうです。