追記
CPANにアップしました
http://search.cpan.org/dist/Log-Minimal/
/追記

アプリケーションサーバでエラーが起きていたり、レスポンスが遅かったりする場合に、Operation Engineer(インフラエンジニア)がまず見るのは、エラーログです。エラーログにでているメッセージを手がかりに原因を探ります。

サーバでエラーが起きている時には、データベースに接続ができなかったり、外部のAPIからレスポンスが得られない、またプログラムのBugが原因となっている場合もあるでしょう。またエラーにならなくても、複数台あるデータベースのスレーブサーバうち一台が落ちて接続をretryしていたり、APIのレスポンスが遅い際にはサーバ全体のパフォーマンスが低下します。

エラーログに障害の原因を探る情報があれば、Operation Engineerは素早く対応を開始できます。逆にエラーログに何も表示されていなければ、ソースコードを追ったり、tcpdumpやstrace、gdbでトレースしなければ原因の特定ができず、対応がどんどん遅れて行きます。ログはアプリケーションを実装するエンジニアとOperation Engineerを結ぶ媒体であり、コミュニケーション手段なのです。

コミュニケーションを円滑にするためはいくつかのプロトコル・制約を決めておくのが定石です。よく使われるのは、ログに残すメッセージに重要度によってレベルをつけることです。DEBUG、INFO、WARN、CRITICALなどのレベルはエンジニアならだれでも見たことがあるはずです。数多く出力されるログから運用ではWARNやCRTICALレベルのメッセージを中心に見れば良くなります。またメッセージがいつ発生したのかの日付情報、加えてどのソースコードで発生したのかの場所についての情報も付属していると障害の原因を追いやすく、またアプリケーションエンジニアとのコミュニケーションも「いつどこそこの何行目でほげほげというエラーがでてる」と具体的に場所を示すことができ、調査に向けての協力も円滑に行うことができます。

つまり何が言いたいかと言うと「アプリケーションからのログを出してください。仕事するのでお願いします」ということです。と、ここまでが前書きで、ログを書き出すための小さいモジュールを書いてみましたので、紹介します。

書いたのはLog::Minimalというモジュールです。まだgithubにしかありません。使い方は

use Log::Minimal;

critf("%s","foo"); # 2010-10-20T00:25:17 [CRITICAL] foo at example.pl line 12
warnf("%d %s", 1, "foo");
infof("foo");
debugf("foo"); # print if $ENV{LM_DEBUG} is true

こんな感じです。crit、warn、info、debugに「f」がくっついたメソッドがExportされます。各メソッドでは引数が複数あった場合、1個目をprintfのフォーマットとして扱います。引数が1つの場合はそのまま出力されます。デフォルトの出力方法は「warn」です

出力方法を変更するには、$Log::Minimal::PRINTで指定します

my $app = sub {
    my $env = shift;
    local $Log::Minimal::PRINT = sub {
        my ( $time, $type, $message, $trace) = @_;
        $env->{psgi.errors}->print("$time [$env->{SCRIPT_NAME}] $type $message $trace\n");
    };
    run_app(....);
};

上記の例では、PSGIのError Streamに対して、ログを出力しますが、その際にリクエストのあったファイル名もログに出力します。こうすることでさらに障害があった際のトレーサビリティを向上させることができます。Gearmanなどのworkerでも同じように実行しているjob名や引数が出力されると便利だと思われます。また、ここでsyslogでログを飛ばしたり、Log::Dispatchに渡したりする処理を入れてもいいでしょう

加えて、crit、warn、info、debugに「ff」という様に「f」を2つつけると、Stacktraceも出力されるようになります。

critff("%s","foo");
# 2010-10-20T00:25:17 [CRITICAL] foo at lib/Example.pm line 10, example.pl line 12

こんな感じに出力されます。

CPANにはLog系のモジュールはたくさんあるのだが、おなじぐらい簡単なジュールは既にあるのかなぁ。

このブログ記事について

このページは、Masahiro Naganoが2010年10月21日 00:10に書いたブログ記事です。

ひとつ前のブログ記事は「There's more than one way to enjoy YAPC! / YAPC::Asia 2010感想」です。

次のブログ記事は「「鉄おも!」という雑誌がすばらしい」です。

最近のコンテンツはインデックスページで見られます。過去に書かれたものはアーカイブのページで見られます。

ウェブページ

OpenID対応しています OpenIDについて
Powered by Movable Type 4.27-ja