SLF4J+LOGBackでログレベル別に出力先を切り分けることは出来るの？

こんにちは。

この間酷い目にあったのでその酷い目に対する対応策として。

皆さん、ログを出力するときにログレベルを定義するかと思うのですが、
１ファイルに全レベルのログを出力していた場合、
「ログレベルの低いログにログレベルの高いログが塗りつぶされる」という経験は無いでしょうか？

特に、検証用環境では「動作を確認するためのログを確認したいが、エラーも確認したい」という形になるため、
ログレベルはINFO、DEBUGといった詳細なものに設定して運用しがちだと思います。

ですが、やっていることがStorm等の高速大量イベントを処理する基盤ともなると、
INFOログであっても量がバカになりません。
そのため、「何か問題が発生したようなのだが、動作ログに埋もれてエラーログが消えている」ということがざらに発生します。

・・・そんなわけで、ログレベルの高いログは別ファイルに分離して出力しておけばそういったことに
悩まされることは無くなるのではないかと考え、LOGBackでログレベル毎にログの出力先を切り替えられないか確認してみました。

すると、LOGBackのページの「Chapter 7: Filters」に
ログレベルやログの内容を基にログをフィルタリングする機能について記述されていたため、ログレベルによるフィルタリングについて確認してみました。

尚、上記のページを見てみるとログレベルやログメッセージのようなものにとどまらず、
特定のMakerを保持するログを受けることでトリガーが入って有効化されるフィルタや、
同一の内容を持つメッセージの出力回数を一定回数までに抑えるフィルタなど、様々なものがありました。
このあたりもいつか何ができるかをきちんと確認しておきたいところではありますね。

1. logback.xmlの記述方法

サイトを参考に、以下のようなログ定義を作成しました。
これでログの出力内容は以下のようになるはずです。

• 「ERROR_FILE」にはERRORレベル以上のログ（ERRORのみ）、
• 「WARN_FILE」にはWARNレベル以上のログ（ERROR、WARNのみ）
• 「INFO_FILE」にはINFOレベルのみのログ

<configuration scan="true" scanPeriod="30 seconds">
    <jmxConfigurator />

    <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/var/log/logbacktest/${logfile.name}_ERROR</file>

        <!-- ERRORレベル以上のログのみを出力するためのフィルタ -->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/var/log/logbacktest/${logfile.name}_ERROR.%d{yyyy-MM-dd}
            </fileNamePattern>
            <maxHistory>14</maxHistory>
        </rollingPolicy>

        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] [%t] [%logger{35}:%line]%msg%n</pattern>
        </encoder>
    </appender>

    <appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/var/log/logbacktest/${logfile.name}_WARN</file>

        <!-- WARNレベル以上のログのみを出力するためのフィルタ -->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>WARN</level>
        </filter>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/var/log/logbacktest/${logfile.name}_WARN.%d{yyyy-MM-dd}
            </fileNamePattern>
            <maxHistory>14</maxHistory>
        </rollingPolicy>

        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] [%t] [%logger{35}:%line]%msg%n</pattern>
        </encoder>
    </appender>

    <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/var/log/logbacktest/${logfile.name}_INFO</file>

        <!-- INFOレベルのログのみを出力するためのフィルタ -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/var/log/logbacktest/${logfile.name}_INFO.%d{yyyy-MM-dd}
            </fileNamePattern>
            <maxHistory>14</maxHistory>
        </rollingPolicy>

        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] [%t] [%logger{35}:%line]%msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="ERROR_FILE" />
        <appender-ref ref="WARN_FILE" />
        <appender-ref ref="INFO_FILE" />
    </root>
</configuration>

2.検証用プログラム

で、検証用プログラムは非常に単純ですが、以下のようになります。

package logbacktest;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * ログ出力のテスト用プログラム
 * 
 * @author kimutansk
 */
public class LogTest
{
    /** Logger */
    private static final Logger logger = LoggerFactory.getLogger(LogTest.class);

    /**
     * パラメータを指定せずにインスタンスを生成する。
     */
    public LogTest()
    {}

    /**
     * ログ出力のテストを行うプログラムエントリポイント
     * 
     * @param args 起動引数(未使用)
     */
    public static void main(String[] args)
    {
        logger.trace("It's trace log");
        logger.debug("It's debug log");
        logger.info("It's info log");
        logger.warn("It's warn log");
        logger.error("It's error log");
    }
}

3.実際に動作させてみる

では、JVMオプションに「-Dlogfile.name=logtest.log」を指定して起動してみます。すると・・・
出力内容は以下の結果となりました。

■/var/log/logbacktest/logtest.log_ERROR

2013-10-26 22:15:37.296 [ERROR] [main] [logbacktest.LogTest:33]It's error log

■/var/log/logbacktest/logtest.log_WARN

2013-10-26 22:15:37.296 [WARN] [main] [logbacktest.LogTest:32]It's warn log
2013-10-26 22:15:37.296 [ERROR] [main] [logbacktest.LogTest:33]It's error log

■/var/log/logbacktest/logtest.log_INFO

2013-10-26 22:15:37.290 [INFO] [main] [logbacktest.LogTest:31]It's info log

とりあえず、「特定のログレベル指定」「一定以上のログレベル指定」でフィルタがかけられることがわかりました。

以上でログレベル毎に出力先ファイルを切り替えることが可能であることの確認ができました。
これで、重要なログが他のログに埋もれて後で追えなくなってしまう・・・ということは回避できそうですね。

Appenderを複数定義する必要があるところが性能的に微妙に気になるところですが、
実際にファイルには出力しない＆Appenderの頭でフィルタリングされて除去されるため、
それほど影響があることは無い、ととりあえず判断します。

Filterの機能は多彩なようなので、今後機会があればそういった機能も試してみたいところですね。