J2SE, v1.4 の新機能 Logging API

Logging API

記録しましょう、ログしましょう、

今回は Logging API です。

Web サービスやアプリケーションサーバで使われる J2EE の場合、ほとんどすべてのアプリケーションでログを使う必要があるのではないでしょうか。かといって、J2SE でログを使わないというわけではありません。いろいろな用途でログが使えることも多いので、使い方をマスターしておいて損をすることはないと思います。

今までは、ログを使うとなると Apache の Log4j などのライブラリを使うか、自作するかしかなかったのですが、v1.4 になってやっとログをとるための API が整備されました。それではさっそく使ってみることにしましょう。

とりあえず使ってみる

まずは、何も考えずにとりあえずログを出してみることから始めましょう。

アプリケーションのソース

LogTest1.java

単にログを出すだけなので、ソースはとても簡単です。

 1: package jp.gr.java_conf.skrb.logging;
 2: 
 3: import java.util.logging.Level;
 4: import java.util.logging.Logger;
 5: 
 6: public class LogTest1 {
 7:     public static void main(String[] args) {
 8:         Logger logger = Logger.getLogger("jp.gr.java_conf.skrb.logging.LogTest1");
 9:         logger.log(Level.INFO, "Logging Test");
10:     }
11: }

Logging API を構成するクラスは java.util.logging パッケージに含まれます。

ログを書き出すには Logger クラスを使用します。Logger オブジェクトを生成するには getLogger メソッドを使用します (8 行目)。このメソッドの引数は Logger の名前となります。通常はアプリケーションのパッケージやクラス名などが使われるようです。

9 行目がログを出力している部分です。Logger オブジェクトの log メソッドを使用することで、ログを出力することができます。log メソッドの引数は最初がログのレベルを示しています。次がログに書き出すメッセージです。

ログにはログの重要度を示すレベルがあります。レベルは Level クラスで表します。次に示すように 7 段階の定数で定義されています。

Level.SEVERE
Level.WARNING
Level.INFO
Level.CONFIG
Level.FINE
Level.FINER
Level.FINEST

1 の SEVER が重要度が最も高く、7 が FINEST が最も重要度が低くなります。

例えば、例外が発生したときは例外処理を行いますが、そのときに例外が発生したことをログに書くとします。こんなときは重要度が高いので、WARNING などを使用します。また、デバッグなどのための情報をログに書き出すときには、重要度が低いので FINE などを使用することができます。

実際にファイルなどにログを書き出すときには、あるレベルを設定しておいて、それより重要なものだけを書き出すというようなことを行います。

さて、LogTest1 を実行してみましょう。

C:\temp>java jp.gr.java_conf.skrb.logging.LogTest1
2002/04/26 22:11:54 jp.gr.java_conf.skrb.logging.LogTest1 main
情報: Logging Test

コンソールにはログらしきものが出力されました。出力された情報には時間、クラス、メソッド、レベル、メッセージがあります。レベルが日本語になっているのはデフォルトロケールが日本語のためです。

これで一応最低限のログが取れるようになれました。次からはもう少し詳しく Logging API を見ていきましょう。

Logging API の全体像

全焼ではとりあえず、Logger クラスだけを使用してログをとってみましたが、Logging API には Logger クラス以外のクラスもあります。どんなクラスがあるのかは、次のクラス構成を見てください。

図 1 Logging API の構成

アプリケーションが直接ログを書き込むのに使用するのが、先ほども使用した Logger クラスです。Handler クラスはログを出力するためのクラスで、出力先に応じて派生クラスが用意されています。現在はファイルに出力する FileHandler、メモリ上にログをキャッシュする MemoryHandler などがあります。

Filter インタフェースはログを記録するかどうかを決めるためのフィルターです。Filter は Logger と Handler に別々に設定できます。もちろん、Filter を設定しないことも可能です。

Formatter は出力するときの形式を設定します。現状ではプレインテキストと XML 形式を選ぶことができますが、自分で作成することも可能です。

最後に、Logger クラスや Hanlder クラスを管理するのが LogManager クラスです。

Logger オブジェクトや Handler オブジェクトは 1 つづつのように見えますが、どちらも複数でかまいません。ですから、File にログを出力しながら、コンソールに出力するなどということもできます。

このクラス図には出ていませんが、この他にログのレベルを定義する Level クラスや、1 つ 1 つのログの記録を保持するための LogRecord クラスがあります。

さて、それぞれのクラスの使い方をサンプルにしたがって調べていくことにしましょう。

記録しましょう、ログしましょう

ここではあるアプリケーションを改造してログを取れるようにしてみます。元になるのは FavoriteNumber.java です。

アプリケーションのソース

FavoriteNumber.java

このアプリケーションはテキストフィールドに数字を入力して、「決定」ボタンをクリックすると、記録するというアプリケーションです。アプリケーション自体にはたいした意味はないのですが、簡単で分かりやすいサンプルということでこのようなアプリケーションにしてみました。

FavoriteNumber クラスを見ていきましょう。ちょっと、長いのですが、全部示してみます。

package jp.gr.java_conf.skrb.logging;
 
import javax.swing.*;
import javax.swing.border.*;
import java.awt.*;
import java.awt.event.*;
 
public class FavoriteNumber {
 
    private JTextField field;
 
    private int favorite;
 
    public FavoriteNumber() {}
 
    public void init() {
        // フレームの生成
        JFrame frame = new JFrame("Favorite Number");
        frame.setBounds(100, 100, 300, 80);
        frame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
        System.out.println("JFrame@" + Integer.toHexString(frame.hashCode())
                           + " is created.");
 
        Container pane = frame.getContentPane();
        pane.setLayout(new BoxLayout(pane, BoxLayout.X_AXIS));
 
        // テキストフィールドの設定
        field = new JTextField(10);
        field.setBorder(new TitledBorder("Your Favorite Number"));
        pane.add(field);
        System.out.println("JTextField@" + Integer.toHexString(field.hashCode())
                           + " is created.");
 
        pane.add(Box.createHorizontalStrut(20));
 
        // 決定ボタンの設定
        JButton button = new JButton("決定");
        button.addActionListener(new ActionListener(){
            public void actionPerformed(ActionEvent event){
                updateNumber();
            }
        });
        pane.add(button);
        System.out.println("JButton@" + Integer.toHexString(button.hashCode())
                           + " is created.");
     
        frame.setVisible(true);
        System.out.println("JFrame@" + Integer.toHexString(frame.hashCode())
                           + " shows.");
    }
        
    // 決定ボタンがクリックされたときのイベント処理
    // テキストフィールドから文字を取り出し、数字に変化してから、コンソールに出力する
    private void updateNumber() {
        System.out.println("updateNumber is called.");
        try {
            favorite = Integer.parseInt(field.getText());
            System.out.println("Your Favorite Number is " + favorite);
        } catch (NumberFormatException ex) {
            System.out.println("Non-number:[" + field.getText() + "] was inputted.");
        } finally {
            field.setText("");
            System.out.println("updateNumber is done.");
        }
    }
 
    public static void main(String[] args) {
        new FavoriteNumber().init();
    }
}

プログラム自体はそれほど難しくはないと思いますが、いろいろとコンソールに出力を行っているのが目立つぐらいだと思います。標準出力に出力しているものには JFrame などが生成したときの確認用のものや、例外が発生したときのメッセージなどがあります。これらの出力をログ対応にしてみようというわけです。

まずは先ほどと同じように、単純に Logger クラスだけを使ってみます。単にログを記録するように FavoriteNumber クラスを変更したのが FavoriteNumberWithLog1 クラスです。

アプリケーションのソース

FavoriteNumberWithLog1.java

まずは Logger オブジェクトを得ることから始めます。Logger オブジェクトを何度も生成するのも無駄なので、ここでは static なプロパティにしてみました。

    protected static Logger logger = Logger.getLogger("jp.gr.java_conf.skrb.logging");

Logger クラスの getLogger メソッドを使ってオブジェクトを生成します。Logger オブジェクトの名前のつけ方には決まりはないのですが、Logger を一意に決めることができるようにします。LogTest1.java ではクラス名を使用しましたが、ここでは同じパッケージのオブジェクトがすべて同じ Logger オブジェクトを使用できるようにパッケージ名にしました。。

ログの書き出しには何種類か方法があります。一番基本的なのは LogTest1.java で使用した log メソッドを使用する方法です。ただし、log メソッドも引数によって 5 種類もあります。また、log メソッドと同じように使用できる logp メソッドと logrb メソッドがあります。logp メソッドが 4 種類、logrb メソッドも 4 種類あります。

No.	メソッド
1	log(Level level, String message)
2	log(Level level, String message, Object param)
3	log(Level level, String message, Object[] params)
4	log(Level level, String message, Throwable thrown)
5	log(LogRecord record)
6	logp(Level level, String sourceClass String sourceMethod, String message)
7	logp(Level level, String sourceClass String sourceMethod, String message, Object param)
8	logp(Level level, String sourceClass String sourceMethod, String message, Object[] params)
9	logp(Level level, String sourceClass String sourceMethod, String message, Thrownable thrown)
10	logrb(Level level, String sourceClass String sourceMethod, String bundleNmae, String message)
11	logrb(Level level, String sourceClass String sourceMethod, String bundleNmae, String message, Object param)
12	logrb(Level level, String sourceClass String sourceMethod, String bundleNmae, String message, Object[] params)
13	logrb(Level level, String sourceClass String sourceMethod, String bundleNmae, String message, Thrownable thrown)

log メソッドは単純にログメッセージをログするものですが、logp メソッドはクラスやメソッドも記述することが可能です。logrb メソッドはlogp を国際化するためのリソースバンドルを指定できるようになったメソッドです。

ただし、log メソッドでも Logger オブジェクトがクラス名やメソッド名を調べてログに書き込んでくれます。logp はこれらの情報を明記するので、log メソッドより高速に処理することができるという利点があります。

log メソッド、logp メソッド、logrb メソッドとも、例外に関連したログをとる場合のものが用意されています。

また、1 つ 1 つのログ自体は LogRecord クラスで表されるのですが、5 は直接 LogRecord オブジェクトを作成して、それを用いてログをとる方法です。

これらのメソッドはすべてレベルを明記する必要があります。しかし、7 段階のログに応じたメソッドも用意されています。

レベル	メソッド
Level.SEVERE	severe(String message)
Level.WARNING	warning(String message)
Level.INFO	info(String message)
Level.CONFIG	config(String message)
Level.FINE	fine(String message)
Level.FINER	finer(String message)
Level.FINEST	finest(String message)

これらのメソッドの実装は log メソッドをレベルを付加してコールしているだけです。

その他に例外のログをとるためのメソッド

throwing

もあります。throwing メソッドを使用した場合、ログのレベルは Level.FINER になります。

Assertion の時に説明した事前条件、事後条件をログにとるためのメソッドも用意されています。事前条件が

entering

事後条件が

exiting

になります。この 2 つのメソッドのログレベルも Level.FINER です。

このように様々なメソッドが用意されているので、場合場合に応じて使い分けるようにしてみましょう。FavoriteNumberWithLog1 クラスでは warning, info, config, entering, exiting の 5 種類のメソッドを使用してみました。

JFrame などのオブジェクトの生成確認には config メソッドを使っています。

        JFrame frame = new JFrame("Favorite Number with Log 1");
        frame.setBounds(100, 100, 300, 80);
        frame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
        logger.config("JFrame@" + Integer.toHexString(frame.hashCode()) + " is created.");

これは FavoriteNumber クラスの println メソッドで出力していたものをそのまま置き換えただけです。

updateNumber メソッドではもう少しいろいろなメソッドを使ってみました。

    private void updateNumber() {
        logger.entering("FavoriteNubmerWithLog1", "updateNubmer");
        try {
            favorite = Integer.parseInt(field.getText());
            logger.info("Your Favorite Number is " + favorite);
        } catch (NumberFormatException ex) {
            logger.log(Level.WARNING,
                       "Non-number:[" + field.getText() + "] was inputted.", ex);
        } finally {
            field.setText("");
            logger.exiting("FavoriteNubmerWithLog1", "updateNubmer");
        }
    }

updateNumber に入った時には entering メソッド、メソッドから抜けるときには exiting メソッドを使用してみました。

テキストフィールドに正しく数字が入力されているときは info メソッドを使用し、例外がおきた場合は log メソッドを使用しています。log メソッドでは発生した例外もログに記録しています。ここで、throwing メソッドを使用しなかったのは、レベルが Level.FINER になってしまうからです。例外が起きているのだから、もう少し高い重要度にしたかったからです。

ログはどこに

ソースはできたので、コンパイルして実行してみましょう。

次に示すのは、JTextField に「123」と入力して「決定」ボタンをクリックし、次に「abc」と入力して「決定」した時の結果です。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1
2002/04/27 1:14:42 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 updateNumber
情報: Your Favorite Number is 123
2002/04/27 1:14:47 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 updateNumber
警告: Non-number:[abc] was inputted.
java.lang.NumberFormatException: abc
        at java.lang.Integer.parseInt(Integer.java:426)
        at java.lang.Integer.parseInt(Integer.java:476)
		         ... (以下、略)

実行してみるとコンソールにログが出力されます。これは System.err で表されるエラー出力に出力されたログになります。しかしこれだけだとなんか物足りないような気がしませんか。やはり、ログといったらファイルですよね。

そこで、ログがどこに出力されているのかを調べてみましょう。これを行うのが FavoriteNumberWithLog2 です。

アプリケーションのソース

FavoriteNumberWithLog2.java

ログの出力を担当するのは図 1 に示してある Handler クラスです。Handler クラスは abstract で、実際にはログを出力する媒体ごとに、Handler クラスを派生させています。現状では次のクラスが用意されています。

クラス	概要
ConsoleHandler	エラー出力にログを出力。
FileHandler	任意のファイルにログを出力。
StreamHandler	ストリームにログを出力。
SocketHandler	ソケットに対してログを出力。
MemoryHandler	メモリ中にログをキャッシュする。他の Handler と組み合わせて使用し、キャッシュしたログをそのHandler に引き渡す。

これらの派生クラスは大別するとストリーム系と、キャッシュ系に分かれます。ストリーム系は StreamHandler の肺性クラスになっており、ConsoleHandler, FileHandler と SocketHandler の 3 種類になります。キャッシュ系が MemoryHandler になります。

さて、デフォルト状態でどの Handler が使われているかを調べてみましょう。FavoriteNumberWithLog2 クラスの listHandler メソッドで Handler の一覧を出力するようにしています。

    private void listHandlers() {
        Handler[] handlers = logger.getHandlers();
        System.out.println("Handler Size = " + handlers.length);
        for (int i = 0 ; i < handlers.length ; i++) {
            System.out.println(handlers[i]);
        }
    }

図 1 に示したように、Logger オブジェクトは Hanler オブジェクトと関連があります。その Handler オブジェクトは getHandlers メソッドで調べることができます。戻り値は Handler オブジェクトの配列なので、それを出力しています。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog2
Handler Size = 0

実行してみた結果を見て、「あれっ」と思いませんでしたか。Logger オブジェクトに Handler オブジェクトが登録されていないのです。でも、ログは出力されている。なぜなんでしょう。

実をいうと、Logger オブジェクトは階層構造になっているのです。ログは Logger オブジェクトの親の Logger オブジェクトに伝播されて、親の Logger オブジェクトに登録されている Handler オブジェクトによって出力されます。

Logger オブジェクトの親を設定するには Logger クラスの setParent メソッドを使用します。また、親 Logger オブジェクトを取得するには getParent メソッドを使用します。

それでは、親をさかのぼって Handler オブジェクトを調べてみましょう。

アプリケーションのソース

FavoriteNumberWithLog3.java

FavoriteNumberWithLog2 と同じように listHandlers メソッドで Handler オブジェクトの一覧を出力させていますが、親にまでさかのぼっている部分が異なっています。

    private void listHandlers() {
        Logger target = logger;
 
        while (target != null) {
            System.out.println("\nLogger: " + target);
 
            Handler[] handlers = target.getHandlers();
            System.out.println("Handler Size = " + handlers.length);
            for (int i = 0 ; i < handlers.length ; i++) {
                System.out.println(handlers[i]);
            }

            target = target.getParent();
        }
    }

さっそく実行してみましょう。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog3
 
Logger: java.util.logging.Logger@26f75b
Handler Size = 0
 
Logger: java.util.logging.LogManager$RootLogger@d1e89e
Handler Size = 1
java.util.logging.ConsoleHandler@835282

logger オブジェクトの親は LogManager.RootLogger クラスのオブジェクトになっています。このクラスは Logger クラスの派生クラスで getLogger オブジェクトで、Logger オブジェクトを生成した場合には自動的に親になるようになっています。

この LogManager.RootLogger オブジェクトが ConsoleHandler オブジェクトを登録していたのです。そして、ログはこの ConsoleHandler オブジェクトによって、コンソールに出力されていたのでした。

親の Handler オブジェクトを使用するかどうかは、Logger クラスの setUseParentHandlers メソッドで設定できます。引数が boolean で、true ならば使用する、false ならば使用しません。

FavoriteNumberWithLog3 では false にしてあるので、ログは出力されないはずです。

しかし、このままだと使いものにならないので、次は Handler オブジェクトを登録して使ってみましょう。

ログファイルを作ってみる

やはりログといえば普通はファイルだと思うので、ここでもファイルにログを記録してみましょう。

ファイルにログを出力するには FileHandler クラスを使用します。

アプリケーションのソース

FavoriteNumberWithLog4.java

Logger オブジェクトに Handler オブジェクトを登録するには addHandler メソッドを使用します。addHandler というメソッド名から分かると思いますが、Logger オブジェクトには複数の Handler オブジェクトを登録することができます。

        try {
            logger.addHandler(new FileHandler("fnumber%g.log", 100000, 4));
        } catch (IOException ex) {
            ex.printStackTrace();
        }

ログファイルを作るにはファイル名を決めなくてはなりません。FileHandler クラスのコンストラクタでファイル名を指定することができますが、便利な省略形を使うことができます。例えば、%t はテンポラリのディレクトリ、%h はユーザのホームディレクトリになります。

また、%g はログファイルを区別できるようにローテーションした数字になります。ここでは、fnumber%g.log というファイルなので、はじめに fnumber0.log というファイルができます。ここで、ログファイルのサイズが指定されたものより大きくなると、fnumber0.log は fnumber1.log にリネームして、fnumber0.log を新しく作ります。

ログファイルのサイズはコンストラクタの第 2 引数で指定されます。ここでは 100,000 byte になります。また、%g が生成する数字の個数はコンストラクタの第 3 引数で指定します。4 の場合は 0 から 3 が使われます。

FileHandler のコンストラクタにはここで使用した以外のものもあります。この場合はサイズなどはデフォルトのものが使用されます。例えば、引数なしのコンストラクタはファイル名が "%h/java%u.log"、サイズは無制限、ローテーションする数字の個数は 1 になります。

ここでは使用しませんでしたが、アプリケーションを立ち上げなおしたときに前のログファイルにアペンドすることもできます。

FileHandler を生成するときにはファイルを作成するため、IOException が発生することがあります。例外処理は忘れずに。

さて、実行してみましょう。カレントディレクトリに fnumber0.log が生成されたでしょうか。

先ほど同じように "123" と入力して、次に "abc" と入力したときのログをエディタで開いてみましょう。

<?xml version="1.0" encoding="MS932" standalone="no"?>
<!DOCTYPE log SYSTEM "logger.dtd">
<log>
<record>
  <date>2002-04-29T00:04:11</date>
  <millis>1020006251393</millis>
  <sequence>0</sequence>
  <logger>jp.gr.java_conf.skrb.logging</logger>
  <level>INFO</level>
  <class>jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1</class>
  <method>updateNumber</method>
  <thread>10</thread>
  <message>Your Favorite Number is 123</message>
</record>
<record>
  <date>2002-04-29T00:04:15</date>
  <millis>1020006255189</millis>
  <sequence>1</sequence>
  <logger>jp.gr.java_conf.skrb.logging</logger>
  <level>WARNING</level>
  <class>jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1</class>
  <method>updateNumber</method>
  <thread>10</thread>
  <message>Non-number:[abc] was inputted.</message>
  <exception>
    <message>java.lang.NumberFormatException: abc</message>
    <frame>
      <class>java.lang.Integer</class>
      <method>parseInt</method>
      <line>426</line>
    </frame>
    <frame>
      <class>java.lang.Integer</class>
      <method>parseInt</method>
      <line>476</line>
    </frame>
        ... (以下、略)

XML でした... ^^;; コンソールに出力されていた情報より詳しい情報が記録されています。例外のスタックトレースも XML なのはなんか変な感じがしますね。

ところで、なんかおかしくないですか。たしか、FavoriteNumberWithLog1 では config メソッドや entering メソッドなどでログを出していたのですが、コンソールにもログファイルにも記録されていません。

これらのログはどこに行ってしまったのでしょう?

ログはどこに No. 2

勘のいい方はうすうす気がついていると思いますが、ログが出たり出なかったりするのはログのレベルによります。

Logger オブジェクトのログレベルを決めるには、Logger クラスの setLevel メソッドを使用します。これを使用して Logger オブジェクトのレベルを変更したものが FavoriteNumberWithLog5 です。

アプリケーションのソース

FavoriteNumberWithLog5.java

レベルを変更しているのは setLevel メソッドです。

    private void setLevel(){
        System.out.println("Old Logger's Level: " + logger.getLevel());
 
        // Logger の Level 設定
        logger.setLevel(Level.ALL);
        System.out.println("New Logger's Level: " + logger.getLevel());
 
        System.out.println("Parent Logger's Level: " + logger.getParent().getLevel());
    }

これで設定したレベルより重要度の高いログを出力するようになります。setLevel メソッドの引数の Level.ALL はすべてのログを出力することを示しており、Level.FINEST と同義になります。

さて、実行してみましょう。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog5
Old Logger's Level: null
New Logger's Level: ALL
Parent Logger's Level: INFO

ログレベルを設定する前はレベルが null になっています。これはどういうことでしょうか。

答えは、レベルが null のときには、親 Logger オブジェクトのレベルを引き継ぐようになっているためでした。

今までは親のレベルが Level.INFO なので、それが適用されて、Level.INFO より重要度の低い Level.CONFIG のログが出力されなかったのです。

FavoriteNumberWithLog5 ではレベル設定を行ったので、すべてのログが記録されているはずです。実行して、ログファイルを見てみましょう。

<?xml version="1.0" encoding="MS932" standalone="no"?>
<!DOCTYPE log SYSTEM "logger.dtd">
<log>
<record>
  <date>2002-04-29T00:56:11</date>
  <millis>998312634750</millis>
  <sequence>0</sequence>
  <logger>jp.gr.java_conf.skrb.logging</logger>
  <level>CONFIG</level>
  <class>jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1</class>
  <method>init</method>
  <thread>10</thread>
  <message>JFrame@29f3b5 is created.</message>
</record>
<record>
  <date>2002-04-29T00:56:12</date>
  <millis>998312635521</millis>
  <sequence>1</sequence>
  <logger>jp.gr.java_conf.skrb.logging</logger>
  <level>CONFIG</level>
  <class>jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog3</class>
  <method><init></method>
  <thread>10</thread>
  <message>JTextField@849bc is created.</message>
</record>
        ... (以下、略)

当然のことながら、Level.CONFIG のログも出力されていました。

しかし、コンソールには Level.CONFIG のログは出力されていません。FavoriteNumberWithLog5 では親 Logger の ConsoleHandler オブジェクトを使用せずに、自前で ConsoleHandler オブジェクトを用意しているのですが、なぜかログは出ないのです。

実はこうなるのは、Handler にもレベルがあるからです。

ConsoleHandler クラスの JavaDoc にはデフォルトでログレベルは Level.INFO であると記述してあります。また、FileHandler クラスの JavaDoc にはデフォルトで Level.ALL と示されています。これが Handler によって出力している内容が異なる理由になります。

そこで、Handler のログレベルも設定してみましょう。Handler クラスの setLevel メソッドでレベルを設定することができます。

アプリケーションのソース

FavoriteNumberWithLog6.java

FileHandler オブジェクトのログレベルは Level.ALL ですから、ConsoleHandler オブジェクトだけ Level.ALL に変更してみましょう。

    private void setLevel(){
        // Logger の Level 設定
        System.out.print("Logger's LogLevel is changed from " + logger.getLevel());
        logger.setLevel(Level.ALL);
        System.out.println(" to " + logger.getLevel());
 
        // Handler の Level 設定
        Handler[] handlers = logger.getHandlers();
        for(int i = 0 ; i < handlers.length ; i++){
            System.out.println(handlers[i] + "'s Level: " + handlers[i].getLevel());
 
            if(handlers[i] instanceof java.util.logging.ConsoleHandler){
                System.out.print("ConsolHandler's LogLevel is changed from "
		                        + handlers[i].getLevel());
                handlers[i].setLevel(Level.ALL);
                System.out.println(" to " + handlers[i].getLevel());
            }
        }
    }

実行してみると、Level.CONFIG のログも確かに出力されるようになりました。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog4
Logger's LogLevel is changed from INFO to ALL
java.util.logging.FileHandler@2b6651's Level: ALL
java.util.logging.ConsoleHandler@4a5ab2's Level: INFO
ConsolHandler's LogLevel is changed from INFO to CONFIG
2002/04/29 1:36:43 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 init>
CONFIG: JFrame@3f3045 is created.
2002/04/29 1:36:44 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 init>
CONFIG: JTextField@4e280c is created.
2002/04/29 1:36:44 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 <init>
CONFIG: JButton@61a408 is created.
2002/04/29 1:36:44 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 <init>
CONFIG: JFrame@3f3045 shows.

ログをキャッシュする

ログを出力するにはそれなりの時間がかかります。ファイルの書き出しなどの I/O 処理は低速なので、アプリケーションのパフォーマンスも気になるところです。

そこで、毎回ログをファイルに書き出すのではなく、ある程度まとまった単位で書き出すようにしましょう。これには MemoryHandler クラスを使用します。

アプリケーションのソース

FavoriteNumberWithLog7.java

Handler オブジェクトの設定を行っている部分を以下に示します。

 1:    private MemoryHandler memoryHandler;
 2:
 3:    private void initHandler(){
 4:        // Handler を生成して、登録
 5:        logger.addHandler(new ConsoleHandler());
 6: 
 7:        Handler fileHandler;
 8:        try{
 9:            fileHandler = new FileHandler("fnumber%u.log");
10:
11:            // FileHandler をターゲットにした MemoryHandler
12:            memoryHandler = new MemoryHandler(fileHandler, 100, Level.WARNING);
13:            logger.addHandler(memoryHandler);
14:
15:            // 定期的にバッファ中のログを push する
16:            Timer timer = new Timer();
17:            timer.schedule(new TimerTask(){
18:                public void run(){
19:                    memoryHandler.push();
20:                    memoryHandler.flush();
21:                }
22:            }, 0, 60000L);
23:        }catch (java.io.IOException ex){
24:            ex.printStackTrace();
25:        }
26:    }

MemoryHandler クラスはバッファを使用して、ログをバッファリングする Handler クラスです。ログのバッファリングをしていて、バッファが一杯になったときはバッファの先頭から上書きします。こういうバッファをリングバッファといいます。

MemoryHandler クラスは単体で使うことはなく、必ず他の Handler クラスとペアで使います。バッファリングしたログを、ペアになった Handler オブジェクトに引き渡すためです。ペアとなる Handler オブジェクトをターゲットというようです。

それでは、使い方を見ていきましょう。

12 行目で MemoryHandler オブジェクトを生成しています。コンストラクタの第 1 引数はターゲットとなる Handler オブジェクト、第 2 引数はバッファのサイズになります。第 3 引数を説明する前に、MemoryHandler オブジェクトがターゲットにログを書き出す条件について説明したいと思います。

バッファリングしたログをターゲットに書き出すのは次のいずれかの条件に合致したときです。

ログが事前に設定したレベル (pushLevel) より、重要度が高い場合。pushLevel のデフォルトは Level.SEVERE。
MemoryHandler クラスの push メソッドがコールされたとき。

この条件の 1 のログのレベルがコンストラクタの第 3 引数になります。コンストラクタ以外でも、setPushLevel メソッドで設定することができます。

今回は、例外が発生したとき Level.WARNING でログを記述していたので、それをターゲットにすぐに書き出せるように Level.WARNING にしました。

ターゲットに書き出すタイミングはいろいろと方法があると思いますが、このサンプルでは一定時間ごとに push メソッドをコールするようにしました。

MemoryHandler オブジェクトがバッファしているログの量が分かれば、それをチェックすることもできるのですが、そのようなメソッドは MemoryHandler クラスには用意されていませんでした。ですから、ログの量で push をコールするようにするには Logger クラスを派生させて、log メソッドをオーバーライドして、ログの量をチェックできるようにすれば可能です。

定期的に push をコールするために、このサンプルでは java.util.Timer クラスを使用しました。17 から 22 行目で繰り返し行う処理の定義をしています。10 分ごとにログを標準出力に出力するようにしました。

通常は push メソッドをコールするだけでいいのですが、ペアとなる Handler クラスによっては flush メソッドもコールしないとログ出力しない場合があります。ペアで使うようにすれば、忘れずにすむと思います。

ログのカスタマイズ

ここまでくると、ログの出力を行うかどうかをもっと細かく指定したくなってきませんか。なんか誘導尋問めいてきましたが ^^;;

ログの出力を行うかどうかを決めるために Filter クラスを使用することができます。Filter オブジェクトは Logger オブジェクトと Handler オブジェクトに、それぞれ別個に設定することができます。Logger オブジェクトに Filter オブジェクトをほどこしたサンプルを見ていきましょう。

アプリケーションのソース

FavoriteNumberWithLog8.java

Filter の設定を行っているのは initLogger メソッドです。

    private void initLogger() {
        logger.setFilter(new Filter() {
            public boolean isLoggable(LogRecord record){
                System.out.println("Level: " + record.getLevel());
                System.out.println("Logger: " + record.getLoggerName());
                System.out.println("Date: " + new Date(record.getMillis()));
                System.out.println("Message: " + record.getMessage());
                System.out.println();

                return record.getLevel().intValue() > Level.INFO.intValue();
            }
        });
    }

Filter はインタフェースなので、これをインプリメントして使用します。Filter インタフェースで定義されているメソッドは 1 つで、isLoggable メソッドです。isLoggable メソッドでは引数として LogRecord オブジェクトが渡されます。Logger クラスの log メソッドなどで書き込まれる 1 つの 1 つのログは、LogRecord クラスのオブジェクトとして表されています。

isLoggable メソッドでは引数の LogRecord オブジェクトを出力するかどうかを戻り値にします。

LogRecord クラスにはログレベルや Logger オブジェクトの名前、クラス名、メソッド名などの情報が保持されており、それぞれ Getter メソッドを使うことでそれらの値を得ることができます。これらの情報を使用して、ログを出力するかどうかを決めるのです。

上記のソースではログのレベルを比較して、ログを出力するかどうか決めています。レベルは Logger オブジェクトと Handler オブジェクトで設定できるので、あまり意味はないんですけど、サンプルなのでゆるしてください。

さらにさらに、ここまでくるとログの出力形式までカスタマイズしてきたくありませんか。

デフォルトで Handler クラスを使用すると、FileHandler クラスは XML で出力され、ConsoleHandler は普通の文字列で出力されます。これらは Formatter クラスによって実現されています。XML を出力するのは XMLFormatter クラス、単なる文字列は SimpleFormatter クラスになります。

それでは、ログの書式を変えてみましょう。

アプリケーションのソース

FavoriteNumberWithLog9.java

Formatter オブジェクトを Handler オブジェクトに登録するには Handler クラスの setFormatter メソッドを使用します。

    private void initFormatter(){
        logger.setLevel(Level.ALL);
        
        // Handler を生成して、登録
        try{
            Handler fileHandler = new FileHandler("fnumber%u.log");
            fileHandler.setFormatter(new SimpleFormatter());
            logger.addHandler(fileHandler);
        }catch (java.io.IOException ex){
            ex.printStackTrace();
        }
 
        // 標準出力に対する Handler
        Handler consoleHandler = new ConsoleHandler();
        consoleHandler.setLevel(Level.ALL);
        consoleHndler.setFormatter(new XMLFormatter());
        logger.addHandler(consoleHandler);
    }

普通と逆に FileHandler クラスに SimpleFormatter オブジェクトを使用し、ConsoleHandler クラスに XMLFormatter クラスを使用してみました。実行してみると、こんな感じになりました。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog9
<?xml version="1.0" encoding="MS932" standalone="no"?>
<!DOCTYPE log SYSTEM "logger.dtd">
<log>
<record>
  <date>2002-04-30T00:53:39</date>
  <millis>1020095619222</millis>
  <sequence>0</sequence>
  <logger>jp.gr.java_conf.skrb.logging</logger>
  <level>CONFIG</level>
  <class>jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1</class>
  <method>init</method>
  <thread>10</thread>
  <message>JFrame@16a786 is created.</message>
</record>
<record>
  <date>2002-04-30T00:53:40</date>
  <millis>1020095620233</millis>
  <sequence>1</sequence>
  <logger>jp.gr.java_conf.skrb.logging</logger>
  <level>FINE</level>
  <class>jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1</class>
  <method>init</method>
  <thread>10</thread>
  <message>JTextField@5f8172 is created.</message>
</record>
       ... (以下、略)

ちゃんとコンソールに XML で出力されました。ログファイルが XML でないことは皆さんで確認してみてください。

ところで、現状で提供されている Formatter クラスは XMLFormatter クラスと SimpleFormatter クラスの 2 つだけです。もし、自分だけのログの書式を作りたいときにはどうすればいいでしょうか。

Formatter クラスで書式を決めているのは format メソッドです。引数が LogRecord オブジェクト、戻り値が整形した文字列になります。ですから、Formatter クラスを派生させて、format メソッドを書き換えれば、自分なりの書式でログを出力できます。

ログの設定

ログをとるのはいいのですが、例えばログを出力するときのレベルを変えたいとき、ソースを変更して再コンパイルするのは面倒です。どうにかしてソース変更をなくして、運用時だけで対応できるようになればいいと思いませんか。

普通はそんなときに設定ファイルを使うと思います。でも、Logging API では設定ファイルを読み込む機能があるので、それを使えば簡単です。

そういえば、例えば Logger のデフォルトのレベルや、デフォルトでコンソールにログが出力されているのはどうやって決まっているのでしょうか。

種明かしをしてしまえば簡単なのですが、システムのログ設定用ファイルが用意されているからでした。設定ファイルは Java 2 SDK をインストールしてあるディレクトリ下の jre\lib (UNIX であれば jre/lib) ディレクトリにあるlogging.properties ファイルです。

このファイルは java.util.Properties で決められたフォーマットでログの設定が書かれています。コメントの部分などを省いたものを次に示しておきます。

############################################################
#  	Global properties
############################################################


# "handlers" specifies a comma separated list of log Handler 
# classes.  These handlers will be installed during VM startup.
handlers = java.util.logging.ConsoleHandler
 
# Default global logging level.
.level= INFO
  
############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

java.util.logging.FileHandler.pattern = %h/java%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.formatter = java.util.loggging.XMLFormatter
 
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

はじめの handlers の後に書いてあるクラス名が RootLogger に登録される Handler オブジェクトになります。ConsoleHandler オブジェクトが生成されるのはここで設定されいていたためです。

その後に .level = INFO と書いてあるのが Logger オブジェクトや Handler オブジェクトのログレベルです。level の前のピリオドがない場合すべての Logger オブジェクトと Handler オブジェクトに相当します。

この後に Handler オブジェクトごとの設定が書かれています。ここで設定できる項目は Handler クラスによって異なります。詳しくは JavaDoc を参照してください。

FileHandler の設定で一番後に記述されているのがログファイルのパターンです。FileHandler クラスのデフォルトのログファイルは %h/java%u.log なので、ユーザのホームディレクトリにログファイルが生成されます。同じようにログファイルの最大サイズやローテーションの数、Formatter についても設定されています。

また、ConsoleHandler のログレベルも INFO に設定されています。だから、コンソールには INFO 以上のものしか出力されていなかったのです。

アプリケーションごとに設定ファイルを使ったログの設定もできます。それを行ってみたのが FavoriteNumberWithLog10 クラスです。

アプリケーションのソース

FavoriteNumberWithLog10.java

initLogConfiguration メソッドの中で、設定の読み込みを行っています。

    private void initLogConfiguration(String configurationFilename) {
        try {
            FileInputStream inputStream = new FileInputStream(configurationFilename);
 
            // 設定ファイルの読み込み
            LogManager.getLogManager().readConfiguration(inputStream);
        } catch (FileNotFoundException ex) {
            ex.printStackTrace();
        } catch (IOException ex) {
            ex.printStackTrace();
        }
    }

設定ファイルを読み込んで、設定を行うのはとても簡単で LogManager クラスの readConfiguration メソッドを使うだけです。引数は InputStream オブジェクトなので、ファイルだけでなくさまざまな媒体で設定を行うことができます。今まで、LogManager クラスは日陰の存在でしたが、全体的な設定となるとすべての Logger オブジェクトを管理する LogManager クラスの登場と相成るわけです。

設定ファイルはアプリケーションの起動時に引数として与えるようにしました。

実行する前に設定ファイルを作りましょう。logging.prop1 という設定ファイルを準備し、内容を次のようにしました。

handlers = java.util.logging.ConsoleHandler
 
java.util.logging.FileHandler.pattern = FavoriteNumber%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 5
java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter
 
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
 
jp.gr.java_conf.skrb.logging.level = ALL

カレントディレクトリにログファイルを置くようにし、ファイル名に使用する数字は 5 までとしています。ログファイルの書式は XML です。

一方のコンソールにはログレベルを Level.INFO として、書式には SimpleFormatter クラスを使用しました。

最後の行で Logger オブジェクトのレベルの設定を行っています。Logger オブジェクトを getLogger メソッドで生成するときに、Logger オブジェクトの名前を引数に使いましたが、その名前をここで使います。

今のところ、Logger オブジェクトの設定はレベルだけのようです。Logger オブジェクトが使用する Handler クラスや Filter クラスなども設定できるといいのにと思いませんか。

では、この設定ファイルを使って実行してみましょう。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog10 logging.prop1
2002/04/30 3:33:51 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 updateNumber
情報: Your Favorite Number is 123
       ... (以下、略)

ConsoleHandler オブジェクトのログレベルは Level.INFO にしたので、フレーム生成などのログは出力されていません。また、カレントにログファイルができているのを確認してみてください。

次に、logging.prop2 という設定ファイルを使ってみました。

handlers= java.util.logging.ConsoleHandler
 
java.util.logging.ConsoleHandler.level = ALL
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
 
jp.gr.java_conf.skrb.logging.level = ALL

ログファイルは使わずにコンソールだけにログを出力するようにしています。ログレベルは Level.ALL にしたので、すべてのログが出力されるはずです。

実行結果はこんな感じになりました。

C:\temp>java jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog10 logging.prop2
2002/04/30 3:35:01 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 init
設定: JFrame@e5b723 is created.
2002/04/30 3:35:01 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 init
設定: JTextField@19d0a1 is created.
2002/04/30 3:35:01 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 init
設定: JButton@4aeb52 is created.
2002/04/30 3:35:02 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 init
設定: JFrame@e5b723 shows.
2002/04/30 3:35:07 FavoriteNubmerWithLog1 updateNubmer
詳細レベル (中): ENTRY
2002/04/30 3:35:07 jp.gr.java_conf.skrb.logging.FavoriteNumberWithLog1 updateNumber
情報: Your Favorite Number is 123
2002/04/30 3:35:07 FavoriteNubmerWithLog1 updateNubmer
詳細レベル (中): RETURN
       ... (以下、略)

logging.prop1 では出力されなかったログもちゃんと出力されるようになりました。また、ログファイルが生成されていないことを確かめてみてください。

最後に

Logging API はログの出力先やフィルター、ログの書式などいろいろとカスタマイズできるので、かなり使える API に仕上がっていると思います。

ただ、Logging API には強力なライバルがいます。それは Apache の Log4J です。はじめて Logging API の構成を見たとき、筆者は Log4J をベースに Java 2 SDK に組み込んだのだと思いました。実際は違っていたのですが、それほど両者は似ています。

Log4J の利点には JDK1.1 ベースで動作することと、すでに多くのアプリケーションで使用されているということがあると思います。また、WindowsNT/2000/XP のイベントログにログを書き出せるなどの機能的な違いもあります。

Logging API は他にライブラリを用意せずにも標準で使えるなどの利点があります。J2SE v1.4 ベースのアプリケーションであれば、Logging API を使用したほうがいいかもしれません。

ところで、Logging API は J2SDK v1.4 のβ版の時からかなり大幅な変更が加わっています。そのせいでこのドキュメントも大幅に改訂 (というかはじめから書き直したというか) したわけです。

例えば、Logger クラスには以前は log メソッドだけだったのが、logp メソッドと logrb メソッドに分化されました。また、今回はあまり触れませんでしたが、リソースバンドルも扱えるようになりました。一番の変更点は LogManager クラスの位置づけだと思います。βの時は、LogManager オブジェクトが直接 Handler オブジェクトを管理していました (GlobalHandler といいました)。それを RootLogger クラス (LogManger の内部クラスです) を導入して、GlobalHandler として扱っていたものは RootLogger が保持する Handler オブジェクトとして扱われるようになっています。

β版のころから使われている方は要注意です。

今回使用したサンプルはここからダウンロードできます。

Logging.zip

参考 URL

Logging API Overview
http://java.sun.com/j2se/1.4/docs/guide/util/logging/overview.html
java.util.logging JavaDoc
http://java.sun.com/j2se/1.4/docs/api/java/util/logging/package-summary.html
Log4J Project 日本語ドキュメント
http://www.ingrid.org/jajakarta/log4j/jakarta-log4j-1.1.3/docs-ja/index.html

(Apr. 2002)