JDK1.4から導入されたロギングAPIを使って、クールな開発を行いましょう。ロギングAPIには、既にlog4jやJLogといった有名どころがあります。log4jは、元IBM Alphaworksで現Apacheプロジェクトの一つとして公開されています。また、log4j創始者がlog4jと決別し新たにlogback(+slf4j)を開発し公開しています。どちらも高機能で優れたロギングAPIなのですが、これから覚えるならば、まずはJDK標準APIであるJava Loggin APIがいいでしょう。Java Logging APIは機能面では他のロギングAPIより劣っている点もありますが、ロギングのようにプログラミングを助けるヘルパー機構は高機能でなくてもシンプルで簡単に使えるのが一番。標準APIならクラスパス設定不要です。なんたってプログラマーには他に覚えなければいけないことが山のようにあるのだから。
JDK 7に合わせて修正・追記実施(2012-07-15)。
プログラムの動作を確認したい時や、バグの原因を探りたい時に、もっとも簡単な(安易な)方法としてプログラムのあちこちにSystem.out.printlnメソッドを入れることがあるでしょう。作っているプログラムが小さなもので、書いた本人だけしか見ないような場合はそれでいいとして、共同開発しているプログラムや第三者にリリースするようなプログラムの場合、System.out.printlnメソッドでやみくもにコンソールに意味不明なメッセージが出るようでは格好悪いものがあります。意味不明じゃないよ、ちゃんと書式を決めているんだ、System.out.printlnメソッドの引数には必ず日時、クラス名、メソッド名を入れているんだ、というプログラマもいるでしょう。でも、それを手で記述するのは面倒です。それにバグが見つかる度にSystem.out.printlnメソッドを書いてはコンパイル・実行し、今度はそれを消してはコンパイル・実行、と単調な作業を繰り返すのはあまりクールなやり方ではないです。クールなプログラミング作業には単純な繰り返し作業はないし、コンソール出力も美しくなくてはね。
以下に、「Javaデバッグ明快技法」(W.D.Mitchell著、鈴木義幸監訳、オーム社刊)の9章デバッグ戦略から9.2.2節"ショットガンアプローチ"を引用します。
バグ修正のために長時間費やす余裕がある場合にのみ、このアプローチを使用して下さい。
連続したPrintln()文 ショットガン方式では、System.out.println();文をクラスの中で均一に撒き散らし、ある変数の値が不正な値になっていることを推測します。二分検索法を使用するという別のアプローチに似ているように見えますが、これとは全く異なります。ショットガン戦略には、いくつもの欠点があります。
- 莫大な量のデータを解析しなければなりません
- ほとんどのデータが、バグに関係していません
- 物理学同様、対象を変えずに測定することができません。println()文によって、変化が生じます。特に、スレッドのタイミングなどが変わります
- println()文が多いと、他のバグを隠蔽したり、または発生させることがあります
- println()文には、後でわかるように、ソースコードに対して何らかの目印を付けなければなりません
この戦略は、ある特定の場合にメリットがあります。プログラムが異常終了した場合には、最後のprintln()文に有益な情報があるかもしれません。しかし、ショットガンアプローチは、他のすべての方法を試して、結果が得られなかった場合に残しておくべきです。言い換えれば、決して使用してはなりません。
最近は、ソースレベルデバッガが大抵の統合開発環境についているので、これを使ってデバッグすることが多いと思うけど、これって効率がいいのだろうか。近視眼的にコードを追いかけて時間だけが浪費されるってことが結構あるように思えます。
以下に、「プログラミング作法」(B.W.Kernighan, R.Pike著、福崎俊博訳、アスキー刊)の5章デバッガから引用します。
我々の個人的な手法で言えば、我々がデバッガを使うのは、せいぜいスタックトレースを実行したり変数の値を1〜2個表示させたりするときくらいにすぎない。その理由のひとつは、デバッガを使うと入り組んだデータ構造や制御フローの迷路にはまり込んでしまいがちだからだ。プログラムをステップ実行するよりも、もっと真剣に考えたり、重要な部分に出力文や自動チェックコードを追加したりするほうが効率的だと思う。クリックして文を実行していく作業は、きちんと整形された表示出力に目を通すより時間がかかる。コードのクリティカルセクションがどこだかわかっていたとしても、そこをシングルステップ実行するよりプリント文の置き場所を考えるほうが手っ取り早い。もっとも重要なのは、デバッグ用の文はプログラムとともに残るのに対し、デバッガセッションは一時的なものにすぎない点だ。
では、まずSystem.out.printlnメソッドを単純に置き換えるだけのloggingAPIの利用例を見てみましょう。
import java.util.logging.Logger; import java.util.logging.Level; public class SimplePrint { public void miscLog() { Logger.getGlobal().info("Welcome to Java Logging API world!"); } public static final void main(final String[] args) { Logger.getGlobal().setLevel(Level.INFO); // バグ回避コード Logger.getGlobal().info("Learning Java Logging API: Ex1"); SimplePrint print = new SimplePrint(); print.miscLog(); } }
まずログ出力のために使用しなくてはならないクラスは、java.util.loggingパッケージに含まれるLoggerクラスです。本格的なloggingAPIの使い方をするにはLoggerクラスをインスタンスとして作成し、様々な設定を行います。だが、最も簡単なprint文がわりに使うだけなら、上記のプログラムのように、System.out.printlnと書くところをLogger.getGlobal().infoで置換えるだけでよいのです。
java.util.logging.LoggerクラスのgetGlobalメソッドは、Java SE 7で導入されたもので、Java SE 6では、java.util.logging.LoggerクラスのgetLoggerメソッドに引数として定数Logger.GLOBAL_LOGGER_NAMEを指定します。
Loggerクラスは直接newして作ることはできず、staticなメソッドgetLoggerを呼び出して取得します。getGlobalは、デフォルトで用意されているグローバルロガーを取得する専用メソッドで、内部的には、引数にグローバルロガーの名前が定義される定数GLOBAL_LOGGER_NAMEを指定してLoggerインスタンスを生成し、それを取得しています。
Java SE 7 Update5時点でのLogger.getGlobal()には実装に問題があり、初期化の問題でログが出ないことがあります。そのときは、最初にLogger.getGlobal().setLevel(Level.INFO)のような呼びだしをしてから使います。上述のコード例で、行末コメントに「バグ回避コード」と記載している行が該当します。
このプログラムをコンパイルし実行した結果を次に示します。
ex1$ java SimplePrint 2008/03/08 10:27:40 SimplePrint main 情報: Learning Java Logging API: Ex1 2008/03/08 10:27:40 SimplePrint miscLog 情報: Welcome to Java Logging API world! ex1$
メソッドで指定した表示文字列の他に、実行年月日時分秒、クラス名、メソッド名、ログレベルが出力されているのが分かりますね。これだけでも、System.out.printlnメソッドからLoggerクラスのinfoメソッドに乗り換える価値があります。
ログレベルは、実行ロケールが日本語なので漢字表示されています。
前節のprint文置き換えでは、infoというメソッドを用いました。これは、Loggerクラスに対して、ログレベルINFOでログ出力するように依頼するメソッドです。普通のSystem.out.println文は、すべてコンソール(標準出力)にメッセージを表示するけど、Loggerクラスはログレベルによってコンソール(だけではないが)にメッセージを表示するものを選択することができます。
まずはLoggerクラスが対応しているログレベルと対応するログ出力メソッドを一覧してみましょう。
ログレベル | Loggerクラスのメソッド | GLOBAL_LOGGER_NAMEのデフォルト |
---|---|---|
FINEST | finest | 表示しない |
FINER | finer | 表示しない |
FINE | fine | 表示しない |
CONFIG | config | 表示しない |
INFO | info | 表示する |
WARNING | warning | 表示する |
SEVERE | severe | 表示する |
ログレベルのレベルは、FINESTが最も低く、SEVEREが最も高い。したがって、GLOBAL_LOGGER_NAMEで取得したLoggerインスタンスは、出力するログレベルとしてINFO以上という設定がなされていることになります。
ログレベルは、java.util.logger.Levelクラスによって表現されます。ここで、GLOBAL_LOGGER_NAMEで取得したLoggerインスタンスがデフォルトで保持しているログレベルを表示し、また各ログレベルの出力メソッドを使って表示されるか否かを試行するプログラム例を次に示します。
import java.util.logging.Level; import java.util.logging.Logger; public class DefaultLevel { private static Logger logger = Logger.getGlobal(); public void logAllLevel() { logger.finest("finest message"); logger.finer("finer message"); logger.fine("fine message"); logger.config("config message"); logger.info("info message"); logger.warning("warning message"); logger.severe("severe message"); } public final static void main(final String... args) { Level level = logger.getLevel(); logger.info("Logger.getGlobal() has " + level + " as fefault"); new DefaultLevel().logAllLevel(); } }
LoggerインスタンスのgetLevelメソッドを呼ぶと、そのLoggerインスタンスに設定されているログレベルを取り出すことができます。また、実際に全レベルのメソッドを呼んで、実際に出力されるログと出力されないログを確認してみます。
上記プログラムを実行した結果は次のとおり。
ex1$ java DefaultLevel 2008/03/08 10:50:19 DefaultLevel main 情報: Logger.getGlobal() has null as fefault 2008/03/08 10:50:19 DefaultLevel logAllLevel 情報: info message 2008/03/08 10:50:19 DefaultLevel logAllLevel 警告: warning message 2008/03/08 10:50:19 DefaultLevel logAllLevel 致命的: severe message ex1$
INFOレベル以上のログメソッドだけが有効となっているのが分かります。ここで登場したjava.util.logging.Levelクラスは、今後ログレベルを指定するのに使うことになります。Levelクラスはログレベルを示す定数がstatic finalなフィールドとして定義されています。
レベル | 定数 | 用途 |
---|---|---|
FINEST | Level.FINEST | 最も優先度が低い |
FINER | Level.FINER | |
FINE | Level.FINE | |
CONFIG | Level.CONFIG | |
INFO | Level.INFO | |
WARNING | Level.WARNING | |
SEVERE | Level.SEVERE | 最も優先度が高い |
Java Logging APIでは、Levelクラスの各定数はLevelクラス型を持っています。単なるintのような基本型で表現されていないので、レベル指定時に横着して数値を直接指定したり、範囲外の値を指定するといった誤りをコンパイル時にチェックできるように、タイプセーフなプログラミングがされている例です。「型に安全な定数」イディオムについては、Javaの格言で紹介されています。
先に登場したgetGlobal()で取得するグローバルロガーや初期設定されているログレベル、ハンドラを変更するには、JREディレクトリのlib下に置かれているlogging.propertiesファイルに記述されている設定を知る必要があります。例えば、JDK 7を、C:\java\jdk1.7.0にインストールした場合、C:\jdk1.7.0\jre\libの下に、logging.propertiesファイルが存在します。このファイルには、次の項目について記述されています。
# "handlers" specifies a comma separated list of log Handler # classes. These handlers will be installed during VM startup. # Note that these classes must be on the system classpath. # By default we only configure a ConsoleHandler, which will only # show messages at the INFO and above levels. handlers= java.util.logging.ConsoleHandler
ハンドラにデフォルトではjava.util.logging.ConsoleHandlerを使用します。
# Default global logging level. # This specifies which kinds of events are logged across # all loggers. For any given facility this global level # can be overriden by a facility specific level # Note that the ConsoleHandler also has a separate level # setting to limit messages printed to the console. .level= INFO
ロガーのレベルはデフォルトでは、INFOを設定します。
# Limit the message that are printed on the console to INFO and above. java.util.logging.ConsoleHandler.level = INFO java.util.logging.ConsoleHandler.formatter = \ java.util.logging.SimpleFormatter
コンソールハンドラのレベルにデフォルトではINFOを設定し、そのコンソールハンドラーのフォーマッターにはjava.util.logging.SimpleFormatterを使用します。
直接プロパティファイルを修正してもよいのですが、そうするとそのJavaVMを使用するすべてのアプリケーションの設定が変更されてしまいます。
そこで、通常はアプリケーション毎に設定ファイルを持つようにし、java実行時にそのアプリケーション固有のプロパティファイルをjavaVMオプションで指定して読ませるようにします。
handlers= java.util.logging.ConsoleHandler .level= ALL java.util.logging.ConsoleHandler.level = ALL java.util.logging.ConsoleHandler.formatter = \ java.util.logging.SimpleFormatter
これをコマンドラインで指定して、先のDefaultLevelを実行します。
ex1$ java -Djava.util.logging.config.file=mylogging.prop \ DefaultLevel 2001/12/29 17:32:27 DefaultLevel main 情報: Logger.global has null as default 2001/12/29 17:32:28 DefaultLevel logAllLevel 詳細レベル (高): finest message 2001/12/29 17:32:28 DefaultLevel logAllLevel 詳細レベル (中): finer message 2001/12/29 17:32:28 DefaultLevel logAllLevel 詳細レベル (低): fine message 2001/12/29 17:32:28 DefaultLevel logAllLevel 設定: config message 2001/12/29 17:32:28 DefaultLevel logAllLevel 情報: info message 2001/12/29 17:32:28 DefaultLevel logAllLevel 警告: warning message 2001/12/29 17:32:28 DefaultLevel logAllLevel 致命的: severe message ex1$
すると、全てのレベルのメッセージが出力されたことが分かります。
Loggerクラスのログ出力メソッドは、ログレベル別に専用のメソッドが提供されているのですが、時にはプログラム中で動的にレベルを指定したいこともあります。また、パラメータを用いて文字列を動的に書式化したいこともあります。そんなときには、logメソッドを使用するとよいでしょう。logメソッドは第一引数にLevelインスタンスを取り、Levelを指定することができるのです。
import java.util.logging.Level; import java.util.logging.Logger; public class DefaultLevelWithLog { private static Logger logger = Logger.getGlobal(); public void logAllLevel() { logger.log(Level.FINEST, "finest message"); logger.log(Level.FINER, "finer message"); logger.log(Level.FINE, "fine message"); logger.log(Level.CONFIG, "config message"); logger.log(Level.INFO, "info message"); logger.log(Level.WARNING, "warning message"); logger.log(Level.SEVERE, "severe message"); } public static void main(String[] args) { Level level = logger.getLevel(); logger.info("Logger.getGlobal() has " + level + " as default"); new DefaultLevelWithLog().logAllLevel(); } } // DefaultLevelWithLog
import java.util.logging.Level; import java.util.logging.Logger; public class DefaultLevelWithLog { private static Logger logger = Logger.getGlobal(); public void logAllLevl(int a, String b) { logger.log(Level.FINEST, "{0} is {1} in English", new Object[]{a, b}); logger.log(Level.FINER, "{0} is {1} in English", new Object[]{a, b}); logger.log(Level.FINE, "{0} is {1} in English", new Object[]{a, b}); logger.log(Level.CONFIG, "{0} is {1} in English", new Object[]{a, b}); logger.log(Level.INFO, "{0} is {1} in English", new Object[]{a, b}); logger.log(Level.WARNING, "{0} is {1} in English", new Object[]{a, b}); logger.log(Level.SEVERE, "{0} is {1} in English", new Object[]{a, b}); } public static void main(String[] args) { Level level = logger.getLevel(); logger.info("Logger.getGlobal() has " + level + " as default"); new DefaultLevelWithLog().logAllLevel(100, "one hundred"); } } // DefaultLevelWithLog
この書式化は、java.text.MessageFormatクラス由来のものなので、詳細はMessageFormatクラスのJavadocを参照してください。
シングルクオート(')は特殊な意味を持つので、メッセージに単にシングルクオートを使いたい場合は、('')のように二重にします。
logger.log(Level.INFO, "I'm fine, {0}", word);
ダメな例では、ログ出力されるメッセージにシングルクォートが無く、{0}が展開されません。
logger.log(Level.INFO, "I''m fine, {0}", word);
前章のprint文に代わるロギングでは、コンソールに出力されるフォーマットはデフォルトのものでした。デフォルトのものは、1つのメッセージが2行に折り返されており、grep派にはあまり好ましいものではありません。そこで、デフォルトのフォーマットをカスタマイズする方法を2つ紹介しましょう。
プロパティファイルの設定で、出力形式をカスタマイズすることができます。JDK 7のデフォルトではコメントアウトされている設定例が次です。
</program> # Example to customize the SimpleFormatter output format # to print one-line log message like this: # <level>: <log message> [<date/time>] # # java.util.logging.SimpleFormatter.format=%4$s: %5$s [%1$tc]%n
いきなり呪文のような設定ですが、この書式は、java.util.Formatterクラスのものです。java.util.logging.SimpleFormatterクラスのformatメソッドのJavadoc APIに説明があります。
順序 | 引数名 | 型 | 備考 |
---|---|---|---|
1 | date | java.util.Date | 年月日時分秒ミリ秒を表す |
2 | source | java.lang.String | 呼び出し箇所を表す |
3 | logger | java.lang.String | ロガー名を表す |
4 | level | java.util.logging.Level | ログレベルを表す |
5 | message | java.util.String | フォーマット済み文字列(Formatter.formatMessage(LogRecord)の戻り値)を表す |
6 | thrown | java.util.String | バックトレース情報(改行込み)を含む例外情報を表す |
上述のパラメータを利用して、任意の文字列を生成します。
次の書式でログ出力を出したいとします。
年-月-日T時:分:秒,ミリ秒 [ログレベル] ロガー名称 呼び出しクラス メソッド メッセージ文字列
プロパティ設定での記述は次のようになります。
java.util.logging.SimpleFormatter.format=%1$tFT%1$tT,%1$tL+%1$tZ %2$s %3$s \ %4$s %5$s %6$s%n
書式記述 | 解説 |
---|---|
%1$tF | 1$でパラメータ(date)を、tで日時、Fで日付書式YYYY-mm-DD (ISO 8601日付形式) |
%1$tT | 1$でパラメータ(date)を、tで日時、Tで時刻書式HH:MM:SS |
%1$tL | 1$でパラメータ(date)を、tで日時、Lで時刻書式3桁ミリ秒 |
%1$tZ | 1$でパラメータ(date)を、tで日時、Zで時刻帯名称 |
%2$s | 2$でパラメータ(source)を、sで文字列 |
%3$s | 3$でパラメータ(logger)を、sで文字列 |
%4$s | 4$でパラメータ(level)を、sで文字列 |
%5$s | 5$でパラメータ(message)を、sで文字列 |
%6$s | 6$でパラメータ(thrown)を、sで文字列 |
logging APIでは、ログを出力する際のフォーマットはFormatterクラス系によって処理されます。前章ではデフォルトのフォーマットとしてjava.util.logging.SimpleFormatterクラスが適用されていました。そこで、これを自分の好みに合わせて作ったMyFormatterに置き替えてみましょう。ここでは次のようなメッセージを吐くFormatterを作成します。
03/09/08 00:18:21.872 10 INFO app.MyLogEx2 [<init>] MyLogEx2 init 03/09/08 00:18:21.933 10 FINEST app.MyLogEx2 [miscLog] Finest! \ Welcome to Java Logging API World!
ここでは、1行に出力する簡単なMyFormatterクラスを作成すします。基本は、java.util.logging.Formatterクラスを継承し、formatメソッドをオーバーライドします。ログ出力するべき情報は、formatメソッドの引数で渡されるLogRecordオブジェクトが保持しています。formatメソッド内でやっていることは以下のとおりです。
package log; import java.util.logging.Formatter; import java.util.Calendar; import java.util.logging.LogRecord; public final class MyFormatter extends Formatter { /** * Logの出力文字列を生成する。 * 出力書式:<br> * 年/月/日/ 時:分:秒.ミリ秒 スレッドID ログレベル クラス名 [メソッド名] メッセージ */ @Override public synchronized String format(final LogRecord aRecord) { final StringBuffer message = new StringBuffer(131); long millis = aRecord.getMillis(); String time = String.format("%tD %<tT.%<tL", millis); message.append(time); message.append(' '); message.append(aRecord.getThreadID()); message.append(' '); message.append(aRecord.getLevel().toString()); message.append(' '); String className = aRecord.getSourceClassName(); message.append(className != null ? className : aRecord.getLoggerName()); message.append(" ["); String methodName = aRecord.getSourceMethodName(); message.append(methodName != null ? methodName : "N/A"); message.append("] "); message.append(formatMessage(aRecord)); message.append('\n'); Throwable throwable = aRecord.getThrown(); if (throwable != null) { message.append(throwable.toString()); message.append('\n'); for (StackTraceElement trace : throwable.getStackTrace()) { message.append('\t'); message.append(trace.toString()); message.append('\n'); } } return message.toString(); } }
MyFormatterクラスを作成しただけではログに使用されないので、ロギング機構に登録する必要があります。ログのプロパティファイルに記述します。ログ出力に使用するハンドラーにformatter属性でクラス名を記述します。
.level = ALL handlers = java.util.logging.ConsoleHandler java.util.logging.ConsoleHandler.level = ALL java.util.logging.ConsoleHandler.formatter = log.MyFormatter MyLogEx2.level = ALL
[1] | ナイジェル・ウォーレン,フィリップ・ビショップ. Javaの格言 よりよいオブジェクト設計のためのパターンと定石. ピアソン・エデュケーション, 2000. |