fluentdのin_tailプラグインの動作について理解する

fluentdは、ログ収集ツールで人気のソフトウェアとして広く知られており、私も以前から大変お世話になっているOSSのひとつです。ログファイルからデータを読み取り後続の処理にデータを流すfluentdに標準で組み込まれているtailプラグインは、最も良く使われる機能のひとつだと思いますが、内部の動作について理解が不十分だと、あれ？？と想定通りの結果が得られずハマってしまうこともあるかもしれません（私がそうでした。。）。ドキュメントを参照しながら設定するだけですぐに使い始められるのですが、何か障害がおきた時に内部動作についてある程度把握していることによって、その後の原因調査をスムースに進められることができると思います。そこで、備忘録の意味も込めて、tailプラグインについて自分なりに調べた内容をまとめてみました。

内容に間違いあれば指摘していただけると幸いです。

tail Input Pluginの動作概要

主に公式のドキュメントを参照して和訳したものです。

• tail -F に類似した振る舞いをする（tail -f でなくtail -Fに注意、-F オプションでは、tailはファイルのrenameやrotateを追跡し、inode numberが変わった場合はファイルをreopenし、tailを再開してくれる）。
• tail開始時、デフォルトではtail対象のファイルの先頭でなく末尾からデータの読み込みを開始する。
• positionファイルを指定することでtailしていたファイルの最終の読み込み位置（pos）を記録し、次回開始時にpos以降のデータから読み込みを開始する。

Fluentd

docs.fluentd.org

tail Input Pluginの内部を追ってみる

in_tailでは、libev^[1]http://libev.schmorp.de/bench.htmlというイベントライブラリベースのCool.io^[2]https://github.com/tarcieri/cool.ioというライブラリを使って、TimerやStat（ファイルやディレクトリの変更）のイベントを監視している。以下全体像を図にしてみる（概要把握のため省略部分あり）。

fluentd v0.12.12のソースを参考。

1. NewTailInputは、fluentd起動時にrefresh_intervalで指定された間隔で発火されるTimerイベントを生成し、Cool.ioのイベントループに登録する。
2. その後はrefresh_intervalごとにTimerイベントが通知され、refresh_watchersメソッドが呼び出される。その中で、既存の古いwatcherの停止や新しくtailに追加されるpathのファイルを監視するためのTailWatcherを新しくセットアップする。
3. TailWatcherは１つ１つのpath（ワイルドカードを含む場合は展開されたもの）に対して生成され、初期化時にデフォルトで1secごとのTimerイベント、Statイベント及びファイルローテートのためのハンドラなどが割り当てられる。
4. TailWatcherのTimer及びStatのイベントが通知されるとTailWatcher#on_notifyメソッドが呼ばれ、登録された各種ハンドラが呼び出される。
5. pathのファイルに読み取るべきデータがあれば、IOHandlerによって一回の処理で最大行数がread_lines_limitを超えないようバッファされ、parserによってパースされ、tag付けされイベントとしてemitされる。

rotateの判定

rotateは、以下のステップで判定される。

1. pos_fileのinodeと新しく検出されたファイルのinode番号が同じ場合は、1) renameした後元に戻された、2) 同じファイルに対するシンボリックリンク・ハードリンクが再作成された、とみなしpos_fileに記録されていたposから読み込みを開始する。
2. pos_fileにあるinode番号が0でない場合、pos_fileを指定しfluentdを以前に起動していたケースと想定し、rotateされたファイルの先頭からデータの読み込みを開始する。
3. 上記以外の場合、read_from_headがtrueであればファイルの先頭から、そうでない場合はファイルの末尾からデータの読み込みを開始する。

pathに時間のformat文字列を含む指定の場合

以下のような指定の場合は、上記の判定ステップの３に該当するため、read_from_headオプションをtrueにしていなかった場合は初期のデータの読み込みをスキップしログを取りこぼしてしまう可能性がある。これは、動作概要にあったようにtailでは末尾からデータの読み込みを開始する事になっているためである。

上記の場合は、時間単位で新しくtail対象のファイルがrefresh_watcherメソッドの呼び出しの中で検出される。この時、pos_fileにtail対象のpathとpos及びinode番号が初期値で記録される。read_from_headオプションがtrueでinode番号が初期値(=0)から更新されていなければ、新しいpathのinode番号とpos(=0)でpos_fileの上書きを試みる。ただし、pathのファイルが存在しない場合は上書きされず、次のようなログを確認できるだろう。

続けて、pathに対するTailWatcherのイベント監視がセットされる。tail対象のpathがファイルシステム上に見つかれば、TailWatcher#on_rotateメソッドの中でinode番号とpos（read_from_headがfalseの場合はstat.size、trueでは0）が更新され、そのpathのIOHandlerが生成される。

pathが固定の場合

以下のようにpathが固定の場合、通常はrotateして新規にファイルを生成する事になるが、この場合は上記判定ステップの2に該当する。

pos_file中のpath名は変わらないが、inode番号とposは更新される。

pos_fileの構造

pos_fileの中はテキストで読める形式になっており、構造は以下の通り。

時間のformat文字列を指定した場合のpos_fileは以下のようになっている。

fff...ffは、pathがunwatch状態であることを示している。

pathが実際に存在しない場合は、posもinodeも0になっている。

in_tailのオプション

tag (必須)

emitするイベントに使われるtag名を指定する。

path (必須)

tail対象のpath。時間のformat文字列や*を指定することもできる。

exclude_path

除外したいpathをarrayで指定する。デフォルトは空。

refresh_interval

pathに対するwatcherを更新するリフレッシュ間隔（秒）を指定する。デフォルトは60。

read_from_head

このオプションが指定されていると、新規にtailされるpathのファイルの先頭からデータの読み込みを開始する。デフォルトはfalse。

pathに時間のformat文字列が含まれるような場合にはtrueにしておくことで、時間単位などのpath指定でファイルの先頭のログだけ送られていないといった思わぬ事態に陥らずに済む。

read_lines_limit

IOHanlderが一回のステップ（IOHandler#on_notify）でログを処理する最大行数。デフォルトで1000。

multiline_flush_interval

formatがmultiline指定の場合に有効で、複数行にまたぐログを扱う時のバッファのflush間隔（秒）。デフォルトは5。

pos_file

pathの読み込み位置（pos）を記録するファイル。

fluentdを再起動しても、最後に記録したpos以降からデータの読み込みを開始できる。できるだけ指定するよう推奨されている。

format (必須)

レコードのparse方式を指定する。noneでログをそのまま扱う。

time_format

timeフィールドが含まれる場合の時間を解釈するための時間のformat文字列。

rotate_wait

rotateされた後に監視を停止するまでの間隔（秒）を指定する。デフォルトで5。

rotateされた後もここで指定された時間の間はtailを継続してくれる。

enable_watch_timer

TailWatcherで1secのTimerイベントを使うか否かを指定する。inotify^[3]https://linuxjm.osdn.jp/html/LDP_man-pages/man7/inotify.7.htmlをサポートしていないシステムのために用意されている。デフォルトはtrue。

その他

pos_fileを誤って削除してしまった場合

LinuxやUnixでは、rmコマンドでpos_fileを削除してもプロセスが生きている限り実態は存在しておりエラーにならない。稼働中はpos_fileが再作成されることはないので、次回起動時に新規にpos_fileが作成される事になる。この時pos_file中のposは、pathで新しくtailを開始した時の値（前出のrotate判定の3）で更新され、read_from_headがtrueの場合はファイルの先頭からデータの読み込みを開始するためデータの重複が起きてしまう。くれぐれもpos_fileを削除しないよう注意するとともに、誤削除防止の意味でもpos_fileは通常のログディレクトリとは別に専用のディレクトリに書くようにした方が良いと思う。

read_from_headオプションtrue時の挙動

read_from_headをtrueにしていた場合、pos_file指定がないとpathで指定されたファイルの先頭からデータの読み込みを開始するので、送られるデータが重複してしまうかもしれない。pos_fileを指定している場合、 read_from_headがtrueだとしても、すでに読み込みされていれば最終のpos以降からデータが読み込まれるのでデータの重複は起こらない。

重複を回避するための方法として、ログにuuidのような一意な識別子を振りアプリケーションで処理する際に重複カットするなどがある。

pathをシンボリックリンクにしリンク先をつけ変えた場合

この場合、前出のrotate判定で2に該当する。inode番号は新規、posは0でpos_fileのエントリが更新され、新しいpathのファイルの先頭からデータの読み込みが開始される。

pathのファイルをrenameした後元に戻した場合

通常行わない操作だと思うが、この場合前出のrotate判定で1に該当する。pathのファイルをrenameした後、pathに対するTailWatcherによる監視はrotate_waitの時間だけ継続される。同時に新しくpathに対するTailWatcherが生成されイベント監視を開始する。mvでrenameしたファイルを元のpathに戻すと、pos_fileに記録されているinode番号が同じであるため、pos_fileに記録されていたpos以降からデータの読み込みを再開する。この時、renameした後のrotate_waitの期間内にデータが追記されていた場合、posはメモリ上更新されるがその変更はpos_fileには反映されない。よって、pos_fileの最後に記録されていたposからデータの読み込みが開始され、既送信済みデータとの重複が起きる可能性があるので注意する。

rotateする前にfluentdがダウンして、rotate後にfluentdを開始した場合

この場合は、前出のrotate判定2にあたる。rotateする前にfluentdがダウンしてpathのファイルにデータが追記された後、pathのファイルがrotateされfluentdを再起動した場合は、新しくポイントされたpathのファイルの先頭からデータの読み込みが開始されるので、fluentdダウン後に追記されたデータは送られてこない。

設定例

時間のformat文字列を含む場合

• formatは指定なしで、{"message": "<line>"}の形式でイベントをemitする。
• pathは時間単位のformat文字列を指定し、時間単位で分けられたファイルをtailする。新規pathの検出の間隔は30sec。
• pos_fileを指定し、再起動後も最終のpos以降からデータの読み込みを開始する。
• read_from_headをtrueに設定し、新しいtail対象のpathが検出された時は、pathで指定されたファイルの先頭から読み込みを開始する。

format jsonでtime_key、time_format指定がある場合

• timeフィールドは、time_formatで指定されたformat文字列で解釈される。
• pathは固定のファイルで、rotateされた後は新しくポイントされたファイルの先頭から読み込みを開始する。

参考リンク

• http://docs.fluentd.org/articles/in_tail
• https://github.com/fluent/fluentd/blob/master/lib/fluent/plugin/in_tail.rb
• https://linuxjm.osdn.jp/html/LDP_man-pages/man7/inotify.7.html