Log4perl でコンソールとファイルにロギング

perl でロギング。INFO レベル以上のログはファイルに日次ローテーションで吐き出す。と同時に標準エラー出力にもデバッグ情報を出してみたりしたい。
で、etc/logger.conf を次のように書いてみた。

#log4perl.rootLogger = INFO, CONSOLE, FILE
log4perl.rootLogger = DEBUG, CONSOLE, FILE

#log4perl.appender.CONSOLE     = Log::Log4perl::Appender::ScreenColoredLevels
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.FILE.Threshold = INFO
log4perl.appender.FILE          = Log::Dispatch::FileRotate
log4perl.appender.FILE.filename = var/log/sample.log
log4perl.appender.FILE.mode     = append
log4perl.appender.FILE.DatePattern = yyyy-MM-dd
log4perl.appender.FILE.layout   = Log::Log4perl::Layout::PatternLayout
log4perl.appender.FILE.layout.ConversionPattern = %d{yyyy/MM/dd HH::mm::ss.SSS} %p %m%n

ScreenColoredLevels を使うとエスケープシーケンスを利用してレベルごとに色づけして出力してくれるっぽい。Time::HiRes もインストールしておかないとミリ秒で出力してくれないらしいので注意。

コンソール側のログはデバッグのための情報が重要なのでプロセス ID やログ出力場所 (ファイル名と行番号) を出力する。ファイル側はリアルタイムに参照するんじゃなくて、あとからプログラムの動作を調査するものだからミリ秒単位でログ時刻を出力。

ロガーを使う側。最初、

use Log::Log4perl qw(:easy);

でお手軽ロギングしていた名残りで DEBUG(), INFO() などの関数をあちこちで呼んでいる。それらを全部

  $logger->debug($message);

なんかに書き替えるのが面倒、あーんど

  DEBUG($message);

のほうがみやすくていいんじゃないの？ということで、これらのログ出力関数を明示的に export してみることにした。プログラムのすべてのパッケージのベースになるパッケージ Sample があったので、

package Sample;
use Log::Log4perl;
Log::Log4perl::init('etc/logger.conf');
my $logger = Log::Log4perl->get_logger;
sub DEBUG {
    local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
    $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()."::DEBUG"} = *DEBUG;
    *{caller()."::INFO"}  = *INFO;
    *{caller()."::WARN"}  = *WARN;
    *{caller()."::ERROR"} = *ERROR;
    *{caller()."::FATAL"} = *FATAL;
}

としてみた。

プログラムの他の部分は

package Sample::Another;
use base qw/Sample/;

となっている。ここで Sample.pm が import されるので、Log4perl を use しなくても INFO() とか使ってログが吐ける。

うむ、これはいいかも。

追記

これだと、%l で出力される関数名、ファイル名、行番号が DEBUG() のものになってしまう。つまり、Sample/Another.pm の something() 関数で DEBUG() を呼び出しても、ロガーには Sample.pm の DEBUG() 関数で呼ばれたことしか記録されない。うーむ。caller もフックしないとだなあ。

追記の追記

caller_depth を上書きすることで対処してみた。上のプログラムは対処済みのもの。