2つのログファイル boot.log と server.log そしてJBossのアーキテクチャ

JBossには2種類のログファイルが存在します．それが"boot.log"と"server.log"です．"server.log"は日付が変わるとローテートされていきますので，"server.log.20050606"のようなファイルも運用環境ではいっぱいできているかもしれません．

さて，この2種類のログファイルですが何がどう違うんでしょう？　

そしてもう1つ，名前からして"boot.log"は起動時のログで"server.log"は起動してからのログという風な雰囲気を漂わせていますが，一体いつこの2つのログファイルの出力先は切り替わるのでしょう？　それとも切り替わっているのじゃなくて2系統のログがあるのかな？

そんな疑問をみなさんも持ったことありませんか．その謎を今日解消します．

現在のJBoss(ver3.x系やver4.x系）ではマイクロカーネルにJMXを使っています．JBossの起動プロセスに関連するソースコードを読んだ方ならご存知だと思いますが，JBossでは起動スクリプト(run.batまたはrun.sh)によりmain()メソッドから起動された後，"org.jboss.system.server.ServerImpl"というクラスにまず制御が移ってきます．そしてこの中で最初にMBeanServerを起動します．

MBeanServerを起動した後，次に行うのはMainDeployerとJARDepoloyerをMBeanとしてMBeanServerへ登録することです．ここまではXMLファイルにではなくJBossのソースコードにハードコーディングされています．しかしここまでくれば後は任意のサービスをJARDeployerによりJARファイルから読み込んで，そしてMainDeployerを通じてデプロイできるようになります．後はXMLで設定が可能な領域です．

MainDeployerとJARDeployerの後は，確かまず"$SERVER/conf/jboss-service.xml"を読みに行ってここを先頭に各種サービスをどかどかデプロイしていきます．jboss-service.xmlを特に変更していなければ，その中にLog4jServiceの記述もかかれていますので，Log4jもサービスとしてデプロイされることになります．

そう実は，"boot.log"と"server.log"の違いは，この一連の過程でLog4jServiceがデプロイされる前か後かという違いなんです．

Log4jServiceがデプロイされる前に使われるのが"boot.log"で，これはJBossが起動する度にゼロから上書きします．つまり今さっきJBossを起動したとすると昨日起動した際のログは上書きされて無くなってしまうわけです．でもこれだと運用を行う立場からすると困りますよね．しかし大丈夫です．"server.log"の方は上書きされずに，ログが追加される形で書き込まれていきます．そして日付が変わればファイルもローテートします．

ではちょっと実際にログを見てみましょう．長いので一部だけですが．まずはboot.logの一番最後の部分．

01:23:00,765 DEBUG [ServiceController] Creating dependent components for: jboss:service=Naming dependents are: []
01:23:00,765 DEBUG [ServiceController] Creating service jboss.system:service=Logging,type=Log4jService
01:23:00,765 DEBUG [Log4jService] Creating jboss.system:service=Logging,type=Log4jService
01:23:00,765 INFO  [Log4jService$URLWatchTimerTask] Configuring from URL: resource:log4j.xml

上記3行目を見ると"Creating ..."となっています．これはJBossのサービス系MBeanを作る際のサポートクラスであるServiceMBeanSupportクラス（Log4jServiceクラスはこのクラスの拡張）のcreateメソッドが呼ばれた際のお決まりのログ出力です．

Log4jServiceクラスではこのメソッドの中で呼び出されるcreateServiceメソッドをオーバーライドして（こういう決まりになっています），あれこれやっているわけです．ここでは上記4行目にあるようにLog4jの設定ファイルを読み込んでいます．

そして次はこれに続くserver.logの一番先頭部分です．

2005-06-07 01:23:00,945 DEBUG [org.jboss.logging.Log4jService] Installed System.out adapter
2005-06-07 01:23:00,945 DEBUG [org.jboss.logging.Log4jService] Installed System.err adapter
2005-06-07 01:23:01,045 DEBUG [org.jboss.logging.Log4jService] Added ThrowableListener: org.jboss.logging.Log4jService$ThrowableListenerLoggingAdapter@50ca0c
2005-06-07 01:23:01,045 DEBUG [org.jboss.logging.Log4jService] Created jboss.system:service=Logging,type=Log4jService  <b><font color="blue">←(3)</font></b>

コンソールで見る時とは違ってクラス名が完全修飾クラス名で表示されてますね．おそらくこの辺はlog4j.xmlにそう書いてあるのでしょう．上記4行目のところでServiceMBeanSupportクラスのcreateメソッドの呼び出しが終わっています．ということはLog4jServiceクラスのcreateServiceメソッドの中でログの出力先が切り替わったんですね．

さて，核心に迫ってみましょう．以下は先ほどの(2)のところででていたインナークラスURLWatchTimerTask（このクラスはThreadの拡張クラスでrunメソッドから起動される）のreconfigureメソッドのソースコードの一部です（620行目くらい）．

 if (xml)
 {
    log.debug("foo");
    DOMConfigurator.configure(configURL);
    log.debug("bar");
 }
 else
 {
    PropertyConfigurator.configure(configURL);
 }

さっそくDEBUGログを突っ込んで見ました．"log4j.xml"の場合はifの中，"log4j.properties"の場合はelseの中に入るのだと思われます．この状態でJBossを再コンパイルし，一度"boot.log"と"server.log"を削除した上でJBoss起動を起動すると・・・

boot.log の最終行

01:45:59,567 DEBUG [ServiceController] Creating dependent components for: jboss:service=Naming dependents are: []
01:45:59,567 DEBUG [ServiceController] Creating service jboss.system:service=Logging,type=Log4jService
01:45:59,567 DEBUG [Log4jService] Creating jboss.system:service=Logging,type=Log4jService
01:45:59,567 INFO  [Log4jService$URLWatchTimerTask] Configuring from URL: resource:log4j.xml
01:45:59,577 DEBUG [Log4jService$URLWatchTimerTask] foo

server.log の先頭行

2005-06-07 01:45:59,627 DEBUG [org.jboss.logging.Log4jService$URLWatchTimerTask] bar
2005-06-07 01:45:59,627 DEBUG [org.jboss.logging.Log4jService] Installed System.out adapter
2005-06-07 01:45:59,627 DEBUG [org.jboss.logging.Log4jService] Installed System.err adapter
2005-06-07 01:45:59,637 DEBUG [org.jboss.logging.Log4jService] Added ThrowableListener: org.jboss.logging.Log4jService$ThrowableListenerLoggingAdapter@56860b
2005-06-07 01:45:59,637 DEBUG [org.jboss.logging.Log4jService] Created jboss.system:service=Logging,type=Log4jService

おぉぉ！予想的中ですね．こんな感じで出力先の切り替え自体はlog4jに設定ファイルを読み込ませることで行っているようですね．

今回，XA関連でいろいろJBossのソースコードにDEBUGメッセージを突っ込んだりして遊んでいたわけですが，思わぬ副産物でこんなことも分かりました．ちなみにこの話はJBossのドキュメントには書いてありませんよ．Wikiには2つのファイルの違いくらいは書いてあるかもですが．

オープンソースはこうやって遊べるのが楽しいですね〜．