読者です 読者をやめる 読者になる 読者になる

たごもりすメモ

コードとかその他の話とか。

#fluentd でアクセスログからメトリクス生成/リアルタイム監視するための設定例

fluent

このエントリは ウィークリーFluentdユースケースエントリリレー の参加エントリです。

いろいろアレでアレなときに回ってきて新ネタを思い付く余裕がないので、手元の設定を晒して解説しお茶を濁そうと思います。ユースケース

前提は以下の通り。

  • アクセスログ
    • このサーバに送られてくる前の段階で適当にparseされている(いちおう in_file の apache 互換の名前のはず?)
    • sampling_filter プラグインにより 1/1, 1/10, 1/100 それぞれの割合でサンプリングされている(基本は1/10)
    • いくつかのメトリクス計算を行い、それらをGrowthForecastへグラフ登録、一部のものはリアルタイム監視を行いIRC通知する
  • ping message
    • ping_message プラグイン(および fluent-agent-lite の -P オプション)による 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 は ... ディレクティブにより条件にマッチしたメッセージだけをチェックの対象にすることができる。ここでは datacounter プラグインが何件のメッセージから出力値を作成したかとして出力する messages を見て、1分間に10メッセージ以下しか流れてきていなかった場合にはチェックの対象外としている。これにより規模の小さいサービスの特に夜間帯など、実際のアクセスがほとんど無く、かつ検索エンジンのクローラなどが404を連発するようなケースで通知が発生してしまうのを抑制している。
またもうひとつの test ディレクティブでは特定のサービス(社内用プロキシ)をチェックの対象外にしている。403/404 や 500 系もよく発生するし、実質的にはあまり監視の必要がないため。

出力値はそのままIRCへ。ちょっと便利なポイントとして、IRCへの通知メッセージに対応するGrowthForecastのグラフURLを入れてある。IRCクライアント上でURLをクリックすればすぐ時系列で確認できるように。

まとめ

長い! あとだいぶ複雑だけど、まあ頑張ればこのくらいはできる。
あと設定ファイル中には例外ケースを除いてサービス名をいっさい書いていないのもわかると思う。このため、新しいサービスのログを流すようになってもfluentdの設定変更はいっさいしなくていいようになっている。こういう状況に最初にしておくと運用が大変ラクちん。

これをそのままコピペしてサンプリング済みログを流せばいろいろとはかどるような気もするので、みなさんぜひ挑戦してみてください。頑張れ!

*1:やfluent-agent-lite

*2:-p オプション

*3:1 や 100のものも増えるようなら forest をかまして 1/10/100 のそれぞれに処理する形になる、httpstatus のところ参照