Log4perl でデバッグログだけ別ファイルに保存する修行

Lo4perl 周り。基本的には Log4J でも同じはず。

やりたいことは、次のとおり。

一次ログとデバッグログを分けたい。
- 一次ログには INFO 以上のログを適度な粒度で出力したい。
- 一次ログにデバッグログが混ざってしまうと解読が困難になるので、デバッグログだけ別ログにしたい。
一次ログとデバッグログはそれぞれのファイルに出力したい。
- それぞれのログファイルは日次ローリングしたい。
- 一次ログはコンソールにも出力したい。

もしかするとデバッグログは日次よりも細かく、たとえば分次とかでローリングしてもいいかもしれない。どれくらい細かく、すなわち大量にログるかって話だが。

etc/logger.conf は次のようにしてみた。

log4perl.rootLogger = INFO, CONSOLE, FIRST_FILE
log4perl.logger.Sample.DEBUG = TRACE, DEBUG_FILE
log4perl.additivity.Sample.DEBUG = 0

log4perl.appender.CONSOLE     = Log::Log4perl::Appender::Screen
log4perl.appender.CONSOLE.layout = Log::Log4perl::Layout::PatternLayout
log4perl.appender.CONSOLE.layout.ConversionPattern = <%P> %p %l - %m%n

log4perl.appender.FIRST_FILE.Threshold = INFO
log4perl.appender.FIRST_FILE          = Log::Dispatch::File::Rolling
log4perl.appender.FIRST_FILE.filename = var/log/first-%d{yyyyMMdd}.log
log4perl.appender.FIRST_FILE.mode     = append
log4perl.appender.FIRST_FILE.layout   = Log::Log4perl::Layout::PatternLayout
log4perl.appender.FIRST_FILE.layout.ConversionPattern = %d{yyyy/MM/dd HH:mm:ss.SSS} %p %m%n

log4perl.appender.DEBUG_FILE.Threshold = TRACE
log4perl.appender.DEBUG_FILE          = Log::Dispatch::File::Rolling
log4perl.appender.DEBUG_FILE.filename = var/log/debug-%d{yyyyMMdd}.log
log4perl.appender.DEBUG_FILE.mode     = append
log4perl.appender.DEBUG_FILE.layout   = Log::Log4perl::Layout::PatternLayout
log4perl.appender.DEBUG_FILE.layout.ConversionPattern = %d{yyyy/MM/dd HH:mm:ss.SSS} %p %m%n

デフォルトのルートロガーの他に Sample.DEBUG ロガーも作る。ルートロガーは INFO レベル以上を受けつけるようにして CONSOLE アペンダと FIRST_FILE アペンダに出力する。Sample.DEBUG ロガーは TRACE レベル以上、つまり全レベルのログを受けつけ DEBUG_FILE アペンダに出力する。そのままだと Sample.DEBUG ロガーがルートロガーのアペンダを継承してしまう、すなわち、デバッグログも CONSOLE アペンダ、FIRST_FILE アペンダに流れてしまうので、additivity を 0 にしておく。

日次でローリングさせるために、FIRST_FILE アペンダ、DEBUG_FILE アペンダともに Log::Dispatch::File::Rolling を利用。

プログラムのそれぞれの場所から use して使う Sample クラスを作って、ロガーもそこに仕込む。

package Sample;
use Log::Log4perl;

Log::Log4perl::init('etc/logger.conf');
my $logger = Log::Log4perl->get_logger(q{});
my $debug_logger = Log::Log4perl->get_logger('Sample::DEBUG');
sub TRACE {
    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
    $debug_logger->trace(@_);
}
sub DEBUG {
    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
    $debug_logger->debug(@_);
}
sub INFO {
    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
    $logger->info(@_);
}
sub WARN {
    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
    $logger->warn(@_);
}
sub ERROR {
    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
    $logger->error(@_);
}
sub FATAL {
    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
    $logger->fatal(@_);
}

sub import {
    no strict 'refs';
    *{caller()."::TRACE"} = *TRACE;
    *{caller()."::DEBUG"} = *DEBUG;
    *{caller()."::INFO"}  = *INFO;
    *{caller()."::WARN"}  = *WARN;
    *{caller()."::ERROR"} = *ERROR;
    *{caller()."::FATAL"} = *FATAL;
}

ルートロガーとして $logger インスタンスを作成し、INFO 以上のログメソッドからはそれを利用するようにした。このとき Log4perl->get_logger() と引数を省略すると望んだロガーが得られない*1。ここでは空文字列を渡している。デバッグロガーとして引数で 'Sample.DEBUG' を指定して $debbug_logger インスタンスを作成。こちらは TRACE と DEBUG の場合に出力対象になる。TRACE、DEBUG などの関数は import 時に import 元のパッケージに名前をさらしてお手軽に使えるようにするのは、Log4perl でコンソールとファイルにロギング - 昨日知ったことでやったとおり。

複数のロガーを使った例はググってもなかなか引っ掛らない。ので書いておいてみた。

課題

コストの高いデバッグログ情報の生成は、ロガーの設定レベルを調べてから行うのが定石だ。

if ($logger->is_debug()) {
    my $message = create_heavy_information();
    $logger->debug($message);
}
先の例に、こういう仕組みを入れるにはどうすればいいか、考える必要あり。

単に
>|perl|
sub IS_DEBUG {
     $debug_logger.is_debug;
}

を用意すればいいのか。でも、そもそもデバッグログを抑制するのであればデバッグログオブジェクトを生成する必要すらない。そこまでやるとなると logger.conf だけでは対応できないだろうな。

*1:Data::Dumper で中身をみたら意図していないものだった、というだけで詳しく解析してない