#fluentd でアクセスログからメトリクス生成/リアルタイム監視するための設定例
このエントリは ウィークリーFluentdユースケースエントリリレー の参加エントリです。
いろいろアレでアレなときに回ってきて新ネタを思い付く余裕がないので、手元の設定を晒して解説しお茶を濁そうと思います。ユースケース！
前提は以下の通り。
- アクセスログ
- ping message
- Flow count
- いくつかのFluentdプロセスについては、それらが処理しているメッセージ数を flowcounter で集計して結果をこのサーバに送っている
- 単純に GrowthForecast でグラフ化する
で、このFluentdプロセス(1プロセス、冗長化のために2サーバ使用、通常は primary 側のみに送信)で使っている設定ファイルはこちら。これをパーツごとに解説していく。
https://gist.github.com/3971251
解説前に全体像をさくっと図にしてみるかー、と思ってやってみたらこんなになった。(クリックで拡大)
この図で、HostName および Service はそのままWebサーバやFluentdのホスト名、およびWebサービスのサービス名が入る。N はサンプリングされたログについてのサンプリングレートを示すもので sampled.100 だったら 1/100 のレートでサンプリングされたログ、ということ。input pluginは in_forward しかない。output plugin の out_ はすべて省略してある。
ちなみに数種類のFluentdクラスタで構成されるネットワーク全図が以下のような感じで、その右下の色つきの部分が今回ご説明の範囲。
ではいってみよう！ なお in_forward については省略。24224でlistenしてるだけだし。
こまごましたものから
flowcounter
先頭に書いてある。
# output to growthforecast directly (none to process about flowcount.**) <match flowcount.**> type growthforecast gfapi_url http://gf.local/api/ service analysis section workers name_keys count,bytes,count_rate,bytes_rate remove_prefix flowcount tag_for name_prefix </match>
単に flowcounter が出力してきたものがやってくるので、必要な項目をGrowthForecastにぶちこんでグラフ化してます。それだけ。
ping message
次はいきなり一番下。
## ping messages
<match ping.**>
type copy
<store>
type ping_message_checker
tag missing.ping
notifications __IS_PRIMARY__
</store>
<store>
type file_alternative
path /var/log/fluentd/ping.%Y%m.log
flush_interval 1s
localtime
output_include_time true
output_include_tag false
output_data_type attr:data
</store>
</match>
## ping missing notification output (to IRC)
<match missing.ping>
type ikachan
host ikachan.local
port 80
channel admin
out_keys data
message Fluentd node down(ping missing): %s
</match>ping.HostName なタグのメッセージcopyプラグインにかけ、ping_messsage_checker での欠落チェック、および file_alternative でのファイル書き出しを行っている。
file_alternative での書き出しは、どのホストからpingが飛んできているか書き込んでおくことでfluentd*1が起動しているサーバの一覧を作るため。普段から作っているわけではないけど、一覧がほしくなったらここから取り出す。
ping_message_checker は notifications __IS_PRIMARY__ に注目。じつはサーバに設定をデプロイするとき、デプロイ先ホストに応じてここが true になったり false になったりする。この設定をデプロイするサーバは primary と スタンバイ用の secondary で2台ある(両方とも常時 fluentd は起動している)んだけど、たまに primary への UDP heartbeat パケットが落ちて secondary にメッセージが飛ぶときがある。 ping message checker は一度やってきたメッセージのホスト名を覚えていて欠落したときには notification を出すんだけど、secondary にたまたま(primaryが生きてるのに)飛んじゃった ping メッセージのせいで延々警告を出されてはたまらない。なので、secondary のサーバではこれを false にして、ping message の欠落については警告を出さないようにしている。
後半は ping_message_checker が出す警告をIRCに書き込むため ikachan に出力する設定。そのままですね。
アクセスログ
入力の分岐
このサーバで出力しているメトリクスは以下の4種類、ステータスコード種別毎の割合、リファラに対するカウント、レスポンスタイム統計値、レスポンスタイム範囲毎の割合。これらに使うため、最初に out_route を用いて分岐する。
なお out_route はFluentdに入っておらず rubygem として公開もされていない frsyuki 製のもの。適当な場所に置いて Fluentd 起動時に読み込ませる必要がある*2。
分岐は以下の設定で行う。なお 10 と入っているところはサンプリングレートで、実際にはサンプリングレート別に3種類書いてある。
<match sampled.10.*>
type route
remove_tag_prefix sampled.10
<route serviceA,serviceB>
add_tag_prefix referer.count.10
copy
</route>
<route *>
add_tag_prefix httpstatus.count.10
copy
</route>
<route *>
add_tag_prefix responsetime.monitor.10
copy
</route>
<route *>
add_tag_prefix responsetime.count.10
copy
</route>
</match>リファラのカウントは特定サービスでしか行わないのでそれを最初に列挙している。あとは普通に、この後に行う処理ごとに tag prefix をつけているだけ。
リファラのカウント
分岐したなかから、まずリファラをカウントする。カウント対象のパターンは必要なぶんだけ列挙する。
### referer counting <match referer.count.10.*> type datacounter tag 10.datacount.referer aggregate tag input_tag_remove_prefix referer.count.10 count_key referer pattern1 yahoo ^https?://[-.a-zA-Z0-9]+\.yahoo\.co(m|\.jp)(/|$) # pattern2 .... </match>
とりあえず 10 のものしか対象になかったので forest はかましてない*3。まあ内容としてはカウントして流すだけ。
注意すべきなのは、ここでのカウントは1/10でサンプリングされたあとの数値なので、カウント数やカウントレートも 1/10 になっている、ということ。これはあとで amplifier_filter を使って復元する。ここで(この後のものも)サンプリングレートをタグの先頭に持ってきている、のは後で amplifier_filter で処理して remove_prefix すれば本来のタグに戻せるように。
HTTPステータスの割合毎のカウント
### HTTP status counting
<match httpstatus.count.**>
type forest
subtype datacounter
remove_prefix httpstatus.count
<template>
unit minute
output_per_tag yes
aggregate tag
output_messages yes
count_key status
pattern1 2xx ^2\d\d
pattern2 3xx ^3\d\d
pattern3 429 ^429
pattern4 4xx ^4\d\d
pattern5 5xx ^5\d\d
</template>
<case 1.*>
tag_prefix datacount.httpstatus
input_tag_remove_prefix 1
</case>
<case 10.*>
tag_prefix 10.datacount.httpstatus
input_tag_remove_prefix 10
</case>
<case 100.*>
tag_prefix 100.datacount.httpstatus
input_tag_remove_prefix 100
</case>
</match>ステータスの種類毎にカウント。サンプリングレート毎に出力時に出すタグのprefixを変える必要があるので forest を使っている。
また429だけ分けてカウントしているのは Apache mod_dosdetector で検出した際のステータスコードを 429 にし、これをリアルタイム障害検知の4xxの対象から外すため。あまり大きくないサービスだと1人が429を垂れ流しただけで通知が上がりまくってひどいことになるのでこのようにしている。
なお counter 系ではこの設定でだけ output_per_tag yes している。こうすることでサービス名をタグに含めることが可能になる。なぜこうしているかというと、後から notifier で障害検出をやるときに特定のサービスだけを対象から外したいから。
レスポンスタイム統計値出力
### response time aggregation
<match responsetime.monitor.**>
type forest
subtype numeric_monitor
remove_prefix responsetime.monitor
<template>
unit minute
tag monitor.responsetime
aggregate tag
monitor_key duration
percentiles 50,90,95,98,99
</template>
<case 1.*>
input_tag_remove_prefix 1
</case>
<case 10.*>
input_tag_remove_prefix 10
</case>
<case 100.*>
input_tag_remove_prefix 100
</case>
</match>レスポンスタイムについて、分単位で平均/最小/最大および50,90,95,98,99の各パーセンタイル値を出力。
これは入力はサンプリングレート毎に tag prefix が異なるため forest を使っているが、出力については(実数カウントではなく統計値なので)特にサンプリングレート毎に分ける必要はない。
レスポンスタイム毎の割合
### response time counting
<match responsetime.count.**>
type forest
subtype numeric_counter
remove_prefix responsetime.count
<template>
unit minute
aggregate tag
count_key duration
pattern1 u100ms 0 100000
pattern2 u500ms 100000 500000
pattern3 u1s 500000 1000000
pattern4 u3s 1000000 3000000
pattern5 long 3000000
</template>
<case 1.*>
tag numcount.responsetime
input_tag_remove_prefix 1
</case>
<case 10.*>
tag 10.numcount.responsetime
input_tag_remove_prefix 10
</case>
<case 100.*>
tag 100.numcount.responsetime
input_tag_remove_prefix 100
</case>
</match>レスポンスタイム毎の割合を時間範囲毎にカウント。カウントしたメッセージ数(実数)も出力されるのでサンプリングレートを tag prefix に付けて出す。
サンプリング済みログからの出力結果の補正
amplifier_filter を使い、サンプリング済み数値を本来の数値に補正して出力、tag prefix からサンプリングレートを除去する。
### amplifying sampling data counting numerics <match 10.datacount.**> type amplifier_filter ratio 10 remove_prefix 10 key_pattern .*_(count|rate)$ </match> <match 100.datacount.**> type amplifier_filter ratio 100 remove_prefix 100 key_pattern .*_(count|rate)$ </match> <match 10.numcount.**> type amplifier_filter ratio 10 remove_prefix 10 key_pattern .*_(count|rate)$ </match> <match 100.numcount.**> type amplifier_filter ratio 100 remove_prefix 100 key_pattern .*_(count|rate)$ </match>
なお datacounter / numeric_counter は *_count, *_rate のほかに *_percentage もあるが、パーセンテージはサンプリングされていても割合は変わらないので補正対象にはしない。
各メトリクスメッセージのルーティング
ここまでで必要な各メトリクスの数値はできているが、これを最終的にどこに出力するかを決めるため再度 out_route にかける。
### output routing into growthforecast and notification generation
<match datacount.httpstatus.**>
type route
remove_tag_prefix datacount
<route **>
add_tag_prefix gf
copy
</route>
<route **>
add_tag_prefix notify
copy
</route>
</match>その後でかける処理によって gf. とか notify. とかprefixをつける形。HTTPステータスはGrowthForecastへのグラフ出力、および4xx/5xxの割合でのリアルタイム障害検出・通知を行うのでこの2つへ分岐する。
これと同様のものが referer, responsetime (monitor/numcount) にもある、が、それらは growthforecast への出力だけしか行わない、が、将来的に配送先が増えることも考えられるので out_route をかまして gf. を付けるようにしている。設定の拡張性は大事ですよ。
GrowthForecastでグラフ出力
### growthforecast output settings
<match gf.httpstatus.**>
type growthforecast
gfapi_url http://gf.local/api/
service accesslog
section httpstatus
tag_for name_prefix
remove_prefix gf.httpstatus
name_key_pattern .*_(rate|percentage)$
</match>
<match gf.{referer,responsetime}>
type forest
subtype growthforecast
<template>
gfapi_url http://gf.local/api/
service accesslog
tag_for section
</template>
<case gf.referer>
remove_prefix gf
name_key_pattern .*_rate$
</case>
<case gf.responsetime>
remove_prefix gf
name_key_pattern .*_(percentage|min|max|avg|percentile_\d+)$
</case>
</match>おなじみ out_growthforecast でグラフ出力する。httpstatusはタグにサービス名が埋まっているので他とすこし設定が違うからそのように分けてある。まあみんな GrowthForecast は使ってるから解説はきっといらないはず。
リアルタイム障害検出・通知
HTTPステータスコード毎の割合を見てアラートを上げる設定。ここではステータスコード500番台が返る割合が 11% 以上の場合に警告、30%以上でクリティカル、としている。また400番台も見ていて50%以上で警告、75%以上でクリティカル。
バグのあるコードを気付かずにデプロイしてしまった場合などに大変お役立ちなので、みなさんもぜひこの設定はすると良いと思います。
## generate notifications
<match notify.httpstatus.**>
type notifier
default_tag notification.httpstatus
input_tag_remove_prefix notify.httpstatus
<test>
check numeric
target_key messages
lower_threshold 10
</test>
<test>
check tag
exclude_pattern ^internal-proxy$
</test>
<def>
pattern status_5xx
check numeric_upward
target_key_pattern ^5xx_percentage$
warn_threshold 11
crit_threshold 30
</def>
<def>
pattern status_4xx
check numeric_upward
target_key_pattern ^4xx_percentage$
warn_threshold 50
crit_threshold 75
</def>
</match>
## notification output (to IRC)
<match notification.httpstatus>
type ikachan
host ikachan.local
port 80
channel sysadg
out_keys pattern,level,message_time,target_tag,value,threshold,target_tag,target_key
message HTTP %s %s [%s] %s: %s (threshold %s) http://gf.local/view_graph/accesslog/httpstatus/%s_%s
</match>out_notifier で検出して out_ikachan でIRCに通知させている。
out_notifier は
またもうひとつの test ディレクティブでは特定のサービス(社内用プロキシ)をチェックの対象外にしている。403/404 や 500 系もよく発生するし、実質的にはあまり監視の必要がないため。
出力値はそのままIRCへ。ちょっと便利なポイントとして、IRCへの通知メッセージに対応するGrowthForecastのグラフURLを入れてある。IRCクライアント上でURLをクリックすればすぐ時系列で確認できるように。
まとめ
長い！ あとだいぶ複雑だけど、まあ頑張ればこのくらいはできる。
あと設定ファイル中には例外ケースを除いてサービス名をいっさい書いていないのもわかると思う。このため、新しいサービスのログを流すようになってもfluentdの設定変更はいっさいしなくていいようになっている。こういう状況に最初にしておくと運用が大変ラクちん。
これをそのままコピペしてサンプリング済みログを流せばいろいろとはかどるような気もするので、みなさんぜひ挑戦してみてください。頑張れ！
