Log4J徹底解説

使い方(1)

目次

QuickStart

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

   static protected Logger log = Logger.getLogger( TestLog4j.class ); 

   public static void main( String [] args ) {
//      BasicConfigurator.configure();
      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( "fatal" ) ) {
               log.fatal( body );
            } else 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( "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!!!

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

fatal
想定外の状況で、アプリケーションの継続が不可能である場合。それこそ syslog に書き込みたい位のシビアなケースがこれ。ちなみに syslogd に fatal レベルを流すと、デフォルトではベルがなったりする程である。一般的なアプリでは指定しない方が無難かな?
error
何かエラーが生じ、サーバだったら停止してるかリクエスト処理に大きな問題がある状態を示す。かなり緊急に対応を要する問題がある、とわかる程度。
warn
警告。何か問題があったが、一応不完全ながらリクエストは完結している状態を示す。
info
情報。実運用の最低ログレベル。サーバの起動とか、リクエストの受け付け・完了をこのレベルにしておくのが良かろう。
debug
デバッグログ。デバッグ用のトレースログを含み、ログファイルのサイズが爆発することなぞ気にせずに「問題解決のためにログを取りまくりたい!」時に指定するものである。当然、実運用でこのログレベルのまま運用すると、後でログファイルを見る時にうんざりする...そんなくらいのレベル。
trace
ver 1.2.12 で新規追加。今までデバッグレベルが大まか過ぎたのを解消するため、一番詳細なログレベルとして追加された。ホントに詳細な動作チェックをするケースで使うべきレベルである。

くらいで認識されているように思う(個人差はあるよ..)。後で触れるが commons-logging を使うと、一番下に trace() レベルがあったり、Sun 純正 java.util.logging クラスだと、fatal() と error() が合体して SEVERE になっていたりする。ここらへんの区分けの仕方には、その作者の趣味が多分に入るな。

で、このようなログ出力を「どう扱うか?」は設定ファイルに記述する。

設定ファイルは、クラスパスの通ったディレクトリに存在する、「log4j.properties」もしくは「log4j.xml」を利用する。ここに具体的なログの処理を書くわけだが、これは「log4j.xml」(XML形式)を先に、「log4j.properties」(プロパティ形式)を後に検索する。その他システムプロパティも見るが、これは後で構わないだろう。

じゃあ、簡単な log4j.properties はこうだ。

### direct log messages to stdout ###
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

### direct messages to file mylog.log ###
log4j.appender.file=org.apache.log4j.FileAppender
log4j.appender.file.File=mylog.log
log4j.appender.file.Append=true
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d %5p %c{1} - %m%n

log4j.rootLogger=debug, stdout, file

これは、「ルートロガー」に対して、ConsoleAppender(名前は「stdout」)と、FileAppender(名前は「file」)を与えている。言い替えれば、標準出力とファイルにログが出る設定である。「ルートロガー」とは、Log4J が「階層カテゴリーロガー」であることは、すでに説明したが、その一番親元となるデフォルトのロガーである。今後さまざまな「カテゴリー」が作られて行くが、その継承元となる「基底ロガー」だと言い替えてもいいかもしれない。つまり、ここで指定された2つの Appender は、以降のカテゴリーに対しても、デフォルトで継承され、効果を持つのである。

大体のフォーマットの形式を書くとこんなところだ。

# Appender の定義
log4j.appender.名前=Appenderの完全修飾名
log4j.appender.名前.オプション=値
log4j.appender.名前.layout=レイアウトクラスの完全修飾名
log4j.appender.名前.layout.オプション=レイアウトのオプション

#カテゴリーの定義
log4j.logger.カテゴリー=ログレベル,適用するAppenderの名前[, Appender名]

#ルートロガーの定義
log4j.rootLogger=ログレベル,適用するAppenderの名前[, Appender名]

「Appdenderの名前」は当然、Javaのクラス名に使える名前ならなんでもOKである。AppnderのオプションはAppenderごとに違うので、これは後でしっかりやる。

ちなみにプログラムのコメントにしてある行

//      BasicConfigurator.configure();

は、このルートロガーに標準出力をデフォルトとして指定するだけのことしかしていない。まあ、この「デフォルトで標準出力に吐く」という動作が邪魔ならば、指定しなくてもどうということはない。名前が大げさなので気になるが、そんなもんである。

1.3 内部ログについて: 実は 1.3 で rootLogger の扱いが少々変更になった。上記の設定ファイルだと、診断メッセージ出力が結構うっとしいものがある。詳細は「1.3 の内部ログ」を参照してくれ。

カテゴリー

じゃあ、今度はこう書き換えてみよう。

(jp.or.nurs.sug.log4j.test.TestLog4j)
package jp.or.nurs.sug.log4j.test;

import org.apache.log4j.Logger;
import org.apache.log4j.NDC;
import org.apache.log4j.PropertyConfigurator;
import org.apache.log4j.xml.DOMConfigurator;

import jp.or.nurs.sug.log4j.test.child.TestChild;

public class TestLog4j {
   protected static Logger log = Logger.getLogger( TestLog4j.class ); 

   public static void main( String [] args ) {
      NDC.push( "level-No.1" );  /* NDC に PUSH */
      log.info( "ENTER: TestLog4j" );
      TestChild tc  = new TestChild();
      tc.doSomething();
      log.info( "EXIT: TestLog4j" );
      NDC.pop();
   }
}
(jp.or.nurs.sug.log4j.test.child.TestChild)
package jp.or.nurs.sug.log4j.test.child;

import org.apache.log4j.Logger;

import java.io.*;
import java.util.*;

public class TestChild {
   protected Logger log = Logger.getLogger( this.getClass() ); 

   public void doSomething( ) {
      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( "fatal" ) ) {
               log.fatal( body );
            } else 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 );
            /* 1.3 をつかうのなら有効にすればいい
	    } else if( cat.equals( "trace" ) ) {
		System.out.println( "TRACE: " + body  );
		log.trace( body );
            */
	    } else if( cat.equals( "exception" ) ) {
		log.error( body, new IOException( "test Exception" ) );
            } else if( cat.equals( "quit" ) ) {
               break;
            }
         }
      } catch( IOException e ) {
         return;
      }
   }
}

パッケージ指定をして、サブディレクトリがある設定である。この時、jp.or.nurs.sug.log4j.test.child.TestChild クラスのログだけをファイルに保存する、という風に設定するのなら、次のようにすればいい(差分のみ。log4j.properties は「クラスパスにあるべき」ものなので、起動ルートパスに移動するように!)。

log4j.rootLogger=debug, stdout
log4j.logger.jp.or.nurs.sug.log4j.test.child.TestChild=debug, file

これで jp.or.nurs.sug.log4j.test.child.TestChild クラスのログは mylog.log に保存されることになるが、jp.or.nurs.sug.log4j.test.TestLog4j クラスのログはそうではない。TestLog4j クラスはルートロガーの設定を引き継ぐから、標準出力にはログが出力される。しかし、Appender file は jp.or.nurs.sug.log4j.test.child.TestChild クラスに対してしか指定されていないのである! なお、TestChild クラスはルートロガーの指定によって、当然標準出力にも出力される。

もし、こうしたらどうなるだろう?

log4j.rootLogger=debug, stdout
log4j.logger.jp.or.nurs.sug.log4j.test=debug, file

この場合には、ロガーの名前として指定した名前(カテゴリー:Logger.getLogger() の引数に与えた完全修飾クラス名)が、「階層的な」ロガーの名前として使われてるので、jp.or.nurs.sug.log4j.test パッケージ以下のクラスすべてに対して、Appender file が適用されることになる。言い替えれば、jp.or.nurs.sug.log4j.test.TestLog4j と jp.or.nurs.sug.log4j.test.child.TestChild の両クラスに対して、Appender file が適用されるのだ。ね、なかなか良くできてるな。だから、こういう「階層」機構をうまく使うために、「ロガーの名前は完全修飾クラス名にしようね!」とされているのである。

ログ出力

じゃあ、ログの要素、というかどんな内容がログとして出力されるんだろう? ログの要素として、こういうものを Log4J は扱っている。ログ自体のオブジェクトは、org.apache.log4j.spi.LoggingEvent であるので、これを見ればわかる。けっこうあるぞ。(内は、LoggingEvent クラスでそのメンバを取得するための公開メソッド)

シーケンス番号(long getSequenceNumber())
ロガーが起動してからのシーケンス番号(1.3で新設
カテゴリー名(String getLoggerName())
すでに説明したカテゴリー(Logger.getLogger()の引数に渡す名前)である。
ログレベル(Level getLevel())
これもすでに説明した。FATALからDEBUGに至るログの出力レベルである。
NDC(String getNDC())
Nested Diagnostic Context(ネスト化診断コンテキスト)という偉そうなものである。直後に見るが、これは「追加情報」みたいなもんであるが、使い方が面白い。
MDC(Object getMDC(String key))1.3で新設
Property(Object getProperty(String key))1.3 deprecated
MDC=「Mapped Diagnostic Context(マップされた診断コンテキスト)」。これも偉そうな名前だが、「追加情報」である。NDC がスタックモデルだったのに対して、これはマップモデルで保存される。ただし、この仕様は1.3で大幅に変わり、汎用的な「プロパティ」と一緒にされた。使用頻度はさほどではないので、ここでは詳説しないが、「ネットワーク系Appender とプロパティ(1.3)」を見てほしい。
メッセージ(Object getMessage())
ログの「本文」というか、ログのメッセージ自体である。
スレッド名(String getThreadName())
Java はマルチスレッドなので、「どのスレッド?」かが判ったらいいな!
投げた例外(ThrowableInfomation getThrowableInfomation())
Logger#debug() とかの実際にロギングを行うメソッドでは、2引数版もあって、メッセージと一緒に例外も渡すことができる。例外ハンドラなんかでは、こういう風に呼び出す。
try {
   ............
} catch( SomeException e ) {
   logger.error( "Exception caught: ", e );
}
そうするとちゃんとスタックトレースに至るまで、Log4J は面倒を見てくれる。
時間(long getStart())
アプリが起動された時間。要するにこの時間と実際のログの発生時間からタイムスタンプを計算していたが...
時間(long getTimeStamp())
ログイベントの発生時間をちゃんと保持するようになった。(1.3で新設
LocationInfo(LocationInfo getLocationInfomation())
これは「どこでログが発生したの?」をキメ細かく追跡してくれるものである。つまり、「発生クラス名」「発生ファイル名」「発生行」「発生メソッド」という4つの要素をこれが扱う。ただし、ネットワーク系の Appender では、通信量が増えるのを抑えるために、これをログイベントとして渡すかどうかは、オプションになる。

こうしてみると、特に説明が必要なのは NDC だけで、残りは自明だね。じゃあ、NDC っていうのは何だろう? 名前がエラソーなのでビビるが、実はそう大したものではない。しかし、使い方次第では便利なものである。

たとえば、何かのサーバでリクエストを受け付けたら、リクエスト毎にスレッドを起動して...なんて定石的処理があるわけだが、この時スレッドに名前を付ける、ってことをしてデバッグを助けるなんていう技をすることもあるよね。つまり、何か「リクエストに対応した追加情報を与えて、デバッグしやすいように工夫する」というのがしたいことなのだ。この要望に答えるのが NDC だ。というわけで「追加情報」自体は自分が判る文字列ならば何でもOKだ。

で、「良く考えられているじゃん!」と感じるポイントは、これが「スタックモデルだ」ということである。つまり、PUSH, POP 動作で NDC を設定し、解除するのである。こんな風である。

import org.apache.log4j.Logger;
import org.apache.log4j.NDC;

   Logger log = Logger.getLogger( this.getClass() );
   NDC.push( "level-No.1" );  /* NDC に PUSH */
   log.info( "test1" );
   NDC.push( "level-No.2" );
   log.info( "test2" );
   NDC.pop();                 /* NDC から POP */
   log.info( "test3" );
   NDC.pop();
   log.info( "test4" );
   NDC.remove();   /* スレッドから NDC を抹消する */

そうして、ログ出力に NDC を出すようにしてやると、こういう風な出力になるわけだ。

2004-09-24 21:48:40,457  INFO TestLog4j [] - ENTER: TestLog4j
2004-09-24 21:48:40,573  INFO TestChild [level-No.1] - test1
2004-09-24 21:48:40,585  INFO TestChild [level-No.1 level-No.2] - test2
2004-09-24 21:48:40,596  INFO TestChild [level-No.1] - test3
2004-09-24 21:48:40,607  INFO TestChild [] - test4
2004-09-24 21:48:40,618  INFO TestLog4j [] - EXIT: TestLog4j

[ ] を NDC の表示にしているが、「上に」積まれているのがよく判ろう。

注意点(というか、便利で面白い点)は、この NDC はスレッドと結びつけられている、ということだ。まあ、スレッドは並行して走るので、こういうスタックとは相性が悪いから当然の実装なのだが、スレッド毎に NDC が確保され、一つのスレッドでの NDC の操作は他のスレッドの NDC にまったく影響を与えない。具体的にはご想像の通り、ハッシュテーブルを確保してスレッド名をキーとして java.util.Stack を保持しているのである。良かったね!

あとこの NDC に似たもので「MDC(Mapped Diagnostic Context:マップされた診断コンテキスト)」というのもあるが、これは NDC がスタックを使うのに対して、マップ形式(キー&ヴァリュー)で追加情報を保存するものである。まあ、これまで説明すると煩雑なのでやめておくが、こんなものまであったりするのである!

レイアウト

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

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

org.apache.log4j.SimpleLayout
デフォルトのレイアウトである。特にオプションはない。
log4j.appender.simple=org.apache.log4j.ConsoleAppender
log4j.appender.simple.Target=System.out
log4j.appender.simple.layout=org.apache.log4j.SimpleLayout
出力結果はこう。凄くシンプルだ。要するにレベルとメッセージしか出さないのである。
INFO - ENTER: TestLog4j
WARN - Test WARNING!!
INFO - EXIT: TestLog4j
org.apache.log4j.TTCCLayout
これは特に時間の出力に対して、いろいろと出来るようになっている。オプションは次の通り。
CategoryPrefixing
「カテゴリー名」を付けるかつけないか。boolean値(true or false)である。
ThreadPrinting
「スレッド名」を付けるかつけないか。boolean値(true or false)である。
DateFormat
「時間情報」のフォーマットを指定する。指定可能なのは、「RELATIVE」(プロセス開始からの時間)、「NULL」(時間表示なし)、「ABSOLUTE」(現在「時間」のみ・日付は入らない)、「DATE」(英米系の日時表記)、「ISO8601」(フルフォーマット)である。
log4j.appender.ttcc=org.apache.log4j.ConsoleAppender
log4j.appender.ttcc.Target=System.out
log4j.appender.ttcc.layout=org.apache.log4j.TTCCLayout
log4j.appender.ttcc.layout.DateFormat=RELATIVE
#log4j.appender.ttcc.layout.DateFormat=NULL
#log4j.appender.ttcc.layout.DateFormat=ABSOLUTE
#log4j.appender.ttcc.layout.DateFormat=DATE
#log4j.appender.ttcc.layout.DateFormat=ISO8601
log4j.appender.ttcc.layout.CategoryPrefixing=true
log4j.appender.ttcc.layout.ThreadPrinting=true
でやってみると、
330 [main] INFO jp.or.nurs.sug.log4j.test.TestLog4j - ENTER: TestLog4j
warn,Test WARNING!!!
15115 [main] WARN jp.or.nurs.sug.log4j.test.child.TestChild - Test WARNING!!!
16603 [main] INFO jp.or.nurs.sug.log4j.test.TestLog4j - EXIT: TestLog4j
となる。要するに、
Date [Thread] Category Context - Message
のフォーマットで出力されるのである。


org.apache.log4j.HTMLLayout
これはHTML形式で出力を出す。一種のテーブルのかたちで個々のログを出すので、FileAppender を使わないとちょっと厄介だ。設定は、

log4j.appender.html=org.apache.log4j.FileAppender
log4j.appender.html.File=mylog.htm
log4j.appender.html.Append=false
log4j.appender.html.layout=org.apache.log4j.HTMLLayout
くらい。出力結果は「出力」を参照。どうもファイルの最後に必要な「</table></body></html>」が欠けるようである。NN系ブラウザだと厄介だな、これ。


org.apache.log4j.XMLLayout
これはXML形式で出力を出す。これも FileAppender くらいでやるのが良かろう。
log4j.appender.xml=org.apache.log4j.FileAppender
log4j.appender.xml.File=mylog.html
log4j.appender.xml.Append=false
log4j.appender.xml.layout=org.apache.log4j.xml.XMLLayout
出力は、
<log4j:event logger="jp.or.nurs.sug.log4j.test.TestLog4j" timestamp="1094812129666"
 level="INFO" thread="main">
<log4j:message><![CDATA[ENTER: TestLog4j]]></log4j:message>
</log4j:event>

<log4j:event logger="jp.or.nurs.sug.log4j.test.child.TestChild" timestamp="1094812140546"
 level="WARN" thread="main">
<log4j:message><![CDATA[Test WARNING!!!]]></log4j:message>
</log4j:event>

<log4j:event logger="jp.or.nurs.sug.log4j.test.TestLog4j" timestamp="1094812146945"
 level="INFO" thread="main">
<log4j:message><![CDATA[EXIT: TestLog4j]]></log4j:message>
</log4j:event>
である。これだとテキトーなトップレベル要素でくくらないといけないな。


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

%cカテゴリー名。これは %c{1} という風に書けて、%c{1} だと一番「下の」
レベル、jp.or.nurs.sug.log4j.test.child.TestChild なら、「TestChild」のみになる。
%Cログを生成したクラス名(≠カテゴリー名)。これも %C{2} という風に書けて、
%C{2} だと一番「下の」レベルから2つ上にたどる。
jp.or.nurs.sug.log4j.test.child.TestChild クラスなら、「child.TestChild」になるわけだ。
%d日付。これは %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ログを生成したソースファイル名。遅いぞ!と警告されている
%Lログを生成した箇所のソースの行番号。遅いぞ!と警告されている
%Mログを生成したメソッドの名前。遅いぞ!と警告されている
%mログメッセージ
%xNDC の値
%X{key}その MDC(1.2)、プロパティ(1.3) に保存された key の値
%n改行コードを生成する。\nじゃないわけである。
%pログレベル(FATALとかINFOとか)
%rアプリケーションが開始してからの通算時間(ミリ秒)
%tログを生成したスレッド名
%throwable{short}1.3で追加。これはレイアウト要素というよりも一種のスイッチである。例外をログメソッドに渡して Log4j を呼ぶと、デフォルトでは例外スタックトレースをすべて出力することになる。とはいえ、これは鬱陶しいケースも多い。なので、この「%throwable{short}」という表現をログフォーマットの末尾につけてやると、例外スタックトレースの最初の行だけを表示することになる。ちょっと動作が例外的なのが気になるが...
%properties{プロパティ名}1.3で追加。ログイベントのプロパティ。使いかたは後述する。


また、それぞれ「%-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