5.6. ロギング

Caution

本バージョンの内容は既に古くなっています。最新のガイドラインはこちらからご参照ください。

Note

本ガイドラインで説明する内容はあくまで指針のため、業務要件に合わせて柔軟に対応すること。

5.6.1. Overview

システムを運用する上、業務使用量の調査、システムダウンや、
業務エラー等でその原因を究明するための情報源として、ログおよびメッセージを出力する。
デバッグ時にログ出力を取り入れることで、解析の作業効率が格段に向上するため、ログを出力しておくことは重要である。
動きを確認するだけであれば、IDEのデバッグ実行や、System.out.printlnのような簡易的な出力で行える。
しかし、出力結果を手動で保存しておかないと、後に結果の確認ができず、解析の作業効率が格段に下がる。
ロギングライブラリを導入してログをとることは、出力するコードを書くのみで、
その後、好きなタイミングでログを確認することができる。
作業の時間、証跡、解析を考えると、ロギングライブラリを導入することを推奨する。
Javaでは、ログ出力の方法は複数あり、多くの方法が選べるが、コーディングの簡易性、変更の容易性、性能を判断して、
本ガイドラインでは、ロギングライブラリに、SLF4J (インタフェース) + Logback (実装)を推奨している。

5.6.1.1. ログの種類

アプリケーション開発時における代表的なログを、以下に示す。
ログレベル カテゴリ 出力目的 出力内容
TRACE 性能ログ
リクエストの処理時間の測定
(本番環境運用時は出力対象としない)
処理開始終了時間、処理経過時間(ms)、
実行処理を判別できる情報(実行コントローラ + メソッド、リクエストURLなど)等
DEBUG デバッグログ
開発時のデバック
(本番環境運用時には出力対象としない)
任意(実行したクエリ、入力パラメータ、戻り値など)
INFO アクセスログ
業務量の把握
アクセス日時、利用ユーザを判別できる情報(IPアドレス、認証情報)、
実行処理を判別できる情報(リクエストURL)等、証跡を残すための情報
INFO 外部通信ログ
外部システムとの通信におけるエラー解析
送信受信時間、送受信データなど
WARN 業務エラーログ 業務エラーの記録
業務エラー発生時間、業務エラーに対応するメッセージIDとメッセージ
入力情報、例外メッセージなど解析に必要な情報
ERROR システムエラーログ システム運用の継続が困難な事象の記録
システムエラー発生時間、システムエラーに対応するメッセージIDとメッセージ
入力情報、例外メッセージなど解析に必要な情報
基本的には、フレームワークが出力し、ビジネスロジックは出力しない。
ERROR 監視ログ 例外発生の監視
例外発生時間、システムエラーに対応するメッセージID
ツールを用いて監視することを考慮し、出力内容は最低限とすること
デバックログ、アクセスログ、通信ログ、業務エラーログ、システムエラーログは、同一のファイルに出力する。
本ガイドラインでは、上記を出力するログファイルを、アプリケーションログと呼ぶこととする。

Note

SLF4JやLogbackのログレベルの順番は、 TRACE < DEBUG < INFO < WARN < ERROR である。 commons-logginsや、Log4Jで用意されていたFATALレベルは、存在しない。

5.6.1.2. ログの出力内容

ログの出力内容として考慮すべき点を、以下に示す。
  1. ログに出力するIDについて
    ログを運用で監視する場合は、運用監視で使用するログに、メッセージIDを含めることを推奨する。
    また、アクセスログを用いて業務量を把握する場合は、集計を容易にするため、メッセージ管理で示しているように、業務ごとに切り分けられるIDをあわせて出力すること。

Note

ログにIDを含めることにより、ログの可読性が高まるため、システム運用時は、故障解析の一次切り分けの短時間化につながる。 ログIDの体系は、メッセージ管理を参考にすると良い。 ただし、すべてのログにIDを付与する必要はなく、debug時には、IDは不要である。運用時に、素早く切り分け可能になることを推奨する。

障害発生時に、ログID(またはメッセージID)を、エラー画面に表示して、システム利用者に通知し、 利用者に対して、そのIDをコールセンターに通知してもらうような運用にすると、障害解析が容易になる。

ただし、障害の内容までエラーが画面に表示してしまうと、システムの脆弱性を晒してしまう可能性があるため、注意すること。

例外が発生した際に、ログや画面にメッセージID(例外コード)を含めるための仕組み(コンポーネント)を共通ライブラリから提供している。 詳細については、「例外ハンドリング」を参照されたい。

  1. トレーサビリティ
    トレーサビリティ向上のために、各ログにリクエスト単位で、一意となるようなTrack ID(以降X-Trackと呼ぶ)を出力させることを推奨する。
    X-Trackを含めたログの例を、以下に示す。
date:2013-09-06 19:36:31    X-Track:85a437108e9f4a959fd227f07f72ca20        message:[START CONTROLLER] (omitted)
date:2013-09-06 19:36:31    X-Track:85a437108e9f4a959fd227f07f72ca20        message:[END CONTROLLER  ] (omitted)
date:2013-09-06 19:36:31    X-Track:85a437108e9f4a959fd227f07f72ca20        message:[HANDLING TIME   ] (omitted)
date:2013-09-06 19:36:33    X-Track:948c8b9fd04944b78ad8aa9e24d9f263        message:[START CONTROLLER] (omitted)
date:2013-09-06 19:36:33    X-Track:142ff9674efd486cbd1e293e5aa53a78        message:[START CONTROLLER] (omitted)
date:2013-09-06 19:36:33    X-Track:142ff9674efd486cbd1e293e5aa53a78        message:[END CONTROLLER  ] (omitted)
date:2013-09-06 19:36:33    X-Track:142ff9674efd486cbd1e293e5aa53a78        message:[HANDLING TIME   ] (omitted)
date:2013-09-06 19:36:33    X-Track:948c8b9fd04944b78ad8aa9e24d9f263        message:[END CONTROLLER  ] (omitted)
date:2013-09-06 19:36:33    X-Track:948c8b9fd04944b78ad8aa9e24d9f263        message:[HANDLING TIME   ] (omitted)

Track ID を出力させることで、不規則に出力された場合でも、ログを結びつけることができる。
上記の例だと、4行目と8,9行目が、同じリクエストに関するログであることがわかる。
共通ライブラリでは、リクエスト毎のユニークキーを生成し、MDCに追加するorg.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilterを提供している。
XTrackMDCPutFilterは、HTTPレスポンスヘッダの”X-Track”にもTrack IDを設定する。ログ中では、Track IDのラベルとして、X-Trackを使用している。
使用方法については、MDCについてを参照されたい。
  1. ログのマスクについて
    個人情報、クレジットカード番号など、
    ログファイルにそのまま出力すると、セキュリティ上問題のある情報は、必要に応じてマスクすること。

5.6.1.3. ログの出力ポイント

カテゴリ 出力ポイント
性能ログ
業務処理の処理時間を計測し、業務処理実行後に出力したり、リクエストの処理時間を計測し、レスポンスを返す際に、ログを出力する。
通常は、AOPやサーブレットフィルタ等で実装する。

共通ライブラリでは、SpringMVCのControllerの処理メソッドの処理時間を、Controllerの処理メソッド実行後に、TRACEログで出力する、
org.terasoluna.gfw.web.logging.TraceLoggingInterceptorを提供している。
デバッグログ
開発時にデバック情報を出力する必要がある場合、ソースコード中に、適宜ログ出力処理を実装する。

共通ライブラリでは、HTTPセッションの生成・破棄・属性追加のタイミングで、DEBUGログを出力するリスナーorg.terasoluna.gfw.web.logging.HttpSessionEventLoggingListenerを提供している。
アクセスログ
リクエストの受付時、レスポンス返却時に、INFOログを出力する。
通常は、AOPやサーブレットフィルタで実装する。
外部通信ログ
外部のシステムと連携前後で、INFOログを出力する。
業務エラーログ
業務例外がスローされたタイミング等で、WARNログを出力する。
通常は、AOPで実装する。

共通ライブラリでは、業務処理実行時にorg.terasoluna.gfw.common.exception.BusinessExceptionがスローされた場合に、WARNログを出力するorg.terasoluna.gfw.common.exception.ResultMessagesLoggingInterceptorを提供している。
詳細は 例外ハンドリング を参照。
システムエラーログ
システム例外や、予期せぬ例外が発生した際に、ERRORログを出力する。
通常は、AOPやサーブレットフィルタ等で実装する。

共通ライブラリでは、org.terasoluna.gfw.web.exception.HandlerExceptionResolverLoggingInterceptorや、
org.terasoluna.gfw.web.exception.ExceptionLoggingFilterを提供している。
詳細は、例外ハンドリング を参照されたい。
監視ログ 業務エラーログ、システムエラーログの出力タイミングと同様である。

Note

ログを出力する際は、どこで出力されたかわかりやすくなるように、他のログと、全く同じ内容を出力にならないように注意すること。


5.6.2. How to use

SLF4J + Logbackでログを出力するには、

  1. Logbackの設定
  2. SLF4JのAPI呼び出し

が必要である。

5.6.2.1. Logbackの設定

Logbackの設定は、クラスパス直下のlogback.xmlに記述する。以下に、設定例を示す。
logback.xmlの詳細な設定方法については、公式マニュアルを参照されたい。

Note

Logbackの設定は、以下のルールによる自動で読み込まれる。

  1. クラスパス上のlogback.grovy
  2. 「1」のファイルが見つからない場合、クラスパス上のlogback-text.xml
  3. 「2」のファイルが見つからない場合、クラスパス上のlogback.xml
  4. 「3」のファイルが見つからない場合、BasicConfiguratorクラスの設定内容(コンソール出力)

本ガイドラインでは、logback.xmlをクラスパス上に配置することを推奨する。 このほか、自動読み込み以外にも、APIによってプログラマティックに読み込んだりシステムプロパティで設定ファイルを指定することができる。

logback.xml

<!DOCTYPE logback>
<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <!-- (1) -->
        <encoder>
            <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tX-Track:%X{X-Track}\tlevel:%-5level\tlogger:%-48logger{48}\tmessage:%msg%n]]></pattern> <!-- (2) -->
        </encoder>
    </appender>

    <appender name="APPLICATION_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <!-- (3) -->
        <file>log/projectName-application.log</file> <!-- (4) -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>log/projectName-application-%d{yyyyMMddHH}.log</fileNamePattern> <!-- (5) -->
            <maxHistory>7</maxHistory> <!-- (6) -->
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset> <!-- (7) -->
            <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tX-Track:%X{X-Track}\tlevel:%-5level\tlogger:%-48logger{48}\tmessage:%msg%n]]></pattern>
        </encoder>
    </appender>

    <appender name="MONITORING_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <!-- (8) -->
        <file>log/projectName-monitoring.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>log/projectName-monitoring-%d{yyyyMMdd}.log</fileNamePattern>
            <maxHistory>7</maxHistory>
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset>
            <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tX-Track:%X{X-Track}\tlevel:%-5level\tmessage:%msg%n]]></pattern>
        </encoder>
    </appender>

    <!-- Application Loggers -->
    <logger name="com.example.sample"> <!-- (9) -->
        <level value="debug" />
    </logger>

    <!-- TERASOLUNA -->
    <logger name="org.terasoluna.gfw">
        <level value="info" />
    </logger>
    <logger name="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor">
        <level value="trace" />
    </logger>
    <logger name="org.terasoluna.gfw.common.exception.ExceptionLogger">
        <level value="info" />
    </logger>
    <logger name="org.terasoluna.gfw.common.exception.ExceptionLogger.Monitoring" additivity="false"><!-- (10) -->
        <level value="error" />
        <appender-ref ref="MONITORING_LOG_FILE" />
    </logger>

    <!-- 3rdparty Loggers -->
    <logger name="org.springframework">
        <level value="warn" />
    </logger>

    <logger name="org.springframework.web.servlet">
        <level value="info" />
    </logger>

    <root level="warn"> <!-- (11) -->
        <appender-ref ref="STDOUT" /> <!-- (12) -->
        <appender-ref ref="APPLICATION_LOG_FILE" />
    </root>

</configuration>
項番 説明
(1)
コンソールにログを出力するための、アペンダ定義を指定する。
出力先を標準出力にするか、標準エラーにするか選べるが、指定しない場合は、標準出力となる。
(2)
ログの出力形式を指定する。何も記述しなければ、メッセージだけが出力される。
時刻やメッセージレベルなど、業務要件に合わせて出力させる。
ここでは”ラベル:値<TAB>ラベル:値<TAB>…”形式のLTSV(Labeled Tab Separated Value)フォーマットを設定している。
(3)
アプリケーションログを出力するための、アペンダ定義を指定する。
どのアペンダを使用するかは、<logger>に指定することもできるが、ここではアプリケーションログはデフォルトで使用するため、root(11)に参照させている。
アプリケーションログを出力する際によく使用されるのは、RollingFileAppenderであるが、ログのローテーションをlogrotateなど別機能で実施する場合、FileAppenderを使用することもある。
(4)
カレントファイル名(出力中のログのファイル名)を指定する。固定のファイル名としたい場合は指定すること。
<file>ログファイル名</file>を指定しないと、(5)のパターンの名称で出力される。
(5)
ローテーション後のファイル名を指定する。通常は、日付か時間の形式が、多く採用される。
誤ってHHをhhと設定してしまうと、24時間表記されないため注意すること。
(6)
ローテーションしたファイルをいくつ残すかを指定する。
(7)
ログファイルの文字コードを指定する。
(8)
デフォルトでアプリケーションログが出力されるように設定する。
(9)
ロガー名は、com.example.sample以下のロガーが、debugレベル以上のログを出力するように設定する。
(10)
監視ログの設定を行う。例外ハンドリング共通設定を参照されたい。
(11)
<logger>の指定が無いロガーが、warnレベル以上のログを出力するように設定する。
(12)
デフォルトでConsoleAppender, RollingFileAppender(アプリケーションログ)が使用されるように設定する。

Tip

LTSV(Labeled Tab Separated Value)について

LTSVは、テキストデータのフォーマットの一つであり、主にログのフォーマットとして使用される。

LTSVは、

  • フィールドの区切り文字としてタブを使用することで、他の区切り文字に比べてフォールドを分割しやすい。
  • フィールドにラベル(名前)を設けることで、フィールド定義の変更(定義位置の変更、フィールドの追加、フィールドの削除)を行ってもパース処理には影響を与えない。

また、エクセルに貼付けるだけで最低限のフォーマットが行える点も特徴の一つである。


logback.xmlで設定するものは、次の3つになる。

種類 概要
appender 「どの場所に」「どんなレイアウト」で出力するのか
root デフォルトでは、「どのログレベル」以上で「どのappender」に出力するのか
logger 「どのロガー(パッケージやクラス等)」は、「どのログレベル」以上で出力するのか

<appender>要素には、「どの場所に」「どんなレイアウト」で出力するのかを定義する。 appenderを定義しただけではログ出力の際に使用されず、 <logger>要素や<root>要素に参照されると、初めて使用される。 属性は、nameとclassの2つで、共に必須である。

属性 概要
name appenderの名前。appender-refで指定される。好きな名前をつけてよい。
class appender実装クラスのFQCN。

提供されている主なappenderを、以下に示す

Appender 概要
ConsoleAppender コンソール出力
FileAppender ファイル出力
RollingFileAppender ファイル出力(ローリング可能)
AsyncAppender 非同期出力。性能を求められる処理中のロギングに使用する。(出力先は、他のAppenderで設定する必要がある。)

Appenderの詳細な種類は、公式マニュアルを参照されたい。


5.6.2.2. SLF4JのAPI呼び出しによる基本的なログ出力

SLF4Jのロガー(org.slf4j.Logger)の各ログレベルに応じたメソッドを呼び出してログを出力する。

package com.example.sample.app.welcome;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Controller;
import org.springframework.ui.Model;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;

@Controller
public class HomeController {

    private static final Logger logger = LoggerFactory
            .getLogger(HomeController.class);

    @RequestMapping(value = "/", method = { RequestMethod.GET,
            RequestMethod.POST })
    public String home(Model model) {
        logger.trace("This log is trace log.");
        logger.debug("This log is debug log.");
        logger.info("This log is info log.");
        logger.warn("This log is warn log.");
        logger.error("This log is error log.");
        return "welcome/home";
    }

}
項番 説明
(1)
org.slf4j.LoggerFactoryからLoggerを生成する。getLoggerの引数にClassオブジェクトを
設定した場合は、ロガー名は、そのクラスのFQCNになる。
この例では、”com.example.sample.app.welcome.HomeController”が、ロガー名になる。
(2)
TRACEレベルのログを出力する。
(3)
DEBUGレベルのログを出力する。
(4)
INFOレベルのログを出力する。
(5)
WARNレベルのログを出力する。
(6)
ERRORレベルのログを出力する。

ログの出力結果を、以下に示す。このcom.example.sampleのログレベルは、DEBUGなので、TRACEログは出力されない。

date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:DEBUG logger:com.example.sample.app.welcome.HomeController    message:This log is debug log.
date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:INFO  logger:com.example.sample.app.welcome.HomeController    message:This log is info log.
date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:WARN  logger:com.example.sample.app.welcome.HomeController    message:This log is warn log.
date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:ERROR logger:com.example.sample.app.welcome.HomeController    message:This log is error log.

ログメッセージのプレースホルダに引数を埋め込む場合は、次のように記述すればよい。

int a = 1;
logger.debug("a={}", a);
String b = "bbb";
logger.debug("a={}, b={}", a, b);

以下のようなログが出力される。

date:2013-11-06 20:32:45    thread:tomcat-http--3   X-Track:853aa701a401404a87342a574c69efbc    level:DEBUG logger:com.example.sample.app.welcome.HomeController    message:a=1
date:2013-11-06 20:32:45    thread:tomcat-http--3   X-Track:853aa701a401404a87342a574c69efbc    level:DEBUG logger:com.example.sample.app.welcome.HomeController    message:a=1, b=bbb

Warning

logger.debug("a=" + a + " , b=" + b);というように、文字列連結を行わないように注意すること。

例外をキャッチする際は、 以下のようにERRORログ(場合によってはWARNログ)を出力し、ログメソッドにエラーメッセージと発生した例外を渡す。

public String home(Model model) {
    // ommited

    try {
        throwException();
    } catch (Exception e) {
        logger.error("Exception happend!", e);
        // ommited
    }
    // ommited
}

public void throwException() throws Exception {
    throw new Exception("Test Exception!");
}

これにより、起因例外のスタックトレースが出力され、エラーの原因を解析しやすくなる。

date:2013-11-06 20:38:04    thread:tomcat-http--5   X-Track:11d7dbdf64e44782822c5aea4fc4bb4f    level:ERROR logger:com.example.sample.app.welcome.HomeController    message:Exception happend!
java.lang.Exception: Test Exception!
    at com.example.sample.app.welcome.HomeController.throwException(HomeController.java:40) ~[HomeController.class:na]
    at com.example.sample.app.welcome.HomeController.home(HomeController.java:31) ~[HomeController.class:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_40]
    (omitted)

ただし、以下のようにキャッチした例外を別の例外にラップして、上位に再スローする場合はログを出力しなくてもよい。通常は上位でエラーログが出力されるためである。

try {
    throwException();
} catch (Exception e) {
    throw new SystemException("e.ex.fw.9001", e);
    // no need to log
}

Note

起因例外をログメソッドに渡す場合は、プレースホルダーを使用できない。この場合に限り、 メッセージの引数を文字列で連結してもよい。

try {
    throwException();
} catch (Exception e) {
    // NG => logger.error("Exception happend! [a={} , b={}]", e, a, b);
    logger.error("Exception happend! [a=" + a + " , b=" + b + "]", e);
    // ommited
}

5.6.2.3. ログ出力の記述の注意点

SLF4JのLoggerは、内部でログレベルのチェックを行い、必要なレベルの場合にのみ実際にログを出力する。

したがって、次のようなログレベルのチェックは、基本的に不要である。

if (logger.isDebugEnabled()) {
    logger.debug("This log is Debug.");
}

if (logger.isDebugEnabled()) {
    logger.debug("a={}", a);
}

ただし、次の場合は性能劣化を防ぐために、ログレベルのチェックを行うこと。

  1. 引数が3個以上の場合

    ログメッセージの引数が3以上の場合、SLF4JのAPIでは引数の配列を渡す必要がある。配列生成のコストを避けるため、 ログレベルのチェックを行い、必要なときのみ、配列が生成されるようにすること。

    if (logger.isDebugEnabled()) {
        logger.debug("a={}, b={}, c={}", new Object[] { a, b, c });
    }
    
  2. 引数の生成にメソッド呼び出しが必要な場合

    ログメッセージの引数を生成する際にメソッド呼び出しが必要な場合、メソッド実行コストを避けるため、 ログレベルのチェックを行い、必要なときのみメソッドが実行されるようにすること。

    if (logger.isDebugEnabled()) {
        logger.debug("xxx={}", foo.getXxx());
    }
    

5.6.3. Appendix

5.6.3.1. MDCの使用

MDC(Mapped Diagnostic Context)を利用することで、横断的なログ出力が可能となる。
1リクエスト中に出力されるログに、同じ情報(ユーザー名やリクエストで一意なID)を
埋め込んで出力することにより、ログのトレーサビリティが向上する。
MDCは、スレッドローカルなMapを内部にもち、キーに対して値をputする。removeされるまで、ログにputした値を出力することができる。
Filterなどでリクエストの先頭でputし、処理終了時にremoveすればよい。

5.6.3.1.1. 基本的な使用方法

次に、MDCを用いた例を挙げる。
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class Main {

    private static final Logger logger = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        String key = "MDC_SAMPLE";
        MDC.put(key, "sample"); // (1)
        try {
            logger.debug("debug log");
            logger.info("info log");
            logger.warn("warn log");
            logger.error("error log");
        } finally {
            MDC.remove(key); // (2)
        }
        logger.debug("mdc removed!");
    }
}

logback.xmlの<pattern>%X{キー名}形式で出力フォーマットを定義することで、 MDCに追加した値をログに出力できる。

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tmdcSample:%X{MDC_SAMPLE}\tlevel:%-5level\t\tmessage:%msg%n]]></pattern>
    </encoder>
</appender>

実行結果は、以下のようになる、

date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:DEBUG     message:debug log
date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:INFO      message:info log
date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:WARN      message:warn log
date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:ERROR     message:error log
date:2013-11-08 17:45:48    thread:main mdcSample:  level:DEBUG     message:mdc removed!

Note

MDC.clear()を実行すると、追加したすべての値が削除される。

5.6.3.1.2. FilterでMDCに値をPutする

共通ライブラリからはFilterでMDCへ値の追加・削除するためのベースクラスとして、org.terasoluna.gfw.web.logging.mdc.AbstractMDCPutFilter
を提供している。またその実装クラスとして、
  • リクエスト毎にユニークなIDをMDCに設定するorg.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilter
  • Spring Securityの認証ユーザ名をMDCに設定するorg.terasoluna.gfw.security.web.logging.UserIdMDCPutFilter
を提供している。
Filterで独自の値をMDCを追加したい場合はorg.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilterの実装を参考に
AbstractMDCPutFilterを実装すればよい。

MDCFilterの使用方法

web.xmlのfilter定義にMDCFilterの定義を追加する。

<!-- omitted -->

<!-- (1) -->
<filter>
    <filter-name>MDCClearFilter</filter-name>
    <filter-class>org.terasoluna.gfw.web.logging.mdc.MDCClearFilter</filter-class>
</filter>

<filter-mapping>
    <filter-name>MDCClearFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

<!-- (2) -->
<filter>
    <filter-name>XTrackMDCPutFilter</filter-name>
    <filter-class>org.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilter</filter-class>
</filter>
<filter-mapping>
    <filter-name>XTrackMDCPutFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

<!-- (3) -->
<filter>
    <filter-name>UserIdMDCPutFilter</filter-name>
    <filter-class>org.terasoluna.gfw.security.web.logging.UserIdMDCPutFilter</filter-class>
</filter>
<filter-mapping>
    <filter-name>UserIdMDCPutFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

<!-- omitted -->
項番 説明
(1)
MDCの内容をクリアするMDCClearFilterを設定する。
各種MDCPutFilterが追加したMDCへの値を、このFilterが消去する。
(2)
XTrackMDCPutFilterを設定する。XTrackMDCPutFilterはキー”X-Track”にリクエストIDをputする。
(3)
UserIdMDCPutFilterを設定する。UserIdMDCPutFilterはキー”USER”にユーザーIDをputする。

MDCClearFilterは以下のシーケンス図のように、後処理としてMDCの内容をクリアするため、 各種MDCPutFilterよりも、先に定義すること。

../_images/logging-mdcput-sequence.png

logback.xmlの<pattern>%X{X-Track}および、%X{USER}を追加することで、リクエストIDとユーザーIDをログに出力することができる。

<!-- omitted -->
<appender name="APPLICATION_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>log/projectName-application.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>log/projectName-application-%d{yyyyMMdd}.log</fileNamePattern>
        <maxHistory>7</maxHistory>
    </rollingPolicy>
    <encoder>
        <charset>UTF-8</charset>
        <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tUSER:%X{USER}\tX-Track:%X{X-Track}\tlevel:%-5level\tlogger:%-48logger{48}\tmessage:%msg%n]]></pattern>
    </encoder>
</appender>
<!-- omitted -->

ログの出力例

date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:   X-Track:97988cc077f94f9d9d435f6f76027428    level:DEBUG logger:o.t.g.w.logging.HttpSessionEventLoggingListener  message:SESSIONID#D7AD1D42D3E77D61DB64E7C8C65CB488 sessionCreated : org.apache.catalina.session.StandardSessionFacade@e51960
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    logger:o.t.gfw.web.logging.TraceLoggingInterceptor      message:[START CONTROLLER] HomeController.home(Locale,Model)
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    level:INFO  logger:c.terasoluna.logging.app.welcome.HomeController  message:Welcome home! The client locale is ja.
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    logger:o.t.gfw.web.logging.TraceLoggingInterceptor      message:[END CONTROLLER  ] HomeController.home(Locale,Model)-> view=home, model={serverTime=2013/09/06 23:05:22 JST}
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    logger:o.t.gfw.web.logging.TraceLoggingInterceptor      message:[HANDLING TIME   ] HomeController.home(Locale,Model)-> 36,508,860 ns

Note

UserIdMDCPutFilterがMDCにputするユーザー情報はSpring SecurityのFilterにより作成される。 前述のようにUserIdMDCPutFilterをweb.xmlに定義した場合、ユーザーIDがログに出力されるのは Spring Securityの一連の処理が終わった後になる。ユーザー情報が生成された後、すぐにログに出力したい場合は、 web.xmlの定義は削除して、以下のようにSpring SecurityのFilterに組み込む必要がある。

spring-security.xmlには以下のような定義を追加する。

<sec:http auto-config="true" use-expressions="true">
    <!-- omitted -->
    <sec:custom-filter ref="userIdMDCPutFilter" after="ANONYMOUS_FILTER"/> <!-- (1) -->
    <!-- omitted -->
</sec:http>

<!-- (2) -->
<bean id="userIdMDCPutFilter" class="org.terasoluna.gfw.security.web.logging.UserIdMDCPutFilter">
</bean>
項番 説明
(1)
Bean定義したUserIdMDCPutFilter を”ANONYMOUS_FILTER”の後に追加する。
(2)
UserIdMDCPutFilter を定義する。

blankプロジェクトではUserIdMDCPutFilterをspring-security.xmlに定義している。

5.6.3.2. 共通ライブラリが提供するログ出力関連機能

5.6.3.2.1. HttpSessionEventLoggingListener

org.terasoluna.fw.web.logging.HttpSessionEventLoggingListenerは、 セッションの生成・破棄・活性・非活性、セッションへの属性の追加・削除のタイミングでdebugログを出力するためのリスナークラスである。

web.xmlに、以下を追加すればよい。

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://java.sun.com/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd"
    version="3.0">
    <listener>
        <listener-class>org.terasoluna.gfw.web.logging.HttpSessionEventLoggingListener</listener-class>
    </listener>

    <!-- omitted -->
</web-app>

logback.xmlには、以下のようにorg.terasoluna.gfw.web.logging.HttpSessionEventLoggingListenerを、debugレベルで設定する。

<logger
    name="org.terasoluna.gfw.web.logging.HttpSessionEventLoggingListener"> <!-- (1) -->
    <level value="debug" />
</logger>

以下のようなデバッグログが出力される。

date:2013-09-06 16:41:33    thread:tomcat-http--3   USER:   X-Track:c004ddb56a3642d5bc5f6b5d884e5db2        level:DEBUG     logger:o.t.g.w.logging.HttpSessionEventLoggingListener  message:SESSIONID#EDC3C240A7A1CCE87146A6BA1321AD0F sessionCreated : org.apache.catalina.session.StandardSessionFacade@f00e0f

@SessionAttributeなど、Sessionを使用してオブジェクトのライフサイクルを管理している場合、 本リスナーを利用して、セッションへ追加した属性が、想定通りに削除されているか確認することを、強く推奨する。

5.6.3.2.2. TraceLoggingInterceptor

org.terasoluna.gfw.web.logging.TraceLoggingInterceptorは、 Controllerの処理開始、終了をログ出力するHandlerInterceptorである。 終了時にはControllerが返却したView名とModelに追加された属性、およびControllerの処理に要した時間も出力する。

spring-mvc.xmlの<mvc:interceptors>内に以下のようにTraceLoggingInterceptorを追加する。

<mvc:interceptors>
    <!-- omitted -->
    <mvc:interceptor>
        <mvc:mapping path="/**" />
        <mvc:exclude-mapping path="/resources/**" />
        <bean
            class="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor">
        </bean>
    </mvc:interceptor>
    <!-- omitted -->
</mvc:interceptors>
デフォルトでは、Controllerの処理に3秒以上かかった場合にWARNログを出力する。
この閾値を変える場合は、warnHandlingNanosプロパティにナノ秒単位で指定する。

閾値を10秒(10 * 1000 * 1000 * 1000 ナノ秒)に変更したい場合は以下のように設定すればよい。

<mvc:interceptors>
    <!-- omitted -->
    <mvc:interceptor>
        <mvc:mapping path="/**" />
        <mvc:exclude-mapping path="/resources/**" />
        <bean
            class="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor">
            <property name="warnHandlingNanos" value="#{10 * 1000 * 1000 * 1000}" />
        </bean>
    </mvc:interceptor>
    <!-- omitted -->
</mvc:interceptors>

logback.xmlには、以下のように、org.terasoluna.gfw.web.logging.TraceLoggingInterceptorをtraceレベルで設定する。

<logger name="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor"> <!-- (1) -->
    <level value="trace" />
</logger>

5.6.3.2.3. ExceptionLogger

例外発生時のロガーとして、org.terasoluna.gfw.common.exception.ExceptionLoggerが提供されている。

使用方法は、”例外ハンドリング”の”How to use”を参照されたい。