Perl logging

51
Perl ロロロロ print かか Log::Dispatch かかかかか 2010/08/07 Hokkaido.pm #1 By [email protected] Hokkaido.pm #1

Transcript of Perl logging

Page 1: Perl logging

Perl ロギングprint から Log::Dispatch の拡張まで

2010/08/07 Hokkaido.pm #1By [email protected]

Hokkaido.pm #1

Page 2: Perl logging

概略

ログのあれこれについて語ります。

対象は Perl 入門者です。※ 後半は初級者向けかも

何でログなのか 必須知識の割には、あまり言及されないみたいなので。

※ 定番サイト、定番本、グーグルで全滅 ログ吐く方法すら分からないとあっては、 Perl 採用への道が遠退き

そうなので。

内容 ログ出力のための Perl の基礎知識 モジュールを使ったログ出力 業務要件に合わせたモジュールの拡張

Hokkaido.pm #1

Page 3: Perl logging

Perl ロギング その 1“ 面倒な”前提知識を再確認

Hokkaido.pm #1

モジュールを使わないでやってみる

Page 4: Perl logging

debug レベル[ 変数の確認とか ]

Hokkaido.pm #1

Page 5: Perl logging

プリント文デバッグは永劫不滅です

use utf8;BEGIN { binmode STDOUT, ':utf8'; }my $hoge = 'hoge';print "hoge は '${hoge}' です \n";↓hoge は 'hoge' です

※ デバッガは lvalue に関するバグがあるよ !

Hokkaido.pm #1

Page 6: Perl logging

Data::Dumper はちょっと不便

use utf8;use Data::Dumper;BEGIN { binmode STDOUT, ':utf8'; }my $hoge = { key => ' 値 ' };print Dumper($hoge);↓$VAR1 = { 'key' => "\x{5024}"};

Hokkaido.pm #1

Page 7: Perl logging

YAML::Syck だといい感じ

use utf8;use YAML::Syck;use feature qw(say);BEGIN { $YAML::Syck::ImplicitUnicode = 1; binmode STDOUT, ':utf8';}say Dump($hoge);↓---key: 値

※ YAML も 0.71 で UTF8 文字化けしなくなったよ !

Hokkaido.pm #1

perlcriticrc[Variables::ProhibitPackageVars]add_packages = YAML::Syck

Page 8: Perl logging

info レベル[ 進捗の確認とか ]

Hokkaido.pm #1

Page 9: Perl logging

処理の終了と開始とか

say '[info] 処理 A 開始 ' . Time::Piece::localtime->cdate; $ ./hoge.pl >> ~/info.log $ cat ~/info.log↓[info] 処理 A 開始 Sun Aug 1 13:29:31 2010

※5.10 から Time::Piece がコア入りしたよ !

Hokkaido.pm #1

Page 10: Perl logging

warning レベル[ 不穏な動きを警告 ]

Hokkaido.pm #1

Page 11: Perl logging

STDERR warn carp

use utf8;BEGIN { binmode STDERR, ':utf8'; }say STDERR ' なんかエラーだ YO! ';warn ' なんかエラーだ YO! '; # 行番号carp ' なんかエラーだ YO! '; # スタックトレー

$ ./hoge.pl 2>>warn.log >>debug.log$ ./hoge.pl >>all.log 2>&1

※ うるさい時には、 $Carp::Internal{' パッケージ名 '}++Hokkaido.pm #1

Page 12: Perl logging

error/critical レベル[ 断末魔の処理 ]

Hokkaido.pm #1

Page 13: Perl logging

exit die croak

exit 1; errono を直指定。何を言ってるのか分かりづらい ジョブネット組む時に使ったりする

die " うぎゃぁ ~ 。銃でやられた ! "; 原因が分かりやすい。単に die すると 255 で固定

croak " やられた ! かくかくしかじか "; 死んだ経緯をしゃべる。スタックトレースつき

Hokkaido.pm #1

Page 14: Perl logging

終了ステータスの変更:$SIG{__DIE__}

捕捉してフックする$SIG{__DIE__} = sub {

my $error = shift;if ($error =~ m{^hello}xms) {

$! = 100;}die $error;

};

Hokkaido.pm #1

Page 15: Perl logging

終了ステータスの変更: $ERRNO

$! = 100;die ' 死亡… ';

use English qw(-no_match_vars);$ERRNO = 100;die ' 死亡… ';

※ -no_match_vars をつけないと Damian 先生に怒られるよ !

Hokkaido.pm #1

Page 16: Perl logging

Perl ロギング その 2Log::Dispatch::* の利用

Hokkaido.pm #1

Page 17: Perl logging

Log::Dispatch

Hokkaido.pm #1

Page 18: Perl logging

Log::Distach とは

ログの出力先を、標準エラー / ファイル / メール /DB/Syslog/Twitter などに自在に切り替えられる

簡単に拡張ができるように設計されている ↓ 拡張モジュールが豊富

$ cpanp m ^Log::Dispatch::50 個以上ヒット !miyagawa 氏の名前とかもある

Hokkaido.pm #1

Page 19: Perl logging

簡単な例:とりあえずファイルに

use Log::Dispatch;use Log::Dispatch::File;my $log = Log::Dispatch->new;$log->add(

Log::Dispatch::File->new(name => 'file_debug',min_level => 'debug',max_level => 'debug',filename=> 'debug.log',mode => 'append',newline => 1,

)

);$log->debug('[debug] デバッグ情報 [' . Time::Piece::localtime->cdate

. ']');

Log::Dispatch::Output のサブクラスを指

Hokkaido.pm #1

Page 20: Perl logging

簡単な例:標準エラーに追加

$log->add(

Log::Dispatch::Screen->new(name => 'screen',min_level => 'debug',newline => 1,stderr => 1,

)

);$log->debug('[debug] デバッグ情報 [' .

Time::Piece::localtime->cdate . ']');

L::D::Screen を継承した

L::D::Screen::Color みたいなものもある

Hokkaido.pm #1

Page 21: Perl logging

Log::Dispatch::Config

Hokkaido.pm #1

Page 22: Perl logging

Log::Dispatch::Config とは Log::Dispatch のサブクラス

(miyagawa プロダクト )

ログ設定を別ファイルに分離できる

出力書式を自由に設定できる$log->debug('[debug] デバッグ情報 [' .

Time::Piece::localtime->cdate . ']');↓ シンプル !

[%p] %m [%d]$log->debug(' デバッグ情報 ')

設定ファイルの形式は、 YAML 、 INI ファイルなどから選べる

Hokkaido.pm #1

Page 23: Perl logging

コード部分

初期化は、 new → add でなく、 configure → instanceuse utf8;use Log::Dispatch::Config;use Log::Dispatch::Configurator::YAML;BEGIN { binmode STDERR, ':utf8'; }

my $log_config = Log::Dispatch::Configurator::YAML->new('./log_conf.yaml');Log::Dispatch::Config->configure( $log_config );my $log = Log::Dispatch::Config->instance; # new じゃない

$log->debug(' デバッグ情報 ');$log->info(' インフォ。 ');

Hokkaido.pm #1

Page 24: Perl logging

設定ファイル (YAML の例 )

dispatchers: - file_debug - screen_color

file_debug: class: Log::Dispatch::File min_level: debug max_level: debug filename: debug.log mode: append newline: 1 format: [%d] [%p] %m at

%F:%L

screen_color: class:

Log::Dispatch::Screen::Color

min_level: debug newline: 1 color: info: text: green warning: text: yellow error: text: red

サブクラスの追加属性

Hokkaido.pm #1

Page 25: Perl logging

Log::WarnDie

Hokkaido.pm #1

Page 26: Perl logging

Log::WarnDie とは

昔は、 Log::Dispatch::WarnDie という名前だった

warn|die|STDERR を Log::Dispatch 、 Log::Log4Perl に統合する warn 、 carp 、 cluck を warning レベルに自動出

力 die 、 croak 、 confess を error レベルに自動出力

use Log::WarnDie $log; とするだけで有効になり、既存コードの変更は不要

Hokkaido.pm #1

Page 27: Perl logging

簡単な例

use Log::Dispatch;use Log::Dispatch::File;use Log::WarnDie; # 一回 use しといて

my $log = Log::Dispatch->new;$log->add( Log::Dispatch::Screen->new(

name => 'screen',min_level => 'debug',

));

use Log::WarnDie $log; # インスタンスを与えてもう一回 use

warn 'warning!';die 'died…';

Hokkaido.pm #1

Page 28: Perl logging

Perl ロギング その 3Log::Dispatch::* の拡張

Hokkaido.pm #1

Page 29: Perl logging

Log::Dispatch::* の拡張 #1Log::Dispatch::Email:*を拡張してみよう

Hokkaido.pm #1

Page 30: Perl logging

Log::Dispatch::Email とは L::D::Output のサブクラス。さらにその Email を継承したクラス

が複数あり、ログをメールに出力してくれる。

サブクラス達 ( 多過ぎ !) Log::Dispatch::Email::EmailSend Log::Dispatch::Email::MIMELite Log::Dispatch::Email::MailSend Log::Dispatch::Email::MailSender Log::Dispatch::Email::MailSendmail

欠点 モダンじゃない 日本語メールが文字化けして嫌な目にあう

じゃあ、モダンで文字化けしないのを作ってしまおう !Hokkaido.pm #1

Page 31: Perl logging

Log::Dispatch::Email::EmailSender

モダンなメール送信クラス Email::EmailSender を利用してメールを送る

エンコードを指定できるので文字化けしない

Email::EmailSender::Transport::Sendmail の他に、 Email::EmailSender::Transport::SMTP にも対応させる

L::D::Email を継承して、 send_email メソッドをオーバーライドすれば完了

Hokkaido.pm #1

Page 32: Perl logging

コンストラクタ: %p → $self へsub new {    my $proto = shift;    my $class = ref $proto || $proto;    my %p = @_;    my $self = $class->SUPER::new(%p);

    $self->{use_transport_smtp} = delete $p{use_transport_smtp};    $self->{host} = delete $p{host};    $self->{port} = delete $p{port};    $self->{ssl} = delete $p{ssl};    $self->{sasl_username} = delete $p{sasl_username};    $self->{sasl_password} = delete $p{sasl_password};

    return $self;}

※ 勝手に拡張したパラメータは、 delete で即座に消すのが流儀らしいHokkaido.pm #1

Page 33: Perl logging

send_email メソッド

sub send_email {    my $self = shift;    my %p = @_;    my $to_str = join ',', @{ $self->{to} };    my $email = _create_email({            from => $self->{from},  to => $to_str,  subject => $self-

>{subject},            header_encode => $self->{header_encode} || 'MIME-

Header-ISO_2022_JP',            body_encode => $self->{body_encode} || 'iso-2022-jp',            body => $p{message},    }); … 省略 …    sendmail( $email, $transport, { to => $self->{to} } );}※ $self からパラメータを受け取り、実際にメールを送信するコードを記述

します。

例外処理とTransport::SMTP

は省略してます

Hokkaido.pm #1

Page 34: Perl logging

_create_email メソッド

sub _create_email { my $opt = shift; my $enc1 = $opt->{header_encode}; my $enc2 = $opt->{body_encode}; my $email = Email::MIME->create( header => [ From => encode( $enc1, $opt->{from} ), To => encode( $enc1, $opt->{to} ), Subject => encode( $enc1, $opt->{subject} ), ], attributes => { content_type => 'text/plain', charset => $enc2, encoding => '7bit', }, body => encode( $enc2, $opt->{body} ), ); return $email;}

Email::MIME->create して、 return してるだけ。

Hokkaido.pm #1

Page 35: Perl logging

使い方: Sendmail

use Log::Dispatch;use Log::Dispatch::Email::EmailSender;my $log = Log::Dispatch->new;$log->add(

Log::Dispatch::Email::EmailSender->new( min_level => 'emerg', from => '[email protected]', to => [ qw( [email protected] [email protected] ) ], subject => 'Big error!', header_encode => 'MIME-Header-ISO_2022_JP', body_encode => 'iso-2022-jp‘ )

);$log->emerg("Something bad is happening");

Hokkaido.pm #1

Page 36: Perl logging

使い方: SMTP

Log::Dispatch::Email::EmailSender->new( min_level => 'emerg', from => '[email protected]', to => [ qw( [email protected] [email protected] ) ], subject => 'Big error!', header_encode => 'MIME-Header-ISO_2022_JP', body_encode => 'iso-2022-jp‘, use_transport_smtp => 1, host => [your smtp host], port => [your smtp port number], sasl_username => [your username], sasl_password=> [your password],)

Hokkaido.pm #1

Page 37: Perl logging

補足など

インストール$ cpanf –m Log::Dispatch::Email::EmailSender$ cpanf –mdi Log::Dispatch::Email::EmailSender

欠点 SSL オプションを使えない (gmail アカウント使えない ) メール送信エラー時のリトライがない 他の Email::Sender::Transport::* に未対応 添付ファイルとか HTML メールとか送れない

バグ報告、パッチ、要望など http://github.com/keroyonn/p5-Log-Dispatch-Email-EmailSender http://rt.cpan.org/ [email protected]

Hokkaido.pm #1

Page 38: Perl logging

Log::Dispatch::* の拡張 #2Log::Dispatch::Configを拡張してみよう

Hokkaido.pm #1

Page 39: Perl logging

こんなことありませんか?

処理速度の傾向を把握したい バッチ処理で、目標とする処理時間がある ランダムなデータでは目標をクリアしているが、実データで実

際どうなるか分からない サービスイン当初はいいが、データ増大と共に重くなるため処

理時間の監視が必要 プロファイルの前に原因箇所にあたりをつけておきたい

捕捉し切れていない例外が総合テストで明らかになって、ふと大丈夫か不安になる

Perl の警告とプログラムの警告ログが別管理されていて、うっかり片方のチェックを忘れてしまう

Hokkaido.pm #1

Page 40: Perl logging

Log::Dispatch::Config::Watcher 特徴

関数の実行状態 ( 時間、成否 ) を監視して、自動でログを出力する。特定の条件で警告ログを追加出力できる

フォーマットが拡張されていて、ナノセカンド単位の時間を表示したりできる

ひとつのアウトプット内で、条件に応じてフォーマットを切り替え可能。

warn と die を監視して、別フォーマットでログ出力できる。

欠点 Coro なら大丈夫だけど、 AnyEvent には対応していない。 重いかも。いや重い。

Hokkaido.pm #1

Page 41: Perl logging

利用例:コード部分 #1

use Log::Dispatch::Config::Watcher;use Log::Dispatch::Configurator::YAML;

my $config = Log::Dispatch::Configurator::YAML->new('/path/to/log.yaml');

Log::Dispatch::Config::Watcher->configure($config);my $log = Log::Dispatch::Config::Watcher->instance;

$log->info('log message');test1();test2();test3();

Hokkaido.pm #1

Page 42: Perl logging

利用例:コード部分 #2 ( つづき )

sub test1 { $log->warn('sample warning.'); sleep 4;}

# eval された diesub test2 { eval { die 'die with expected exception'; }; warn $@ if $@;}

# eval されてない diesub test3 { sleep 5; die 'die with unexpected exception.';}

Hokkaido.pm #1

Page 43: Perl logging

利用例:設定ファイル #1

dispatchers: - screenscreen: class: Log::Dispatch::Screen min_level: debug format: '[%p] %F:%L %m [%D{%F %T.

%6N%z}]' # DateTime::Format::Strptime newline: 1 stderr: 1

Hokkaido.pm #1

Page 44: Perl logging

利用例:設定ファイル #2 ( つづき )

watch: watch_die: 1 watch_only_unexpected_die: 1 watch_warn: 1 die_level: critical warn_level: warning formats: start: '[%p] START:%j [%D{%F %T.%6N%z}]' end: '[%p] END:%j(%t) [%D{%F %T.%6N%z}]' end_with_die: '[%p] ABNORMALLY_ENDED:%j(%e) [%D{%F %T.

%6N%z}]' die: '[%p] UNEXPECTED_DIE (%e) [%D{%F %T.%6N%z}]' warn: '[%p] PERL_WARNING (%e) [%D{%F %T.%6N%z}]' timeover: '[%p] TIMEOVER:%j(%t)‘

%j … 関数の詳細説明%t … 関数の実行時間%e … 警告メッセージ

Hokkaido.pm #1

Page 45: Perl logging

利用例:設定ファイル #3 ( つづき )

watch: ~ #2 参照 ( 略 ) ~ functions: main::test1 # パッケージ名に注意 description: sleep 4 seconds process warn_duration: 5.0 # 秒数を指定 notice_duration: 3.5 main::test3: description: sleep 5 seconds process warn_duration: 4.0 notice_duration: 2.5

Hokkaido.pm #1

Page 46: Perl logging

実行結果

素の $log->info()[info] ./log.pl:13 log message [2010-07-30 15:34:16.316215+0900]

監視対象 : test1() warn → sleep 4;[info] START:"sleep 4 seconds process" [2010-07-30 15:34:16.319123+0900][warn] ./log.pl:19 sample warning. [2010-07-30 15:34:16.320854+0900][notice] TIMEOVER:"sleep 4 seconds process"(=>00:00:04.005179167)[info] END:"sleep 4 seconds process"(=>00:00:04.005179167) [2010-07-30

15:34:20.324692+0900]

非監視対象 : test2() eval された die[warning] PERL_WARNING (die with expected exception at ./log.pl line 25.)

監視対象 :test3() eval されない die[info] START:"sleep 5 seconds process" [2010-07-30 15:34:25.328754+0900][warning] TIMEOVER:"sleep 5 seconds process"(=>00:00:05.00351812)[critical] ABNORMALLY_ENDED:"sleep 5 seconds process"(die with

unexpected exception. at ./log.pl line 30.) [2010-07-30 15:34:25.330754+0900]

Hokkaido.pm #1

Page 47: Perl logging

拡張方法 #1 フック

create_instance のオーバーライド インスタンス生成時、設定ファイルの更新時に実行されるメ

ソッド

Hook::LexWrap を利用してメソッドの起動と終了をフックする

$SIG{__DIE__} 、 $SIG{__WARN__} で die 、 warn をフックする

同一Output クラス内でのフォーマット書き換えを実現するため、フォーマットのバックアップ→出力→フォーマットのリシュームを行う

Hokkaido.pm #1

Page 48: Perl logging

拡張方法 #2 拡張書式

format_to_cb のオーバーライド ログメッセージの生成時に実行されるメソッド

DateTime 、 DateTime::HiRes 、 DateTime::Format::Strptime などを利用して複雑な時刻書式に対応させる

正規表現でパースしているので、その部分を拡張して、拡張フォーマットに対応させる

ソースをコピーして上書きするという美しくない拡張Hokkaido.pm #1

Page 49: Perl logging

補足など

インストール$ cpanf –m Log::Dispatch::Config::Watcher$ cpanf –mdi Log::Dispatch::Config::Watcher

欠点 main パッケージのメソッドにも main:: が必要 拡張方法が美しくない $SIG{__WARN__} 書き換えによる不具合とか起こりそう ( たぶん )重い

バグ報告、パッチ、要望など http://github.com/keroyonn/p5-Log-Dispatch-Config-Watcher http://rt.cpan.org/ [email protected]

Hokkaido.pm #1

Page 50: Perl logging

まとめ

Perl は意外に約束事が多い PerlMonger じゃない人には丁寧に教えてあげよう

CPAN には良いログモジュールがある プロジェクト単位でログモジュールを自作してしまう前に、ちゃんと検討しよう

特別な事情がなければ、汎用性のある CPAN モジュールを使おう

CPAN のモジュールは拡張性が高い 業務要件を満たせない場合には、薄いラッパーを作ってみる

のもいいけど、モジュールの拡張にもチャレンジしてみよう

Hokkaido.pm #1

Page 51: Perl logging

ご清聴ありがとうございました

Hokkaido.pm #1