tweeeetyのぶろぐ的めも

アウトプットが少なかったダメな自分をアウトプット<br>\(^o^)/

td-agent(fluentd)のposファイルの作成タイミングとかその他もろもろもメモ

はじめに

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ファイル自分で勝手に書いた場合

試す構成

このときの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 起動時にその内容を参照してその続きから再開する

参考→http://colopl.co.jp/tech/blog/2012/05/1808/

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ファイルに書けばそっから再度読んでくれる

時間あるとき忘れなかったらちゃんと書きます汗


なるほど的な。