2013年03月

fluentdを使ったログ監視 〜 Haikanko OSS化への道(3)

こんにちは @sonots です。ちょっと間が空いてしまいましたが、Haikanko OSS化への道と称した Fluentd 連載第三回です。過去の記事はこちら
今回は Haikanko が提供する1つのフィーチャー(SIer 的に言うソリューション!)であるログ監視の機能についてお話したいと思います。


続きを読む

fluent-agent-lite と fluentd agent の比較(2) 〜 Haikanko OSS化への道(2)

fluent-agent-lite と fluentd agent の比較(1) 〜 Haikanko OSS化への道(2) の続きです。

flushのタイミングは?

fluent-agen-lite の場合

コードを追いながら ^ ^;

まず前提として fluent-agent-lite はログの監視に tail -F コマンドを利用しています。
fluent-agent-lite#L123
fluent-agent-lite#L175

ログが出力されると-b BUFF_SIZE オプションで指定したバイト数(デフォルト1MB)を超えるまで、ログ内容を読み込んで flush するようです。
AgentLite.pm#L187
AgentLite.pm#L132

BUFF_SIZE に達する前にファイルの末尾に達した場合は、その時点で flush します。(コード的には読み込みループを抜けている)
AgentLite.pm#L190

tail -F なので、ファイルになんらかの入力があった場合に、イベントドリブン的に内容が読み込まれ、即座に flush される挙動となるようです。

送信に失敗したデータは捨てます
AgentLite.pm#L151

送信に失敗した場合はSEND_RETRY_MAX(4回)リトライを試みて(追記: 受け取り側の fluentd が落ちているなどの理由で syswrite で例外が発生した場合はリトライせずにループを抜けます。多くの失敗ではこちらの挙動になりそうです
AgentLite.pm#L300

それでも失敗した場合は、次の送信に回します(コード的には last で次のループに移るので $pending_packed がリセットされずそのまま)
AgentLite.pm#L151

また、TCPとしても、ローカルのTCPスタックが再送を試みているはずです。再送設定は
/proc/sys/net/ipv4/tcp_retries1
/proc/sys/net/ipv4/tcp_retries2
などで確認できます。こちらが参考になります。手元の環境だとそれぞれ 3, 15 でしたね。

fluentd out_foward の場合

buffer_chunk_limit (デフォルト8MB)を超えるか flush_interval (デフォルト60s) がすぎると flush されます。
cf. http://d.hatena.ne.jp/tagomoris/20130123
cf. http://d.hatena.ne.jp/tagomoris/20120731/1343707793

データ送信に失敗した場合は、buffer しておいて次回再送します。最大でいくつまで buffer するかは buffer_queue_limit (デフォルト64)で設定できます。

まとめ

fluent-agent-lite は新しいログがくると即座に flush する(ような)挙動をしますが、fluentd は一定時間間隔で flush する挙動をします。

fluent-agent-lite のほうがリアルタイム性が高いということですね。fluentd agent で fluent-agent-lite のような動作をさせたい場合は flush_interval 1s にするなど flush 間隔を短くして運用する形になりそうです。リアルタイム監視とか。

一方、fluentd agent はデータ送信に失敗した場合再送する仕組みを持っています。fluentd agent のほうがデータ信頼性が高いということですね。

ロードバランシングは?

fluent-agen-lite の場合

PRIMARY_SERVER_LIST で指定したサーバのうちいずれか1つにランダムで接続を試みます。そのサーバにつながらなかった場合、SECONDARY_SERVER_LIST のいずれか1つに接続を試みます。※ PRIMARY_SERVER すべてを試してからではないので注意!
AgentLite.pm#L89

1度つながったら connection_keepalive_time をすぎるまで、そのサーバにリクエストを送り続けます。
AgentLite.pm#L116

その connection_keepalive_time は 30分 + α
AgentLite.pm#L34

30分後に primary が生き返っていれば、そちらに戻るようです。
cf. http://d.hatena.ne.jp/tagomoris/20120314/1331716214

fluentd out_forward の場合

設定ファイルで指定した weight を元に Weighted Random でどのサーバにつなぐかが選択されます。

その際、通常のサーバのうちいずれかが通信不能になっていた場合、設定ファイルで standby true と設定した standby サーバもリストに追加してつなぐサーバを選択します。
out_forward.rb#L159

つなぐサーバリストは heatbeat_interval (デフォルト1秒)の周期で、生死確認をしたうえで再生成されます。
out_forward.rb#L110
out_forward.rb#L279

つまり、fluent-agent-lite のように特定の間(30分)同じサーバにデータを送り続けるのではなく、都度別のサーバにデータを送ります。

まとめ

fluent-agent-lite と fluentd out_forward プラグインの挙動が大分違いますね。

fluent-agent-lite の場合は、30分同じ fluentd サーバに(サーバが死なない限り)データを送ってくれるので、counter 系プラグインでホスト毎の集計をとることなどができたのですが、fluentd out_forward プラグインの場合は、都度分散するので、特定プロセスのみで集計を取ることができなくなります。集計用の fluentd サーバ (いわゆる serializer)にさらにデータを送ってそちらで集計するような仕組みを取る必要がありますね。

それだとちょっとカジュアルに fluentd クラスタを作れなかったので、fluent-plugin-keep-forwardというプラグインを作っています。30分という時間制御機能はまだ入れていませんが、可能な限り同じ fluentd サーバにデータを送り続けてくれる out_foward プラグインの拡張です。これについてはまた後で書きます。

負荷は?

職場のとある環境で測ったものですが大分ぼやっとさせてます (CPU使用率 / MEM使用率)

fluent-agent-litefluentd agent
とあるアプリのログに仕込んだ場合0.0% / 0.0%0.4% / 0.1%
yes でログを吐き続けた場合7.2% / 3.2%100% / 24%

fluent-agent-lite 軽いですねぇ。

※性能比較もしっかりやりたかったんですが、色々準備が大変でちょっと時間切れ orz. fluentd ベンチマークフレームワークが欲しいですね(チラッ

まとめ

総じてまとめると、軽くてリアルタイム性のある fluent-agent-lite と、データ信頼性の高い fluentd agent ってかんじでしょうか!?

用途に応じて使い分けるのが良さそうです。

それでは!

fluent-agent-lite と fluentd agent の比較(1) 〜 Haikanko OSS化への道(2)

こんにちは @sonots です。Haikanko OSS化への道、連載第二回です。1回目はこちら fluent-plugin-grepcounter をリリースしました 〜 Haikanko OSS化への道(1)

今回は fluent-agent-lite と fluentd ベースで設定した agent の比較記事を書いてみようと思います。まだ、調べきれていない所もあるので、間違ってるよ、とか、ここはこうだよ、とかあれば是非ツッコミをいただきたく。

では早速、まずは fluent-agent-lite から

fluent-agent-lite

fluent-agent-lite とは、@tagomoris さんによる fluentd プロトコルに対応した perl の別実装です。ログ収集対象のサーバに agent (ログ送るやつね)としてインストールすることに特化されており、その分 fluentd に比べて小さいです。

使う動機

fluent-agent-lite を利用すると、ログをそのまま次の fluentd に流すことができます。正規表現パースしないため動作が軽く、負荷の高いアプリケーションサーバに同居させてもCPUを使わない、という利点があります。

インストール

rpm を作ってインストールするのが吉です。@riywo さんの fluent-agent-liteのrpm作るだけのshell — Gist. あたりが参考になると思います。

設定ファイル

設定ファイルは次のように記述します。シェルスクリプトで記述できるので、けっこうなんでもアリにできます。設定を1つにまとめたかったので自分はここでファイル作ったりもしてます ^ ^; ちなみに、LOGS に 複数のログファイルを指定した場合、その数だけ fluent-agent-lite プロセスが起動します。

/etc/fluent-agent-lite.conf

# pre-process
mkdir -p /etc/fluent-agent-lite
cat <<"EOF" > /etc/fluent-agent-lite/primary_servers_list.conf
host1:22000
host2:22000
EOF
cat <<"EOF" > /etc/fluent-agent-lite/secondary_servers_list.conf
host3:22000
EOF
# configuration
TAG_PREFIX=raw
LOGS=$(cat <<EOF
syslog.`hostname` /var/log/syslog
fluent-agent.`hostname` /tmp/fluent-agent.log
EOF)
PRIMARY_SERVER_LIST=/etc/fluent-agent-lite/primary_servers_list.conf
SECONDARY_SERVER_LIST=/etc/fluent-agent-lite/secondary_servers_list.conf
LOG_PATH=/tmp/fluent-agent.log

fluentd agent

@yteraoka さん作の fluent-plugin-tail-asis (アズイズ: そのままの意) を利用すると、ログを正規表現でパースすることなく送信することができます。あとはそれを out_forward すると次の fluentd に流すことができるので、fluent-agent-lite に近い形で利用することができます。 ※ 実装はすごくシンプルで、TailInput を継承してパーサーのみ変更しているようですね。すばらしい。

2013.09.30 追記: 最新版の fluentd では in_tail プラグインに format none という、fluent-plugin-tail-asis と同じことをするフォーマットが追加されているのでそちらを利用できます :D

使う動機

fluentd の in_tail プラグインには、fluent-agent-lite にはないログポジションを覚える機能があります。また、out_forward には再送機能などがあるので、ログをできる限りロストしたくない場合に良さそうです。とはいえ、実際に動かしてみると fluent-agent-lite よりは多少CPUを使ってしまう点が欠点です。

インストール

agent に限らず fluentd の話ですが、td-agent という名前で ruby 同梱の deb および rpm パッケージが提供されているので、それを使ってさっくりインストールすることができます。ruby 同梱なのがけっこううれしかったります。 http://packages.treasure-data.com/

設定ファイル

こんな設定ファイルで fluent-agent-lite と同等の機能を実現できるでしょう。

ポイント: fluent-agent-lite では hostname コマンドでやっていたタグへのホスト名の挿入は、fluentd の場合は fluent-plugin-config-expander を利用することで可能ですね。また、fluent-agent-lite での SECONDARY_SERVER_LIST 相当は standby オプションで可能でした。

ドキュメントには書かれてませんでしたが、コードを読んだら実装してありました。

/etc/td-agent/td-agent.conf

<source>
  type config_expander
  <config>
    type tail_asis
    path /var/log/syslog
    pos_file /var/tmp/_var_log_syslog.pos
    asis_key message
    tag raw.syslog_warn_app_name.${hostname}
  </config>
</source>

<match **>
  type forward
  send_timeout 60s
  recover_wait 10s
  heartbeat_interval 1s
  phi_threshold 8
  hard_timeout 60s
  buffer_type memory
  buffer_chunk_size 156
  buffer_chunk_limit 8m
  flush_interval 1s
  retry_wait 1.0
  retry_limit 17

  <server>
    name host1:22000
    host host1
    port 22000
    weight 50
  </server>
  <server>
    name host2:22000
    host host2
    port 22000
    weight 50
  </server>

  <server>
    name host3:22000
    host host3
    port 22000
    weight 50
    standby true
  </server>

  <secondary>
    type file
    path /var/log/td-agent/td-agent-failed.log
  </secondary>
</match>

比較

ここからは、細かい動作仕様の比較をしていきます。

ログファイルの追い方

1. ファイル切り詰め (copytruncate)

ファイルをコピーして元ファイルを切り詰める、いわゆる copytruncate をした場合どうなるかの実験です。

$ cp /var/log/syslog /var/log/syslog.1
$ echo -n > /var/log/syslog

fluent-agent-lite のログメッセージ

/usr/bin/tail: /var/log/syslog: ファイルが切り詰められました

fluentd のログメッセージ

2013-03-15 20:44:13 +0900 [info]: detected rotation of /var/log/syslog; waiting 5 seconds
2013-03-15 20:44:17 +0900 [info]: following tail of /var/log/syslog

どちらも切り詰めたファイルの末尾から再度追ってくれます。

2. rename

ファイルを mv して新しく作った場合はどうなるかの実験です。

$ mv /var/log/syslog /var/log/syslog.1
$ touch /var/log/syslog

fluent-agent-lite

/usr/bin/tail: `/var/log/syslog' has become inaccessible: そのようなファイルやディレクトリはありません
/usr/bin/tail: `/var/log/syslog' has appeared; following end of new file
/usr/bin/tail: `/var/log/syslog' has been replaced; following end of new file

fluentd

2013-03-15 20:49:40 +0900 [info]: detected rotation of /var/log/syslog; waiting 5 seconds
2013-03-15 20:49:51 +0900 [info]: detected rotation of /var/log/syslog
2013-03-15 20:49:51 +0900 [info]: following tail of /var/log/syslog

どちらも新しいファイルを追ってくれますが、ここが一番の違いで、fluentd の場合は、ログの取りこぼしがないように5秒間だけ元のファイルのファイルディスクリプタを追ってくれるようです。

3. シンボリックリンクおきかえ

アプリが連番(もしくは日時付き)のログを吐く場合、fluentd で追えるようにするにはシンボリックリンクを貼って常に同じ名前のログファイルを用意する必要があります。その場合の実験です。

$ ln -s /var/log/syslog.1 /var/log/syslog
↓一定時間後おきかえ
$ ln -s /var/log/syslog.2 /var/log/syslog

fluent-agent-lite

/usr/bin/tail: `/var/log/syslog' has been replaced; following end of new file

fluentd

2013-03-15 20:49:40 +0900 [info]: detected rotation of /var/log/syslog; waiting 5 seconds
2013-03-15 20:49:51 +0900 [info]: detected rotation of /var/log/syslog
2013-03-15 20:49:51 +0900 [info]: following tail of /var/log/syslog

どちらも新しいファイルを追いかけ始めてくれ、新しいファイルは先頭行から読み込んでくれるようです。fluentd は 先ほどと同じく5秒間元のファイルディスクリプタを追います。

4. 存在しないファイルにシンボリックリンクを貼ってみる

ちょっといじわるに存在しないファイルにシンボリックリンクを貼った場合の実験です。

$ ln -sf /var/log/hogehoge /var/log/syslog
↓後でファイルを作ってみる
$ touch /var/log/hogehoge

fluent-agent-lite

/usr/bin/tail: `/var/log/syslog' has become inaccessible: そのようなファイルやディレクトリはありません
/usr/bin/tail: `/var/log/syslog' has appeared; following end of new file

fluentd

2013-03-12 18:57:34 +0900: detected rotation of /var/log/syslog; waiting 5 seconds
2013-03-12 18:58:02 +0900: following tail of /var/log/syslog

どちらも1度ファイルがなくなったと判断した後、ファイルを追いかけ始めてくれました。

5. 同じファイルにもう一度シンボリックリンクを貼ってみる

またちょっといじわるに同じファイルにシンボリックリンクを貼った場合の実験です。

$ ln -sf /var/log/syslog.1 /var/log/syslog
$ ln -sf /var/log/syslog.1 /var/log/syslog

fluent-agent-lite

出力なし

fluentd

2013-03-12 18:56:02 +0900: detected rotation of /var/log/syslog; waiting 5 seconds
2013-03-12 18:56:06 +0900: following tail of /var/log/syslog

fluentd の場合は新しいファイルができたと勘違いしてしまったようです。まぁ、そんなことやらないけど。

まとめ

基本的にどちらもいいかんじです。一番の違いはやはり fluentd の場合は、ログの取りこぼしがないように5秒間だけ元のファイルのファイルディスクリプタを追う所ですね。fluent-agent-lite の挙動は内部で利用している tail コマンドの挙動なので、そちらをすでに把握している人にはわかりやすいと思います。

あとは、明らかなので実験はしませんでしたが、fluentd の in_tail プラグインにはログポジションを覚えておく機能があるので、再起動時に続きからログを読み込むことができます。fluent-agent-lite は内部的に tail -F を利用しているだけなので、再起動時は最新行からの読み込みになりますね。

※ tail -F を利用してログ書き込みがあれば即座に取り込むという fluent-agent-lite の仕組みはだいぶシンプルで cool だと思います。ログポジションを覚えようとすると、その分リソースも使ってしまいますし仕組みも複雑になるので、あえて実装しないのが良手だと思います :D

ちなみに @oranie さんのブログ記事 にあった @frsyuki さんの言を引用させてもらうと fluentd は次のような挙動をするようです。確かにそういう挙動でしたね。データの取りこぼしにかなり気を使っているそうです。

1)新規に設定されたファイルは終端から読む
2)ログローテーションされたら次のファイルを先頭から読む
3)再起動時には前回読み終わった位置から読み始める(位置はファイルに保存しておく) 

ぜぇぜぇ、書くのだいぶ疲れてきましたが、続きます。fluent-agent-lite と fluentd agent の比較(2) 〜 Haikanko OSS化への道(2)

fluent-plugin-grepcounter をリリースしました 〜 Haikanko OSS化への道(1)

こんにちは @sonots です。
Haikanko OSS化への道、連載第一弾です。Haikanko は大分できあがった感があるんですが、OSS化するためには内部モジュールの gem 化やテスト、ドキュメントの整備作業していないとむりだなー、と感じているので、連載と称して少しずつやっていこうと思ってます。※ Haikanko についてはこちら => HaikankoというFluentdクラスタ管理ツールの話をしてきた(1) #fluentdcasual

ということで、その第一弾と称して、fluent-plugin-grepcounter という fluentd のプラグインを gem 化して rubygems に置いたので紹介します。

何するもの?

ログメッセージを grep のように正規表現で絞り込むと同時に、マッチしたメッセージの数をカウントしてくれるものです。カウントがある一定数を超えた場合のみ出力する、といった制御もできます。

やりたかったこと/できること

fluent-agent-lite を使ってアプリが出力しているログを fluentd に送り、5分の間に出力された "warn" という文字列にヒットするログメッセージが xx 件以上ならば、IRCおよびメールで通知、といったようなことがやりたかったので作りました。メールの本文にはヒットしたログメッセージ全件を貼付けたかったので、既存の fluent-plugin-datacounter + fluent-plugin-notifier ではそれはできないなー、と思って作成しました。

使い方

https://github.com/sonots/fluent-plugin-grepcounter の README にも書いていますが。

例えば、以下のようなメッセージが fluent-agent-lite から送られてくるとして
syslog.host1: {"message":"2013/01/13T07:02:11.124202 INFO GET /ping" }
syslog.host1: {"message":"2013/01/13T07:02:13.232645 WARN POST /auth" }
syslog.host1: {"message":"2013/01/13T07:02:21.542145 WARN GET /favicon.ico" }
syslog.host1: {"message":"2013/01/13T07:02:43.632145 WARN POST /login" }

こんなかんじで設定すると

<match syslog.**>
  type grepcounter
  input_key message
  regexp WARN
  count_interval 60
  exclude favicon.ico
  threshold 1
  add_tag_prefix warn.count
</source>

message (input_key)フィールドの文字列のうち、WARN (regexp)という文字がヒットする数を60秒間(count_interval)カウントします。exclude で指定した文字は除外され、カウント数が threshold で指定した値を超えた場合だけ、出力されます。add_tag_prefix で出力メッセージのタグを改変できます。

出力はこんなかんじになります。count はもちろん出力されますが、自分の利便性のために、入力のタグ名と、その最後の要素も出力されるようになっています。ホスト名を取りたかったんですよね。


warn.count.syslog.host1: {
  "count":2,
  "input_tag":"syslog.host1",
  "input_tag_last":"host1"
  "message":["2013/01/13T07:02:13.232645 WARN POST /auth","2013/01/13T07:02:43.632145 WARN POST /login"],
}


ヒットしたメッセージはデフォルトでは出力されないので、もし、出力したい場合は output_matched_message オプションを true にして、delimiter を指定してください。

(2013年05月05日 加筆) デフォルトでヒットしたメッセージも出力されるようになりました。
(2013年11月30日 加筆) delimiter オプションで delimiter を指定すると message が join されて配列ではなく文字列として出力されます。

<match syslog.**>
  type grepcounter
  count_interval 60
  input_key message
  regexp WARN
  exclude favicon.ico
  threshold 1
  add_tag_prefix warn.count
  delimiter \n
</source>

出力はこんなかんじになります。

warn.count.syslog.host1: {
  "count":2,
  "input_tag":"syslog.host1",
  "input_tag_last":"host1",
  "message":"2013/01/13T07:02:13.232645 WARN POST /auth\n2013/01/13T07:02:43.632145 WARN POST /login"
}


Acknowledgements

fluent-plugin-grepcounter を作成するにあたって、例によって @tagomoris さんの  https://github.com/tagomoris/fluent-plugin-datacounter を大分参考にさせていただきました。ありがとうございます。

また、今回テストは fluentd のプラグインにしては珍しく、rspec で書いています。rspec でテストを書くにあたって、@SpringMT さんの https://github.com/SpringMT/fluent-plugin-resque_stat を参考にさせていただきました。ありがとうございます。

おわりに

fluent-plugin-grepcounter は以前書いたこちらの記事 HaikankoというFluentdクラスタ管理ツールの話をしてきた(2) - Fluentd側の話 #fluentdcasual で fluent-plugin-watchcatcounter と呼んでいたやつですね。それを汎用的なプラグインとして整理して、それなりの名前を付け直してリリースしました。Haikanko でログのキーワード監視機能を実現するために使用しています。

こんな感じで、整理作業を進めていくのでよろしくお願いいたします。かしこ。
A Ruby and Fluentd committer working at DeNA. 記事本文および記事中のコード片は引用および特記あるものを除いてすべて修正BSDライセンスとします。 #ruby #fluentd #growthforecast #haikanko #yohoushi #specinfra #serverspec #focuslight
はてぶ人気エントリー