logback+MDCでWebアプリのリクエスト内容を簡単にログに出力する方法

logbackにはMapped Diagnostic Contexts (MDC)というログに追加情報を付与する機能があります。
この機能は、Webアプリでログ出力を行う時にはとても便利です。

説明

簡単な例を以下に記述します。

class MyAppController {
  org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger("myapp");

  public void indexAction()  {
    MDC.put("action", "index");

    logger.debug("logging in indexAction");
    func();

    MDC.remove("action");
  }

  private void func() {
    logger.debug("logging in func");
  }
}

logback.xml

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%date %level %logger{64} [%X{action}] %msg%n</pattern>
    </encoder>
</appender>

MDC.put()で任意のキー名に対して出力したい文字列を指定します。(ここでは"action"というキー)
こうしておいた上で、ログ出力を行うとその出力時にMDC.put()で指定した文字列が毎回出力されるようになります。
出力するにはlogback.xmlのログ出力フォーマットに「%X{キー名}」という表記で出力箇所を指定します。

上記の処理結果として以下のようなログが出力されます。
2014-08-10 19:00:00,000 DEBUG myapp [index] logging in indexAction 2014-08-10 19:00:01,000 DEBUG myapp [index] logging in func

MDC.put()で指定した内容はスレッドローカルな値で、そのスレッド内のすべてのログ出力箇所に影響します。
出力が不要になったキーは、MDC.remove()で削除します。（removeしなければリークになるかも)

Webアプリケーションでの利用

この機能は、Webアプリケーションのログにはかなり有効です。
logbackには、ch.qos.logback.classic.helpers.MDCInsertingServletFilterというServletFilterが用意されています。
このフィルタを、web.xmlですべてのパスに適応しておくだけでHTTPのリクエスト内容をMDCに設定してくれます。

このフィルタの実装は以下で参照できますが、かなりシンプルでわかりやすいものです。
http://logback.qos.ch/xref/ch/qos/logback/classic/helpers/MDCInsertingServletFilter.html

これを参考にすることで、例えば「ログインが必要なWebサイトで、すべてのログ出力にアクセスしたユーザIDを一緒に出力する」といったことが簡単に実現できます。

MDCの出力先

このMDCの機能は便利ですが、１行のログに様々な内容を出力しても読みづらくなってしまいます。
そういう場合にはSentryのようなログ集約ツールが便利です。
Sentryは総合的なログの集約Webアプリで、１件ごとのログ出力内容をWeb画面で表示でき、MDCで指定したすべての内容を見やすく表形式で表示してくれます。

logbackでの出力の設定方法は、raven-logback という公式のクライアントを使うことでを使うことで以下のようにAppenderとして指定するだけで簡単に利用できます。

logback.xml

<configuration>
    <appender name="Sentry" class="net.kencochrane.raven.logback.SentryAppender">
        <dsn>https://publicKey:secretKey@host:port/1?options</dsn>
        <tags>tag1:value1,tag2:value2</tags>
        <!-- Optional, allows to select the ravenFactory -->
        <!--<ravenFactory>net.kencochrane.raven.DefaultRavenFactory</ravenFactory>-->
    </appender>

    <root level="warn">
        <appender-ref ref="Sentry"/>
    </root>
</configuration>

補足

Sentryに関しては、MDCInsertingServletFilterを使うよりもSentryのクライアントライブラリに含まれるnet.kencochrane.raven.servlet.RavenServletRequestListenerを使った方が、Sentryに沿ったログ出力ができるようです。

使い方は、web.xmlでこのクラスをlistenerに追加するだけです。

web.xml

    <listener>
        <listener-class>net.kencochrane.raven.servlet.RavenServletRequestListener</listener-class>
    </listener>