Powered by SmartDoc

Java Logging API

Mon Jan 07 12:58:10 JST 2013
TAKAHASHI, Toru
http://www.02.246.ne.jp/~torutk/

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メソッドの引数には必ず日時、クラス名、メソッド名を入れているんだ、というプログラマもいるでしょう。でも、それを手で記述するのは面倒です。それにバグが見つかる度にSystem.out.printlnメソッドを書いてはコンパイル・実行し、今度はそれを消してはコンパイル・実行、と単調な作業を繰り返すのはあまりクールなやり方ではないです。クールなプログラミング作業には単純な繰り返し作業はないし、コンソール出力も美しくなくてはね。

以下に、「Javaデバッグ明快技法」(W.D.Mitchell著、鈴木義幸監訳、オーム社刊)の9章デバッグ戦略から9.2.2節"ショットガンアプローチ"を引用します。

バグ修正のために長時間費やす余裕がある場合にのみ、このアプローチを使用して下さい。

  • 連続したPrintln()文

    ショットガン方式では、System.out.println();文をクラスの中で均一に撒き散らし、ある変数の値が不正な値になっていることを推測します。二分検索法を使用するという別のアプローチに似ているように見えますが、これとは全く異なります。ショットガン戦略には、いくつもの欠点があります。

    この戦略は、ある特定の場合にメリットがあります。プログラムが異常終了した場合には、最後のprintln()文に有益な情報があるかもしれません。しかし、ショットガンアプローチは、他のすべての方法を試して、結果が得られなかった場合に残しておくべきです。言い換えれば、決して使用してはなりません。

  • 最近は、ソースレベルデバッガが大抵の統合開発環境についているので、これを使ってデバッグすることが多いと思うけど、これって効率がいいのだろうか。近視眼的にコードを追いかけて時間だけが浪費されるってことが結構あるように思えます。

    以下に、「プログラミング作法」(B.W.Kernighan, R.Pike著、福崎俊博訳、アスキー刊)の5章デバッガから引用します。

    我々の個人的な手法で言えば、我々がデバッガを使うのは、せいぜいスタックトレースを実行したり変数の値を1〜2個表示させたりするときくらいにすぎない。その理由のひとつは、デバッガを使うと入り組んだデータ構造や制御フローの迷路にはまり込んでしまいがちだからだ。プログラムをステップ実行するよりも、もっと真剣に考えたり、重要な部分に出力文や自動チェックコードを追加したりするほうが効率的だと思う。クリックして文を実行していく作業は、きちんと整形された表示出力に目を通すより時間がかかる。コードのクリティカルセクションがどこだかわかっていたとしても、そこをシングルステップ実行するよりプリント文の置き場所を考えるほうが手っ取り早い。もっとも重要なのは、デバッグ用の文はプログラムとともに残るのに対し、デバッガセッションは一時的なものにすぎない点だ。

    System.out.printlnを置き換えるLogger.infoメソッド

    では、まずSystem.out.printlnメソッドを単純に置き換えるだけのloggingAPIの利用例を見てみましょう。

    print文のような使い方
    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 SE 6では、Logger.getLogger(Logger.GLOBAL_LOGGER_NAME)

    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)のような呼びだしをしてから使います。上述のコード例で、行末コメントに「バグ回避コード」と記載している行が該当します。

    このプログラムをコンパイルし実行した結果を次に示します。

    LikePrintクラス実行結果
    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インスタンスがデフォルトで保持しているログレベルを表示し、また各ログレベルの出力メソッドを使って表示されるか否かを試行するプログラム例を次に示します。

    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インスタンスに設定されているログレベルを取り出すことができます。また、実際に全レベルのメソッドを呼んで、実際に出力されるログと出力されないログを確認してみます。

    上記プログラムを実行した結果は次のとおり。

    DefaultLevelの実行結果
    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なフィールドとして定義されています。

    Levelクラスの定数一覧
    レベル 定数 用途
    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ファイルが存在します。このファイルには、次の項目について記述されています。

    logging.propertiesのGlobalハンドラ設定
    # "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を使用します。

    logging.propertiesのログレベルデフォルト設定
    # 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を設定します。

    logging.propertiesのConsoleHandler設定
    # 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オプションで指定して読ませるようにします。

    mylogging.propの内容
    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メソッド

    Loggerクラスのログ出力メソッドは、ログレベル別に専用のメソッドが提供されているのですが、時にはプログラム中で動的にレベルを指定したいこともあります。また、パラメータを用いて文字列を動的に書式化したいこともあります。そんなときには、logメソッドを使用するとよいでしょう。logメソッドは第一引数にLevelインスタンスを取り、Levelを指定することができるのです。

    Loggerクラスのlogメソッドを使った例
    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
    
    Loggerクラスのlogメソッドをパラメータ付きで使った例
    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を参照してください。

    MessageFormat書式化の注意点

    シングルクオート(')は特殊な意味を持つので、メッセージに単にシングルクオートを使いたい場合は、('')のように二重にします。

    logメソッドの文字列にシングルクォートを使うダメな例
            logger.log(Level.INFO, "I'm fine, {0}", word);
    

    ダメな例では、ログ出力されるメッセージにシングルクォートが無く、{0}が展開されません。

    logメソッドの文字列にシングルクォートを使う例
            logger.log(Level.INFO, "I''m fine, {0}", word);
    

    フォーマットを変更する

    前章のprint文に代わるロギングでは、コンソールに出力されるフォーマットはデフォルトのものでした。デフォルトのものは、1つのメッセージが2行に折り返されており、grep派にはあまり好ましいものではありません。そこで、デフォルトのフォーマットをカスタマイズする方法を2つ紹介しましょう。

    プロパティファイルの設定で出力形式を指定する

    プロパティファイルの設定で、出力形式をカスタマイズすることができます。JDK 7のデフォルトではコメントアウトされている設定例が次です。

    logging.propertiesのフォーマットカスタマイズ設定
    </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 バックトレース情報(改行込み)を含む例外情報を表す

    上述のパラメータを利用して、任意の文字列を生成します。

    書式例1

    次の書式でログ出力を出したいとします。

    年-月-日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で文字列

    自分のFormatterを作る

    logging APIでは、ログを出力する際のフォーマットはFormatterクラス系によって処理されます。前章ではデフォルトのフォーマットとしてjava.util.logging.SimpleFormatterクラスが適用されていました。そこで、これを自分の好みに合わせて作ったMyFormatterに置き替えてみましょう。ここでは次のようなメッセージを吐くFormatterを作成します。

    自分の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!
    

    MyFormatterクラスの作成

    ここでは、1行に出力する簡単なMyFormatterクラスを作成すします。基本は、java.util.logging.Formatterクラスを継承し、formatメソッドをオーバーライドします。ログ出力するべき情報は、formatメソッドの引数で渡されるLogRecordオブジェクトが保持しています。formatメソッド内でやっていることは以下のとおりです。

    MyFormatter.java
    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を設定する

    MyFormatterクラスを作成しただけではログに使用されないので、ロギング機構に登録する必要があります。ログのプロパティファイルに記述します。ログ出力に使用するハンドラーにformatter属性でクラス名を記述します。

    log.properties
    .level = ALL
    handlers = java.util.logging.ConsoleHandler
    java.util.logging.ConsoleHandler.level = ALL
    java.util.logging.ConsoleHandler.formatter = log.MyFormatter
    
    MyLogEx2.level = ALL
    

    loggingに関するリンク集

    参考文献

    [1]ナイジェル・ウォーレン,フィリップ・ビショップ. Javaの格言 よりよいオブジェクト設計のためのパターンと定石. ピアソン・エデュケーション, 2000.