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

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

[Chapter 8: Mapped Diagnostic Context] (http://logback.qos.ch/manual/mdc.html)

説明

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

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"がキー)。
出力するにはlogback.xmlのログ出力フォーマットに「%X{キー名}」という表記で出力箇所を指定します。
これでログ出力を行うと、ログにMDC.put()で指定した文字列が毎回出力されるようになります。

上記の処理結果として以下のようなログが出力されます。

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しなければそのスレッドに対して設定され続けることになります（勝手に消えたりしません）。スレッドプールを使っているときは、明示的に削除するなどした方が良いです。ある処理で使ったスレッドがそのまま別の処理でも再利用された時に、設定されたMDCの内容が残ったままになるので、ログに誤った情報が出力されることになります。

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] (https://getsentry.com/)のようなログ集約ツールが便利です。
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>