Norikraでログ集計してアプリのエラーを素早く検知しようという話

背景

webアプリを書いていると，以下のようなロギングコードを至る所にちりばめる事になると思います．

$c->log(error => "Chou Yabai ERROR!");

ただいくらログを吐いても，アプリのログからは片時も目を話さないよ！！みたいな真面目なエンジニアじゃない限り，せっかく吐かれたログに気づけないとかあるわけです．そこで特に重要なログについては別途ikachanとかでIRC等にpostするコードを入れといて，即応できるようにしてることと思います．

でも，levelがerrorとかcriticalで吐かれてるログって全部重要だし全部すぐ知りたくね？それにいちいち別途ikachanするコードとか入れるのめんどくね？っていう需要があるわけです．そこでロガーメソッドにif ($level == 'error') { post_to_irc($message) }みたいなコードを仕込むことを考えるわけですが，これだともしアプリがバグってて，リクエスト毎にエラーが出る，みたいな状況だと，完全にSPAMになってしまうわけですね．

対策

なので，最近私が書いてるアプリで試しているのが，アプリのログをサマライズして通知する方法です．

私が普段仕事をしている環境には幸いなことにすごいオペレーションエンジニアの人が居て，fluentdクラスタが整備されているため，アプリケーション内のロガーメソッドに以下のようなコードを仕込む事ができます．

$fluent_logger->post('proj.applog', {
    level   => $level, # 'info', 'error', 'critical' ...
    host    => $host,  # hostname of this app working on
    file    => $file,
    line    => $line,
    message => $message,
});

こうしておくことで，アプリケーションのログが全てfluentdに溜め込まれます．

重ねて幸いなことに，このfluentdに溜められたログはNorikraというCEPサーバから参照できるようになっているので，以下のようなSQLっぽいクエリでリアルタイムに集計ができます．

SELECT level, file, line, LAST(host) AS host,
       LAST(message) AS message, COUNT(*) AS count
FROM proj_applog.win:time_batch(5 min)
WHERE level = 'error' OR level = 'critical'
GROUP BY level, file, line

このクエリをNorikraに登録しておくと，level，file，lineが同じログをまとめてカウントし，5分毎に結果をストアしてくれます．ログが吐かれたレベル，ファイル，行が同じであれば，ログの内容は同じようなものであると仮定できるので，messageの内容に変数が含まれていても同じような内容のログを纏められるわけです． messageの内容については代表としてどれか1つが伝われば良い(どうせ詳細はファイルのログ見にいくし)ので，LAST()関数で最後の一つを選択するようにしています．

あとは，cronで5分置きに集計結果をfetchしてIRCにpostするスクリプトを仕込んでおけば，IRCを汚す事なくサマライズされたエラーログ通知が得られるというわけですね．

実装

以下は実際に私が使っているスクリプトです．どういうクエリで集計した結果なのかが分かった方が良いと思うので，スクリプト内にSQLを書いて，./norikra-error-notify.pl registerのように実行された場合に，クエリを登録するようにしています．

#!/usr/bin/env perl
use strict;
use warnings;
use Norikra::Client;
use Proj; # Project class

my $IntervalMinutes = 5;

my $c = Proj->bootstrap;
my $norikra = Norikra::Client->new('norikra.server.address', 26571);

my $group = 'proj';
my $query_name = "${group}_errors_in_${IntervalMinutes}min";

if (@ARGV && $ARGV[0] eq 'register') {
    # For one time registration
    $norikra->register($query_name, $group, qq{
      SELECT level, file, line, LAST(host) AS host,
             LAST(message) AS message, COUNT(*) AS count
      FROM proj_applog.win:time_batch($IntervalMinutes min)
      WHERE level = 'error' OR level = 'critical'
      GROUP BY level, file, line
    });
    exit 0;
}

my $events = $norikra->event($query_name);
for my $event (@$events) {
    my ($time, $log) = @$event;
    next if $log->{count} == 0;
    my $level = uc($log->{level});
    my $msg = "[proj][$ENV{PLACK_ENV}][$log->{host}][$level]"
             ." $log->{message} at $log->{file} line $log->{line}";
    if ($log->{count} > 1) {
        my $count = $log->{count} - 1;
        $msg .= " ... and $count more similar log in this $IntervalMinutes minutes";
    }
    $c->ikachan($msg); # post to IRC via ikachan
}

まとめ

ログは吐くだけじゃ意味ないからちゃんと活用しようぜという話でした．アプリの吐くすべてのログが対象になるので，最長5分以内でアプリの異常が知れてかなりイイ感じです．

あとNorikraはあらかじめクエリを登録しておくだけで，設定したタイムウィンドウで勝手に集計しておいてくれるので，event fetchの処理は本当に一瞬です．1分間隔での集計とか余裕(というかリアルタイム処理が売り)なので，これまでHadoop + Hiveとかで定期実行してた集計処理があるけど，時間かかるので1時間に1回が限界だったけど本当は1分毎に結果欲しいんだ！みたいな悩みがある人は，Norikraを試してみるといいと思いました．