環境

アプリが出力するログをtailプラグインを使ってアグリゲータに送信
アグリゲータはs3にログをputする
送信側のtd-agent バージョンは 1.1.3
送信ログは2GBごとにローテートされる
以下のようにだいたい10分に1回ローテートされます。

[root@送信 ~]# ls -ltrh /var/log/test.log*
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 10:16 /var/log/test.log.20
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 10:25 /var/log/test.log.19
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 10:34 /var/log/test.log.18
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 10:43 /var/log/test.log.17
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 10:52 /var/log/test.log.16
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:00 /var/log/test.log.15
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:09 /var/log/test.log.14
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:17 /var/log/test.log.13
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:26 /var/log/test.log.12
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:34 /var/log/test.log.11
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:42 /var/log/test.log.10
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:50 /var/log/test.log.9
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 11:58 /var/log/test.log.8
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 12:06 /var/log/test.log.7
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 12:14 /var/log/test.log.6
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 12:22 /var/log/test.log.5
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 12:29 /var/log/test.log.4
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 12:37 /var/log/test.log.3
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 12:45 /var/log/test.log.2
-rw-rw-r-- 1 ec2-user ec2-user 2.1G Apr 10 12:52 /var/log/test.log.1
-rw-rw-r-- 1 ec2-user ec2-user 115M Apr 10 12:53 /var/log/test.log

設定

具体的な設定は以下のようにしました。

今回は受信側の設定も載せていますがあんまり関係ないですね。

送信側

test.logをtailします

<match tail.test>
  @type forward
  transport tcp

  <buffer tag,time>
    @type file
    path /var/log/td-agent/buffer/
    chunk_limit_size 64m
    queue_limit_length  2560
    timekey 3600 # 1 hour partitioon
    timekey_use_utc true # use utc
    flush_mode interval
    flush_interval 5s
    flush_at_shutdown
    retry_timeout 5m  #default = 72h
    #retry_max_times 5  #default = none
  </buffer>

  <server>
    host xxxxxxxxxxxxx
    port 24224
  </server>
</match>

<source>
  @type tail
  format none
  path /var/log/test.log
  pos_file /var/log/td-agent/test.pos
  tag tail.test
</source>

受信側

今回は確認のために受信した内容をそのままファイルに吐き出します。

<match tail.test>
  @type file
  format single_value
  path /var/log/td-agent/tmp.log
  append true

  <buffer>
    @type file
    path /var/log/td-agent/buffer/
    flush_mode interval
    flush_interval 5s
  </buffer>
</match>

## built-in TCP input
## @see http://docs.fluentd.org/articles/in_forward
<source>
  @type forward
  port 24224
  bind 0.0.0.0
</source>

確認方法と事象

送信側のlogに適当に書き込みます

[root@送信 ~]# for i in `seq -w 01 05` ; do echo "`date`      $i" >> test.log ; done

受信側で確認します

[root@受信 ]# tailf tmp.log
Tue Apr 10 11:54:58 UTC 2018      01
Tue Apr 10 11:54:58 UTC 2018      02
Tue Apr 10 11:54:58 UTC 2018      03
Tue Apr 10 11:54:58 UTC 2018      04
Tue Apr 10 11:54:58 UTC 2018      05

送信側のtd-agentを止めて、先ほどと同じ要領でログを追記してみます

[root@送信 ~]# /etc/init.d/td-agent stop
Stopping td-agent: td-agent                                [  OK  ]

[root@送信 ]# for i in `seq -w 06 10` ; do echo "`date`      $i" >> test.log ; done

[root@送信 ]# cat test.log
Tue Apr 10 11:54:58 UTC 2018      01
Tue Apr 10 11:54:58 UTC 2018      02
Tue Apr 10 11:54:58 UTC 2018      03
Tue Apr 10 11:54:58 UTC 2018      04
Tue Apr 10 11:54:58 UTC 2018      05
Tue Apr 10 13:00:54 UTC 2018      06
Tue Apr 10 13:00:54 UTC 2018      07
Tue Apr 10 13:00:54 UTC 2018      08
Tue Apr 10 13:00:54 UTC 2018      09
Tue Apr 10 13:00:54 UTC 2018      10

手動でtest.logをローテートします

[root@送信 ]# logrotate -f /etc/logrotate.d/test

再度ログを書き込んでみます

[root@送信 ]# for i in `seq -w 11 15` ; do echo "`date`      $i" >> test.log ; done

[root@送信 ]# cat test.log
Tue Apr 10 13:10:59 UTC 2018      11
Tue Apr 10 13:10:59 UTC 2018      12
Tue Apr 10 13:10:59 UTC 2018      13
Tue Apr 10 13:10:59 UTC 2018      14
Tue Apr 10 13:10:59 UTC 2018      15

td-agentを起動して受信側のログを確認します

[root@送信 ]# /etc/init.d/td-agent start
td-agent td-agent:                                         [  OK  ]

[root@受信 ]# tail tmp.log
Tue Apr 10 11:54:58 UTC 2018      01
Tue Apr 10 11:54:58 UTC 2018      02
Tue Apr 10 11:54:58 UTC 2018      03
Tue Apr 10 11:54:58 UTC 2018      04
Tue Apr 10 11:54:58 UTC 2018      05
Tue Apr 10 13:10:59 UTC 2018      11
Tue Apr 10 13:10:59 UTC 2018      12
Tue Apr 10 13:10:59 UTC 2018      13
Tue Apr 10 13:10:59 UTC 2018      14
Tue Apr 10 13:10:59 UTC 2018      15

td-agentが止めてから書き込まれたログは無視されています。

ローテート後のファイルからしかforwardされていません

考察

posファイルにはwatchするログのi-nodeと位置が記録されていますが、プロセスが落ちて起動させた際、これまでのposファイルに記録されたファイルや位置に関係なく、設定されたtail対象のファイルを探してi-nodeが更新されてしまうようです。

僕はposファイルのi-nodeが更新される前に、posファイルに記録されているi-nodeのファイルを最後まで読み切ってから次のファイルを見つけてtailすると思っていたのですが、そのような挙動では無いんですね、、

回避方法

約10分に1回ローテートが走る今回の環境ではtd-agentのプロセスが突然死する障害が起きた場合、例えば30分程度検知〜復旧に時間がかかると欠損が出てしまいます。

いろいろ調べましたが今回の事象を回避するようなオプションを見つけることが出来ませんでした。

このような場合にはいかにtd-agentのプロセスが死んでからの復旧を早めるかが重要になりそうです。

今回はmonitやsupervisorなどを使ってなるべくプロセスが死亡し続けないようにして回避できればなと考えています。

最後に

こんなのこういう風にすれば回避できるよとかあれば情報を頂けると助かりますm( )m

何か思い立った時に書くやつ

td-agent のプロセスが死んでから復旧するまでの間に in_tail で監視しているファイルにログが追記されてローテートされると追記されたログが拾えない

環境

設定

送信側

受信側

確認方法と事象

考察

回避方法

最後に