第9章 ログの分離

問題：ログの分離

本章では、同じWebコンテナあるいはEJBコンテナ上で稼働する複数のアプリケーションで、ログを分離するにはどうすればいいのか検討します。文中で"application"という言葉を使う時は、WebアプリケーションかJ2EEアプリケーションのどちらかを表しています。分離されたログ環境では、それぞれのアプリケーションは独立したlogback環境になります。したがって、アプリケーションのlogbackの設定は、他の設定には影響しません。技術的な言葉で言うと、それぞれのWebアプリケーションは専用の独立したLoggerContextを使用します。logbackに話を戻します。LoggerContextに生成されたロガーオブジェクトは、メモリ上に残っている間はLoggerContextに割り当てられたままです。類似の問題として、アプリケーションのロギングとコンテナのロギングの分離、というものがあります。

一番簡単でわかりやすい方法

コンテナが子孫優先クラスローディングをサポートしていることにしましょう。その場合 slf4j と logback の jar ファイルをアプリケーション自体に含めるようにすればログを分離することができます。WebアプリケーションならWEB-INF/libディレクトリの下に置くだけで、アプリケーションごとのロギングを分離するには十分です。logbackがメモリにロードされるとき、WEB-INF/classesに置かれたlogback.xmlのコピーが選ばれます。

コンテナがクラスローダーを別々にしてくれるので、Webアプリケーションは自分のLoggerContextに自分のlogback.xmlを選ばせることができます。

朝飯前です。

少し正確さにかけますね・・・SLF4Jとlogbackを全てのアプリケーションからアクセスできる場所に置かなければならないこともあるでしょう。共有ライブラリがSLF4Jを使っている場合などです。そうすると、全てのアプリケーションは同じlogback環境を共有することになってしまいます。他にも、全てのアプリケーションから参照できる場所にSLF4Jとlogbackを置かなければならないような状況はあるでしょう。そして、それはクラスローダー分離に基づくログの分離を不可能にしてしまいます。絶望しなくてもいいですよ。まだ希望は残されています。読み進めてください。

コンテキストセレクタ

logbackにはメモリにロードされている単一のインスタンスによって複数のLoggerContextを扱う仕組みがあります。次のように書いたとしましょう。

Logger logger = LoggerFactory.getLogger("foo");

LoggerFactoryのgetLogger()メソッドは、SLF4JのバインディングにILoggerFactoryを問い合わせます。SLF4Jがlogbackにバインドされているときは、ILoggerFactoryを返すというタスクが、ContextSelectorに委譲されるのです。ContextSelectorは常にLoggerContextのインスタンスを返すので気をつけておきましょう。ContextSelectorは、ILoggerFactoryインターフェイスを実装しています。言い換えると、コンテキストセレクタは独自の基準に従ってLoggerContextのインスタンスを返すことができるのです。だからコンテキストセレクタという名前なのです。

デフォルトでは、logbackバインディングはDefaultContextSelectorを使います。これは、デフォルトのロガーコンテキストと呼ばれる常に同じLoggerContextを返します。

システムプロパティのlogback.ContextSelectorを使うと、別のコンテキストセレクタを指定することができます。コンテキストセレクタにmyPackage.myContextSelectorを指定したければ、次のように指定すればよいのです。

-Dlogback.ContextSelector=myPackage.myContextSelector

コンテキストセレクタは、ContextSelectorインターフェイスを実装しなければなりません。そして、LoggerContextを唯一の引数とするコンストラクタが必要です。

ContextJNDISelector

logback-classic の配布物にはContextJNDISelectorというコンテキストセレクタが含まれています。これは JNDI を介して参照できるロガーコンテキストを選択できるようにするものです。これは J2EE の仕様にある JNDI のデータ分離に基づいています。したがって、同じ環境変数を使って、アプリケーションごとに異なる値を渡すことが出来るようになります。言い換えると、単独のLoggerFactoryを全てのアプリケーションで共有している状態でも、それぞれのアプリケーションによるLoggerFactory.getLogger()の呼び出しに対して、独立したロガーコンテキストに割り当てられたロガーを返すようになるのです。これでログを分離することができるでしょう。

ContextJNDISelectorを有効化するには、システムプロパティのlogback.ContextSelectorに"JNDI"を指定します。

-Dlogback.ContextSelector=JNDI

JNDIという値は、ch.qos.logback.classic.selector.ContextJNDISelectorの省略形です。

JNDI変数の設定

それぞれのアプリケーションが、専用のコンテキスト名を設定しなければなりません。Webアプリケーションの場合、JNDI環境変数はweb.xmlで指定します。アプリケーション名が "knobi" なら、web.xml に次のような設定を追加すればよいでしょう。

<env-entry>
  <env-entry-name>logback/context-name</env-entry-name>
  <env-entry-type>java.lang.String</env-entry-type>
  <env-entry-value>kenobi</env-entry-value>
</env-entry>

ContextJNDISelectorが有効になっているとしたら、kenobiアプリケーションのロガーは"kenobi"ロガーコンテキストに割り当てられたものになっているでしょう。また、"kenobi"ロガーコンテキストの設定ファイルは、命名規約にしたがって logback-kenobi.xmlという名前になります。スレッドコンテキストクラスローダーのリソースから見つけて初期化に使われます。つまり、kenobiアプリケーションのWEB-INF/classesの下にlogback-kenobi.xmlを配置しておかなければなりません。

"logback/configuration-resource" という JNDI 環境変数を使えば、命名規約に関わらず他の名前の設定ファイルを使うこともできます。例えば、kenobiアプリケーションで命名規約に従ったlogback-kenobi.xmlではなくaFolder/my_config.xmlを使うとしたら、次のような設定をweb.xmlに追加することになります。

<env-entry>
  <env-entry-name>logback/configuration-resource</env-entry-name>
  <env-entry-type>java.lang.String</env-entry-type>
  <env-entry-value>aFolder/my_config.xml</env-entry-value>
</env-entry>

my_config.xmlは、WEB-INF/classes/aFolder/の下に置かなければなりません。設定ファイルは、現在のスレッドのコンテキストクラスローダーによってJavaのリソースと同じように探索されるということを覚えておいてください。

ContextJNDISelectorを使うためのTomcatの設定

まず、logback.jar（logback-classic-1.1.2.jar logback-core-1.1.1.jar slf4j-api-1.7.6.jar）をTomcatのグローバルな共有クラスフォルダ（shared）に置きましょう。Tomcat 6.x の場合は、$TOMCAT_HOME/lib の下に置いてください。

そして、$TOMCAT_HOME/bin/catalina.sh（Windows の場合は catalina.bat）の適切な場所で、次のようにシステムプロパティのlogback.ContextSelectorを設定してください。

JAVA_OPTS="$JAVA_OPTS -Dlogback.ContextSelector=JNDI"

ホットデプロイ

アプリケーションがリサイクルされるとき、あるいは、シャットダウンするとき、利用中のLoggerContextはクローズしましょう。確実にガベージコレクションされるためには欠かせません。声を大にしておすすめします。logbackの配布物にはContextDetachingSCLというServletContextListenerが含まれています。これは古いアプリケーションのインスタンスに関連付けられているContextSelectorをデタッチするためだけに用意されたものです。web.xmlに次のような設定を追加すれば有効になります。

<listener>
  <listener-class>ch.qos.logback.classic.selector.servlet.ContextDetachingSCL</listener-class>
</listener>

ほぼ全てのコンテナ実装は、web.xml に記載された順番でリスナーのcontextInitialized()メソッドを呼び出します。ですが、contextDestroyed()メソッドの呼び出される順番は記載された順番の逆順です。つまり、web.xmlに複数のServletContextListenerを宣言している場合は、ContextDetachingSCLを先頭で宣言しなければならないということです。そうすれば、contextDestroyed()メソッドは一番最後に呼び出されるようになります。

パフォーマンスの改善

ContextJNDISelectorが有効になっていると、ロガーを取得するたびにJNDIの検索が行われるようになります。このことが、性能に悪影響を及ぼす可能性があります。特に静的変数ではない（インスタンス変数の）ロガーを使っている場合はその可能性は高まります。logbackの配布物にはLoggerContextFilterというサーブレットフィルターが含まれています。これはJNDIの検索にかかるコストを解消するために設計されたものです。web.xmlに次のような設定を追加すれば有効になります。

<filter>
  <filter-name>LoggerContextFilter</filter-name>
  <filter-class>ch.qos.logback.classic.selector.servlet.LoggerContextFilter</filter-class>
</filter>
<filter-mapping>
  <filter-name>LoggerContextFilter</filter-name>
  <url-pattern>/*</url-pattern>
</filter-mapping>

HTTPリクエストを受け付けたら、まず初めにLoggerContextFilterはアプリケーションに関連付けられたロガーコンテキストを取得して、ThreadLocalに保存します。ContextJNDISelectorは、最初にThreadLocal変数が設定されているかどうかをチェックします。設定されているときは、JNDIの検索をスキップします。HTTPリクエストの処理の最後に、ThreadLocal変数はnullにされるので気をつけてください。LoggerContextFilterを使うようにすると、ロギングの性能は大幅に改善します。

ThreadLocalの変数はnullになるので、アプリケーションがリサイクルされるときや停止するときのガベージコレクションでちゃんと回収されます。

共有ライブラリ内部の静的参照を飼いならす

全てのアプリケーションでSLF4Jとlogbackを共有しているとき、ContextJNDISelectorを使うとうまくログを分離できます。ContextJNDISelectorが有効なら、それぞれのアプリケーションのLoggerFactory.getLogger()メソッドの呼び出しは、アプリケーションに関連付けられたロガーコンテキストに割り当てられたロガーを返してくれます。

静的変数としてロガーを参照するのが一般的なイディオムです。

public class Foo {
  static Logger logger = LoggerFactory.getLogger(Foo.class);
  ...
}

静的変数でロガーを参照するのは、メモリとCPUのどちらにとっても効率的です。そのクラスの全てのインスタンスは、ただ一つの参照を使いまわせるからです。また、ロガーのインスタンスを取得するのは、クラスがメモリにロードされたときだけです。ロガー静的変数を持っているクラスが kenobi アプリケーションに含まれているなら、そのロガーのインスタンスはContextJNDISelectorから取得したkenobi用のロガーコンテキストに割り当てられることになります。同様に、別のアプリケーション yoda に含まれているクラスのロガーインスタンスは、やはりContextJNDISelectorから取得した yoda用のロガーコンテキストに割り当てられることになります。

もしkenobiアプリケーションとyodaアプリケーションの両方で共有しているライブラリに含まれるMustafarクラスだったら、ただしMustafarクラスではインスタンス変数やローカル変数でロガーを参照していたらどうなるでしょうか。LoggerFactory.getLogger()メソッドは、それが呼ばれたアプリケーションに関連付けられたロガーコンテキストに割り当てられたロガーを返してくれるでしょう。しかし、Mustafarクラスが静的変数でロガーを参照していたらどうなるでしょう。その場合、最初にそのクラスを参照したアプリケーションに関連付けられたロガーコンテキストに割り当てられたロガーになってしまいます。つまり、ContextJNDISelectorは、共有ライブラリのクラスが保持する静的変数のロガーについては、ログの分離ができないのです。このような状況は特に限定的なもので、長い間解決策が望まれつつも今に至ります。

この問題を文句のつけようもないくらいに完全に解決するには、別の観点でロガーの内部事情に切り込まなければなりません。たとえば、ロガーは実際の仕事をするロガーを内包するものとして、ロガーに対するメッセージは内包するロガーに委譲するようにします。そして、内包されたロガーは適切なロガーコンテキストを参照するようにするのです。このアプローチは実装が大変だし、オーバーヘッドが非常に高くなってしまうでしょう。取りかかる気にはなれません。

クラスの共有を止めて、アプリケーションの内部に移動してしまうのが、"共有クラスの静的ロガー"問題に対するお手軽な解決方法の1つであることは言うまでもありません。共有しないようにするのが不可能なら、SiftingAppenderの魔法を使ってログの分離を実現するしかないでしょう。

logbackの配布物にはJNDIBasedContextDiscriminatorという弁別器が含まれています。これはContextJNDISelectorの返すロガーコンテキストの名前を返すものです。SiftingAppenderとJNDIBasedContextDiscriminatorを組み合わせると、アプリケーションごとに別々のアペンダーインスタンスを生成することができます。

<configuration>

  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator">
      <defaultValue>unknown</defaultValue>
    </discriminator>
    <sift>
      <appender name="FILE-${contextName}" class="ch.qos.logback.core.FileAppender">
        <file>${contextName}.log</file>
        <encoder>
          <pattern>%-50(%level %logger{35}) cn=%contextName - %msg%n</pattern>
         </encoder>
      </appender>
     </sift>
    </appender>

  <root level="DEBUG">
    <appender-ref ref="SIFT" />
  </root>
</configuration>

kenobi と yoda というWebアプリケーションがあるとして、この設定ファイルを使うと yoda のログは yoda.logに、kenobi のログはkenobi.logに出力されるようになります。これは共有クラスの静的ロガーでも有効です。

logback-starwarsプロジェクトを使えば、ここで説明したテクニックを実際に試してみることができます。

上記のアプローチは、ログの分離問題を解決できますがかなり複雑です。適切なContextJNDISelectorの設定や、アペンダーをSiftingAppenderでラップするこは、手傷を負った猛獣のように手が付けられません。

それぞれのロギングコンテキストは、同じ設定ファイルでも、それぞれ別の設定ファイルでも設定できることを忘れないようにしましょう。選ぶのはあなたです。コンテキストごとに設定ファイルをメンテナンスするよりは、全て同じ設定ファイルを使うようにするほうが簡単です。アプリケーションごとに設定ファイルをメンテナンスするのは大変ですが、柔軟性はあります。

これで終わりでしょうか？勝どきを上げて、気持ちよく我が家に帰れるのでしょうか？実はまだ続くんです。

yodaがkenobiより前に初期化されるとしましょう。yodaを初期化するため、http://localhost:port/yoda/servletを参照してYodaServletを呼び出します。このサーブレットは単に挨拶を返すだけです。ただし、ログを取得してからMustafarのfoo()メソッドを呼び出します。このメソッドは単純にログを取得するだけのものです。

YodaServletが呼び出された後、yoda.logの内容は次のようになります。

DEBUG ch.qos.starwars.yoda.YodaServlet             cn=yoda - in doGet()
DEBUG ch.qos.starwars.shared.Mustafar              cn=yoda - in foo()

どちらのログも、"yoda"アプリケーションに関連付けられたロガーコンテキストによるものであることが分かりますか。ここからサーバーが停止するまで、ch.qos.starwars.shared.Mustafarのロガーは、"yoda"コンテキストに割り当てられたものになります。

http://localhost:port/kenobi/servletにアクセスした後のkenobi.logの内容は次のようになります。

DEBUG ch.qos.starwars.kenobi.KenobiServlet          cn=kenobi - in doGet()
DEBUG ch.qos.starwars.shared.Mustafar               cn=yoda - in foo()

なんと、ch.qos.starwars.shared.Mustafarのロガーはkenobi.logに出力しているのに、"yoda"コンテキストに割り当てられているロガーのままです。つまり、別のロガーコンテキストに割り当てられたロガーが同じファイル（この場合はkenobi.log）に出力してしまうのです。それぞれのコンテキストが参照しているFileAppenderのインスタンスは、別々のSiftingAppenderのインスタンスに内包されたもので、同じファイルにログを出力しています。ログの分離は思った通りに機能しているように見えますが、prudentモードを有効化しない限り、FileAppender は同じファイルへのログの書き込みを安全に行うことができません。そうしないとファイルの内容が壊れてしまいます。

prudent モードを有効にした設定ファイルを見てください。

<configuration>

  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator">
      <defaultValue>unknown</defaultValue>
    </discriminator>
    <sift>
      <appender name="FILE-${contextName}" class="ch.qos.logback.core.FileAppender">
        <file>${contextName}.log</file>
        <prudent>true</prudent>
        <encoder>
          <pattern>%-50(%level %logger{35}) cn=%contextName - %msg%n</pattern>
         </encoder>
      </appender>
     </sift>
    </appender>

  <root level="DEBUG">
    <appender-ref ref="SIFT" />
  </root>
</configuration>

ここまでの議論を読み解いてきて、その上で logback-starwars プロジェクトを試してみたのなら、きっともうロギングのことが頭から離れなくなっていると思います。これ以上のことは専門家の助けを借りるしかないでしょう。