効率的なログ出力をCommonsで実現：現場に活かすJakarta Project（9）

» 2003年08月23日 00時00分公開

　プログラムを作成する際に、地味ですが重要な作業の1つとしてログの出力部分の作成があります。ログの出力が適切でないと、トラブルが発生した場合にその原因をつかむのが難しくなります。ログの出力が適切であれば、問題の原因を特定することが容易になるでしょう。

　また、システムの処理時間をログの要所に入れておけば、プロファイラなどを使わなくても、ボトルネックがある程度解析できます。レスポンスタイムなどのシステム状態の統計を取っておけば、問題の把握などにも役立つでしょう。本稿では、そんな縁の下の力持ちともいえるログの出力機能を提供するCommonsプロジェクトのLoggingとlog4jについて紹介します。

Logginで実現できること

　Loggingは、log4jやJ2SDK 1.4のLogging APIなど、複数のログAPIへのラッパーとして利用できるライブラリです。Loggingを利用すると、次のようなメリットがあります。

ログの実装を自由に切り替えることができる
別のアプリケーションのログシステムと親和性が高い

　ログ実装には、前述のJ2SDK 1.4から導入されたLogging APIのほかに、Jakartaでもlog4jやLogkitなどを提供しています。どれを利用するかは、一長一短であり悩める問題ですが、取りあえずLoggingを利用して実装しておけば、実際にログを出力する実装は後で別のものに切り替えることができるのが利点です。

　ある「アプリケーションA」がlog4jを利用していて、その「アプリケーションA」のログと自分で作成したアプリケーションのログを同じログファイルに統一された形式で出力したいとします。Loggingを利用すれば、ログ出力の実装にlog4jを利用するように設定するだけで、統一された形式のログを出力することが可能となります。また、「アプリケーションB」がJDK 1.4のログAPIを利用している場合でも、簡単にJ2SDK 1.4のAPIに合わせることができます（図1）。

図1　CommonsのLoggingを利用すれば統一された形式のログを生成できる

　上図では、ライブラリのログをアプリケーションに合わせていますが、もちろん別のファイルに出力することもできます。

Loggingを使う

　さて、早速ですが、Loggingの使い方をサンプルと一緒に実際に見てみましょう。Loggingを利用したサンプルをリスト1に示します。

リスト1　LogTest.java

import org.apache.commons.logging.*;

            

            public class LogTest {

              // ログインスタンスを取得

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

              public static void main(String args[]) {

                //　致命的なエラーの出力

                log.fatal("fatalメッセージ");

            

                //　通常のエラーの出力

                log.error("errorメッセージ");

            

                // 警告の出力

                log.warn("warnメッセージ");

            

                // 情報の出力

                log.info("infoメッセージ");

            

                // デバッグ情報の出力

                log.debug("debugメッセージ");

            

                // 詳細なデバッグの出力

                log.trace("traceメッセージ");

            

                try {

                  throw new Exception("Error Message");

                } catch (Exception e){

                  // Exceptionのスタックトレースを出力

                  log.error("Error Occurs:",e);

                }

            

                int[] ary = new int[10000];

            

                if(log.isDebugEnabled()){

                  for(int i = 0;i < 10000; i++){

                     log.debug("array["+i+"]="+ary[i]);

                  }

                }

              }

            

            }

　リスト1を実行してみましょう。Loggingをhttp://jakarta.apache.org/site/binindex.htmlからダウンロードします。ここでは、バージョン1.0.3を利用しました。次に、ダウンロードしたファイルからcommons-logging.jarを取り出し、次のようにして実行します。

> javac -classpath 
            commons-logging.jar:. LogTest.java

            > java -classpath commons-logging.jar:. LogTest

            2003/04/24 23:26:46 LogTest main

            致命的: fatalメッセージ

            2003/04/24 23:26:47 LogTest main

            致命的: errorメッセージ

            2003/04/24 23:26:47 LogTest main

            警告: warnメッセージ

            2003/04/24 23:26:47 LogTest main

            情報: infoメッセージ

            2003/04/24 23:26:47 LogTest main

            致命的: Error Occurs:

            java.lang.Exception: Error Message

            at LogTest.main(LogTest.java:27)

　J2SDK 1.4を利用する場合、Loggingによるログ出力の実装は、デフォルトとしてJ2SDK 1.4のログAPIが利用されます。そのため、上記のメッセージはJ2SDK 1.4のログAPIにより出力されたものとなっています。

　より具体的に使い方を見ていきましょう。

■Logインスタンスの取得

public class LogTest {

              // ログを埋め込むクラス

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

　ここで、LogFactoryのgetLogメソッドにログを埋め込むクラスを指定することに注意してください。これにより、このLogインスタンスはLogTestというクラスに対応づけられ、log4jやJ2SDK 1.4のログAPIを利用する際、ログの出力単位をパッケージ名やクラス名で指定できるようになります。このLogは、staticメンバ変数として取得しておくとよいでしょう。

■ログの出力

　ログを出力するには、前出のリスト1のように、fatal／error／warn／info／debug／traceを利用します。Exceptionのエラーメッセージとスタックトレースをログに出力したい場合は、ログ出力メソッドの後にExceptionのオブジェクトを指定します。

} catch (Exception e){

              log.error("メッセージ",e);

            }

　ログの出力には、fatalからtraceまで6段階のレベルを指定することができますが、実際に現場で開発する場合には、各レベルで何を出力するか表1のように決めておいた方がよいでしょう。

**表1　ログレベルの利用例**
	ログレベル	用途
	fatal	システムがこれ以上動作できない致命的なエラーが発生した場合
	error	予期せぬ動作などにより、正しく処理できない場合
	warn	なんらかの問題が発生したが、動作には影響がない場合
	info	設定ファイルを読み込んだときの設定情報、システム開始／停止時の状態出力など
	debug	デバッグ情報。例えば、外部モジュールから呼ばれるメソッドの入出力情報など
	trace	詳細なデバッグ情報。モジュール内部の情報、ループの繰り返しで大量に出力される情報など

■パフォーマンスの向上

　ログ出力メソッドが頻繁に呼び出されたり、メソッド内で文字列操作を行ったり、ループで何度もログを出力するとオーバーヘッドが発生します。例えば、次のようなコーディングは避けるべきです。

log.debug("パラメータ="+param);

for(int i=0; i< args.length;i++){

              log.trace("パラメータ["+i+"]="+args[i]);

            }

　このコーディングでは、ログレベルをinfoなどにした場合でも、"パラメータ="+paramの部分で毎回文字列の結合が発生し、ループ内の処理も毎回実行されるなど、パフォーマンスの低下が懸念されます。isDebugEnable()などのメソッドを利用すると、指定したログレベルが有効かどうか確認することができます。これを利用して、次のようにコーディングするとよいでしょう。

if(log.isDebugEnable()){

              log.debug("パラメータ="+param);

            }

if(log.isTraceEnable()){

              for(int i=0; i< args.length;i++){

                 log.trace("パラメータ["+i+"]="+args[i]);

              }

            }

log4jを利用したログの出力

　さて、Loggingでログの出力方法が分かったところで、次にlog4jを利用してログの出力を制御してみましょう。ここでは、Loggingとlog4jを一緒に使うことを前提に紹介します。log4jを利用することにより、次のようなことが可能になります。

パッケージ／クラス名などを指定して、パッケージやクラスごとにログを出力
カテゴリと呼ばれる仕組みにより、パッケージやクラスごとにログの粒度を指定できるようになっています。例えば、プログラムをデバッグしていて、バグが潜むパッケージが特定されてくると、バグの疑いがあるパッケージだけログを細かく出力したくなることがありますが、この機能により、簡単に粒度を設定できます。
ログの出力先を柔軟に変更可能
アペンダと呼ばれる仕組みにより、ログをコンソールだけでなく、ファイル、メール、データベースなど、さまざまな媒体に出力することができます。また、ログを出力するレベルも媒体ごとに自由に変更できます。例えば、致命的なエラーが発生した場合、メールで開発者にログを送信するといった使い方もできます。
柔軟な出力形式
レイアウトと呼ばれる仕組みにより、ログの出力形式を自由に変更することができます。

　J2SDK 1.4からはログAPIが標準で含まれているので、log4jの存在を疑問視する人もいますが、安定性を求めるシステムなどで、J2SDK 1.3を利用する場合には、log4jが有用ですし、将来的にJ2SDK 1.4を利用するにしても、log4jを使えばいままでのノウハウをそのまま流用できます。また、log4c（C）／log4cpp（C++）／log4net（.NET）など、ほかの処理系に対する実装も用意されているので、別の言語を利用する場合でも応用できます。

log4jを使う

　Loggingに含まれるcommons-logging.jarとhttp://jakarta.apache.org/site/binindex.htmlからlog4j（ここではjakarta-log4j-1.2.8.zip）をダウンロードし、中のdest/libディレクトリに含まれるlog4j-1.2.8.jarを取り出しておきます。

　次に、log4jの設定ファイルlog4j.xmlを用意します。

リスト2　log4j.xml（文字コードはutf-8で保存）

<?xml version="1.0" encoding="UTF-8" ?>

            <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

            

            <log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/'>

            

              <!--テキストにログを出力するConsoleAppenderをSTDOUTとして定義 -->

              <appender name="STDOUT" class="org.apache.log4j.ConsoleAppender" >

            

                <!-- デフォルトのログレベル -->

                <param name="threshold" value="WARN"/>

            

                <!-- ログの出力形式を指定 -->

                <layout class="org.apache.log4j.PatternLayout">

                  <param name="ConversionPattern"

            value="%d %-5p [%t] (%F:%L) - %m%n"/>

                </layout>

              </appender>

            

              <!--決められた期間でログを別ファイルに切り替えて書き込む

                  DailyRollingFileAppenderをDAILYとして定義 -->

              <appender name="DAILY"

             class="org.apache.log4j.DailyRollingFileAppender">

                <!-- ログのファイル名 -->

                <param name="file" value="daily-log" /> 

            

                <!-- デフォルトのログレベル -->

                <param name="threshold" value="INFO"/>

            

                <!-- 日付が変わる瞬間daily-log-2002-06-23のような形式で

                現在のログがリネーム -->

            

                <!-- すでにログが存在する場合、ファイルにログを追加 -->

                <param name="append" value="true" />

            

                <!-- ログの出力形式を指定 -->

                <layout class="org.apache.log4j.PatternLayout">

                  <param name="ConversionPattern" 

            value="'%c', '%p', '%d', '%m'%n" /> 

                </layout>

            

              </appender>

            

              <!-- パッケージmypkgに対してコンソールにinfo以上のログを出力 -->

              <category name="osbook.log2">

                <priority value="info" />

                <appender-ref ref="STDOUT"/>

              </category>

            

            <!-- DAILYアペンダに対してossbook.log2.MyClass2をdebugに設定 -->

            <category name="osbook.log2.MyClass2">

               <priority value="debug" />

              <appender-ref ref="DAILY" />

            </category>

   <!-- すべてのログをinfo -->

              <root>

                <appender-ref ref="STDOUT" />

                <appender-ref ref="DAILY" />

              </root>

            

            </log4j:configuration>

■実行結果

　さて、実行してみましょう。リスト1、リスト2、commons-loggin.jar、log4j-1.2.8.jar、そして先ほどコンパイルしたLogTest.classを同一ディレクトリ上に配置します。実行結果は以下のとおりです。

> java -classpath 
            commons-logging.jar;log4j-1.2.8.jar;. LogTest

            003-07-06 15:13:44,711 FATAL [main] (LogTest.java:8) - fatalメッセージ

            003-07-06 15:13:44,731 ERROR [main] (LogTest.java:11) - errorメッセージ

            003-07-06 15:13:44,741 WARN [main] (LogTest.java:14) - warnメッセージ

            003-07-06 15:13:44,761 ERROR [main] (LogTest.java:29) - Error Occurs:

            Java.lang.Exception: Error Message

            at LogTest.main(LogTest.java:26)

　画面に表示されたログ以外に、daily-log.txtファイルにもログが出力されます。実行時の注意として、commons-logging.jarとlog4j-1.2.8.jarが%JAVA_HOME%\jre\lib\extにインストールされているとカレントディレクトリのlog4j.xmlが読み込まれず正しく動作しません。動作がおかしい場合は、extディレクトリを調べて、これらのjarがインストールされているようであれば、削除してください。

設定ファイルlog4j.xml

　さて、log4jを動かせるようになったところで、log4j.xmlの記述方法を見ていきましょう。log4jでは、次の3つの設定を行うことによりさまざまなログの出力形式を指定することができます。

アペンダ
ログの出力対象の設定。例えば、コンソール、ファイル、メール、データベースなどをログの出力先として指定することができます。また、出力先は複数指定することができます。
レイアウト
ログの出力形式を指定します。日付、ログレベル、ログを出力したソースファイル名、行番号、スレッド番号などを指定することができます。このレイアウトは、アペンダごとに設定でき、例えば、コンソールには、日付、ログレベル、メッセージだけ表示しておき、ファイルにはこれらに加えてソースファイル名や行番号など、より詳細な情報を出力するという使い方もできます。
カテゴリ
カテゴリは、ログの設定単位です。Javaのパッケージもしくは、クラス単位でログの出力レベルを制御することができます。この制御は各アペンダで異なる設定を行うこともできます。

　それでは、アペンダ、レイアウト、カテゴリについて説明しましょう。

■アペンダ

　<appender>要素で、ログの出力対象を決めるアペンダを指定します。ログの出力対象には、コンソール、ファイル、データベース、メール、JMS、Syslogなどがあります。アペンダの設定は次のように行います。

<appender name="定義名" class="アペンダクラス" 
            >

            <param name="パラメータ名" value="パラメータ値"/>

            ... 

            

            <layout class="レイアウトクラス">

              <param name="レイアウトのパラメータ名"   value="レイアウトのパラメータ値"/>

              </layout> 

            </appender>

　パラメータ名では、出力するファイル名、データベースのURL、メールアドレスなど、ログの設定に関する情報を設定します。すべてのアペンダで共通に利用できるパラメータとしては、thresholdがあります。このパラメータは、debug／info／warn／error／fatalを取り、デフォルトのログの出力レベル（log4jのマニュアルでは優先度（Priority）と呼ばれていますがここではLoggingに合わせてレベルと呼びます）を制御できます。この値は、あくまでデフォルト値であり、後で説明するカテゴリの設定で特定のクラスやパッケージに対する設定を変更することができます。なお、log4jにはTraceのログレベルはなく、LoggingのTraceはDebugに対応づけられています。アペンダにはさまざまなものが用意されていますが、代表的なものを表2に示します。

**表2　代表的なアペンダ**
	アペンダ	機能
	ConsoleAppender	コンソールにログを出力する
	FileAppender	ファイルにログを出力する
	DailyRollingFileAppender	ファイルにログを出力するが毎日／毎週といった、一定期間でログのバックアップを取り、新しいファイルにログを出力することができる
	JDBCAppender	データベースにログを出力する
	SMTPAppender	メールにログを出力する

　なお、オリジナルのlog4j（1.2.8以前）では、SMTPAppenderで日本語を正しく扱うことができません。そこで、SMTPAppenderを日本語で扱えるようにしてみました。オリジナルのlog4j-1.2.8.jarの代わりにlog4j-1.2.8-ja.jarを用いて、パラメータに以下を追加してください。

<param name="Charset" value="ISO-2022-JP" 
            />

■レイアウト

　<appender>要素の中で<layout>要素を指定してログの出力形式を決めるレイアウトを指定します。あらかじめ用意されているPatternLayoutを利用すると、さまざまなフォーマットのログを簡単に出力できます。PatternLayoutは、次のようにAppenderタグの中で指定します。

<appender name="STDOUT" class="org.apache.log4j.ConsoleAppender" 
            >

              ...

              <layout class="org.apache.log4j.PatternLayout">

                <param name="ConversionPattern" 
            value="%d %-5p [%t] (%F:%L) - %m%n"/>

              </layout> 

            </appender>

　上記のCoversionPatternパラメータのvalue属性でフォーマットを決めます。上記の例では、以下のような形式になります。

　ログのフォーマットに利用できる文字を表3に示します。

**表3　PatternLayoutで利用できる代表的な書式**
	変数	説明
	%c	カテゴリ名。%c{n}で表示するカテゴリ階層を指定する。例えば、a.b.cというカテゴリに対して、%c{2}はb.cを出力する
	%d	日付。HHを時間、mmを分、ssを秒、SSSをミリ秒としたとき、%d{HH:mm:ss,SSS}, %d{dd MMM yyyy HH:mm:ss,SSS}という形式で指定できる。また%d{ISO8601},%d{ABSOLUTE}という形式でも指定可能
	%L	行番号
	%m	メッセージ
	%n	改行。ログメッセージの最後に挿入
	%p	優先度（fatal／error／warn／info／debug）
	%r	アプリケーションの実行開始からの経過時間
	%t	スレッド名。マルチスレッドのプログラムの場合、利用を勧める

　また、「%4p」など、数字を入れることで最大表示文字数を4文字に抑制したり、「%-p」とマイナスを入れることで左ぞろえにしたりすることができます。「%.5p」とピリオドを用いると、最小文字数を指定（足りない部分は空白で埋める）こともできます。

■カテゴリ

　カテゴリは、ログの設定単位です。Loggingの解説でログの初期化を次のように行うと書きましたが、以下のコードによってクラス名がカテゴリとして設定されます。

public class LogTest {

            ...

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

　通常はjp.co.xxx.MyClassのようなパッケージ階層を伴ったクラス名だと考えてください。このカテゴリにより、特定のパッケージや特定のクラスのログの出力レベルの設定をアペンダごとに変更することができます。

　すべてのカテゴリに対するログを設定するには、次のように<root>要素で設定します。

<root>

              <priority value="info" />

              <appender-ref ref="STDOUT" />

              <appender-ref ref="DAILY" />

            </root>

　この例では、<appender>要素で定義したSTDOUTアペンダとDAILYアペンダのすべてのカテゴリに対してinfoレベルでログを出力します。

　また、特定のカテゴリとアペンダを指定してログレベルを設定するには、<category>要素を利用します。

　なお、<category>要素は、<root>要素の前に定義します。カテゴリの設定例をリスト3に示します。リスト3の設定により、図2のように各アペンダのカテゴリに対してログレベルが設定されます。

リスト3　<category>要素

<!-- STDOUTアペンダに対してossbook.log2以下のレベルをdebugに設定 --> 

            <category name="osbook.log2">

              <priority value="debug" />

              <appender-ref ref="STDOUT" />

            </category>

            

            <!-- DAILYアペンダに対してossbook.log2.MyClass2をdebugに設定 -->

            <category name="osbook.log2.MyClass2">

              <priority value="debug" />

              <appender-ref ref="DAILY" />

            </category>

図2　各アペンダのカテゴリに対してログレベルが設定される

まとめ

　Loggingとlog4j、2つのログツールの概要を紹介してきましたが、いかがだったでしょうか？これらのツールをうまく利用することにより、ログのハンドリングを快適に行うことができるようになります。log4jについてはすでに利用されている方も多いと思いますが、すでに利用されている方にも参考になるように今回はTips的な内容を加えてみました。本稿が皆さまの参考になれば幸いです。

筆者プロフィール

岡本隆史（おかもとたかし）

岡山大学工学研究科修了後、（株）NTTデータに入社。文字認識ソフトウェアの研究開発を経て、Webサービス関連の研究開発に携わる。個人では、Debian GNU／Linuxの優れたメンテナンス性とほかのディストリビューションを圧倒するパッケージ数に引かれDebianを使い始めたのをきっかけに、Debianプロジェクトの開発者となる。DebianプロジェクトのStefan Gybas、Ola Lundqvistらとともに、Javaサポートの強化を行う。Jakartaに関しては、Tomcat／JMeter／ORO／Luceneなどの国際化／日本語へのローカライズ、AntのKaffe VM対応などを行っている。『Jakartaプロジェクト徹底攻略』（技術評論社）、『WEB+DB PRESS』（技術評論社）、『Java World』（IDGジャパン）、『JAVA Developer』（ソフトバンクパブリッシング）などで執筆活動を行っている。

Ja-Jakarta Projectについて
Ja-Jakartaプロジェクトでは、Jakartaプロジェクトのドキュメントの和訳やプロダクトの国際化／日本語化などを行っている。現在、プロジェクトのメンバーを募集中。Ja-Jakartaプロジェクトの活動に参加しようという方は、「Ja-Jakartaプロジェクトへの参加方法」（http://www.ingrid.org/jajakarta/site/getinvolved.html）を参照。

「次回」へ

「現場に活かすJakarta Project」バックナンバー