Java EE インジェクト可能なロガーの作り方と注意点

はじめに

システムの状態の変化やトラブルシューティングに必要な情報を記録するためロガーを利用する場面はよくあると思います。
Java EEでロガーを作る場合、ロガーがインジェクト可能だと使い勝手がよくなります。
この記事ではインジェクト可能なロガーの作り方とその注意点について解説します。
環境：JavaEE7

基本的なロガーの作り方

CDIビーンではないオブジェクトをインジェクトするためには「@Produces」アノテーションを使います。
基本的なロガーは次のように作ります。

基本的なロガー

@Dependent
public class LoggerProducer {
    @Inject
    InjectionPoint point;

    @Produces
    public Logger getLogger() {
        String loggerName = point.getMember().getDeclaringClass().getName();
        Logger logger = Logger.getLogger(loggerName);
        return logger;
    }
}

ロガー利用側

@Named
@RequestScoped
public class BackingBean {
    @Inject
    transient Logger logger;
    // ...
}

InjectionPointはインジェクトされた場所の情報を格納するクラスです。
上の例では格納先のクラス名を使ってロガーを取得します。

ログをファイルへ出力する際の注意点

ここからがこの記事のメインです。
ログはログファイルに出力できないと意味がありません。
ロガーにファイルへ出力させる場合、注意点があります。

大量の「.lck」ファイルが生成されてしまう

FileHandlerをロガーに登録してファイルへ出力させようとするとコードは次のようになります。（try-catch文省略）

FileHandlerを使ってログをファイルに出力する

@Dependent
public class LoggerProducer {
    @Inject
    InjectionPoint point;

    @Produces
    public Logger getLogger() {
        String loggerName = point.getMember().getDeclaringClass().getName();
        Logger logger = Logger.getLogger(loggerName);
        // dest : 出力先
        Handler handler = new FileHandler(dest, 10000, 1, true);
        logger.addHandler(handler);
        return logger;
    }
}

この実装は「ロガーごとに出力先を変えたい場合」（厳密に言えば2つ以上のロガーが同じファイルを出力先としない場合）は正しい実装です。
例えばインジェクト先のクラス名をログのファイル名にしたいと言った場合です（多分ないと思います…… いい例があったら教えて下さい）。
その場合、次のようになります。（try-catch文省略）

インジェクト先のクラス名をログのファイル名にする

@Dependent
public class LoggerProducer {
    @Inject
    InjectionPoint point;

    @Produces
    public Logger getLogger() {
        String loggerName = point.getMember().getDeclaringClass().getName();
        Logger logger = Logger.getLogger(loggerName);
        String dest = point.getMember().getDeclaringClass().getName() + ".log";
        Handler handler = new FileHandler(dest, 10000, 1, true);
        logger.addHandler(handler);
        return logger;
    }
}

しかし、「一つの出力先にログを出力する場合」は間違った実装です。
以下の例は「dest.log」というファイルにログを出力することを期待したコードです。
（try-catch文省略）

「dest.log」へログを出力する

@Dependent
public class LoggerProducer {
    @Inject
    InjectionPoint point;

    @Produces
    public Logger getLogger() {
        String loggerName = point.getMember().getDeclaringClass().getName();
        Logger logger = Logger.getLogger(loggerName);
        Handler handler = new FileHandler("dest.log", 10000, 1, true);
        logger.addHandler(handler);
        return logger;
    }
}

この実装で実行し、いろいろ動かしてみてログを見てみると「dest.log」「dest.log.lck」「dest.log.1」「dest.log.1.lck」……　といったファイルが大量にできると思います。
出力されたログも散らばっています。

「lck」ファイルが大量生成される原因

FileHandlerがファイルへ出力する場合、まずそのファイルをロックします。
ロックすると言っても「ファイル名.lck」というマーカーファイルを同じディレクトリに作るだけです。
このファイルがあると他のハンドラーからはそのファイルがロックされていると認識されます。
対象ファイルがロックされていると認識したハンドラーは「ファイル名.連番」というファイルを作ってそちらに出力しようとします。

1. 「dest.log」へ出力しようとする
2. 「dest.log.lck」ファイルが存在する
3. 「dest.log」はロック中と認識する
4. 「dest.log.1」というファイルを作りそちらへ作成
5. ロックしていることを示すため「dest.log.1.lck」というマーカーファイルを作成

「dest.log.連番」、「dest.log.連番.lck」が大量に発生したのは、このようなロックの連鎖が発生したためです。
ロックを解除するためにはFileHandlerの close() というメソッドを実行する必要があります。
この実装のまま解決しようとすると利用側でいちいちFileHandlerをクローズしなければいけません。
無駄なコードが増える上、CDIビーンのスコープによってはクローズするタイミングが悪いとログが出力されなくなる原因となります。

親ロガーを作りログの出力を委譲する

Loggerにはツリー構造があります。
「foo」という名前のロガーは「foo.bar」「foo.baz」といった名前のロガーの親になります。
ロガーはログを出力する際、親のロガーのハンドラーにも同じ内容を渡します。
この構造を利用して、ファイルへの出力は親のロガーに一任させ、子ロガーには出力させないようにします。
こうすることでロガーごとにロックされることがなくなり、出力先へ正しく出力できます。
親のロガーは1回だけ作ればいいのでstatic初期化ブロックを使います。

「dest.log」へログを出力する

@Dependent
public class LoggerProducer {
    @Inject
    InjectionPoint point;
    // ガベージコレクションに回収されないように強参照で保持する
    private final static Logger parentLogger = Logger.getLogger("myapp");

    static {
        try {
            Handler handler = new FileHandler("dest.log", 10000, 1, true);
            parentLogger.addHandler(handler);
        } catch(Exception ex) {
            // 例外処理
        }
    }

    @Produces
    public Logger getLogger() {
        String loggerName = "myapp." + point.getMember().getDeclaringClass().getName();
        return Logger.getLogger(loggerName);
    }
}

子ロガーの名前は必ず「myapp.」のように「親ロガーの名前.子ロガーの名前」となるように設定してください。
private final static Logger parentLogger = Logger.getLogger("myapp");
は忘れないようにしてください。
初期化ブロックの中で親ロガーを作ってしまうとガベージコレクションに回収されて上手く機能しなくなります。

アプリケーション終了時にロックを解除する

先述した実装でロガーを作れば正常に出力されます。
しかし、親ロガーのFileHandlerによるロックを解除してあげないとアプリケーションを起動するたびに「.連番」ファイルができてしまいます。
アプリケーション終了のタイミングでハンドラーをクローズします。
この処理はサーブレットのライフサイクルリスナーを使って実装します。

アプリケーション終了時にクローズ

public class LifecycleListener implements ServletContextListener {
    @Override
    public void contextInitialized(ServletContextEvent sce) {
    }

    @Override
    public void contextDestroyed(ServletContextEvent sce) {
        Logger logger = Logger.getLogger("myapp");
        for (Handler h : logger.getHandlers()) {
            h.close();
        }
    }
}

おわりに

一応期待する動作は実現できました。
間違ってる点や不適切な点、「こういうやり方もあるよ」って方はぜひ教えて下さい。

参考

http://docs.oracle.com/javase/jp/7/api/java/util/logging/Logger.html#getLogger(java.lang.String)
http://www.akirakoyasu.net/2011/11/06/finally-understood-java-util-logging/
http://d.hatena.ne.jp/kenpoco/20080627/1214535998
http://www.techscore.com/tech/Java/JavaEE/Servlet/7/