Perlからログを出力方法

ここからは、実際にPerlでログを出力する方法をコードを交えながら説明します。

Perlのスクリプトから最も簡単にログを吐くには、組込み関数のwarnを使います。

warn "request timeout";

これを実行すると、標準出力に対して、

request timeout at log.pl line 7.

のようにwarnを記したファイル名と行があわせて出力されます。

しかしこれだけでは前節で説明したログに必要な項目を満たしていないので、情報を追加していきます。

my @time = localtime();
warn sprintf "%04d-%02d-%02dT%02d:%02d:%02d [%s] %s",
  $time[5]+1900, $time[4]+1, @time[3,2,1,0],  ―（1）
  "WARN",  ―（2）
  "request timeout";

（1）で日付時刻を追加し、（2）でログのレベルを指定しています。実際に実行すると、

2011-08-05T16:47:12 [WARN] request timeout at log.pl 
line 8.

となり、時間とログレベルを追加できました。

ただしログを出力するたびにこのコードを書くのは冗長ですので、再利用できるようにします。リスト3が完成した関数になります。

sub logf {
    my ($level,$message) = @_;
    my ($pkg,$file,$line) = caller; ―（1）
    my @time = localtime;
    warn sprintf "%04d-%02d-%02dT%02d:%02d:%02d [%s] %s at %s line %d.\n", ―（2）
        $time[5]+1900, $time[4]+1, @time[3,2,1,0],
        $level, $message,
        $file, $line;
}

実行方法と出力は次のようになります。

# 実行
logf("INFO","request timeout");
# 出力
2011-08-05T17:01:09 [INFO] request timeout at log.pl 
line 18.

そのままlogf関数内でwarnを実行すると、logfを呼んだファイル名・行ではなく、warnを呼んだlogf内のファイル名・行が出力されてしまうので、リスト3（1）でcaller関数を使い呼び出し元の情報を得ています。そしてリスト3（2）でwarnにてログを書き出すのですが、その際は改行を最後に付け、warnが必要のないファイル名・行を追加しないようにします。

これで、シンプルで再利用可能なログ関数を作ることができました。

CPANに登録されているログモジュール

前節ではログを出力するための簡単な関数を作成してみましたが、ログを出すためのモジュールはすでにCPANに多く登録されています。本節ではCPANに登録されている代表的なログモジュールをいくつか紹介します。

Log::Log4perl

Log::Log4perlは、その名のとおりJavaでよく使われるログツールLog4JのPerl版となります。Log::Log4perlはcpanmコマンドにて簡単に導入できます。

$ cpanm Log::Log4perl

基本的な使い方はリスト4のようになります。まず（1）でログの出力方法を定義した設定ファイルを読み込みます。次に（2）で使用するloggerオブジェクトを作成し、（2）以降でログを出力します。ログを出力するメソッドはレベルごとにtrace、debug、info、warn、error、fatalの6つが用意されています。

use Log::Log4perl;
Log::Log4perl::init('./log4perl.conf'); ―（1）

my $logger = Log::Log4perl->get_logger('develop'); ―（2）
$logger->debug('This is a debug message'); ―（3）
$logger->warn('This is a warn message');
$logger->fatal('Fatal error has occurred');

リスト5はリスト4（1）で読み込む設定ファイルです。1行目でloggerを定義します。ここではdevelopというloggerを作成し、出力するレベルをDEBUG以上、ログ出力方法としてScreenという設定を使うと宣言しています。2行目以降は出力方法の定義です。2行目ではログを出力するモジュールとしてLog::Log4perl::Appender::Screen（標準エラーにログを出力）を指定し、3行目、4行目でログの形式を設定しています。各設定の詳しい内容はモジュールのドキュメントを確認してください。

log4perl.logger.develop         = DEBUG, Screen
log4perl.appender.Screen        = Log::Log4perl::Appender::Screen
log4perl.appender.Screen.layout = Log::Log4perl::Layout::PatternLayout
log4perl.appender.Screen.layout.ConversionPattern = %d [%p] %m %F at %L.%n

log4perl.plを実行すると、リスト6のような結果が得られます。ログのレベルやログの呼び出し元も出力されています。Log4perlでは標準エラーにログを吐き出すモジュールのほかに、ファイルやデータベースに書き込むモジュールも用意されており柔軟なカスタマイズができます。

2011/08/11 17:58:39 [DEBUG] This is a debug message log4perl.pl at 9.
2011/08/11 17:58:39 [WARN] This is a warn message log4perl.pl at 10.
2011/08/11 17:58:39 [FATAL] Fatal error has occurred log4perl.pl at 11.

Log::Dispatch

Log::DispatchはDateTimeやMooseの開発者として知られているDave Rolsky氏によるログモジュールで、拡張性が高いのが特徴であり、CPANにも多くの拡張モジュールやフレームワークのプラグインが登録されています。

リスト7がLog::Dispatchの基本的な使い方です。（1）でLog::Dispatchのインスタンスを作成します。サンプルでは出力方法として、（2）で標準出力あるいは標準エラーに書き出すScreenモジュールを採用しています。Log::Dispatchはインスタンス作成時に複数の出力モジュールを指定することで、同時にさまざまなログ出力方法が利用できます。（2）以降でログを吐き出しています。Log4perlと同様にログレベルごとのメソッドが用意されています。サポートされているのはdebug、info、notice、warning、error、critical、alert、emergencyの8個です。

use Log::Dispatch;
my $log = Log::Dispatch->new( ―（1）
    outputs => [[
        'Screen', ―（2）
        min_level => 'debug',
        stderr    => 1,
        newline   => 1,
    ]],
);

$log->debug('debug message'); ―（3）
$log->info('info message');
$log->notice('notice message');
$log->emergency('emergency message');

しかしLog4perlと異なり、Log::Dispatchではログレベルや時刻、ログ呼び出し元の情報がログに一切含まれません。リスト7を実行しても、

debug message
info message
notice message
emergency message

というメッセージだけが表示され、ログとしての必要項目が満たせていません。そこでインスタンス作成時にリスト8のようにコールバックを追加します。これでLog4perlと同じ結果が得られます。

my $log = Log::Dispatch->new(
    outputs => [[
        'Screen',
        min_level => 'debug',
        stderr    => 1,
        newline   => 1,
        callbacks => sub {
            my %args = @_;
            my ($pkg,$file,$line);
            my $caller = 0;
            while ( ($pkg,$file,$line) = caller($caller) ) {
                last if $pkg !~ m!^Log::Dispatch!;
                $caller++;
            }
            my @time = localtime;
            sprintf "%04d-%02d-%02dT%02d:%02d:%02d [%s] %s at %s line %d.",
                $time[5]+1900, $time[4]+1, @time[3,2,1,0],
                $args{level}, $args{message},
                $file, $line;
            }
        },
    ]]
);

Log::Minimal

Log::Minimalは拙作のログモジュールで、極力シンプルに利用できるよう設計されています。

リスト9はLog::Minimalの利用例です。Log::Minimalをuseするといくつかの関数がエクスポートされるので、それを使いログを出力します。インスタンスの作成などが必要なく、少ない手数でログを書けます。サポートしているログレベルはcritical、warn、info、debugの4つで、それぞれcritf、warnf、infof、debugfという関数が用意されています。さらに、warnffのように「f」が2つ付く関数もあり、こちらはスタックトレースが付加されます。

use Log::Minimal;

critf("crtical message");
warnf("warning message");
infoff("infomation message");
debugff("debug message");

Log::Minimalはシンプルながらもいくつかカスタマイズできるようになっているので、以降で紹介します。

デバッグメッセージの表示

Log::Minimalでdebugfもしくはdebugffを使っても、標準ではそのログは出力されません。LM_DEBUGという環境変数を有効にすることで初めて、デバッグメッセージが出力されるようになります。

$ENV{LM_DEBUG} = 0;
debugf("debug message"); #表示されない

$ENV{LM_DEBUG} = 1;
debugf("debug message"); #表示される

アプリケーション開発中はLM_DEBUGを有効にし、本番環境では無効にすることで、本番環境で必要のないログを残さないようにできます。

ログのカラーリング

ターミナル上でログを表示した際に、ログメッセージに色を付けることができます。$Log::Minimal::COLOR変数に1を入れると色付け機能が有効になります。ログに色を付けることで開発時にログが見やすくなるでしょう。

次のコードを実行すると、図1のようにメッセージ部分がカラーリングされターミナルに表示されます。

$ENV{LM_DEBUG}=1;
$Log::Minimal::COLOR=1;

debugf("foo debug");
infof("bar info");
warnf("foo warn");
critf("bar critical");

なお、Log::Log4perlではLog::Log4perl::Appender::ScreenColoredLevels（ディストリビューション同梱⁠）⁠、Log::DispatchではCPANに登録されているLog::Dispatch::Screen::Colorモジュールを利用することで、同じようにログに色を付けることができます。

メッセージのフォーマットと自動シリアライズ

Log::Minimalのログ出力関数に2つ以上の引数を渡すと、1つ目をprintfのフォーマット文字列として利用します。

$name="gihyo";
id="65";
warnf("user:%s id:%d",$name,$id);

上記は、次のようにフォーマットされて表示されます。

2011-08-05T17:01:09 [INFO] user:gihyo id:65 at log.pl 
line 8

また、$Log::Minimal::AUTODUMP変数に1を代入しておくと、ハッシュや配列のリファレンスやオブジェクトをログ関数に渡した場合、自動的にシリアライズして出力します。

my $user = {
  id => 65,
  name => 'gihyo',
  point => 1480,
};
local $Log::Minimal::AUTODUMP = 1;
infof("user:%s",$user);

上記のコードを実行すると、リスト10のように展開されてログ出力されます。環境変数や追加情報・デバッグ情報の表示に便利です。

2011-08-14T02:09:04 [INFO] user: {
 'point' => 1480,
 'name' => 'gihyo',
 'id' => 65
} at /tmp/minimal.pl line 9

ログ出力方法の変更

デフォルトのLog::Minimalは、warn関数を通して標準エラーにログを出力しています。もし出力方法をカスタマイズをしたい場合は、$Log::Minimal::PRINTという変数を上書きします。リスト11ではファイルにログを記録するよう変更しています。

open( my $fh, ">>", "app.log");
local $Log::Minimal::PRINT = sub {
    my ( $time, $type, $message, $trace) = @_;
    print $fh "$time [$type] $message at $trace\n";
};

$Log::Minimal::PRINTに渡したサブルーチンリファレンスには、フォーマットされた時刻、ログレベル、メッセージ、呼び出し元の情報が渡されるので、自由に情報の追加／削除を行って、ログの書き出しができます。

ログモジュールの比較

ここまで紹介したLog::Log4perl、Log::Dispatch、Log::Minimalの機能比較を表2にまとめました。CPANにはこれ以外にも数多くのログモジュールが登録されていますが、それらを選択する際の参考していただければと思います。個人的には時間や書き出し元の情報がデフォルトで追加され、ログを書き出すという目的まで最も手間が少ない拙作のLog::Minimalをお勧めします。