第8章 診断コンテキスト

logbackの設計目標の1つとして、複雑な分散アプリケーションの監査とデバッグに使うことがあります。現実世界のほとんどの分散型システムは、同時に複数のクライアントの相手をしなければなりません。こういうシステムの典型的なマルチスレッドの実装は、スレッドが別々のクライアントを処理するものです。それぞれのクライアントに対するログ出力を分離するために実際に行われているアプローチは、クライアントごとに新しいロガーを用意するという少々残念なものです。このやり方ではやたらめったらロガーを生成することになりますし、管理のためのオーバーヘッドも馬鹿になりません。

もう少し軽めのやり方としては、リクエストを受け付けたクライアントの固有の情報をログに出力する方法があります。この方法は書籍「Patterns for Logging Diagnostic Messages in Pattern Languages of Program Design 3」（Addison-Wesley, 1997）でニール・ハリソンが紹介しています。logback が利用しているのはSLF4J API の診断コンテキスト（MDC）で、これはさっき紹介した技法を応用したものです。

リクエストごとの固有の情報として、利用者はコンテキストの情報をMDC（Mapped Diagnostic Contextの略です）に設定します。MDCクラスの特筆すべき部分を紹介します。メソッドの完全な説明はMDCのjavadocを参照してください。

package org.slf4j;

public class MDC {
  //Put a context value as identified by key
  //into the current thread's context map.
  public static void put(String key, String val);

  //Get the context identified by the key parameter.
  public static String get(String key);

  //Remove the context identified by the key parameter.
  public static void remove(String key);

  //Clear all entries in the MDC.
  public static void clear();
}

MDCクラスには静的メソッドしかありません。おかげで、開発者が診断コンテキストに設定した情報は、logback のありとあらゆるコンポーネントから取得できるようになるのです。MDCはコンテキストの情報をスレッドごとに管理します。子スレッドは、親の診断コンテキストのコピーを自動的に継承します。普通なら、開発者はクライアントから受け付けた新しい要求の処理を始めるところで、クライアント識別子、IPアドレス、リクエストパラメーターなどの適切なコンテキスト情報をMDCに設定します。logback のコンポーネントがちゃんと設定されていれば、こういった情報は自動的にログ項目に含まれるようになります。

logback-classic の MDC 実装は、値の書き込みが比較的穏やかに行われることを想定しているのでくれぐれも注意してください。

SimpleMDCアプリケーションを使ってこの基本原則を説明しましょう。

例7.1：MDCの基本的な使い方（logback-examples/src/main/java/chapters/mdc/SimpleMDC.java）

package chapters.mdc;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import ch.qos.logback.classic.PatternLayout;
import ch.qos.logback.core.ConsoleAppender;

public class SimpleMDC {
  static public void main(String[] args) throws Exception {

    // You can put values in the MDC at any time. Before anything else
    // we put the first name
    MDC.put("first", "Dorothy");

    [ SNIP ]
    
    Logger logger = LoggerFactory.getLogger(SimpleMDC.class);
    // We now put the last name
    MDC.put("last", "Parker");

    // The most beautiful two words in the English language according
    // to Dorothy Parker:
    logger.info("Check enclosed.");
    logger.debug("The most beautiful two words in English.");

    MDC.put("first", "Richard");
    MDC.put("last", "Nixon");
    logger.info("I am not a crook.");
    logger.info("Attributed to the former US president. 17 Nov 1973.");
  }

  [ SNIP ]

}

mainメソッドでは、まずキーfirstで値DrothyをMDCに設定します。MDCに指定するキーも値も利用者の自由です。同じキーで書き込むと前の値を上書きします。コード上ではlogbackの設定が行われているところです。

簡潔にするため、logbackをsimpleMDC.xmlで設定しているところは省略しました。設定ファイル中の該当する箇所は次のようになっています。

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> 
  <layout>
    <Pattern>%X{first} %X{last} - %m%n</Pattern>
  </layout> 
</appender>

PatternLayoutの変換パターン文字列中の%X変換指定子の使い方を見てください。％X変換指定子二回登場しています。一つ目のキーにはfirst、二つ目のキーにはlastを指定しています。SimpleMDC.classのロガーを取得した後で、MDCにキーlastで値Parkerを設定しています。それから、メッセージを変えて二回ロギング要求を発行しています。最後に、また別の値をMDCに設定してから、いくつかロギング要求を発行しています。SimpleMDCを実行すると次のような出力になります。

Dorothy Parker - Check enclosed.
Dorothy Parker - The most beautiful two words in English.
Richard Nixon - I am not a crook.
Richard Nixon - Attributed to the former US president. 17 Nov 1973.

SimpleMDCアプリケーションを見れば、logbackを適切に設定すると、MDCの値がどのようにレイアウトされて出力されるのかがわかります。また、MDCに設定された情報はロガーの呼び出し一度だけでなく、何度も利用できることがわかります。

応用

診断コンテキストが一番脚光を浴びるのはクライアント・サーバーアーキテクチャだ。一般的に、複数のクライアントはサーバ上の複数のスレッドで処理されます。しかしMDCクラスには静的メソッドしかないので、診断コンテキストはスレッドごとに管理するしかありません。つまり、サーバー上のスレッドそれぞれがMDCの分のコストを負うことになるのです。MDCのput()やget()ような操作は、現在のスレッドと子スレッドのMDCにしか影響しません。他のスレッドのMDCは影響を受けないのです。MDCの情報はスレッドごとに管理されているので、それぞれのスレッドは自分用のMDCを持っていることになります。したがって、開発者はスレッド安全性やスレッド間同期のことを考える必要はありません。MDCはそういったことを安全に、透過的に扱えるのです。

次の例は少し凝っています。クライアント・サーバ環境でどのようにMDCを使うのか説明したものです。サーバーは例7.2のNumberCrucherインターフェイスを実装します。The NumberCruncherインターフェイスには、factor()というメソッドが1つあるだけです。クライアントは、RMIによってサーバアプリケーションのfactor()メソッドを呼び出して、指定した整数の素因数を取得します。

例7.2：サービスインターフェイス（logback-examples/src/main/java/chapters/mdc/NumberCruncher.java）

package chapters.mdc;

import java.rmi.Remote;
import java.rmi.RemoteException;

/**
 * NumberCruncher factors positive integers.
 */
public interface NumberCruncher extends Remote {
  /**
   * Factor a positive integer number and return its
   * distinct factor's as an integer array.
   * */
  int[] factor(int number) throws RemoteException;
}

例7.3のNumberCruncherServerアプリケーションがNumberCruncherインターフェイスを実装しています。mainメソッドはlocalhost上でRMIレジストリを公開して、well-knownポートでリクエストを待ち受けます。

例7.3：サーバー実装（logback-examples/src/main/java/chapters/mdc/NumberCruncherServer.java）

package chapters.mdc;

import java.rmi.RemoteException;
import java.rmi.registry.LocateRegistry;
import java.rmi.registry.Registry;
import java.rmi.server.UnicastRemoteObject;
import java.util.Vector;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.joran.JoranConfigurator;
import ch.qos.logback.core.joran.spi.JoranException;


/**
 * A simple NumberCruncher implementation that logs its progress when
 * factoring numbers. The purpose of the whole exercise is to show the
 * use of mapped diagnostic contexts in order to distinguish the log
 * output from different client requests.
 * */
public class NumberCruncherServer extends UnicastRemoteObject
  implements NumberCruncher {

  private static final long serialVersionUID = 1L;

  static Logger logger = LoggerFactory.getLogger(NumberCruncherServer.class);

  public NumberCruncherServer() throws RemoteException {
  }

  public int[] factor(int number) throws RemoteException {
    // The client's host is an important source of information.
    try {
      MDC.put("client", NumberCruncherServer.getClientHost());
    } catch (java.rmi.server.ServerNotActiveException e) {
      logger.warn("Caught unexpected ServerNotActiveException.", e);
    }

    // The information contained within the request is another source
    // of distinctive information. It might reveal the users name,
    // date of request, request ID etc. In servlet type environments,
    // useful information is contained in the HttpRequest or in the  
    // HttpSession.
    MDC.put("number", String.valueOf(number));

    logger.info("Beginning to factor.");

    if (number <= 0) {
      throw new IllegalArgumentException(number +
        " is not a positive integer.");
    } else if (number == 1) {
      return new int[] { 1 };
    }

    Vector<Integer> factors = new Vector<Integer>();
    int n = number;

    for (int i = 2; (i <= n) && ((i * i) <= number); i++) {
      // It is bad practice to place log requests within tight loops.
      // It is done here to show interleaved log output from
      // different requests. 
      logger.debug("Trying " + i + " as a factor.");

      if ((n % i) == 0) {
        logger.info("Found factor " + i);
        factors.addElement(new Integer(i));

        do {
          n /= i;
        } while ((n % i) == 0);
      }

      // Placing artificial delays in tight loops will also lead to
      // sub-optimal results. :-)
      delay(100);
    }

    if (n != 1) {
      logger.info("Found factor " + n);
      factors.addElement(new Integer(n));
    }

    int len = factors.size();

    int[] result = new int[len];

    for (int i = 0; i < len; i++) {
      result[i] = ((Integer) factors.elementAt(i)).intValue();
    }

    // clean up
    MDC.remove("client");
    MDC.remove("number");

    return result;
  }

  static void usage(String msg) {
    System.err.println(msg);
    System.err.println("Usage: java chapters.mdc.NumberCruncherServer configFile\n" +
      "   where configFile is a logback configuration file.");
    System.exit(1);
  }

  public static void delay(int millis) {
    try {
      Thread.sleep(millis);
    } catch (InterruptedException e) {
    }
  }

  public static void main(String[] args) {
    if (args.length != 1) {
      usage("Wrong number of arguments.");
    }

    String configFile = args[0];

    if (configFile.endsWith(".xml")) {
      try {
        LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
        JoranConfigurator configurator = new JoranConfigurator();
        configurator.setContext(lc);
        lc.reset();
        configurator.doConfigure(args[0]);
      } catch (JoranException je) {
        je.printStackTrace();
      }
    }

    NumberCruncherServer ncs;

    try {
      ncs = new NumberCruncherServer();
      logger.info("Creating registry.");

      Registry registry = LocateRegistry.createRegistry(Registry.REGISTRY_PORT);
      registry.rebind("Factor", ncs);
      logger.info("NumberCruncherServer bound and ready.");
    } catch (Exception e) {
      logger.error("Could not bind NumberCruncherServer.", e);

      return;
    }
  }
}

特に大事なのがfactor(int number)メソッドの実装です。最初に、MDCへキーclientでクライアントのホスト名を設定しています。そして、クライアントから渡された素因数分解する数をキーnumberでMDCに設定します。計算が終わったらクライアントに結果を返します。ですが、結果を返す前に、キーclientとキーnumberで設定された値をクリアするため、MDC.remove()メソッドを呼んでいます。普通ならput()操作とremove()操作が同じ数だけ登場するべきです。そうしないと、MDCに特定のキーの値が残ってしまうからです。出来る限りremove()操作をfinallyブロックで実行するように仕込んでおくことをおすすめします。確実に実行されることを保証するためです。

理屈っぽい説明が続きましたが、cruncer アプリケーションを実行する準備が整いました。次のコマンドを実行してサーバーを起動しましょう。

java chapters.mdc.NumberCruncherServer src/main/java/chapters/mdc/mdc1.xml

mdc1.xmlの内容は次のとおりです。

例7.4：設定ファイル（logback-examples/src/main/java/chapters/mdc/mdc1.xml）

<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <layout>
      <Pattern>%-4r [%thread] %-5level C:%X{client} N:%X{number} - %msg%n</Pattern>
    </layout>	    
  </appender>
  
  <root level="debug">
    <appender-ref ref="CONSOLE"/>
  </root>  
</configuration>

パターン·オプションに％X変換指定子が使われているのを見てください。

次のコマンドでNumberCruncherClientアプリケーションを実行しましょう。

java chapters.mdc.NumberCruncherClient hostname

hostnameの部分にはNumberCruncherServerを実行しているサーバのホスト名を指定します。

複数のクライアントを実行して、最初に起動したクライアントがサーバに129を要求して、その後すぐに二つ目のクライアントから71を要求したときのサーバ側のコンソールには、次のように出力されています。

70984 [RMI TCP Connection(4)-192.168.1.6] INFO  C:orion N:129 - Beginning to factor.
70984 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 2 as a factor.
71093 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 3 as a factor.
71093 [RMI TCP Connection(4)-192.168.1.6] INFO  C:orion N:129 - Found factor 3
71187 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 4 as a factor.
71297 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 5 as a factor.
71390 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 6 as a factor.
71453 [RMI TCP Connection(5)-192.168.1.6] INFO  C:orion N:71 - Beginning to factor.
71453 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 2 as a factor.
71484 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 7 as a factor.
71547 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 3 as a factor.
71593 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 8 as a factor.
71656 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 4 as a factor.
71687 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 9 as a factor.
71750 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 5 as a factor.
71797 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 10 as a factor.
71859 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 6 as a factor.
71890 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 11 as a factor.
71953 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 7 as a factor.
72000 [RMI TCP Connection(4)-192.168.1.6] INFO  C:orion N:129 - Found factor 43
72062 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 8 as a factor.
72156 [RMI TCP Connection(5)-192.168.1.6] INFO  C:orion N:71 - Found factor 71

クライアントはorionというホスト名のマシンで実行されていることがわかります。サーバーがほぼ同時に別のスレッドでクライアントの要求を処理する場合でも、それぞれのクライアントからのリクエストによるログ出力は、MDCの出力を見れば分かるようになっています。たとえば、numberとして印付けられた素因数分解する数です。

注意深い人なら、スレッド名を見るだけでもリクエストを区別できることが分かるでしょう。サーバ側の実装がスレッドを再利用するようになっていると混乱させられるかもしれません。そうなってしまったら、いつリクエストを受け付けて、いつ応答を返したのかを特定するのは難しいかもしれません。MDCを管理するのはアプリケーション開発者なので、そういった問題が起きることはありません。

MDCへの自動的なアクセス

これまでに見てきたように、MDCがあると複数のクライアントの相手をするとき便利です。ユーザー認証のあるWebアプリケーションなら、MDCにユーザー名を設定して、ログアウトするときにそれを削除するようにしておくのが、1つの簡単なソリューションになるでしょう。残念ながら、そのテクニックを使っていても常に確実な結果を得られるわけではありません。MDCがスレッド毎にデータを管理している限り、サーバがスレッドをリサイクするようになっていると、間違った情報が設定されていることがあるかもしれません。

リクエストを処理するとき、いつでもMDCに正しい情報が設定されていることを確実にするためにできるのは、処理の始めにユーザー名を設定して、処理の終わりに削除することです。こういう場合サーブレットFilterを使うとよいでしょう。

サーブレットフィルターのdoFilter()メソッドで、リクエストに関連する情報（cookieも）を集めて、それをMDCに設定するのです。他のフィルターで行う後続処理やサーブレットからは、自動的に今設定したばかりのMDCの情報を参照することができます。最後にまたサーブレットフィルターが仕事をするとき、MDCに設定した内容を削除することができます。

フィルターの実装例を見てみましょう。

例7.5：ユーザー名サーブレットフィルター（logback-examples/src/main/java/chapters/mdc/UserServletFilter.html）

package chapters.mdc;

import java.io.IOException;
import java.security.Principal;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpSession;

import org.slf4j.MDC;

public class UserServletFilter implements Filter {

  private final String USER_KEY = "username";
  
  public void destroy() {
  }

  public void doFilter(ServletRequest request, ServletResponse response,
    FilterChain chain) throws IOException, ServletException {

    boolean successfulRegistration = false;

    HttpServletRequest req = (HttpServletRequest) request;    
    Principal principal = req.getUserPrincipal();
    // Please note that we could have also used a cookie to 
    // retrieve the user name

    if (principal != null) {
      String username = principal.getName();
      successfulRegistration = registerUsername(username);
    } 

    try {
      chain.doFilter(request, response);
    } finally {
      if (successfulRegistration) {
        MDC.remove(USER_KEY);
      }
    }
  }

  public void init(FilterConfig arg0) throws ServletException {
  }
  

  /**
   * Register the user in the MDC under USER_KEY.
   * 
   * @param username
   * @return true id the user can be successfully registered
   */
  private boolean registerUsername(String username) {
    if (username != null && username.trim().length() > 0) {
      MDC.put(USER_KEY, username);
      return true;
    }
    return false;
  }
}

doFilter()メソッドが呼ばれたら、最初にリクエストオブジェクトからjava.security.Principalオブジェクトを取得します。このオブジェクトからは、現在認証されているユーザーのユーザー名を取得することができます。ユーザー情報があったらそれをMDCに設定します。

フィルターチェインが完了すると、フィルターではMDCからユーザー情報を削除します。

ここで紹介したやり方は、スレッドがリクエストを処理している間だけMDCに値を設定するものです。他のスレッドは影響を受けません。さらに、あらゆるスレッドが、任意の時点で正確なMDCデータを持つようになります。

MDCおよび管理スレッド

ワーカースレッドが自身を初期化するとき、どんなときでも診断コンテキストを継承するわけではありません。これはjava.util.concurrent.Executorsがスレッドを管理しているときに発生します。例えば、 newCachedThreadPoolはThreadPoolExecutorオブジェクトを作成しますが、他のスレッドプールを生成するコードでも、スレッドの生成は複雑なロジックになっています。

そういう場合、元のスレッド（master）でタスクをエグゼキューターに渡す前に、MDC.getCopyOfContextMap()メソッドを呼ぶようにするとよいでしょう。タスクが実行されるとき、まず最初にMDC.setContextMapValues()メソッドを呼ぶようにするべきです。そうすると新しいExecutorのスレッドに、元のMDCの値を関連付けることができます。

MDCInsertingServletFilter

Webアプリケーションでは、受け付けたHTTPリクエストに関連するホスト名、リクエストURI、ユーザーエージェント文字列などがわかるようになっていると便利なのはよくご存知だと思います。MDCInsertingServletFilterはMDCに次のようなキーと値を設定します。

MDCInsertingServletFilterを使用するには、Webアプリケーションのweb.xmlに次の設定を追加します。

<filter>
  <filter-name>MDCInsertingServletFilter</filter-name>
  <filter-class>
    ch.qos.logback.classic.helpers.MDCInsertingServletFilter
  </filter-class>
</filter>
<filter-mapping>
  <filter-name>MDCInsertingServletFilter</filter-name>
  <url-pattern>/*</url-pattern>
</filter-mapping> 

複数のフィルターを使用している場合、MDCInsertingServletFilterを他のフィルターより先に宣言するようにしてください。 たとえば、アプリケーションの主な処理がフィルター'F'で行われるとしたら、その前にMDCInsertingServletFilterを置かないと、MDCに設定される値を'F'から参照することはできません。

フィルターを配置したら、上記のMDCのキーを%X変換指定子で使えるようになります。例えば、リモートホストとリクエストURIを一行に出したければ、次のような変換パターン文字列を指定すればよいでしょう。

%X{req.remoteHost} %X{req.requestURI}%n%d - %m%n