Log4J徹底解説

使い方(logback)

このページでは、大体 使い方(1,2)でやったのに準じて、Logback の使い方を解説する。

目次

Logback の呼び方、というか slf4j 解説

まあ、抽象論よりも、具体的なコードを見ようじゃないか。サンプルコードはこんなものだ。

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

public class Test {
   protected static Logger log = LoggerFactory.getLogger( TestLogback.class ); 

   public static void main( String [] args ) {
      new SimpleTest();
   }
   SimpleTest( ) {
      try {
         BufferedReader br = new BufferedReader( new InputStreamReader( System.in ) );
         while( true ) {
            String line = br.readLine();
	    if( line == null ) {
		break;
	    }
            int at = line.indexOf( "," );
            if( at == -1 ) {
               break;
            }
            String cat = line.substring( 0, at );
            String body = line.substring( at + 1 );
            if( cat.equals( "error" ) ) {
               log.error( body );
            } else if( cat.equals( "warn" ) ) {
               log.warn( body );
            } else if( cat.equals( "info" ) ) {
               log.info( body );
            } else if( cat.equals( "debug" ) ) {
               log.debug( body );
	    } else if( cat.equals( "trace" ) ) {
		log.trace( body );
            } else if( cat.equals( "quit" ) ) {
               break;
            }
         }
      } catch( IOException e ) {
         e.printStackTrace();
      }
   }
}

これだと、コードを見てお分かりのように、標準入力から、

info,Hello my Log4J world!
warn,This is WARNING!!!

というような入力をいれてやると、

2004-09-10 17:13:09,754  INFO SimpleTest - Hello my Log4J world!
2004-09-10 17:13:33,261  WARN SimpleTest - This is WARNING!!!

というようなログ出力が出る、という寸法だ。error(), warn(), info(), debug() と言った Logger クラスのメソッドは、言うまでもなく「ログレベル」(ログの重要度)である。この順でキッツイ方から並べてある。

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

Log4j と比較すると、fatal がなくなって、Log4j では最近登場したばかりの trace がちゃんと最初から入っている。ここで注意すべきは、Log4j の場合、org.apache.log4j.Logger のLog4j 内のクラスで、ロガーを得て使っていたのだが、Logback の場合、slf4j という commons-logging 相当のパッケージ経由で使うのが、普通のやり方になってる。だから、

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

がロガーを使う側のクラスでの import 宣言になって、基本的に logback 自体のパッケージである ch.qos.logback.* は出てこない...ということになる。こうやって守備範囲を明確に分けているのは良い点と言えると思う。だから、本質的にログ取りメソッド以外何もない commons-logging と違い、MDC(NDCは廃止して MDC に統合した雰囲気)が slf4j の担当になっている。あと、新概念として、Marker というものがやはり slf4j に新設されているが、どっちか言えばこれ application プロパティみたいなかたちで使うもののようである。

で、ログ取りメソッドが異常に強化されている。基本的にこういうかたちでログ取りメソッドを呼び出す。

  public boolean isInfoEnabled();
  public boolean isInfoEnabled(Marker marker);

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

やたらと増えたが、これ要するに、

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

の2つのフィーチャーに整理できる。まず、フォーマット展開は、こんな感じですればいい。

  String name = "安倍";
  Integer score = new Integer(30);
  String result = "赤点";
  Object [] arg = { name, score, result };
  logger.info( "{} くんの成績は {} 点で{}でした", arg );

単に 「{}」を引数に展開するだけである。Java5 で可変長引数定義が加わって、ここらへん何も考えなくてできるわけだ。あ、一つだけ超重要なポイントがある。

Logback は、JDKのバージョンに応じて、パッケージがある...

実際、デフォルトのパッケージは、汎用ライブラリとしては珍しいが、ほんと内部的には Generics とか使い倒しで書いてあるので、Java 4 以前ではまともに動くものではない。だから、logback-*.jar は Java5 以降専用、logback-*-jdk14.jar は Java 1.4 用というかたちになっている。使うにあたっては、これだけ気をつけてね。

で、Marker だが、これ要するに、MDCでカバーしきれない「メタな情報」を渡したい時に、これを使うのがいい。だから、SocketAppender などで対応しかけている Application プロパティは、slf4j+logback だったらこの Marker で対応した方がいいだろう。つまり、割とグローバルにアプリ上で使うような識別情報(アプリ名とかサブパッケージとか)を、この Marker のかたちで管理できる。たとえば、こんな感じだ。

package jp.or.nurs.sug.logback.test;

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

public class TestSlf4j {
    protected static Logger log = LoggerFactory.getLogger( TestLogback.class ); 
    protected static Marker marker = MarkerFactory.getMarker( "test" );

    public static void main( String [] args ) {
	log.info( "ENTER: TestSlf4j" );
	if( args.length > 0 ) {
	    MDC.put( "arg1", args[0] );
	}
	String name = "安倍";
	Integer score = new Integer(30);
	String result = "赤点";
	Object [] arg = { name, score, result };
	log.info( marker, "{}くんの成績は{}点で{}です", arg );
	MDC.remove( "arg1" );
	log.info( "EXIT: TestSlf4j" );
    }
}

まあ、こういう風に、アプリ側で出てきそうなインターフェイスは、Logback の側じゃなくて、全部抽象層の Slf4j にさせちゃっているわけである。それゆえ、Logback を使う...と言っても、アプリ側では Logback 固有のクラスをまったく使わない(これが狙い)ので、後から他のロガーに差し替えるとか、簡単なのである。このこと自体は commons-logging が狙ってたことだが、Log4j の多機能に馴れちゃうと、ついつい Log4j 依存の NDC とか使いたくなっちゃうが、NDC は commons-logging の知ったことじゃない。そういうわけで、

Log4j の刺激によって進化した commons-logging(logback対応)

くらいのノリでこれを理解するのがいいだろう。

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

しかし、今のサンプル、適当なlogback設定ファイル(logback.xml)を使ってやると、単にクラスパスに、

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

を含めただけで、きっちりログを出してくれちゃうんである。....あれ、何か間違ってません?

となるのは、「slf4j-api-1.4.3.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-1.4.3.jar のソースではこれら3クラスがあって、コンパイルができるのだが、jar で固める際に、この3つの impl クラスは積極的に排除して slf4j-api-1.4.3.jar を作っている。だから、この Jar は中途半端で自己完結していない Jar ファイルのわけである。だから、ホントにこれを実装したクラスが、クラスパスの通った Jarファイル(でなくてもいいが)の中になければならない。

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

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

で済むことになる。とはいえ、Log4j が後発(でライバルの息のかかった)の slf4j のことなんて知らないので、Slf4j を Log4j で使いたいのならば、クラスパスには

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

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

  1. slf4j-jcl-1.4.3.jar * Jakarta Commons Logging 用
  2. slf4j-jdk14-1.4.3.jar * JDK1.4 Logger 用
  3. slf4j-log4j12-1.4.3.jar * Log4j 用実装
  4. slf4j-simple-1.4.3.jar * ただ出すだけの実装
  5. slf4j-nop-1.4.3.jar * NOP Logger 実装

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

logback.xml

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

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

....これだけである。まあ、logback-test.xml はテスト用っぽい名前だから、あまりこれに依存してアプリを作らない方が良いように感じる。だから、単純に「クラスパス上の logback.xml」という、極めてクリアな世界だ。勿論、log4j.properties に相当するプロパティ形式設定ファイルなぞ、時代遅れとして排除され跡形もない。

じゃあ、簡単な 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="jp.or.nurs.sug">
    <level value="DEBUG" />
  </logger>

  <root>
    <level value="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 エレメントの扱い

があるので、これらはまたページを改めてきっちり解説する。

で、あといわゆるデバッグフラグと、診断ログだけど、

<configuration debug="true">

で診断ログが出る。設定などで「あれ?」と悩んだら、出してみるのがいいな。こんな出力になる。

|-INFO in ch.qos.logback.core.joran.action.AppenderAction - 
         About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
|-INFO in ch.qos.logback.core.joran.action.AppenderAction - 
         Naming appender as [STDOUT]
|-INFO in ch.qos.logback.core.joran.action.AppenderAction - 
         Popping appender named [STDOUT] from the object stack
|-INFO in ch.qos.logback.classic.joran.action.LevelAction - 
         root level set to TRACE
|-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - 
         Attaching appender named [STDOUT] to Logger[root]
|-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - 
         End of configuration.
17:41:23 [] INFO   j.o.n.sug.logback.test.TestLogback - ENTER: TestLogback

17:41:48 [] INFO   j.o.n.sug.logback.test.TestLogback - EXIT: TestLogback

みたいな感じで、頭に「|-」が付くのが診断ログだ。

ログ出力

じゃあ、ログの要素、というかどんな内容がログとして出力されるんだろう? ログの要素として、こういうものを Logback は扱っている。ますは通常の classic パッケージは log4j 同様に ch.qos.logback.classic.spi.LoggingEvent である。log4j の LoggingEvent と比較すると、結構整理された感じである。(内は、LoggingEvent クラスでそのメンバを取得するための公開メソッド)

ロガー(LoggerRemoteView getLoggerRemoteView())
さて、ロガーは Log4j とは違って、オブジェクトになっている。この LoggerRemoteView は、Logger の表示&転送用のオブジェクトで、これのフィールドである LoggerContextRemoteView は LoggerContext の表示&転送用オブジェクトである。で、ロガー名は String getLoggerRemoteView().getName() で拾え、ロガーに与えられたプロパティは、ここの Map getLoggerRemoteView().getLoggerContextRemoteView().getPropertyMap() で参照可能になる。
時間(long getTimeStamp())
ログイベントの発生時間はちゃんと保持している。
時間(long getStartTime())
アプリが起動された時間。
ログレベル(Level getLevel())
これもすでに説明した。ERRORからTRACEに至るログの出力レベルである。
スレッド名(String getThreadName())
Java はマルチスレッドなので、「どのスレッド?」かが判ったらいいな!
メッセージ(Sting getFormattedMessage())
レンダリングされたメッセージ。もしレンダリング前のが欲しければ、getMessage() で取れる。
ログ取りメソッドの引数(Object [] getArgumentArray())
このイベントの原因となる、ログ取りメソッドを起動した時に渡した引数。
投げた例外(ThrowableInformation getThrowableInformation())
ログ取りメソッドでは、Throwable を引数に渡す版もあるのを見たが、メッセージと一緒に例外も渡すことができる。その例外情報。
ログ発生箇所情報(CallerData [] getCallerData())
Log4j で言う LocationInfo だが、Logback は単に発生箇所だけではなくて、そのスタック上の位置をスタックトレースから得て、配列のかたちで保持する。しかし、どうもこの取得ロジックは、ロガー名に正しく FQCN をセットしないと動作しないようだ。CallerData オブジェクトの中に、ファイル名とか発生行とか発生メソッドとかクラス名とかの情報がある。わざわざ積極的にこれは取りに行かないと、取得できない情報なので、「わざわざこれを得るか?」というAppenderプロパティがあるケースもある。
マーカー(Marker getMarker())
slf4j でセットされるマーカー。これはセットするログ取りインターフェイスがあるんだから、これがログイベントに保持されるのは当り前というものだ。
MDC(Map <String,String> getMDCPropertyMap())
MDC=「Mapped Diagnostic Context(マップされた診断コンテキスト)」。偉そうな名前だが、マップモデルで保存される「追加情報」である。実際、Logback では汎用的なプロパティ風に使われる。

レイアウト

あとは、上記のログ出力要素を具体的に出力するための「レイアウト」である。Appender 毎に個別に設定可能な要素である「レイアウト」は、具体的な出力のパターンであり、これがいじれないんじゃ意味がない...となるが、当然 layout 要素によってこれを勝手に変えることが可能である。

一応、これもいろいろなレイアウトがある。用意されているパターンは次のものである。

ch.qos.logback.core.EchoLayout
デフォルトのレイアウトである。特にオプションはない。
出力結果はこう。凄くシンプルだ。要するにレベルとメッセージしか出さないのである。
INFO] ENTER: TestLog4j
WARN] Test WARNING!!
INFO] EXIT: TestLog4j


まあ、本来「[INFO]」であるべきだ。バグである(LoggingEvent#toString())。
ch.qos.logback.classic.html.HTMLLayout
ch.qos.logback.access.html.HTMLLayout
これはHTML形式で出すものである。形式はきっちり決まっていて、あまり動かせる余地はない。 出力はこんな感じである。
<!DOCTYPE HTML PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html>
<head>
<title>Logback Log Messages</title>
<STYLE  type="text/css">
table { margin-left: 2em; margin-right: 2em; border-left: 2px solid #AAA; }
TR.even { background: #FFFFFF; }
TR.odd { background: #EAEAEA; }
TR.warn TD.Level, TR.error TD.Level, TR.fatal TD.Level {font-weight: bold; color: #FF4040 }
TD { padding-right: 1ex; padding-left: 1ex; border-right: 2px solid #AAA; }
TD.Time, TD.Date { text-align: right; font-family: courier, monospace; font-size: smaller; }
TD.Thread { text-align: left; }
TD.Level { text-align: right; }
TD.Logger { text-align: left; }
TR.header { background: #596ED5; color: #FFF; font-weight: bold; font-size: larger; }
TD.Exception { background: #A2AEE8; font-family: courier, monospace;}
</STYLE>

</head>
<body>
<hr size="1" noshade="true" width="50%" align="left" />
Log session start time Sun Sep 30 19:36:28 GMT+09:00 2007<br />
<br />
<table cellspacing="0">
<tr class="header">
<td class="Date">Date</td>
<td class="Thread">Thread</td>
<td class="Level">Level</td>
<td class="Logger">Logger</td>
<td class="MDC">MDC</td>
<td class="Message">Message</td>
</tr>


<tr class="info even">
<td class="Date">2007-09-30 19:36:28,834</td>
<td class="Thread">main</td>
<td class="Level">INFO</td>
<td class="Logger">jp.or.nurs.sug.logback.test.TestLogback</td>
<td class="MDC"></td>
<td class="Message">ENTER: TestLogback</td>
</tr>

<tr class="warn odd">
<td class="Date">2007-09-30 19:36:35,987</td>
<td class="Thread">main</td>
<td class="Level">WARN</td>
<td class="Logger">jp.or.nurs.sug.logback.test.child.TestChild</td>
<td class="MDC"></td>
<td class="Message">test</td>
</tr>

<tr class="error even">
<td class="Date">2007-09-30 19:36:35,991</td>
<td class="Thread">main</td>
<td class="Level">ERROR</td>
<td class="Logger">jp.or.nurs.sug.logback.test.child.TestChild</td>
<td class="MDC"></td>
<td class="Message">test</td>
</tr>
<tr><td class="Exception" colspan="6">java.io.IOException: test Exception
<br />    jp.or.nurs.sug.logback.test.child.TestChild.doSomething(TestChild.java:37)
<br />    jp.or.nurs.sug.logback.test.TestLogback.main(TestLogback.java:14)
</td></tr>

である。これだとテキトーにファイルの最後を、
</table></body></html>
で閉じないといけない。


org.apache.log4j.PatternLayout
さて、これが真打ち。勝手に自分でレイアウトを決めてやることができる、とっても重要なレイアウトである。一番よく使うと言っても過言ではない。printf の編集フォーマットとか、Apache の CustomLog ディレクティブみたいに、「%t」とかの % で始まる1文字で、いろいろな要素をシンボル化して指定する。そういうエスケープ文字のリストはこうだ。

%c,%lo,%loggerカテゴリー名。これは %c{1} という風に書けて、%c{1} だと一番「下の」
レベル、jp.or.nurs.sug.log4j.test.child.TestChild なら、「TestChild」のみになる。
%C,%classログを生成したクラス名(≠カテゴリー名)。これも %C{2} という風に書けて、
%C{2} だと一番「下の」レベルから2つ上にたどる。
jp.or.nurs.sug.log4j.test.child.TestChild クラスなら、「child.TestChild」になるわけだ。
%d, %date日付。これは %d{yyyy-MMM-dd HH:mm:ss,SSS} みたいに細かく書けるし、
また、TTCCLayout で使ったシンボルを使って、 %d{ISO8601}
みたいに書いても良い。
%l以下3つはいわゆる「LocationInfo」と呼ばれる、「ソース上どこでログイベントが発生したか?」についてのレイアウト指定である。これらの情報は有益だが、通信系Appenderの場合は「いらない情報をわざわざネット越しに送る」ことになるとか、スタックフレームを参照するのでJVMによってはうまく動かないケースがないわけではないとか、そもそもスピードが遅いとか、いろいろと問題を抱えているログ要素である。だから、これらは独立して「出す/出さない」の設定が可能なことが多い。で、この「%l」は3つの「LocationInfo」をまとめて出すオプション指定である。たとえば、「jp.or.nurs.sug.log4j.test.TestLog4j.main(TestLog4j.java:18)」のような出力になる。
%F,%fileログを生成したソースファイル名。遅いぞ!と警告されている
%L,%lineログを生成した箇所のソースの行番号。遅いぞ!と警告されている
%M,%methodログを生成したメソッドの名前。遅いぞ!と警告されている
%m,%msg,%messageログメッセージ
%X{key},%mdc{key}その MDC に保存された key の値
%n改行コードを生成する。\nじゃないわけである。
%p,%le,%levelログレベル(FATALとかINFOとか)
%r,%relativeアプリケーションが開始してからの通算時間(ミリ秒)
%t,%threadログを生成したスレッド名
%throwable{short}1.3で追加。これはレイアウト要素というよりも一種のスイッチである。例外をログメソッドに渡して Log4j を呼ぶと、デフォルトでは例外スタックトレースをすべて出力することになる。とはいえ、これは鬱陶しいケースも多い。なので、この「%throwable{short}」という表現をログフォーマットの末尾につけてやると、例外スタックトレースの最初の行だけを表示することになる。ちょっと動作が例外的なのが気になるが...
%nopex,%noexceptionスイッチとして動作し、例外出力を抑止する
%callerCallerData を出すが....
%markerマーカーを出力する。


また、それぞれ「%-5.12p」のように、「-」(左詰め)、「5」(最小字数)、「.12」(最大字数)のように指定が可能だったりする。ここらへん、printfに近いやり方だ。 だから、次のようにしてこのパターンをオプションとして指定する。
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %5p %c{1} - %m%n
そうすると出力は、
2004-09-10 17:13:09,754  INFO TestLog4j - Hello my Log4J world!
2004-09-10 17:13:33,261  WARN TestLog4j - This is WARNING!!!




copyright by K.Sugiura, 1996-2006