Perl Hackers Hub

第11回 ログでアプリケーションの改善プロセスを回す(2)

この記事を読むのに必要な時間:およそ 4.5 分

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が完成した関数になります。

リスト3 logf関数

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つが用意されています。

リスト4 log4perl.pl

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行目でログの形式を設定しています。各設定の詳しい内容はモジュールのドキュメントを確認してください。

リスト5 log4perl.conf

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では標準エラーにログを吐き出すモジュールのほかに,ファイルやデータベースに書き込むモジュールも用意されており柔軟なカスタマイズができます。

リスト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個です。

リスト7 log_dispatch.pl

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と同じ結果が得られます。

リスト8 log_dispatch_callback.pl

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;
            }
        },
    ]]
);

著者プロフィール

長野雅広(ながの まさひろ)

NHN Japan株式会社 ウェブサービス本部 開発2室 開発支援チーム所属。オペレーションエンジニアとしてlivedoor blogやポータルサービスなど自社サービスの運用に携わっている。サーバリソース情報の収集,アプリケーション設計のアドバイス,ミドルウェアの設定,障害対応のフォローなど,Webアプリケーションエンジニアにかかる運用の負担を減らすことが主な業務。

URL:http://blog.nomadscafe.jp/

Twitter:kazeburo

コメント

コメントの記入