tweeeetyのぶろぐ的めも

アウトプットが少なかったダメな自分をアウトプット<br>＼(＾o＾)／

td-agent(fluentd)でtailするファイルをいろいろしたときのメモ

td-agent fluentd

はじめに

td-agentのin_tailプラグインを使うと
指定したファイルをtail-fしてるように読みこんでからごにょごにょしてくれるわけですが、sourceディレクティブに指定するpath(tailするファイル)について確認してみました

in_tailプラグインとは

tail インプットプラグインは、Fluentdがイベントログをテキストファイルの末尾から読み取れるようにします。その読み取り方は tail -F コマンドによく似ています。

引用→http://documents.mazgi.com/fluentd/doc/plugin.html#tail
公式→http://docs.fluentd.org/ja/articles/in_tail

試したい内容

tailするファイル自体や中身の有無、変更について試してみます

1.tail監視前にtailするファイルがある(中身数件ある）→td-agent起動してtailはじめる、の場合
2.tail監視中→td-agent停止→tailするファイルに数件書き込み→td-agent起動、の場合
3.tail監視中にtailするファイルをカラにした場合
4.tail監視中にtailするファイルを移動した場合
5.検証4で移動したファイルを元に戻してみる
6.tail監視中にtailするファイルを消して再度作った場合
7.シンボリックリンクでのログをtail監視中に100万件書き込み→書き込み中にンボリックリンク変更(rotate_wait指定なし)

試す構成

ためす構成は

fluentd(td-agent)使ってサーバ間でjsonログを転送してみる＆詳細ログも出してみるテスト
でやったのと同じです。こんな感じ

このときのconfファイルはこんなん
  • td-agent.conf(送信側)
<source>
  type tail
  format json
  path /var/log/td-agent/tail_test_input.log
  pos_file /var/log/td-agent/tail_test_input_log.pos
  tag json.tail.test
</source>
<match json.tail.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.tail.test>
  type file
  path /var/log/td-agent/tail_test_output.log
  buffer_chunk_limit 1G
</match>
tailするファイルに書き込むスクリプト

直接関係はないですけど、tailするファイルに書き込むスクリプトはこんな感じにしました
td_agent_input_test.pl

#!/usr/bin/perl
use strict;
use Time::Piece;
use JSON;

my $input_count = $ARGV[0]||1;

# write to input file
my $input_file_path = "/var/log/td-agent/posfile_test_input.log";
&create_input_file($input_file_path);
open(FH, ">> $input_file_path");
for (1..$input_count)
{
  print FH &json($_) . "\n";
}
close(FH);

# create file with owner=td-agent:td-agent
sub create_input_file
{
  my $file_path = shift;
  if (! -e $file_path) 
  {
    # create file
    open FH, ">", $file_path or die "$file_path : $!";
    close FH;

    # chown file
    my $cmd_ret = `chown td-agent:td-agent $file_path`;
  }
}

# return json string
sub json
{
  my $cnt = shift||1;
  my $json_str = &json_tpl;
  my $datetime = localtime->strftime('%Y-%m-%dT%H:%M:%S');
  $json_str =~ s/#cnt#/$cnt/;
  $json_str =~ s/#time#/$datetime/;
  return $json_str;
}

# return json string template
my $json_tpl;
sub json_tpl
{
  if(!$json_tpl)
  {
    $json_tpl = JSON::encode_json({
      "msg" => "imput message from sv1",
      "date" => "#time#",
      "msg_cnt" => '#cnt#'
    });
  }
  return $json_tpl;
}
1;

使い方

# sudo perl td_agent_input_test.pl 2000
※{"msg":"imput message from sv1","msg_cnt":"1","date":"2013-12-11T15:16:47"}
※というjson文字列を2000回対象ファイルに書き込む
※対象ファイルはベタ書きしてます

1.tail監視前にtailするファイルがある(中身数件ある）→td-agent起動してtailはじめる、の場合

一番普通の挙動です
数件すでにtailするファイルの中身がかかれた状態で起動するとどうなるか、的な。
受信側は正常に動いてる状態です

オペレーション(td-agent送信側のみ)
※起動する前に数件書き込み
# sudo perl td_agent_input_test.pl 10

※一応posファイル無いの確認
# ls -l
 -rw-r--r-- 1 td-agent td-agent   771 12月 13 16:26 2013 tail_test_input.log
 -rw-r--r-- 1 td-agent td-agent 23772 12月 13 16:23 2013 td-agent.log
 -rwxrwxr-x 1 hoge     hoge      1246 12月 13 16:23 2013 td_agent_input_test.pl

※td-agent起動
# sudo /etc/init.d/td-agent start
Starting td-agent:                                         [  OK  ]

※一応posファイル有るの確認
# ls -l
 -rw-r--r--  1 td-agent td-agent   771 12月 13 16:26 2013 tail_test_input.log
 -rw-r--r--  1 td-agent td-agent    64 12月 13 16:30 2013 tail_test_input_log.pos
 -rw-r--r--  1 td-agent td-agent 27675 12月 13 16:30 2013 td-agent.log
 -rwxrwxr-x  1 hoge     hoge      1246 12月 13 16:23 2013 td_agent_input_test.pl


※追加で20件書き込み
# sudo perl td_agent_input_test.pl 20
送信側td-agent.log

特に無し

受信側td-agent.log

2013-12-13 16:32:16 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172667655320
2013-12-13 16:32:16 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172667655320

受信側のoutputのログ
# ls -l
 drwxrwxrwx 2 td-agent td-agent  4096 12月  2 21:48 2013 buffer
 -rw-r--r-- 1 td-agent td-agent  1181 12月 13 16:32 2013 tail_test_output.log.20131213.b4ed65762b580aba1
 -rw-r----- 1 td-agent td-agent 10588 12月 13 16:32 2013 td-agent.log

# cat tail_test_output.log.20131213.b4ed65762b580aba1
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"1","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"2","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"3","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"4","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"5","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"6","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"7","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"8","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"9","date":"2013-12-13T16:32:16"}
2013-12-13T16:32:16+09:00       json.tail.test  {"msg":"imput message from sv1","msg_cnt":"10","date":"2013-12-13T16:32:16"}

最初のなので全般的にのっけました。
どこかの記事にも書いてありましたが、起動したタイミングではtailするファイルの最終行からwatchします。

2.tail監視中→td-agent停止→tailするファイルに数件書き込み→td-agent起動、の場合

今度は通常運用でありそうな、tailするログファイルへの書き込みは続いてるけどtd-agentいったん止めた場合パターンです。

オペレーション(td-agent送信側)

tail監視されている状態でtd-agent停止します

# sudo /etc/init.d/td-agent stop
Shutting down td-agent:                                    [  OK  ]
送信側td-agent.log

2013-12-13 16:46:40 +0900 [debug]: fluent/supervisor.rb:237:block in install_supervisor_signal_handlers: fluentd supervisor process get SIGTERM
2013-12-13 16:46:40 +0900 [debug]: fluent/supervisor.rb:352:block in install_main_process_signal_handlers: fluentd main process get SIGTERM
2013-12-13 16:46:40 +0900 [debug]: fluent/supervisor.rb:355:block in install_main_process_signal_handlers: getting start to shutdown main process
2013-12-13 16:46:40 +0900 [info]: fluent/engine.rb:216:run: shutting down fluentd
2013-12-13 16:46:41 +0900 [info]: fluent/supervisor.rb:186:supervise: process finished code=0

受信側td-agent.log

特に無し

オペレーション(td-agent送信側)

停止のまま100件書き込んでから起動

# sudo perl td_agent_input_test.pl 100

# sudo /etc/init.d/td-agent start
Starting td-agent:                                         [  OK  ]
送信側td-agent.log

特に無し

受信側td-agent.log

2013-12-13 16:50:32 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172647135100
2013-12-13 16:50:32 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172647135100

pos_fileにて読み込みを記録してるところから読み込みを開始して転送されます
outputのログにも正常に100件来てました

3.tail監視中にtailするファイルをカラにした場合

tail監視中のファイルが100件ほどあったとして(tailもされていてpos_fileにも100件までの情報がある)
カラにしてから記録した件数未満の書き込みをしたらどーなるかテストです

オペレーション(td-agent送信側)
※数百件書き込まれた状態
# ls -l tail_test_input.log
 -rw-r--r-- 1 td-agent td-agent 31168 12月 13 20:26 2013 tail_test_input.log

※カラにする
# sudo cp /dev/null tail_test_input.log

# ls -l tail_test_input.log
 -rw-r--r-- 1 td-agent td-agent 0 12月 13 20:27 2013 tail_test_input.log
送信側td-agent.log

2013-12-13 20:27:22 +0900 [info]: plugin/in_tail.rb:230:on_rotate: detected rotation of /var/log/td-agent/tail_test_input.log; waiting 5 seconds
2013-12-13 20:27:25 +0900 [info]: plugin/in_tail.rb:289:initialize: following tail of /var/log/td-agent/tail_test_input.log

受信側td-agent.log

特に無し

再度100件書き込む
# sudo perl td_agent_input_test.pl 100
送信側td-agent.log

特に無し

受信側td-agent.log

2013-12-13 20:28:10 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172645843780
2013-12-13 20:28:10 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172645843780

ってことでカラにしても、カラにしてからの100件は正常に送れました。

ちなみに、オペレーションでカラにした後の送信側td-agent.logに

detected rotation of /var/log/td-agent/tail_test_input.log; waiting 5 seconds

と出てますが、5秒経過後にカラにしたファイルの先頭からtailされました。
この値はconfigのsourceディレクティブにrotate_waitという値を設定することで変更できます
rotate_waitについてはこちらなんかに説明があるのでお借りします。
→fluentd tailプラグインの仕様について

ファイル自体だけじゃなく
読み込み位置が変わったことでもrotate_wait秒待ってから新しく読み込みなおそうとしてくれるみたいです。



4.tail監視中＆tailするファイルに100万件書き込み中＆ファイルを移動した場合

これはローテートされて移動されてしまってもディスクリプタを追ってくれるかっていうお試しです

オペレーション(td-agent送信側)
※移動する前のinode確認してみる
# ls -il tail_test_input.log
21725444 -rw-r--r-- 1 td-agent td-agent 0 12月 13 21:15 2013 tail_test_input.log

※移動する前のposファイルをcatしてみる
# cat tail_test_input_log.pos
/var/log/td-agent/tail_test_input.log   0000000000000000        014b8104

※100万件書き込む
# sudo perl td_agent_input_test.pl 1000000

※書き込みが終わる前に移動する
# sudo mv tail_test_input.log tail_test_input.log_

※移動した後のinode確認してみる
# ls -il tail_test_input.log_
21725444 -rw-r--r-- 1 td-agent td-agent 81888896 12月 13 21:21 2013 tail_test_input.log_

※移動した後のposファイルをcatしてみる
# cat tail_test_input_log.pos
/var/log/td-agent/tail_test_input.log   0000000001273fd7        014b8104
送信側td-agent.log

2013-12-13 21:02:30 +0900 [info]: plugin/in_tail.rb:230:on_rotate: detected rotation of /var/log/td-agent/tail_test_input.log; waiting 5 seconds

受信側td-agent.log

2013-12-13 21:02:26 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172612455460
2013-12-13 21:02:26 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172612455460
2013-12-13 21:02:28 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172551960900
2013-12-13 21:02:31 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172622140180
2013-12-13 21:02:31 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172551960900
2013-12-13 21:02:35 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172570665860
2013-12-13 21:02:35 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172622140180
2013-12-13 21:02:38 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172603127760
2013-12-13 21:02:38 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172570665860
2013-12-13 21:02:42 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172599221180
2013-12-13 21:02:42 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172603127760
2013-12-13 21:02:42 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172599221180

受信側tail_test_output.log.20131213.b4ed65762b580aba1の中身

・・・省略・・・
2013-12-13T21:02:35+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"237323","date":"2013-12-13T21:02:35"}
2013-12-13T21:02:35+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"237324","date":"2013-12-13T21:02:35"}
--END OF FILE--

msg_cntが221989なので、20万件ほどまで転送されて後は切られてしまったようです。

また、送信側td-agent.logにこんな感じでログがでます
detected rotation of /var/log/td-agent/tail_test_input.log; waiting 5 seconds
これはファイルがなくなっても5秒間はディスクリプタを追ってくれてるようで
上記3で行った検証にも記載したrotate_waitを30秒とかにして同じことを試すと100万件すべて転送されました。



5.検証4で移動したファイルを元に戻してみる

これは、4の検証で移動しただけではinodeが変わらないのを確認しておいたので、
再度、もとの名前に戻すと途中から転送が始まるか?っていうののお試しです

オペレーション(td-agent受信側)
※カラにしておく
# ls -l tail_test_output.log.20131213.b4ed65762b580aba1
 -rw-r--r-- 1 td-agent td-agent 48120024 12月 13 21:02 2013 tail_test_output.log.20131213.b4ed65762b580aba1

# sudo cp /dev/null tail_test_output.log.20131213.b4ed65762b580aba1
# ls -l tail_test_output.log.20131213.b4ed65762b580aba1
 -rw-r--r-- 1 td-agent td-agent 0 12月 13 21:13 2013 tail_test_output.log.20131213.b4ed65762b580aba1
オペレーション(td-agent転送)
※戻す前にinode確認してみる
# ls -il tail_test_input.log_
21725444 -rw-r--r-- 1 td-agent td-agent 81888896 12月 13 21:44 2013 tail_test_input.log_

※戻す前にposファイルcatしてみる
# cat tail_test_input_log.pos
/var/log/td-agent/tail_test_input.log   0000000001273fd7        014b8104

※ファイルを元に戻してみる
# sudo mv tail_test_input.log_ tail_test_input.log

※inode確認してみる
# ls -il tail_test_input.log
21725444 -rw-r--r-- 1 td-agent td-agent 81888896 12月 13 21:21 2013 tail_test_input.log

※posファイルcatしてみる
# cat tail_test_input_log.pos
/var/log/td-agent/tail_test_input.log   00000000034417e1        014b8104

# cat tail_test_input_log.pos
/var/log/td-agent/tail_test_input.log   0000000004058fe1        014b8104

# cat tail_test_input_log.pos
/var/log/td-agent/tail_test_input.log   0000000004e18680        014b8104

# cat tail_test_input_log.pos
/var/log/td-agent/tail_test_input.log   0000000004e18680        014b8104
送信側td-agent.log

2013-12-13 21:49:25 +0900 [info]: plugin/in_tail.rb:226:on_rotate: detected rotation of /var/log/td-agent/tail_test_input.log
2013-12-13 21:49:25 +0900 [info]: plugin/in_tail.rb:289:initialize: following tail of /var/log/td-agent/tail_test_input.log

受信側td-agent.log

2013-12-13 21:49:25 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172545862220
2013-12-13 21:49:27 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70172542854320
・・・省略・・・
2013-12-13 21:50:12 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70172568155840

受信側tail_test_output.log.20131213.b4ed65762b580aba1の中身

--file先頭--
2013-12-13T21:49:25+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"1","date":"2013-12-13T21:43:49"}
2013-12-13T21:49:25+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"2","date":"2013-12-13T21:43:49"}
・・・省略・・・
2013-12-13T21:49:42+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"999999","date":"2013-12-13T21:44:14"}
2013-12-13T21:49:42+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"1000000","date":"2013-12-13T21:44:14"}
--END OF FILE--

これはどうやら途中から読んでくれず、先頭からtailで読み込んでしまうようです。

ちなみにrotate_waitを30秒とかに設定して30秒以内に4と5の検証をやってみましたが
それも同じで一度移してから戻すと先頭から読まれてしまうようです
受信側outputファイルはこんな感じになりました

--FILE先頭--
2013-12-13T22:01:02+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"1","date":"2013-12-13T22:01:02"}
2013-12-13T22:01:02+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"2","date":"2013-12-13T22:01:02"}

・・・省略・・・
2013-12-13T22:01:09+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"270740","date":"2013-12-13T22:01:09"}
2013-12-13T22:01:09+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"270741","date":"2013-12-13T22:01:09"}
2013-12-13T22:01:09+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"1","date":"2013-12-13T22:01:02"}
2013-12-13T22:01:09+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"2","date":"2013-12-13T22:01:02"}
2013-12-13T22:01:09+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"3","date":"2013-12-13T22:01:02"}
・・・省略・・・

2013-12-13T22:01:27+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"999999","date":"2013-12-13T22:01:27"}
2013-12-13T22:01:27+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"1000000","date":"2013-12-13T22:01:27"}
--END OF FILE--

これもできるかと思ったんですがダメなんですね。。。何か間違ったかな？
検証4の最後と検証5の最初に確認したposファイルの中身って読み込み位置もinodeも同じだから途中から読んでくれるかと思ってました汗
眠くぼーっとオペレーション間違ってたらすみません。

とりあえずつぎへ。。

6.tail監視中にtailするファイルを消して再度作った場合

ちょっと書くのダレてはぶいちゃいますが
これは新しく作ったファイルの末尾からちゃんと読んでくれました。

7.シンボリックリンクでのログをtail監視中に100万件書き込み→書き込み中にンボリックリンク変更(rotate_wait指定なし)

はじめに

実際に運用するときはapacheのアクセスログなど、日付入りのファイル名でかつ日が変わるごとにローテートされるようなことが多いかと思います。
日付入りのファイルをsourceディレクティブに指定して毎日configファイルを書き換えるわけにはいかないので
シンボリックリンクを使い指定するファイルを固定にします

sudo ln -nfs /var/log/td-agent/tail_test_input.log.`date "+%Y-%m-%d"` /var/log/td-agent/tail_test_input.log

これを毎日cronなどで実行してファイルを固定します

オペレーション(td-agent転送側)
※今日の日付を確認
# date
2013年 12月 16日 月曜日 12:20:37 JST

※ローテートされる想定でローテートされる前のファイルを用意する
※とりあえずシンボリックリンクはる
# sudo touch tail_test_input.log.2013-12-15
# sudo ln -nfs /var/log/td-agent/tail_test_input.log.2013-12-15 /var/log/td-agent/tail_test_input.log
# ls -l
 lrwxrwxrwx  1 root     wheel      48 12月 16 12:49 2013 tail_test_input.log -> /var/log/td-agent/tail_test_input.log.2013-12-15
 -rw-r--r--  1 root     wheel       0 12月 16 12:49 2013 tail_test_input.log.2013-12-15
 -rw-r--r--  1 td-agent td-agent   64 12月 16 12:50 2013 tail_test_input_log.pos
 -rw-r--r--  1 td-agent td-agent 4652 12月 16 12:50 2013 td-agent.log
 -rwxrwxr-x  1 hoge     hoge     1246 12月 13 16:23 2013 td_agent_input_test.pl

※100万件書き込み(2013-12-15に対して)
# sudo perl td_agent_input_test.pl 1000000

※書き込みが終わる前にリンク先変更
※`date "+%Y-%m-%d"`は当日をあらわすので2013-12-16へのリンクになる
# sudo n -nfs /var/log/td-agent/tail_test_input.log.`date "+%Y-%m-%d"` /var/log/td-agent/tail_test_input.log

# ls -al
 lrwxrwxrwx  1 root     wheel          48 12月 16 14:31 2013 tail_test_input.log -> /var/log/td-agent/tail_test_input.log.2013-12-16
 -rw-r--r--  1 root     wheel    14168064 12月 16 14:31 2013 tail_test_input.log.2013-12-15
 -rw-r--r--  1 td-agent td-agent       64 12月 16 14:31 2013 tail_test_input_log.pos
 -rw-r--r--  1 td-agent td-agent    15133 12月 16 14:31 2013 td-agent.log
 -rwxrwxr-x  1 hoge     hoge         1246 12月 13 16:23 2013 td_agent_input_test.pl
ここまでの送信側td-agent.log

2013-12-16 14:31:48 +0900 [info]: plugin/in_tail.rb:230:on_rotate: detected rotation of /var/log/td-agent/tail_test_input.log; waiting 5 seconds

ここまでの受信側td-agent.log

2013-12-16 14:31:50 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70084682710380
2013-12-16 14:31:53 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70084698350900
・・・省略・・・
2013-12-16 14:32:00 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70084678626980

オペレーション(td-agent転送側)
※アプリがファイルを作成するほうが遅い想定で後からファイル作成
# sudo touch tail_test_input.log.2013-12-16;sudo perl


※10件書き込み(2013-12-16に対して)
# sudo perl td_agent_input_test.pl 10
送信側td-agent.log

2013-12-16 14:31:57 +0900 [info]: plugin/in_tail.rb:226:on_rotate: detected rotation of /var/log/td-agent/tail_test_input.log
2013-12-16 14:31:57 +0900 [info]: plugin/in_tail.rb:289:initialize: following tail of /var/log/td-agent/tail_test_input.log

受信側td-agent.log

2013-12-16 14:32:00 +0900 [trace]: plugin/in_forward.rb:152:initialize: accepted fluent socket object_id=70084674813520
2013-12-16 14:32:00 +0900 [trace]: plugin/in_forward.rb:193:on_close: closed fluent socket object_id=70084674813520

また、受信側のoutputログファイルはこんな感じになりました

--FILE先頭--
2013-12-16T14:31:48+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"1","date":"2013-12-16T14:31:48"}
・・・省略・・・
2013-12-16T14:31:54+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"278882","date":"2013-12-16T14:31:54"}
2013-12-16T14:31:54+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"278883","date":"2013-12-16T14:31:54"}
2013-12-16T14:31:58+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"1","date":"2013-12-16T14:31:57"}
2013-12-16T14:31:58+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"2","date":"2013-12-16T14:31:57"}
・・・省略・・・
2013-12-16T14:31:58+09:00 json.tail.test {"msg":"imput message from sv1","msg_cnt":"10","date":"2013-12-16T14:31:57"}
--END OF FILE--

rotate_waitの指定無しでやったので、シンボリックリンク先を変更したタイミングで5秒間は追ってくれてるようですが
書き込みが終わる前にリンク先を変更しているので5秒間の間に追えたところまで("msg_cnt":"278883"まで)が転送されてから
次の10件も正常に転送されました。

これもrotate_wait=30で設定してやってみたら100万件すべて転送できたので
実際のローテーションも考慮すると結構長めに設定しておくことでログの取りこぼしをなるべく少なく抑えられそうです。


とりあえず今日はここまでで。

こちらも参考にしてみてください
→td-agent(fluentd)を本番サ―ビスで小さく使ってみたメモ－まとめ - tweeeetyのぶろぐ的めも