Post on 11-Jun-2015
Perl ロギングprint から Log::Dispatch の拡張まで
2010/08/07 Hokkaido.pm #1By keroyon@cpan.org
Hokkaido.pm #1
概略
ログのあれこれについて語ります。
対象は Perl 入門者です。※ 後半は初級者向けかも
何でログなのか 必須知識の割には、あまり言及されないみたいなので。
※ 定番サイト、定番本、グーグルで全滅 ログ吐く方法すら分からないとあっては、 Perl 採用への道が遠退き
そうなので。
内容 ログ出力のための Perl の基礎知識 モジュールを使ったログ出力 業務要件に合わせたモジュールの拡張
Hokkaido.pm #1
Perl ロギング その 1“ 面倒な”前提知識を再確認
Hokkaido.pm #1
モジュールを使わないでやってみる
debug レベル[ 変数の確認とか ]
Hokkaido.pm #1
プリント文デバッグは永劫不滅です
use utf8;BEGIN { binmode STDOUT, ':utf8'; }my $hoge = 'hoge';print "hoge は '${hoge}' です \n";↓hoge は 'hoge' です
※ デバッガは lvalue に関するバグがあるよ !
Hokkaido.pm #1
Data::Dumper はちょっと不便
use utf8;use Data::Dumper;BEGIN { binmode STDOUT, ':utf8'; }my $hoge = { key => ' 値 ' };print Dumper($hoge);↓$VAR1 = { 'key' => "\x{5024}"};
Hokkaido.pm #1
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
info レベル[ 進捗の確認とか ]
Hokkaido.pm #1
処理の終了と開始とか
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
warning レベル[ 不穏な動きを警告 ]
Hokkaido.pm #1
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
error/critical レベル[ 断末魔の処理 ]
Hokkaido.pm #1
exit die croak
exit 1; errono を直指定。何を言ってるのか分かりづらい ジョブネット組む時に使ったりする
die " うぎゃぁ ~ 。銃でやられた ! "; 原因が分かりやすい。単に die すると 255 で固定
croak " やられた ! かくかくしかじか "; 死んだ経緯をしゃべる。スタックトレースつき
Hokkaido.pm #1
終了ステータスの変更:$SIG{__DIE__}
捕捉してフックする$SIG{__DIE__} = sub {
my $error = shift;if ($error =~ m{^hello}xms) {
$! = 100;}die $error;
};
Hokkaido.pm #1
終了ステータスの変更: $ERRNO
$! = 100;die ' 死亡… ';
use English qw(-no_match_vars);$ERRNO = 100;die ' 死亡… ';
※ -no_match_vars をつけないと Damian 先生に怒られるよ !
Hokkaido.pm #1
Perl ロギング その 2Log::Dispatch::* の利用
Hokkaido.pm #1
Log::Dispatch
Hokkaido.pm #1
Log::Distach とは
ログの出力先を、標準エラー / ファイル / メール /DB/Syslog/Twitter などに自在に切り替えられる
簡単に拡張ができるように設計されている ↓ 拡張モジュールが豊富
$ cpanp m ^Log::Dispatch::50 個以上ヒット !miyagawa 氏の名前とかもある
Hokkaido.pm #1
簡単な例:とりあえずファイルに
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
簡単な例:標準エラーに追加
$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
Log::Dispatch::Config
Hokkaido.pm #1
Log::Dispatch::Config とは Log::Dispatch のサブクラス
(miyagawa プロダクト )
ログ設定を別ファイルに分離できる
出力書式を自由に設定できる$log->debug('[debug] デバッグ情報 [' .
Time::Piece::localtime->cdate . ']');↓ シンプル !
[%p] %m [%d]$log->debug(' デバッグ情報 ')
設定ファイルの形式は、 YAML 、 INI ファイルなどから選べる
Hokkaido.pm #1
コード部分
初期化は、 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
設定ファイル (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
Log::WarnDie
Hokkaido.pm #1
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
簡単な例
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
Perl ロギング その 3Log::Dispatch::* の拡張
Hokkaido.pm #1
Log::Dispatch::* の拡張 #1Log::Dispatch::Email:*を拡張してみよう
Hokkaido.pm #1
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
Log::Dispatch::Email::EmailSender
モダンなメール送信クラス Email::EmailSender を利用してメールを送る
エンコードを指定できるので文字化けしない
Email::EmailSender::Transport::Sendmail の他に、 Email::EmailSender::Transport::SMTP にも対応させる
L::D::Email を継承して、 send_email メソッドをオーバーライドすれば完了
Hokkaido.pm #1
コンストラクタ: %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
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
_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
使い方: 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 => 'logger@example.com', to => [ qw( foo@example.com bar@example.org ) ], subject => 'Big error!', header_encode => 'MIME-Header-ISO_2022_JP', body_encode => 'iso-2022-jp‘ )
);$log->emerg("Something bad is happening");
Hokkaido.pm #1
使い方: SMTP
Log::Dispatch::Email::EmailSender->new( min_level => 'emerg', from => 'logger@example.com', to => [ qw( foo@example.com bar@example.org ) ], 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
補足など
インストール$ 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/ keroyon@cpan.org
Hokkaido.pm #1
Log::Dispatch::* の拡張 #2Log::Dispatch::Configを拡張してみよう
Hokkaido.pm #1
こんなことありませんか?
処理速度の傾向を把握したい バッチ処理で、目標とする処理時間がある ランダムなデータでは目標をクリアしているが、実データで実
際どうなるか分からない サービスイン当初はいいが、データ増大と共に重くなるため処
理時間の監視が必要 プロファイルの前に原因箇所にあたりをつけておきたい
捕捉し切れていない例外が総合テストで明らかになって、ふと大丈夫か不安になる
Perl の警告とプログラムの警告ログが別管理されていて、うっかり片方のチェックを忘れてしまう
Hokkaido.pm #1
Log::Dispatch::Config::Watcher 特徴
関数の実行状態 ( 時間、成否 ) を監視して、自動でログを出力する。特定の条件で警告ログを追加出力できる
フォーマットが拡張されていて、ナノセカンド単位の時間を表示したりできる
ひとつのアウトプット内で、条件に応じてフォーマットを切り替え可能。
warn と die を監視して、別フォーマットでログ出力できる。
欠点 Coro なら大丈夫だけど、 AnyEvent には対応していない。 重いかも。いや重い。
Hokkaido.pm #1
利用例:コード部分 #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
利用例:コード部分 #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
利用例:設定ファイル #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
利用例:設定ファイル #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
利用例:設定ファイル #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
実行結果
素の $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
拡張方法 #1 フック
create_instance のオーバーライド インスタンス生成時、設定ファイルの更新時に実行されるメ
ソッド
Hook::LexWrap を利用してメソッドの起動と終了をフックする
$SIG{__DIE__} 、 $SIG{__WARN__} で die 、 warn をフックする
同一Output クラス内でのフォーマット書き換えを実現するため、フォーマットのバックアップ→出力→フォーマットのリシュームを行う
Hokkaido.pm #1
拡張方法 #2 拡張書式
format_to_cb のオーバーライド ログメッセージの生成時に実行されるメソッド
DateTime 、 DateTime::HiRes 、 DateTime::Format::Strptime などを利用して複雑な時刻書式に対応させる
正規表現でパースしているので、その部分を拡張して、拡張フォーマットに対応させる
ソースをコピーして上書きするという美しくない拡張Hokkaido.pm #1
補足など
インストール$ 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/ keroyon@cpan.org
Hokkaido.pm #1
まとめ
Perl は意外に約束事が多い PerlMonger じゃない人には丁寧に教えてあげよう
CPAN には良いログモジュールがある プロジェクト単位でログモジュールを自作してしまう前に、ちゃんと検討しよう
特別な事情がなければ、汎用性のある CPAN モジュールを使おう
CPAN のモジュールは拡張性が高い 業務要件を満たせない場合には、薄いラッパーを作ってみる
のもいいけど、モジュールの拡張にもチャレンジしてみよう
Hokkaido.pm #1
ご清聴ありがとうございました
Hokkaido.pm #1