きっかけ
- ということで、td-agent(fluentd) の
in_tailプラグインでログのローテーションをどのように捕捉して追従していくかを調べたい
やってみた
下記の環境においてクライアントから apache に ab でアクセスさせて確認する。
確認したいこと
td-agentを介してログを記録している状況において、ログローテーションが発生した場合に td-agent はログの切り替わりを知って、それに追従するか。- 純粋に access.log ファイルに記録される内容（件数）と
td-agentを介した記録内容（件数）に際が発生ないか。（ちょっとした負荷テスト的なことも）
環境
サーバー
クライアント
- Ubuntu 13.04
- ab 2.3
Apache へのアクセス
以下のようなパラメータでアクセスをシュミレートする。
ab -c 1000 -n 20000 http://xxx.xxx.xxx.xxx/
ログの切り替わり
ログの切り替わりは logrotate を参考に以下のように実行してシュミレートする。（実際にコマンドを実行する）
mv access.log access.log.1 && invoke-rc.d apache2 reload
また、検証を行う度に redis-server は redis-cli で FLUSHALL を実行してレコードをクリアしている。
td-agent 無し
新規で access_log を作成し、ab を実行する。
access.log の件数
なんてこと無い 20000 レコードが記録されている。
td-agent あり（アクセスが発生していない状態でログが切り替える）
では本題。td-agent に /var/log/apache2/access.log を tail させた状態で、ab を実行前にログの切り替えを行う。ログの切り替えに伴い apache のリロードが発生する。
apache をリロードしてみる。
td-agent.log の出力
注目したいのは detected rotation of /var/log/apache2/access.log; waiting 5 seconds の部分。詳細は後述。
access_log の件数
td-agent を介さない場合と同じように 20000 レコードが記録されている。
redis-server のレコード数
また、td-agent を介して redis-server に記録されたレコードも access.log と同様に 20000 レコードとなり取りこぼし等皆無。
td-agent あり（アクセス中にログが切り替わる）
いよいよ本丸。ab を実行後、10000 アクセスが完了した段階（アクセスの最中）でログの切り替えを行う。ログの切り替えに伴い apache のリロードが発生する。
絶妙のタイミング（汗）で apache のリロードを行い、且つ、スクリーンショットを撮る荒業。もっと良い検証の方法があるかもしれない...（汗
td-agent.log の出力
前述と同様に apache の reload（ログの切り替わり）のタイミングで detected rotation of /var/log/apache2/access.log; waiting 5 seconds が出力される。
access_log の件数
ログの切り替わりに伴い access.log と access.log.1 に分割されてしまっているが、合計で 20000 レコードとなる。
redis-server のレコード数
同じように redis-server にも 20000 レコードが記録されている。
ログが切り替わる時に何が起きるのか？
せっかくなのでソースコードを見る！
あの 5 秒は何？
スキル的にソースコードを読み解くことは出来ないが本当に残念だが、検証時にログが切り替わった段階で出力される detected rotation of /var/log/apache2/access.log; waiting 5 seconds に関しては in_tail.rb の以下が該当するのは解った。
あくまでも予想の範囲だが、この 5 秒時間というのは切り替わる直前のログをチェックしている時間なのかな...と思ったら、こちらでとても詳しく解説されていた。この設定は td-agent.conf の rotate_wait で指定することが出来る。
上記のようなイメージになると思われる（図中は fluentd と記載されているが td-agent と読み替えて頂ければ幸いです）。
ポジションファイルが重要みたい
in_tail プラグインを利用している場合にはポジションファイルを解析して td-agent がログの最新の位置を追っかけてくれているので、何らかの原因でサーバーが再起動してしまっても、最新の位置からログを追っかけてくれる。
赤線の左からフルパス指定のログファイル、ポジション、inode となる。
ということで
- ログが切り替わる瞬間を目の当たりにすることが出来た
- また、
td-agentがどのようにしてローテションを捕捉しているのかが理解出来た（但し、細かい部分は引き続き...） - 今宵は良く眠れそう
