nDiki

2004年3月2日 (火)

■ [ Perl ] Log::Log4perlのはまりどころ

WiKicker / DiKicker の Log::Log4perl 対応作業。

www.naney.org は Apache の VirtualHost としてエラーログも個別に吐かれている
エラーログは自分のホームディレクトリに吐かれるものの、root 所有である
ディレクトリは自分に所有権があり、エラーログが肥大化したら消す事もできるのだが、Apache をリスタートする権利がないので(週に1度のシステム側のローテーションが起きるまで)二度とエラーログが見れなくなる。

ということで、warn -> Apache のエラーログに流れている警告メッセージも、Log::Log4perl の方に流して、好きに消せるようにしておくことにする。

@ Log::Log4perl->init_once

SpeedyCGI 下で動かす事を想定して初期化は、init_once で行うようにする。可能な限り早く初期化すべきなので、設定ファイル名/設定文字列はプロパティファイルに記述しておくのではなく、CGI プログラムで最初に生成する Controller オブジェクトの初期化パラメータで指定するように。

@ $SIG{WARN} を設定

$SIG{__WARN__}を設定して、warn のメッセージを Log::Log4perl に送る。最初はほぼ FAQ の例のまま、以下のように記述。

 use Log::Log4perl qw(:easy);
 BEGIN {
   $::SIG{__WARN__} = sub {
     local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
     WARN(@_);
   };
 }

しかし期待していた通りに動かず悩む。原因は前述する init_once との絡み。 use Log::Log4perl qw(:easy) した時点でデフォルトの初期化が行われてしまうため、初期化済みになってしまって init_once での設定処理がスキップされていたのが問題。

 use Log::Log4perl;
 BEGIN {
   $::SIG{__WARN__} = sub {
     local $Log::Log4perl::caller_depth = $Log::Log4perl::caller_depth + 1;
     if (Log::Log4perl->initialized) {
       Log::Log4perl->get_logger->warn(@_);
     }
   };
 }

と修正。 get_logger も暗黙的に初期化を行うので、init_once する前に warn されるとやはりデフォルトの初期化がおこってしまう。それではまずいので initialized が真(=初期化済み)の時のみロギングするようにする。ただしこれだと init_once する前の warn メッセージが失なわれる(STDERR あたりに print するようにすればいいかもしれない)。

@ CGI::Carpとの絡み

CGI::Carp も $SIG{__WARN__} を上書きするので同時に使えない。以前に use していたのが残っていてはまる。

@ Log::Log4perl::Appender::Synchronized で core dump ?

NaneyOrgWiki、nDiki でロギングしはじめたところ、CGI プログラムの処理はきちんと成功しているもののその後(?) speedy_backend が core dump してしまう事があるようだ。最初は $::SIG{__WARN__} の設定あたりに問題があるのかと思ったが、Log::Log4perl::Appender::Synchronized を使わないようにしたところ core を吐かなくなった。

IPC::Shareable、IPC::Semaphoreなんて使っているしやっぱりこれが怪しい。とりあえず外しておくことにする。

しかし何らかの方法でシンクロしておかないとログファイルが壊れるはずだから、本当はどうにかしなければならないな。もっと簡単に flock とかで排他制御する Appender とか無いのかな。自分で書くしかない?