Simple Logging Facade for Javaをしっかりと

この辺、アーキに任せっきりで自分で調べたり
してなかったので調べることにするっす。
つか仕事しろよ！ってツッコミはいらんですよ！

What's logback?

logbackはlog4jプロジェクトの後継プロジェクトです。
log4jの創始者Ceki Gülcüによって設計されています。
log4jよりも高速で洗練されたインタフェースが提供されています。

◆必須モジュール

1. slf4j-api.jar
2. logback-core.jar
3. logback-classic.jar

これらのモジュールをclasspathに通せば使い始めることができます。

◆ログレベル

1. error
2. warn
3. info
4. debug
5. trace

log4jと比較すると、fatalがなくなっていて、traceが追加になっている。
注意点：log4jの場合、org.apache.log4j.Loggerのlog4j内のクラスで
ロガーを得て使っていたのだが、logbackの場合は、slf4jというcommons-logging相当
のパッケージ経由で使うのが普通のやり方になっている。

以下サンプル

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
	
public class HelloWorld1 {

    public static void main(String[] args) {
        Logger logger = LoggerFactory
                .getLogger("org.rsw87.logging.chapter1.HelloWorld1");
        logger.debug("Hello world.");
    }
}

import宣言を見てもらうとわかるが、基本的にlogback自体のパッケージである
ch.qos.logback.*は出てこない。

◆ログ取得APIの強化

ログ取得メソッドが異常に強化されている。基本的に以下のような形
でログ取得メソッドを呼び出す。

public boolean isDebugEnabled();
public boolean isDebugEnabled(Marker marker);

public void debug(String msg);
public void debug(String format , Object arg);
public void debug(String format , Object arg1, Object arg2);
public void debug(String format , Object[] argArray);
public void debug(String msg, Throwable t);
public void debug(Marker marker, String msg);
public void debug(Marker marker, String format, Object arg);
public void debug(Marker marker, String format, Object arg1, Object arg2);
public void debug(Marker marker, String format, Object[] argArray);
public void debug(Marker marker, String msg, Throwable t);

やたらとインタフェースが増えているが、これは

1. Markerを第1引数にとるタイプの新設
2. フォーマット展開による引数置換

の2つのフィーチャーに整理できる。まず、フォーマット展開は以下のように行う。

String name = "きむら";
Integer score = new Integer(30);
String result = "赤点";
Object args = { name, score, result };
logger.debug( "{} くんの成績は {} 点 でした",args );

単に {} を引数に展開するだけである。

・org.slf4j.Markerについて

これは要するに、MDCでカバーしきれない「メタな情報」を渡したい時に、
これを使うのがよいみたいである。
つまり、割とグローバルにアプリ上で使うような識別情報を
このMarkerのかたちで管理できる。

以下サンプル

package org.rsw87.logging;

import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

/**
 * @author ryo
 *
 */
public class Slf4jTest {

    private static final Logger logger = LoggerFactory
            .getLogger(Slf4jTest.class);
    private static final Marker marker = MarkerFactory.getMarker("test");

    @Test
    public void testLogging() {
        logger.info("ENTER: TestSlf4j");
        String[] args = { "markerTest" };
        if (args.length > 0) {
            MDC.put("arg1", args[0]);
        }
        String name = "きむら";
        Integer score = new Integer(30);
        String result = "赤点";
        Object[] arg = { name, score, result };
        logger.info(marker, "{}君の成績は{}点で{}です", arg);
        MDC.remove("arg1");
        logger.info("EXIT: TestSlf4j");
    }
}

以下実行結果
16:33:46.625 [main] INFO org.rsw87.logging.Slf4jTest - ENTER: TestSlf4j
16:33:46.625 [main] INFO org.rsw87.logging.Slf4jTest - きむら君の成績は30点で赤点です
16:33:46.625 [main] INFO org.rsw87.logging.Slf4jTest - EXIT: TestSlf4j

と何がなんだかわからないから、web漁ってみたら、以下のエントリがあったので
http://d.hatena.ne.jp/taichitaichi/20090220/1235124140
ちょっと読んでみたんだけど。
Markerの使いどころがどうやらフレームワーク実装時に
埋め込むログに使うのがよさげというのがわかったのでちょっと一旦別物扱いしちゃうよ。

◆slf4jのロガー実装切り替えメカニズム

今までのサンプルでは、適当なlogback.xmlを使ってやると、単にクラスパスに
1. slf4j-api-X.X.X.jar
2. logback-core-0.9.8.jar
3. logback-classic-0.9.8.jar

を含めただけで、きっちりログを出してくれるのである。。あれ？？

となるのは、「slf4j-api-X.X.X.jarは抽象的なAPI記述に過ぎないのに、なんでlogbackが
使えることがslf4j Apiにわかるのだろう？」ということである。

commons-loggingなら、commons-logging.propertiesファイルがあって、そこからログ実装
クラスを探すというような仕様が「どこから実装クラスを探すのか？」と絡んで色々ややこしく
存在している。が、どこをどうみてもそういう「優先順位」っぽいコードが無いのである。

実は、これかなり原始的だがラヂカルなやり方で解決している。要するにここらへんのロガー
実装になるのは、slf4j apiの中で

1. org.slf4j.impl.StaticLoggerBinder
2. org.slf4j.impl.StaticMarkerBinder
3. org.slf4j.impl.StaticMDCBinder

の3クラスであり、slf4j-api.jarのソースではこれら3クラスがあって、
コンパイルができるのだが、jarで固める際に、この3つのimplクラスは積極的に排除して
slf4j-api.jarを作っている。だからこのjarは中途半端で自己完結していないjarファイルなのである。

だから、ホントにこれを実装したクラスが、クラスパスの通ったjarファイル（でなくてもいいが）の中に
なければならない。

logbackを使う場合だと、logback-classic-0.9.8.jarの中にこのimpl 3クラスがあって、これに解決
されるわけである。だからロガー実装を切り替える際には、設定ファイルがとか全然不要で、単に

クラスパスに適切なライブラリを含ませることで

済むことになる。とはいえ、Log4jが後発のslf4jのことなんかしらないので,slf4jをlog4jで使いたいの
ならば、クラスパスには、

1. slf4j-api-X.X.X.jar
2. slf4j-log4j12-1.4.3.jar ※slf4jパッケージに入っているimpl 3実装
3. log4j-1.2.*.jar

をセットしてやればよい。ということになる。こんな感じでそういう実装が

1. slf4j-jcl-X.X.X.jar ※Jakarta Commons Logging用
2. slf4j-jdk14-X.X.X.jar ※JDK1.4 Logger用
3. slf4j-log4j12-X.X.X.jar ※log4j用実装
4. slf4j-simple-X.X.X.jar ※ただ出力するだけの実装
5. slf4j-nop-X.X.X.jar ※NOP Logger実装

という形で配布パッケージ中に並んでいる。ここから好きなのを選んでクラスパスに入れろというノリ。
あと、jcl104-over-slf4j.jarは、commons-logging用のslf4jの実装で、commons-loggingのインタフェースで
slf4jの実装を呼ぶようになっている...だから、内部的にロガーをいじるとかしてないならば
これを使えばlog4j用に書いたコードを何も修正せずに、slf4j経由でたとえばlogbackを使うなんてできてしまう。

◆logback.xml

設定ファイルは、クラスパスの通ったディレクトリに存在する「logback.xml」だけを利用する。
log4jだと色々とSystemプロパティを参照してややこしくなってるが、logabckはここらへんシンプルだ。
後述のコンテキストセレクタを別にすれば、単に、

1. クラスパス上のlogback-test.xmlを探す
2. なければクラスパス上のlogback.xmlを探す

これだけ。

簡単なlogback.xmlは以下のようなものになる

<configuration>
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<Target>System.out</Target>
		<layout class="ch.qos.logback.classic.PatternLayout">
			<Pattern>%d{HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</Pattern>
		</layout>
	</appender>
	<logger name="org.domain.library">
		<level value="DEBUG">
	</logger>
	<root level="INFO">
		<appender-ref ref="STDOUT"/>
	</root>
</configuration>

まぁ、階層構造自体は、log4j.xmlと大差があるわけではないが、これDTDは使わないという今風の
考え方がで、JoranConfiguratorという強烈なXMLパースのやり方をしているために、実際エレメント名に
特別な制限がなく、特にパラメタを渡すのにlog4j.xmlのように、

<param name="Target" value="System.out"/>

のように、paramエレメントのname属性で示唆される名前のsetterをvalue属性値で呼ぶとか
きっちり固定されているわけではない（一応paramの古い書き方も通る）。そうではなくて
ここらへんエレメント名を見て特別な役割を与えられた名前じゃない限り、その親エレメントの属性名として
扱うというやり方になっている。で、このとき、特にさらに入れ子に出来る/出来ないというのを
エレメント名で制御する、ということにはなっておらず、実際にそのエレメントによって生成された
オブジェクトの型（class属性)から、単純にリフレクトして動的に解決している。
比喩的に言えば、すべてのエレメントがLayoutのような振る舞いをする、と考えてもいいのではとも思われる。

だから、単に「set○○」「add○○」という名前のメソッドが生成されたオブジェクトにあれば、
それでプロパティ値がセットされるという格好である。ここらへん今風で小規模なSpringみたいな雰囲気だ。

以下が、デフォルトのルールに従わない特殊な名前となる

configuration/substituteProperty
プロパティ置換が出来てすごく便利な機能
configuration/contextProperty
プロパティをコンテキストにセットする。セットされたプロパティはMDCとして参照可能である
configuration/conversionRule
新たなパターンレイアウト変換ルールをセットし、新しいシンボルを PatternLayout の置換で使えるようにする。
configuration/appender
Appenderは特別扱いが要る
configuration/appender/appender-ref
Appender内部の定義されたAppenderの参照なので、入れ子Appenderのケースである。
configuration/newRule
まったく新しいJoranルールを決める（かなり凄い機能）
*/param
旧式のparamエレメントの扱い

○デバッグフラグと診断ログについて

とすると、診断ログが出る。設定などで「あれ？」と悩んだら出力してみるとよい。
以下のように出力される。

17:59:20,000 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
17:59:20,000 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/dev3/workspace/rsw87-concurrent/target/test-classes/logback.xml]
17:59:20,000 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath.
17:59:20,000 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/C:/dev3/workspace/rsw87-concurrent/target/test-classes/logback.xml]
17:59:20,000 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/C:/dev3/workspace/rsw87-concurrent/target/classes/logback.xml]
17:59:20,093 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
17:59:20,109 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]