アプリ開発ときどきアウトドア

主にJavaを使ったアプリ開発やトラブルシューティング等のノウハウ、キャンプや登山の紹介や体験談など。

1. システムエンジニアリング Java 実装技術

slf4jで独自ログ項目を追加(MDC)

投稿日:2020年3月5日 更新日:

業務要件、障害発生時の処理追跡や証跡等、ログ出力に特定項目を含めたい場合があります。
共通のログ出力ユーティリティやライブラリを作って、その中でログ出力内容を変更しても良いのですが、MDC(Mapped Diagnostic Context)という仕組みで簡単に実装できます。
なお、ここで前提としているslf4jについて知りたい方は、こちらをご覧ください。

はじめてのMDC

一般的なログ出力ライブラリを使って、任意のメッセージを指定してログを出力すると、指定したメッセージの他に、日時、ログレベル、ロガー(クラス名)等のログ項目も併せて出力されます。MDCを使用すると、このような既定のログ項目の他に、独自のログ項目を出力できるようになります。

また、このようなログ項目をどのような書式で出力するかのログ出力書式は、ログ出力ライブラリの設定ファイルで定義されています。例えば、日時であれば”%d”、ログレベルであれば”%p”等のように定義されており、設定ファイルを変更することで、プログラムを変更せずに柔軟にログ出力仕様を変更できます。MDCで追加したログの項目は、”%X{ログ項目名}”のように、他の項目と同様にログ出力書式で指定できるようになります。

Webアプリのログファイルに、独自のログ項目としてユーザIDを追加する例を説明します。
(Wildfly13で動作するサーブレットやJSF等のJavaプログラムで、SLF4Jを使う前提。)

  • SLF4Jで独自ログ項目を出力する場合、MDCというスタティッククラスを使用します。
    ログ項目”userid”として”a00001″を出力する場合、次のようにMDCクラスを使用します。
        ...
        MDC.put("userid", "a00001");
        ...
        Logger logger = LoggerFactory.getLogger(getClass());
        logger.trace("successfully logined")
        ...
    
  • 上記で出力したログ項目は、設定ファイルで次のように”%{userid}”で指定できます。
    ...
    <pattern-formatter pattern="%d{HH:mm:ss,SSS} %X{userid} %-5p [%c] ... %s%e%n"/>
    ...
    
  • ログ出力は次のようになります。
    上記の”%X{userid}”に対応する位置に”a00001″が出力されます。
    ...
    2020-03-01 20:07:01,126 a00001 TRACE [example.web.servlet.xxx] ... successfully logined
    ...
    

MDCの詳細

  • 複数クライアントからの同時アクセス時のログ出力のパターンとしてMDCが考案されました。これは、”Patterns for Logging Diagnostic Messages in Pattern Languages of Program Design 3″という書籍が原型のようです。
  • 汎用的なロギングAPIであるslf4jでもMDCを使用することができます。ただし、実際にMDCを使ってログを出力するためには、slf4jにバインドされているログ出力ライブラリが対応している必要があります。
  • ポピュラーなログ出力ライブラリである、log4j2logback等はMDCを実装しています。
    Wildfly11/EAP7ではjboss-loggingが使われており、こちらもMDCを実装しています。
  • MDCの基本的な仕組みは、MDCのログ内容をスレッド毎の変数領域に格納しています。そのため、あるリクエスト(スレッド)で出力したログは、そのスレッドのログ出力時のみ有効です。別のリクエスト(スレッド)でのログ出力では参照できません。
  • MDCのログを出力する基本的にはリクエストに対して独自のログ項目を出力する想定であり、サーブレットフィルタ, JSF フェーズリスナ, インターセプター等の比較的に早いタイミングでのログ埋め込みをお薦めします。(MDCログを出力するタイミングが遅すぎると該当項目が空になってしまうので。)
  • スレッドは性能向上のためにスレッドを終了せずに再利用(スレッドプール)する場合があります。このケースでは、前回のリクエストの処理で設定したログ内容が残っている可能性があります。そのため、リクエストの処理終了後に初期化した方が安全です。
  • 参考ですが、MDCと同様にNDC(Nested Diagnostic Context)と呼ばれる方法もあります。MDCはスレッドに対してkey=valueのみの指定ですが、NDCではスレッドで複数の処理を行う際の深さをスタックで表現できるようです。私が業務で使ったことがないので、ここでは割愛します。

業務での活用例

私が業務で使ったことがある例を紹介します。

用途の例(項目名) 説明・用途
ログイン中のユーザID ユーザ認証が完了し、セッション情報に保持されているユーザIDを出力します。特定ユーザの操作やログを追跡する際にユーザIDが各ログ行に含まれていると抽出しやすい。
セッションID セキュリティ要件が厳しいアプリで出力する場合がある。
カンバゼーションID カンバゼーション単位(JavaEEのセッションより小さいスコープ)で操作を追跡する際に便利である。カンバゼーションに不慣れな開発者向けに開発用で出力する場合がある。
X-Forwared-For(XFF)ヘッダ ロードバランサやリバースプロキシの背後にアプリサーバを配置する場合、リクエストの送信元IPアドレスが当該ヘッダに設定される場合があるので、この値を出力する。
コンテキスト名 結合試験等で、あるWebアプリを名前(”/example-web1″, “/example-web2″等のコンテキスト名)を変えて複数デプロイしたい場合がある。これらのWebアプリが同一のログファイルに出力されてしまうと、どのWebアプリからのログか判断できなくなるため、コンテキスト名を出力して判別できるようにする。

サンプル

Webアプリに対する全てのリクエストに対してMDCログを出力できるようにすサーブレットフィルタのサンプルです。
Webアプリのプロジェクトはこちらで公開しています。

サーブレットフィルター

セッションID、HTTPリクエストのHOSTヘッダ値をMDCでログに出力します。
完全なソースはこちらを参照のこと。

...
@WebFilter(filterName = "mdc-filter", urlPatterns = "/*")
public class MDCServletFilter implements Filter {

	// HTTPヘッダ名

	/** HTTPヘッダ名: Host */
	private static final String HTTP_ITEM_HOST = "Host";

	
	// MDC項目名

	/** MDC項目名: host */
	private static final String MDC_ITEM_HOST = "host";

	/** MDC項目名: session_id */
	private static final String MDC_ITEM_SESSION_ID = "session_id";

	
	/** MDC出力値が空の場合の値 */
	private static final String EMPTY_VALUE = "-";

	private Logger logger = LoggerFactory.getLogger(getClass());

	@Override
	public void init(FilterConfig filterConfig) throws ServletException {
		logger.trace("init(): invoked!");
	}

	@Override
	public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
			throws IOException, ServletException
	{
		logger.trace("doFilter(): invoked!");

		// 念のため初期化
		resetMdc();

		// MDC関連
		setupMdc(request);
		logger.trace("doFilterでテストロギング");
		
		try {
			// 本来の業務処理
			chain.doFilter(request, response);
		}finally {
			// 他のスレッドでの誤使用防止
			resetMdc();
		}
	}

	@Override
	public void destroy() {
		logger.trace("destroy(): invoked!");
	}

	private void setupMdc(ServletRequest request) {
		try {

			// HTTP要求以外の場合は何もしない
			if (!(request instanceof HttpServletRequest)) {
				return;
			}
			HttpServletRequest httpRequest = (HttpServletRequest) request;

			// 非セッション関連項目の挿入 --------------------------------------

			// Hostヘッダ
			String hostVal = httpRequest.getHeader(HTTP_ITEM_HOST);
			MDC.put(MDC_ITEM_HOST, hostVal != null ? hostVal : EMPTY_VALUE);

			// セッション関連項目の挿入 ----------------------------------------
			HttpSession ss = httpRequest.getSession(false); // 存在しない場合は作成しない

			// セッションID
			MDC.put(MDC_ITEM_SESSION_ID, ss != null ? ss.getId() : EMPTY_VALUE);

		} catch (Exception e) {
			// 上記のようなロギングは付加的な処理であり、例外が発生しても、
			// 本来の業務処理を止めてはならず、続行すべきである。
			// 念のため、例外の事実を検知できるよう最低限ロギングする。
			logger.warn("unexpected exception: {}", e.getMessage());
		}
	}
	
	private void resetMdc() {
		MDC.clear();
	}
}

Wildfly13設定(standalone.xml)

上記のプログラムで指定したログ項目名(MDC_ITEM_HOST: “host”, MDC_ITEM_SESSION_ID: “session_id”)を、ログ出力書式に指定します。

...
        <subsystem xmlns="urn:jboss:domain:logging:5.0">
...
            <periodic-rotating-file-handler name="FILE" autoflush="true">
                <formatter>
                    <named-formatter name="PATTERN"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="server.log"/>
                <suffix value=".yyyy-MM-dd"/>
                <append value="true"/>
            </periodic-rotating-file-handler>
...
            <logger category="example.web">
                <level name="TRACE"/>
            </logger>
...
            <formatter name="PATTERN">
                <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %X{host} %X{session_id} %-5p [%c] (%t) %s%e%n"/>
            </formatter>
...
        </subsystem>
...

実行結果

...
... 22:09:08,418   INFO  [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: WildFly   started in 17434ms - Started 521 of 713 services (320 services are lazy, passive or on-demand)
... 22:10:55,873   TRACE [example...MDCServletFilter] (default task-1) init(): invoked!
... 22:10:55,877   TRACE [example...MDCServletFilter] (default task-1) doFilter(): invoked!
... 22:10:55,881 localhost:8080 - TRACE [example...MDCServletFilter] (default task-1) doFilterでテストロギング
... 22:10:56,209 localhost:8080 - INFO  [example...HelloWorldView] (default task-1) 初期化
... 22:11:01,552   TRACE [example...MDCServletFilter] (default task-1) doFilter(): invoked!
... 22:11:01,553 localhost:8080 uUmEUCVb...6E9WoB17HY TRACE [example...MDCServletFilter] (default task-1) doFilterでテストロギング
... 22:11:01,566 localhost:8080 uUmEUCVb...6E9WoB17HY INFO  [example...HelloWorldView] (default task-1) 実行
...


(adsbygoogle = window.adsbygoogle || []).push({});


(adsbygoogle = window.adsbygoogle || []).push({});

-1. システムエンジニアリング, Java, 実装技術

執筆者:

関連記事

CentOS7のマルチホーム化

サイトの存在を隠しつつも、sftpサーバを公開し、後輩と1G以上のファイルのやりとりしたい。 パブリック側のIPアドレスを教えてしまうと、どこのサーバだろうかとブラウザで開いたりするとサイトの存在がわ …

システム開発でのmybatis-generatorの利用

システム開発における製造工程の前段では、開発メンバの負荷軽減や共通化のために、各テーブルに対するSELECT/INSERT/UPDATE/DELETEを容易に行うための共通クラスを準備することが望まれ …

Windows10で開発・検証用のプロキシサーバを構築

本番環境でプロキシを介して通信を行うアプリを開発したいが、開発環境ではプロキシがない… そんな時のためにローカルに検証用のプロキシサーバを構築してみます。 概要 Windows 10(64 …

EAP7のインストールとパッチ適用

仕事でredhat社のEnterprise Application Server7(EAP7)を扱うことが多いので備忘録として記載します。 なお、このサイトでWebアプリを公開したいと考えていますが、 …

wildflyへのwarデプロイの自動化

更新したWebアプリをWildflyにデプロイするのが面倒なのでスクリプトを作成してみました。 前提 実行環境はCentOS Linux 7です。 JavaEEのWebアプリの配布形式であるwarファ …

プロフィール ゆっきーです。
都内でシステムエンジニアをやっています。
もっと詳細を見る