はじめに
td-agentのin_tailプラグインを使うと
指定したファイルをtail-fしてるように読みこんでからごにょごにょしてくれるわけですが、sourceディレクティブに指定するpos_fileの挙動について確認してみました
in_tailプラグインとは
tail インプットプラグインは、Fluentdがイベントログをテキストファイルの末尾から読み取れるようにします。その読み取り方は tail -F コマンドによく似ています。
引用→http://documents.mazgi.com/fluentd/doc/plugin.html#tail
公式→http://docs.fluentd.org/ja/articles/in_tail
補足
そんなにテクニカルでも有用でもないカモですがこちらにメモまとめをメモっておきました
→td-agent(fluentd)を本番サ―ビスで小さく使ってみたメモ－まとめ
試したい内容
1.pos_fileオプションの指定
2.posファイルができるタイミングと中身とか
3.途中でposファイル消した場合
4.tail監視前にtailするファイルがある(中身数件ある）→td-agent起動してtailはじめる場合のpos
5.tail監視中に、tailするファイルをカラにした場合のpos
6.tail監視中に、tailするファイルを消した場合のpos
7.tail監視中に、受信側が落ちて転送できないけど、tailするファイルには書き込みが続いてるときのpos
8.posファイル自分で勝手に書いた場合
試す構成
ためす構成は
fluentd(td-agent)使ってサーバ間でjsonログを転送してみる＆詳細ログも出してみるテスト
でやったのと同じです。こんな感じ
このときのconfファイルはこんなん
- td-agent.conf(送信側)
<source>
type tail
format json
path /var/log/td-agent/posfile_test_input.log
pos_file /var/log/td-agent/posfile_test_input_log.pos
tag json.forward.test
</source>
<match json.posfile.test>
type forward
<server>
host 192.168.72.101
port 24224
</server>
#flush_interval 1s
</match>
- td-agent.conf(受信側)
<source> type forward port 24224 </source> <match json.posfile.test> type file path /var/log/td-agent/posfile_test_output.log </match>
ではさっそく
1.pos_fileオプションの指定
pos_file指定とは
path で指定したログファイルの読み込んだ位置(IO#seek で指定する位置)とログファイルの inode を記録して、fluentd 起動時にその内容を参照してその続きから再開する
pos_file指定方法
↑でもうでちゃってますが、td-agent.conf(送信側)のsourceディレクティブのpos_fileに指定します。
<source> type tail format json path /var/log/td-agent/posfile_test_input.log pos_file /var/log/td-agent/posfile_test_input_log.pos←こんなん tag json.forward.test </source>
2.posファイルができるタイミングと中身とか
タイミング
td-agent.conf(送信側)で指定してるので/var/log/td-agent/にposファイルができます。td-agent起動前と起動後はこんな感じ
- td-agetn起動前
# pwd /var/log/td-agent # ls -l -rw-r--r-- 1 td-agent td-agent 46737 12月 11 14:59 2013 td-agent.log
- td-agetn起動後
# sudo /etc/init.d/td-agent start Starting td-agent: [ OK ] # ls -l -rw-r--r-- 1 td-agent td-agent 46737 12月 11 14:59 2013 td-agent.log -rw-r--r-- 1 td-agent td-agent 67 12月 11 15:02 2013 posfile_test_input_log.pos
起動時にできるみたいですね。当たり前ですが、ここではまだpathに指定したtailするファイルはできてません
posファイル中身(tailするファイル無いまま起動)
# cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000000000 00000000
pathに指定したログファイルの読み込んだ位置と、ファイルのinodeを記録するとあったのでどっちがどっちかわからないですが、初期値で000...と指定されてるようです。
posファイル中身(tailするファイル作成＆書き込み時)
# pwd /var/log/td-agent ※tailするファイル作成して中身に100回書き込み # sudo perl td_agent_input_test.pl 100 # ls -l -rw-r--r-- 1 td-agent td-agent 7792 12月 11 15:24 2013 posfile_test_input.log -rw-r--r-- 1 td-agent td-agent 67 12月 11 15:24 2013 posfile_test_input_log.pos -rw-r--r-- 1 td-agent td-agent 55901 12月 11 15:24 2013 td-agent.log -rwxrwxr-x 1 hoge hoge 1249 12月 11 12:17 2013 td_agent_input_test.pl ※中身確認してみる # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000001e70 014b8100 ※tailするファイルのiノードを確認 # ls -i posfile_test_input.log 21725440 posfile_test_input.log ※ファイルのinodeを16進数に変換してみる # printf '%#x\n' 21725440 0x14b8100 ※posfileの0000000000001e70を10進数に変換してみる # printf '%d\n' 0x1e70 7792
やってみた感じ
0000000000001e70：読み込んだ位置(バイト単位)
0x14b8100：ファイルのinode
のようです。
今回は、「sudo perl td_agent_input_test.pl 100」でファイルの作成＆書き込みを同時におこなっちゃってますが
touchなどでファイルを作成しただけの場合は、読み込んだ位置はそのままにファイルのinodeだけ更新されました。
3.途中でposファイル消した場合
td-agentの送受信が正常に起動してる場合にposファイル消した場合です
※正常起動中にposファイル消す # sudo rm posfile_test_input_log.pos ※再度100件書き込み # sudo perl td_agent_input_test.pl 100 ※tailファイルに書き込みとかしても再度作られたりしない # ls -l -rw-r--r-- 1 td-agent td-agent 23376 12月 11 16:30 2013 posfile_test_input.log -rw-r--r-- 1 td-agent td-agent 70221 12月 11 16:25 2013 td-agent.log -rwxrwxr-x 1 hoge hoge 1249 12月 11 12:17 2013 td_agent_input_test.pl
こちらも当たり前かもしれませんが、起動時にしかposファイルはできないようです。
ただ、td-agent(受信側)のoutputファイルを見てみるとログとしての転送は正常に行われていました
4.tail監視前にtailするファイルがある(中身数件ある）→td-agent起動してtailはじめる場合のpos
監視前なのでtd-agent(送信側)はstop、posファイルなども消してから行います
※起動前に100件書き込み # sudo perl td_agent_input_test.pl 100 ※posファイルが無いのを確認 # ls -l -rw-r--r-- 1 td-agent td-agent 7792 12月 11 16:03 2013 posfile_test_input.log -rw-r--r-- 1 td-agent td-agent 61036 12月 11 16:02 2013 td-agent.log -rwxrwxr-x 1 hoge hoge 1249 12月 11 12:17 2013 td_agent_input_test.pl ※td-agent起動 # sudo /etc/init.d/td-agent start Starting td-agent: [ OK ] # ls -l -rw-r--r-- 1 td-agent td-agent 7792 12月 11 16:03 2013 posfile_test_input.log -rw-r--r-- 1 td-agent td-agent 67 12月 11 16:09 2013 posfile_test_input_log.pos -rw-r--r-- 1 td-agent td-agent 64938 12月 11 16:09 2013 td-agent.log -rwxrwxr-x 1 hoge hoge 1249 12月 11 12:17 2013 td_agent_input_test.pl # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000001e70 014b8104 ※この時点でtd-agent(受信側)のoutputファイルには書き込みはありません ※再度100件書き込み # sudo perl td_agent_input_test.pl 100 # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000003ce0 014b8104 ※この時点でtd-agent(受信側)のoutputファイルには2回目に100回書き込んだjsonのみ書き出されてる
どこかの記事にも書いてありましたが、起動したタイミングでtailするファイルの最終行からwatchするようです。
5.tail監視中に、tailするファイルをカラにした場合のpos
100件書き込み×2回やった後、中身を消してから再度100件書き込んでみます
※最初のposファイル見とく # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000000000 00000000 ※100件書き込み # sudo perl td_agent_input_test.pl 100 ※posファイル見とく # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000001e70 014b8100 ※さらに100件書き込み # sudo perl td_agent_input_test.pl 100 ※posファイル見とく # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000003ce0 014b8100 ※inputファイルの中身をカラにする＆確認 # sudo cp /dev/null posfile_test_input.log # ls -l posfile_test_input.log -rw-r--r-- 1 td-agent td-agent 0 12月 11 16:40 2013 posfile_test_input.log ※posファイル見てみる # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000003ce0 014b8100 ※100件書き込み # sudo perl td_agent_input_test.pl 100 ※posファイル見てみる # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000001e70 014b8100
途中で消した場合も、しれっとそのままやってくれるみたいです。
中身をカラにした後は、読み込み位置が最初に100件書き込んだ場所と同じ場所に戻りました。
6.運用中にtailするファイルを消して再度作った場合
ローテートされたりした想定の確認です。
※通常tail監視中のposを確認 # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000001e70 014b8104 ※tailするファイルを消す # sudo rm posfile_test_input.log ※無駄に適当なファイル作っておく(消す前のinodeが空いて同じinodeが使われそうなので) # sudo touch aaaa_1.log; sudo touch aaaa_0.log; sudo touch aaaa_2.log ※tailするファイル作成＆100件くらい書き込み # sudo perl td_agent_input_test.pl 100 ※posを確認 # cat posfile_test_input_log.pos /var/log/td-agent/posfile_test_input.log 0000000000001e70 014b810c
読み込むファイルのinodeは変わったものの特に問題なく動きました。転送先のログにも正常に書き込んだ100件が送られてました。
ちなみに、このときtd-agent.logにはこんな感じで出てます
2013-12-13 11:36:25 +0900 [info]: plugin/in_tail.rb:226:on_rotate: detected rotation of /var/log/td-agent/posfile_test_input.log
2013-12-13 11:36:35 +0900 [info]: plugin/in_tail.rb:289:initialize: following tail of /var/log/td-agent/posfile_test_input.log
detectedされるものの、新しくファイルができるとfollowingが始まるようです。
7.tail監視中に、受信側が落ちて転送できないけど、tailするファイルには書き込みが続いてるときのpos
※通常に転送できてるposを確認 # ls -al lrwxrwxrwx 1 root wheel 57 12月 18 13:23 2013 receiver_down_test_input.log -> /var/log/td-agent/receiver_down_test_input.log.2013-12-18 -rw-r--r-- 1 td-agent td-agent 771 12月 18 18:10 2013 receiver_down_test_input.log.2013-12-18 -rw-r--r-- 1 td-agent td-agent 73 12月 18 18:10 2013 receiver_down_test_input_log.pos -rw-r--r-- 1 td-agent td-agent 27769 12月 18 18:10 2013 td-agent.log -rwxrwxr-x 1 hoge hoge 1320 12月 18 13:22 2013 td_agent_input_test.pl ※posファイル確認 # cat receiver_down_test_input_log.pos /var/log/td-agent/receiver_down_test_input.log 0000000000000303 014b8115 ※posfileの0000000000000303を10進数に変換してみる # printf '%d\n' 0x0303 771 ※※※※ココで受信側をstopしてからやってみる※※※※ ※100件書き込み # sudo perl td_agent_input_test.pl 100 # ls -l -rw-r--r-- 1 td-agent td-agent 7092 12月 18 18:51 2013 buffer.json.receiver_down.test.q4edcbfe673558e99.log lrwxrwxrwx 1 root wheel 57 12月 18 13:23 2013 receiver_down_test_input.log -> /var/log/td-agent/receiver_down_test_input.log.2013-12-18 -rw-r--r-- 1 td-agent td-agent 8563 12月 18 18:51 2013 receiver_down_test_input.log.2013-12-18 -rw-r--r-- 1 td-agent td-agent 73 12月 18 18:51 2013 receiver_down_test_input_log.pos -rw-r--r-- 1 td-agent td-agent 40765 12月 18 18:52 2013 td-agent.log -rwxrwxr-x 1 hoge hoge 1320 12月 18 13:22 2013 td_agent_input_test.pl ※posファイル確認 # cat receiver_down_test_input.log /var/log/td-agent/receiver_down_test_input.log 0000000000002173 014b8115 ※posfileの0000000000002173を10進数に変換してみる # printf '%d\n' 0x2173 8563
当たり前かもですが、何かしらの理由で受信側に転送できないときでもposファイルの中身(ファイルの読み込み位置)は変更されてるようです。
代わりにbuffer.json.receiver_down.test.q4edcbfe673558e99.logみたいなbufferファイルができているので転送できなかった分はこちらに溜まってくようです。
bufferについての挙動はまた別のときに。。
8.posファイル自分で勝手に書いた場合
試したのを記載するのがちょっと面倒だったのでいったん結論だけ。
結論
pathで指定したファイルに対してnバイトまで読んだってこにしたい場合、
・指定ファイルのinodeを16進数に変換したもの
・nバイトを16進数に変換したもの
をposファイルに書けばそっから再度読んでくれる
時間あるとき忘れなかったらちゃんと書きます汗
なるほど的な。
