log4j

使い方(2)

目次

• QuickStart
• カテゴリー
• ログ出力
• レイアウト
• log4Jの初期化
• 1.3 の内部ログ
• XML設定ファイル
• JoranConfigurator(1.3)
• Filter機能
• commons-loggingから使う
• 速度に対する配慮

---

log4j の初期化

ここで少し log4j の初期化について話しておこう。実際には、

Logger log = org.apache.log4j.Logger.getLogger( this.getClass() );

のように、org.apache.log4j.Logger クラスのクラスメソッドである getLogger() を呼び出して利用を開始するのだが、これは

  /**
     Retrieve a logger by name.
  */
  static
  public
  Logger getLogger(String name) {
    return LogManager.getLogger(name);
  }

Logger クラスの中で定義されている。では org.apache.log4j.LogManager クラスはどうか、というと、このクラスの初期化ブロックの中で、初期化ファイルを読んでいるのである。ということは、初めて getLogger メソッドが呼ばれた時に、一度だけ LogManager クラスの初期化がなされることになる。この部分はこうだ。

  /**
   * @deprecated 
   * */
  static public final String DEFAULT_CONFIGURATION_FILE = "log4j.properties";
    static final String DEFAULT_XML_CONFIGURATION_FILE = "log4j.xml";  
   
  /**
   * @deprecated これらの変数は内部使用限定である。そのうち private にする
   * */
  static final public String DEFAULT_CONFIGURATION_KEY="log4j.configuration";
  static final public String CONFIGURATOR_CLASS_KEY="log4j.configuratorClass";
  public static final String DEFAULT_INIT_OVERRIDE_KEY = 
                                                 "log4j.defaultInitOverride";
  static {
    // By default we use a DefaultRepositorySelector which always returns 'h'.
    Hierarchy h = new Hierarchy(new RootCategory((Level) Level.DEBUG));
    repositorySelector = new DefaultRepositorySelector(h);

    /** CLASSPATH の中から log4j.properties ファイルを探す */
    String override =OptionConverter.getSystemProperty(DEFAULT_INIT_OVERRIDE_KEY,
                                                       null);

    // もし、 default init override がなければ、ユーザが指定したリソースか、
    // デフォルトの設定ファイルを取得する。
    if(override == null || "false".equalsIgnoreCase(override)) {
      // システムプロパティを見ている。
      String configurationOptionStr = OptionConverter.getSystemProperty(
                                        DEFAULT_CONFIGURATION_KEY, null);

      String configuratorClassName = OptionConverter.getSystemProperty(
                                        CONFIGURATOR_CLASS_KEY, null);

      URL url = null;

      // log4j.configuration プロパティをユーザが指定しなかった場合、
      // まず "log4j.xml" を探し、それから"log4j.properties" を探す
      if(configurationOptionStr == null) {      
        url = Loader.getResource(DEFAULT_XML_CONFIGURATION_FILE);
        if(url == null) {
          url = Loader.getResource(DEFAULT_CONFIGURATION_FILE);
        }
      } else {
        try {
          url = new URL(configurationOptionStr);
        } catch (MalformedURLException ex) {
          // ということは、resource は URL ではない。
          // ファイル名だと考えて、CLASSPATH から探す。
          url = Loader.getResource(configurationOptionStr); 
        }       
      }
      
      // url が null でなければ、残りの設定を OptionConverter.selectAndConfigure
      // メソッドに任す。
      if(url != null) {
        LogLog.debug("Using URL ["+url+"] for automatic log4j configuration.");      
        OptionConverter.selectAndConfigure(url, configuratorClassName, 
                                           LogManager.getLoggerRepository());
      } else {
        LogLog.debug("Could not find resource: ["+configurationOptionStr+"].");
      }
    }  
  } 

となっている。

ここらへん 1.3 では実装が大きく変わっている....が、基本ラインはそうそう変わるものではない。大きな変更は、「log4j.repositorySelecter」というシステムプロパティが追加され、この値が「JNDI」ならば、JNDI経由で設定が可能になったことである。詳細はorg.apache.log4j.selecter.ContextJNDISelecter のドキュメントを参照されたい。

これで設定ファイルは自由自在だ。しかしこれはデフォルトの設定である。プログラム上で明示的にプロパティを指定するには、次のようにする。

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 ) {
       PropertyConfigurator.configure( "myapp.log4j.properties" );
       log.info( "ENTER: TestLog4j" );
       TestChild tc  = new TestChild();
       tc.doSomething();
       log.info( "EXIT: TestLog4j" );
   }
}

これで myapp.log4j.properties というファイルを設定ファイルとすることができる。myapp.log4j.properties と log4j.properties が両方あった場合には、基本的に両方ともがマージされることになるが、どうやら同一のカテゴリーに対して、同じ Appender が設定された時には、後の方（PropertyConfiguratorで明示的に設定する方）によって、上書きされるようである。逆に言えば、カテゴリーが違っていて、継承によって結果的にダブる場合は、両方が出力されることになる。

あと、便利なオプションとして、「debug=true」がある。これは具体的なログの「debug」ではなくて、log4j 自体のデバッグのためのフラグである。これは log4j.properties の中で、

log4j.debug=true

と指定すると、

% java jp.or.nurs.sug.log4j.test.TestLog4j
log4j: Parsing for [root] with value=[debug, stdout].
log4j: Level token is [debug].
log4j: Category root set to DEBUG
log4j: Parsing appender named "stdout".
log4j: Parsing layout options for "stdout".
log4j: Setting property [conversionPattern] to [%d %5p %c{1} - %m%n].
log4j: End of parsing for "stdout".
log4j: Setting property [target] to [System.out].
log4j: Parsed "stdout" options.
log4j: Parsing for [jp.or.nurs.sug.log4j.test] with value=[info, file].
log4j: Level token is [info].
log4j: Category jp.or.nurs.sug.log4j.test set to INFO
log4j: Parsing appender named "file".
log4j: Parsing layout options for "file".
log4j: Setting property [conversionPattern] to [%d %5p %c{1} - %m%n].
log4j: End of parsing for "file".
log4j: Setting property [append] to [true].
log4j: Setting property [file] to [mylog.log].
log4j: setFile called: mylog.log, true
log4j: setFile ended
log4j: Parsed "file" options.
log4j: Handling log4j.additivity.jp.or.nurs.sug.log4j.test=[null]
log4j: Finished configuring.
2004-09-12 23:24:26,538  INFO TestLog4j - ENTER: TestLog4j

といった診断メッセージを出してくれる。便利なので、困った時には使うと設定ファイルの間違いが判るんじゃないかな？

1.3 の内部ログ

RootLogger の扱いが、1.3 で少し変わっている。Log4J はそれ自身としての「診断メッセージ（設定ファイルが正しく書かれているか？）」を出すのだが、1.2 までは「診断メッセージを出す」かどうかは、「log4j.debug=true」で出す指定をする必要があった。言い替えると RootLogger にたとえば ConsoleAppender のような「標準出力にログを出す」Appender を追加しても、特に「log4j.debug=true」にしなければ、一切診断メッセージ（及び内部ログ）は出さなかった。

この動作が変わった。1.3 では、「RootLogger は診断メッセージの担当」という感じの動作をするようになり、RootLogger に特に DEBUG レベルの出力をさせると、大量の診断メッセージと進行状況に応じた内部ログを出す。これは実際結構うっとおしい。

で「log4j.debug=true」の扱いだが、これは 1.3 では実質上無意味になった。たとえば、「log4j.debug=true」を指定し、RootLogger に Appender を何も設定しないケースだと、次のような出力になる。

最初の行として、常にこの行が出る。
log4j:INFO Using URL [file:/usr/local/bizet/log4j/log4j.xml] for automatic log4j configuration of repository named [default]. 
LOG4J-INTERNAL: 2006-04-12 11:52:12,244 DEBUG [main] org.apache.log4j.joran.action.ConfigurationAction#begin:42)- Starting internal logs on console.
LOG4J-INTERNAL: 2006-04-12 11:52:12,271 DEBUG [main] org.apache.log4j.joran.action.AppenderAction#begin:52)- About to instantiate appender of type [org.apache.log4j.ConsoleAppender]
LOG4J-INTERNAL: 2006-04-12 11:52:12,282 DEBUG [main] org.apache.log4j.joran.action.AppenderAction#begin:67)- Appender named as [stdout]

要するに、「debug=true」の場合は、「LOG4J-INTERNAL」という「内部ログ専用の ConsoleAppender」が「ある」ことになり、これに診断メッセージを出すことになる。更にRootLogger に Appender があって出力設定があると、この内部ログがその出力に出る。

ということは、筆者の 1.3 での結論＆オススメはこうだ。「RootLogger に Appender を設定してログを出す、という指定の仕方は 1.3 からは止めよう」。個別の「log4j.logger.カテゴリー」にのみ、Appender を設定し、「log4j.rootLogger」には単に「log4j.rootLogger=debug」でデフォルトのログレベルを指定するだけにするか、まったく「log4j.rootLoger」行をなしにした方が、うっとおしくなくて良かろう。

ちなみに最初に出てしまう、

log4j:INFO Using URL [file:/usr/local/bizet/log4j/log4j.xml] for automatic log4j configuration of repository named [default]. 

の行だが、これは org.apache.log4j.util.LogLog という標準出力に出すだけ（System.out.println なんて使ってる）のログである。インターフェイスは Log4j の Logger みたいな格好をしているが、実装は無関係なものである。これを出ないようにするためには、システムプロパティの「log4j.coreDebug=false」にしないといけない...つもりなのかもしれないが、現状の実装はレベルが debug の時にしかこの LogLog によるログは排除できない。要するに、現状ではこのログは常に標準出力に出てしまう。（QuietMode を有効にしろよ！）...その他 SocketAppender でも DEBUG レベルでの出力があったりもする...全然不統一なので、これは多分、正規のディストリビューションでは何か解決があるのでは？とも感じる。

XML形式の設定ファイル

ここで、log4j.xml というXML形式の設定ファイルの書き方を説明しよう。これは「単純に log4j.properties ファイルを XML 形式にしたもの」程度のファイルである。

### 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
log4j.logger.jp.or.nurs.sug.log4j.test=info, file

だったら、

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" >
  <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
     <param name="Target" value="System.out" /> 
     <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d %5p %c{1} - %m%n" />
     </layout>
  </appender>
  <appender name="file" class="org.apache.log4j.FileAppender">
     <param name="File" value="mylog.log" />
     <param name="Append" value="true" />
     <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d %5p %c{1} - %m%n" />
     </layout>
  </appender>

  <category name="jp.or.nurs.sug.log4j.test" >
    <priority value ="info" />
    <appender-ref ref="file" />
  </category>  
  <root>
    <priority value ="debug" />
    <appender-ref ref="stdout"/>
  </root>
</log4j:configuration>

といった具合になる。まあ、素直にプロパティ形式をXML化している、という感じだな。念のために、log4j.xml で使う DTD を表示しておこう。これは jar ファイルの org/apache/log4j/xml/log4j.dtd として同封されている。→log4j.dtd

要注意: 1.3 では log4j.xml にちょっとばかり古いバージョンとの間での互換性がないケースがある。大きな変更は、

1. DOMは使わなくなったので、DOCTYPE 宣言はなくてよい。
2. category エレメント → logger エレメント。である。以前から logger エレメントはあったが、1.3 では category エレメントは廃止されたので、logger エレメントの方だけを使わなくてはならない。
3. priority よりも level の方が望ましい。

というあたりだ。だから、1.3 用の log4j.xml は次のようになる。

<?xml version="1.0" encoding="UTF-8" ?>
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" >
  <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
     <param name="Target" value="System.out" /> 
     <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d %5p %c{1} - %m%n" />
     </layout>
  </appender>
  <appender name="file" class="org.apache.log4j.FileAppender">
     <param name="File" value="mylog.log" />
     <param name="Append" value="true" />
     <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d %5p %c{1} - %m%n" />
     </layout>
  </appender>

  <logger name="jp.or.nurs.sug.log4j.test" >
    <level value ="info" />
    <appender-ref ref="file" />
  </logger>  
  <root>
    <level value ="debug" />
    <appender-ref ref="stdout"/>
  </root>
</log4j:configuration>

ちなみにさっき述べた log4j.debug=true は XML 形式だとトップレベルでこうする。

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="true" >

で、log4j.xml は既に述べたように、クラスパス上の log4j.properties よりも優先して設定ファイルとして解釈される。言い替えれば両方あった時には、log4j.xml 「だけ」が設定ファイルとして認識されることは、すでに述べた通りだ。

じゃ、プログラムの中から、特定のXML設定ファイルを指定するにはどうすれば良いか、というと、

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

import org.apache.log4j.Logger;
import org.apache.log4j.xml.DOMConfigurator;
/* 1.3 の場合
import org.apache.log4j.joran.JoranConfigurator;
import org.apache.log4j.LogManager;

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 ) {
          DOMConfigurator.configure( "myapp.log4j.xml" );
	  /* 1.3 の場合は、
          JoranConfigurator jc = new JoranConfigurator();
          jc.doConfigure( "myapp.log4j.xml", LogManager.getLoggerRepository());
	  の方が望ましい 

          log.info( "ENTER: TestLog4j" );
          TestChild tc  = new TestChild();
          tc.doSomething();
          log.info( "EXIT: TestLog4j" );
     }
}

とやってやればいいだけである。

バグ回避：筆者はこの XML 設定ファイルで随分苦労させられたぞ...というのは、筆者の Linux 環境は J2SDK が 1.3系 だったのもあって、例の有名な「XML系API問題」にブチ当ってしまったのだ。勿論 1.4 系以降を使うのならば、jaxp や crimson が JVM の標準 API として持ち持ちなので、こういう問題は起きないのだが...
log4j は「どのDOMパーサを使うのか？」という問題について、jaxp を使うので、自動でクラスパスの中の各種 jar を見て、それを解決しようとするのである。しかし、org.apache.xerces.jaxp.DocumentBuilderImpl（ファイルは xercesImpl-2.0.2.jar とか） が先に見つかってしまうと、どうやらバグがあるようで、うまく XML設定ファイルをパースできず、次のような例外を投げる。

% java jp.or.nurs.sug.log4j.test.TestLog4j
log4j:ERROR Could not parse input source [org.xml.sax.InputSource@eb7859].
java.lang.NullPointerException
        at org.apache.xerces.parsers.DOMParser.parse(DOMParser.java:257)
        at org.apache.xerces.jaxp.DocumentBuilderImpl.parse(DocumentBuilderImpl.java:209)
        at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:665)
        at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:616)
        at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:602)
        at org.apache.log4j.helpers.OptionConverter.selectAndConfigure(OptionConverter.java:460)
        at org.apache.log4j.LogManager.(LogManager.java:113)
        at org.apache.log4j.Logger.getLogger(Logger.java:94)
        at jp.or.nurs.sug.log4j.test.TestLog4j.(TestLog4j.java:7)
log4j:WARN No appenders could be found for logger (jp.or.nurs.sug.log4j.test.TestLog4j).
log4j:WARN Please initialize the log4j system properly.

参ったね、こりゃ。で、これは要するに JAXP の自動検索で見つかる DocumentBuilderFactory の問題なので、システムプロパティを設定することで、問題のない crimson 版(crimson.jar とか)を見つけさせることができる。これはこうする。

% java -Djavax.xml.parsers.DocumentBuilderFactory=org.apache.crimson.jaxp.DocumentBuilderFactoryImpl 
     jp.or.nurs.sug.log4j.test.TestLog4j

ふう、困ったことだが仕方がない。これでお悩みの方はこうしてくれ。もっと知りたい人は、org/apache/log4j/xml/DOMConfigurator.java の doConfigure() メソッドを見れば何してるのか見当がつくぞ。

JoranConfigurator(1.3)

さて、1.3 の目玉の１つが JoranConfigurator である。これは 1.3 では DOMConfigurator に完全に置き換わり、log4j.xml のような XML 形式設定ファイルはコレでパースすることになる。ポイントは DOM ベースの実装から、SAX+XPath ベースになり、柔軟性が格段にアップしたことである。

だから、log4j.dtd は JoranConfigurator の場合、無関係になる。DOMConfigurator では当然 DTD でそのその妥当性をチェックするわけだから、エレメントの順番など厳格に守らなくてはならなかったが、JoranConfigurator の場合、順番はどうでもよくなる...だけではない。DOM のの代わりにこれは XPath 形式で設定がなされるので、org.apache.log4j.joran.JoranConfigurator を覗くと、どういうものか見当がつく。実際、設定されている XPath から拾い出すと、こういうエレメントの構造になる（順不同）。

configuration -+- substitutionProperty
               +- repositoryProperty
               +- conversionRule
               +- plugin
               +- logger         ←1.3 では category は logger に吸収
               |    +- level
               |    +- priority  ←1.3 では deprecated 扱いとなり、
               |    |            level を使え！とのメッセージが出る
               |    +- appender-ref
               +-root
               |    +- level
               |    +- priority
               |    +- appender-ref
               +-appender
               |    +- appender-ref 
               |    +- layout
               +-jndiSubstitutionProperty 
               +-newRule

でお馴染みの <param> とかは、どこにでも使えるし、それ以外のエレメントもappender エレメント内などには使えちゃうわけである。ここらへんは実際にはその Appender について、JavaBeans 風のリフレクションによって、Appender ごとに有効かどうかのチェックがなされていく。

言い替えると、その Appender クラスに、

public class SomeAppender extends AppdenerSkelton {
   ......
   public void setAbcd( String val ) { ...... }
}

みたいな、基本型とかString型のような単純な引数を取るメソッドが定義されていれば、その「Abcd」について、

   <appender name="A" class="org.apache.log4j.SomeAppender">
      <param name="Abcd" value="the value" />
   </appender>

のように <param> エレメントを書くことができるわけである。そうではなくて、もっと複雑なクラスを引数に取るメソッドが Appender に定義され、そのクラスが org.apache.log4j.spi.OptionHandler を implements する場合、「Strategy」パターンでいろいろと実装を差し替えながら柔軟な設定をすることができる。「Strategy」なので、その「差し替え可能な戦略」を定義する interface を、該当する Appender のセッタでは、その引数の「型」とする。

public class SomeAppender extends AppdenerSkelton {
   ......
   public void setAbcd( SomeInterface nam ) { ...... }
}

public interface SomeInterface extends OptionHandler {
   .....
   public void setSomeParam( String value );
}

public class SomeConcreteClass implements SomeInterface {
   /* activateOptions() は OptionHandler が要求する唯一のメソッド */
   public void activateOptions() { /* 設定が終った時点で呼ばれる */ }
   public void setSomeParam( String value ) { ..... }
}

この時、次のように log4j.xml の中で「子持ちエレメント」にすることができる。この時、その interface に JavaBeans 形式のセッタがあれば、「子持ちエレメント」の中の <param> にすることも可能である。

   <appender name="A" class="org.apache.log4j.SomeAppender">
      <Abcd class="SomeConcreteClass" >
         <param name="someParam" value="the value" />
      </Abcd>
   </appender>

多分これはバグだが、SMTPAppender の Evaluator オプションに設定可能な interface である、TriggeringEventEvaluator は、この OptionHandler を extends していない。だから、ちょっと困った動作をしたりする...というのを後で見る。まあ、そういう風に interface をうまく使い、それを設定ファイルの形式にうまく適合させている、というあたりがポイントである。

その他、logger、root、appender のエレメントは今までの DOMConfigurator と互換なので、特に付け加えることはなかろう。問題は、新しく出てきたエレメントたちである。

一番使いでのある新エレメントは、substitutionProperty である。これは、別ファイルに書いたプロパティを、log4j.xml に「取り込んで」使えるというスグレ物だ。要するに ant の build.xml が「${変数名}」のかたちでプロパティを読み込んで使えるのと同じような機能である。

これは、

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration>
<log4j:configuration debug="true">
  <substitutionProperty file="mysql.properties";/>
  <appender name="DB" class="org.apache.log4j.db.DBAppender">
   <param name="locationInfo" value="true"/>
   <connectionSource class="org.apache.log4j.db.DriverManagerConnectionSource">
     <param name="driverClass" value="${driverClass}<"/>
     <param name="url" value="${url}"/>
     <param name="user" value="${user}"/>
     <param name="password" value="${password}"/>
   </connectionSource>
  </appender>
  .....

のように log4j.xml に書き、「file="mysql.properties"」で指定されるプロパティ形式のファイルにあるプロパティによって、「${driverClass}」のような表現を置き換える、というものである。だから、mysql.properties はこんな感じのものである。

driverClass=com.mysql.jdbc.Driver
dataSourceClass=com.mysql.jdbc.jdbc2.optional.MysqlDataSource
pooledDataSourceClass=com.mysql.jdbc.jdbc2.optional.MysqlConnectionPoolDataSource
url=jdbc:mysql://127.0.0.1/log4j?useUnicode=true&characterEncoding=SJIS
user=root
password=

ここで定義された各プロパティが、log4j.xml の中で置換されて使われる、というわけである。なかなか賢い機能であるので、活用はいろいろと出来そうだ。

とはいえ、他のエレメントたちは、現実にはそれほどの活用場面はなさそうだ。とりあえず、どういうことができるエレメントかだけをまとめて、それぞれのハックは別ページとしよう。

jndiSubstitutionProperty

これは JNDI 経由で置換すべきプロパティの値を取得するものだ。たとえば JNDI でDBのアカウント＆パスワードを管理し、それを取得して log4j.xml に埋め込む...なんてのが一番考えられる利用法である。

repositoryProperty

これは「レイアウト」の項で紹介だけした、「ログイベントのプロパティ」に関連する機能である。要するに、このエレメントを使うと、指定するロガーに対して、任意のプロパティを与えることができ、そのロガーについて発生したログイベントについて、ここで与えたプロパティが付与されることになる。参考として「ネットワーク系Appender とプロパティ(1.3)」を見ると見当が付くだろう。

conversionRule

これは強烈な機能である。任意の Joran のアトリビュートを、動的に展開するようなコードサポートを与えることができる。実際サンプルとして、ディストリビューションの examples/src/pattern に呼ばれるごとに１つ値の増える「カウンタ」の実装があったりする！

plugin

Pluginを設定する。実際に「Plugin」になっているのは、1.3 で本格実装された「receiver」であり、これは「Log4j が生成したログイベント」を受け付ける「ログビューア」の側で、Appender と対になるかたちでクラスが作られているものだ。だから、たとえば Chainsaw のような「Log4j用ログビューア」の設定と共用するためのものであり、「Log4j でログを出す」という側では特に意味がない。

newRule

JoranConfigurator は「パターン→アクション」のルールによって動作するが、これは設定ファイルレベルで、「新しい Joran のパターン→アクション」を設定するというちょいとメタな機能だ。一般ユーザレベルでは無関係。

Filter機能

Filter機能とは、「ログイベントが指定する条件に合致しているか？」を判定する機能である。結構前から Appender に対してこの Filter を指定してやって、指定条件が成立していれば Appender を実行する、という機能が実装されていた。言い替えると、ロガーの level オプションとか、Appender 自体にある「Threshold オプション」は、単に「ログレベルが○○以上ならば～」という条件で、Appender の実行を制御するものなのだが、Filter はもっときめ細かい制御ができる。

この機能は結構ややこしいので、独立したページする。「Filter機能」を見て欲しい。

commons-logging から使う

さて、残りはあまりハッキーではない。まず、Struts なんかがやっている jakarta-commons-logging との連係プレーである。jakarta-commons-logging は、それ自身として標準出力に吐く org.apache.commons.logging.impl.SimpleLog と、何もせず握りつぶす org.apache.commons.logging.NoOpLog の２つを持つのと同時に、さまざまなログライブラリへのブリッジとして動作する。

現在のところ、Log4J の他に、J2SDK1.4で登場した java.util.logging パッケージ（こいつを使った例は「対戦型五目並べ～サーバ～メインクラス」にある）と、Jakarta の基底フレームワークでデカ過ぎて謎な Avalon（Cocoon,James,JMeterなんかが使ってる....そういえば Avalon って結局プロジェクトが廃止になったようだ....） の LogKit に対応している。

そういえば James に関連して、Avalon の Logkit についても書いてしまったぞ...まあ、利用度は不明だが、こんなん書いたのないと思うので、関心ある方はご覧になっておくれ。

呼び方はこんなところである。

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

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import jp.or.nurs.sug.log4j.test.child.TestChild;

public class TestCommons {
     static Log log = LogFactory.getLog( TestCommons.class ); 

     public static void main( String [] args ) {
          log.info( "ENTER: TestCommons" );
          TestChild tc  = new TestChild();
          tc.doSomething();
          log.info( "EXIT: TestCommons" );
     }
}

基本的に大差はない。じゃあ、どこで「実際に使うログライブラリを指定するの？」という大問題だが、これはクラスパスの通った「commons-logging.properties」に、

org.apache.commons.logging.Log=org.apache.commons.logging.impl.Log4JLogger

と書いておきゃ充分だ（そりゃ、システムプロパティでもイケるが）。これが、

Log4J	org.apache.commons.logging.impl.Log4JLogger
java.util.logging	org.apache.commons.logging.impl.Jdk14Logger
Avalon LogKit	org.apache.commons.logging.impl.LogKitLogger
標準出力	org.apache.commons.logging.impl.SimpleLog
何もしない	org.apache.commons.logging.impl.NoOpLog

という値を取るようになっている...というか、もっとやり方はイイカゲンだ。ホントは commons-loggin.properties なんか無くても動く。ちょっとまとめると正確にはこうだ（参考は org.apache.commons.logging.LogFatory#getFactory() ）

1. カレントディレクトリのファイル「commons-logging.properites」から、「org.apache.commons.logging.Log(あるいは org.apache.commons.logging.log、これ旧バージョンのもの)」を探す。
2. システム・プロパティから「org.apache.commons.logging.LogFactory」を探す。
3. カレントディレクトリから「META-INF/services/org.apache.commons.logging.LogFactory」があればそれを読む。まあ、こりゃ Servlet 対策だな。

で指定されるが、その指定が無いときには強引にでもさらに探す。（org.apache.commons.logging.impl.LogFactoryImpl#getLogClassName() ）。

4. クラスパスの中に Log4J のライブラリがあれば、Log4J を使う。
5. JVM が 1.4 なら、java.util.logging パッケージを使う。
6. JVM が 1.3 で、Lumberjack版の java.util.logging が使えるならそれを使う。
7. 仕方ないので、org.apache.logging で実装されている SimpleOpLog を使う。

というわけで、「Log4J を使え！」と言わんばかりである。

ちなみにログレベルのマッピングは次の通りである。commons-logging は、fatal, error, warn, info, debug, trace の６段階のログレベルを区別するが、Log4J は fatal, error, warn, info, debug で５段階（traceがない）で区別している。まあ、ここらへん「どんなログレベルが必要だ！」というのは、ライブラリ実装者の趣味に依存することが多いので、そこらへんをうまく吸収するようになっているのが、この commons-logging というわけだ。この対応表を示そう。

commons-logging	fatal	error	warn	info	debug	trace
Log4J	fatal	error	warn	info	debug	debug
JDK1.4	SEVERE	SERVER	WARNING	INFO(CONFIG)	FINE(FINER)	FINEST
Avalon	FATAL_ERROR	ERROR	WARN	INFO	DEBUG	DEBUG

log4j が 1.3 になる...ということで、commons-logging の対応は？というと、これは別に影響がないようだ。最新は 1.0.4 だが、古いバージョンでも、1.3 だろうが 1.2系だろうが、問題なく動く。とはいえ、1.2.12 で追加された trace ログレベルの対応は、次のバージョン 1.0.5 で対応される見込みである。だからまあ、この trace ログレベルの追加ってのは、commons-logging との整合性を追求したようなものなのかもしれない。

速度に対する配慮

さて、次は速度への配慮である。「製品コードにデバッグコードを含めるべきか否か？」というのはなかなか難問である。そりゃ製品コードは「可能な限り速く！」動いて欲しいのがプログラマの人情というものだ。しかし、問題が起きた時に、ユーザ環境で「何が問題か？」を知るために、デバッグフラグをオンにしてコンパイルし直すのはバカバカしい。というわけで、デバッグコードをたとえば assertion とか条件コンパイルコードの中に書いてやり、製品コードには含めないようにする、という技がいろいろとあったりするのだが、Log4J では「積極的に含めてもそう遅くならないよ！」ということで、実際には「製品コードに含める」ことを薦めている。

まあ、速度重視で Log4J は書かれており、そうは遅くならない（Appender によってはクソ遅いものもあったりする）が、それでも debug() のような「製品コードには含めない！」デバッグコードを呼び出すのは避けれるとウレシイ。つまり、debug() の呼び出しより、「debug() で出力があるか？」を判定するコードが速く動作すれば、問題は防げるのである。

これはこうする。

if( log.isDebugEnabled() ) {
    log.debug( "Some Debug Message: " + someComplexObject.toString() );
}

これで log.debug() の引数構築のコストも避けることが可能になる。commons-logging を介しているケースでも同様（同じく isDebugEnabled() メソッドで検査）である。

じゃ、実際に isDebugEnabled() メソッドの定義を確認して、ホントに速いかどうか見てみよう（疑り深いな...）

(org.apache.log4j.Logger の基底クラス org.apache.log4j.Category の)
  public
  boolean isDebugEnabled() {
    if(repository.isDisabled( Level.DEBUG_INT))
      return false;
    return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
  }

  public
  Level getEffectiveLevel() {
    for(Category c = this; c != null; c=c.parent) {
      if(c.level != null)
	return c.level;
    }
    return null; // If reached will cause an NullPointerException.
  }


(org.apache.log4j.spi.LoggerRepository の実装クラス org.apache.log4j.Hierarchy)
  public
  boolean isDisabled(int level) {
    return thresholdInt > level;
  }

(org.apache.log4j.Level の実装クラス org.apache.log4.Priority)
  public
  boolean isGreaterOrEqual(Priority r) {
    return level >= r.level;
  }

まあ、１回ループで親の Category を辿って行く、というのがあるだけで、後はどってことない処理ばっかだ。まあ、許せる？