5.6. ロギング¶

Caution

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

Overview
How to use
Appendix
- MDCの使用
  - 基本的な使用方法
  - FilterでMDCに値をPutする
- 共通ライブラリが提供するログ出力関連機能

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. ログの出力内容 ¶

ログの出力内容として考慮すべき点を、以下に示す。

ログに出力するIDについて

ログを運用で監視する場合は、運用監視で使用するログに、メッセージIDを含めることを推奨する。

また、アクセスログを用いて業務量を把握する場合は、集計を容易にするため、メッセージ管理で示しているように、業務ごとに切り分けられるIDをあわせて出力すること。

Note

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

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

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

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

トレーサビリティ

トレーサビリティ向上のために、各ログにリクエスト単位で、一意となるような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についてを参照されたい。

ログのマスクについて

個人情報、クレジットカード番号など、

ログファイルにそのまま出力すると、セキュリティ上問題のある情報は、必要に応じてマスクすること。

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でログを出力するには、

Logbackの設定
SLF4JのAPI呼び出し

が必要である。

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);   // (1)

    @RequestMapping(value = "/", method = { RequestMethod.GET,
            RequestMethod.POST })
    public String home(Model model) {
        logger.trace("This log is trace log."); // (2)
        logger.debug("This log is debug log."); // (3)
        logger.info("This log is info log.");   // (4)
        logger.warn("This log is warn log.");   // (5)
        logger.error("This log is error log."); // (6)
        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);
}

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

引数が3個以上の場合
ログメッセージの引数が3以上の場合、SLF4JのAPIでは引数の配列を渡す必要がある。配列生成のコストを避けるため、ログレベルのチェックを行い、必要なときのみ、配列が生成されるようにすること。
if (logger.isDebugEnabled()) { logger.debug("a={}, b={}, c={}", new Object[] { a, b, c }); }
引数の生成にメソッド呼び出しが必要な場合
ログメッセージの引数を生成する際にメソッド呼び出しが必要な場合、メソッド実行コストを避けるため、ログレベルのチェックを行い、必要なときのみメソッドが実行されるようにすること。
if (logger.isDebugEnabled()) { logger.debug("xxx={}", foo.getXxx()); }

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.gfw.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”を参照されたい。

項番	説明
(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)	監視ログの設定を行う。例外ハンドリングの共通設定を参照されたい。 Warning additivityの設定値について `false`を指定すること。`true`(デフォルト値)を指定すると、上位のロガー(例えば、root)によって、同じログが出力されてしまう。具体的には、監視ログは3つのアペンダー(`MONITORING_LOG_FILE`、`STDOUT`、`APPLICATION_LOG_FILE`)によって出力される。
(11)	<logger>の指定が無いロガーが、warnレベル以上のログを出力するように設定する。
(12)	デフォルトでConsoleAppender, RollingFileAppender(アプリケーションログ)が使用されるように設定する。

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

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

Table Of Contents

Previous topic

Next topic

This Page

5.6. ロギング¶

5.6.1. Overview ¶

5.6.1.1. ログの種類 ¶

5.6.1.2. ログの出力内容 ¶

5.6.1.3. ログの出力ポイント ¶

5.6.2. How to use ¶

5.6.2.1. Logbackの設定 ¶

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

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

5.6.3. Appendix ¶

5.6.3.1. MDCの使用 ¶

5.6.3.1.1. 基本的な使用方法 ¶

5.6.3.1.2. FilterでMDCに値をPutする ¶

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

5.6.3.2.1. HttpSessionEventLoggingListener ¶

5.6.3.2.2. TraceLoggingInterceptor ¶

5.6.3.2.3. ExceptionLogger ¶

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

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