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

2020年3月5日
2023年1月6日
Java, システムエンジニアリング, 実装技術

1 はじめに
2 はじめてのMDC
3 MDCの詳細
4 業務での活用例
5 サンプル

はじめに

業務要件、障害発生時の処理追跡や証跡等、ログ出力に特定項目を含めたい場合があります。
共通のログ出力ユーティリティやライブラリを作って、その中でログ出力内容を変更しても良いのですが、MDC(Mapped Diagnostic Context)という仕組みで簡単に実装できます。
なお、ここで前提としているslf4jについて知りたい方は、こちらをご覧ください。
ログ全般の設計・実装ポリシーに興味がある方には、こちらが参考になれば幸いです。
NDW
経験から思うログの設計・実装ポリシー
一般的なログ種別・ログ出力項目の紹介、例外時や稼働監視システムを考慮したログ設計の注意点等を紹介します。また、実装時のロ…

はじめての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") ...
1
2
3
4
5
6
    ...
    MDC.put("userid", "a00001");
    ...
    Logger logger = LoggerFactory.getLogger(getClass());
    logger.trace("successfully logined")
    ...
上記で出力したログ項目は、設定ファイルで次のように”%{userid}”で指定できます。
standalone.xml
...<pattern-formatter pattern="%d{HH:mm:ss,SSS} %X{userid} %-5p [%c] ... %s%e%n"/>...
1
2
3
...
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %X{userid} %-5p [%c] ... %s%e%n"/>
...
ログ出力は次のようになります。
上記の”%X{userid}”に対応する位置に”a00001″が出力されます。
server.log
1
2
3
...
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にバインドされているログ出力ライブラリが対応している必要があります。
ポピュラーなログ出力ライブラリである、log4j2、logback等は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 = "private static final String HTTP_ITEM_HOST = "Host";// MDC項目名private static final String MDC_ITEM_HOST = "host";private static final String MDC_ITEM_SESSION_ID = "session_id";private static final String EMPTY_VALUE = "-";private Logger logger = LoggerFactory.getLogger(getClass());@Overridepublic void init(FilterConfig filterConfig) throws ServletException {logger.trace("init(): invoked!");}@Overridepublic 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();}}@Overridepublic 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); // 存在しない場合は作成しない// セッションIDMDC.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();}}

...

@WebFilter(filterName = "mdc-filter", urlPatterns = "

private static final String HTTP_ITEM_HOST = "Host";

// MDC項目名

private static final String MDC_ITEM_HOST = "host";

private static final String MDC_ITEM_SESSION_ID = "session_id";

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>...

...

...

<periodic-rotating-file-handler name="FILE" autoflush="true">

<named-formatter name="PATTERN"/>

</formatter>

</periodic-rotating-file-handler>

...

</logger>

...

<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) 実行

...