fluent-plugin-multiprocessと戯れた話

こんにちは、こちらはFluentd Advent Calrendar 24日目の記事です。

このところ遊んでいたfluent-plugin-multiprocessの挙動についてさっくりと紹介していきます。触っていたバージョンは、v0.1.2です。

なお、td-agentを利用しているので、設定ファイルとログファイルは特に断りがない場合は、td-agent.conf, td-agent.logとしています。

利用方法

td-agent.conf

<source>
  type multiprocess
  <process>
    cmdline -c /etc/td-agent/td-agent_child1.conf --log /var/log/td-agent/td-agent_child1.log
    sleep_before_start 3s
  </process>
  <process>
    cmdline -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_child2.log
    sleep_before_start 3s
  </process>
</source>

fluent-plugin-multiprocessは、親プロセスがfluentdコマンドを打って子プロセスを作るようなイメージのpluginです。
<process>ディレクティブ内に、利用する設定ファイルやプロセスを起動するまでの待ち時間等を設定します。
基本的には、READMEにあるとおりの設定でOKです。

起動させる

いつもどおりtd-agentを起動するだけ

$ sudo /etc/init.d/td-agent start

すると以下の様なプロセスツリーになるはずです

 2965 ?        Sl     0:00 /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
 2968 ?        Sl     0:00  \_ /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
 2973 ?        Sl     0:00      \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_child2.log
 2975 ?        Sl     0:00      |   \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_child2.log
 2989 ?        Sl     0:00      \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child1.conf --log /var/log/td-agent/td-agent_child1.log
 2992 ?        Sl     0:00          \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child1.conf --log /var/log/td-agent/td-agent_child1.log

子プロセス(2973, 2975, 2989, 2992)もシグナルを待ち受けるプロセスと、ワーカープロセスが立っているのがわかります。

ログファイル

READMEにあるように、multiprocess pluginを利用して起動した子プロセスのログは親プロセスのログファイルに書き出されないので、cmdlinオプションに--log <%= ログファイルのパス %>と子プロセス用のログファイルを指定するオプションを追加したほうが良いです。なお、子プロセスが起動に失敗した場合、失敗した理由によっては何もログがでないことがあるので注意が必要です。

設定ファイルへのパスが間違っていた場合には、子プロセスのログには設定ファイルを読んだ旨のメッセージだけが残り、以下のように子プロセスがゾンビ化します。

  551 ?        Sl     0:00 /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
  554 ?        Sl     0:00  \_ /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
  559 ?        Z      0:00      \_ [ruby] <defunct>
  569 ?        Z      0:00      \_ [ruby] <defunct>

ほかに、設定ファイルを読み込んでる時にエラーで落ちた場合には、子プロセス側にだけメッセージが出力され、子プロセスはゾンビ化します。

  676 ?        Sl     0:00 /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
  679 ?        Sl     0:00  \_ /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
  684 ?        Sl     0:00      \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_child2
  686 ?        Sl     0:00      |   \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_ch
  691 ?        Z      0:00      \_ [ruby] <defunct>

multiprocess pluginを利用した際の起動後の確認は、親プロセスのログファイルだけではなく子プロセス用のログファイルと、psコマンドでプロセスの状態を確認しておいたほうが良さそうです。
なお、親プロセスの起動後から各子プロセスが立ち上がるまで数秒かかります。

挙動について

ここではいくつか気になった挙動を紹介していきます。

子プロセス間で同じパスを利用してしまった場合

たとえば以下の様な設定ファイルだった場合を考えます。

子プロセス1

<match hoge.**>
  type file
  path /var/log/td-agent/child1
  time_slice_format %Y%m%d_%H%M
  time_slice_wait 60s
</match>

子プロセス2

<match hoge.**>
  type file
  path /var/log/td-agent/child1
  time_slice_format %Y%m%d_%H%M
  time_slice_wait 60s
</match>

これら２つの子プロセスは受け取ったログを/var/log/td-agent/child1に対して書き込もうとします。
起動時に/var/log/td-agent/child1*なファイルがない場合は、動いてくれます。しかし起動時に/var/log/td-agent/child1*なファイルがある場合、特にそのファイルがバッファ状態の場合には、以下の様な状態に陥ります。
1. どのバッファファイルに書き出すか不定になる
2. バッファファイルを確定状態にする際にエラーとなる

この現象は、in_multiprocessに限ったことではなく、何らかの方法でfluentdプロセスを複数立ち上げた場合に起こりうる問題です。
プロセスの起動時にエラーメッセージもないので、設定ファイルを作成する際に注意するしかありません。
（何か良い回避方法があったら教えて下さいmm）

USR1シグナルについて

USR1シグナルをfluentdプロセスに送ることでバッファを強制的にflushさせることが可能です。
td-agentの場合は、以下のように実行することが多いです。

$ sudo kill -USR1 `cat /var/run/td-agent/td-agnet.pid`

しかし、multiprocess pluginを利用した状態の親プロセスに対して、USR1シグナルを送っても、親プロセスはそれを子プロセスに伝搬してくれません。なので、psコマンド等で子プロセスのpidを調べてシグナルを送る必要があります。

ログローテート

子プロセス用のログファイルを追加した場合、そのログファイルの肥大化を防ぐためにログローテートしてあげる必要があります。

親プロセス用のログローテートファイルは、td-agentの場合だと以下のとおりです。

/var/log/td-agent/td-agent.log {
  daily
  rotate 30
  compress
  delaycompress
  notifempty
  create 640 td-agent td-agent
  sharedscripts
  postrotate
    pid=/var/run/td-agent/td-agent.pid
    test -s $pid && kill -USR1 "$(cat $pid)"
  endscript
}

ローテート後に、USR1シグナルを送っています。これはこのあたりでログファイルを開き直しているためで、ログローテート後の新しいファイルにログを出力するために必要な処理です。ログローテートとUSR1シグナルは切っても切れない縁なのです。

シグナルを送らずに強制的に子プロセス用のログファイルをローテートさせた場合には、設定にもよりますが

td-agent_child1.log   ← ここにはなにも書き込まれない
td-agent_child1.log.1 ← ここにずっと書き込まれ続ける

という状態に陥ります。td-agent用の設定ファイルだと対象ファイルが空の場合はローテートされないため、td-agent_child1.log.1にログが書きだされ続けます。

ログファイルが空の場合でもローテートするような設定にした場合には、

td-agent_child1.log        ← ここも空
td-agent_child1.log.1      ← 以降はひたすら空
td-agent_child1.log.2.gz   ← 初めてcompressされるまでのログが入ってる

といった状態になり、２度目のローテート後からfluentdのログが喪失してしまいます。

子プロセスもログローテートできるようにしてみる

ログローテートの設定ファイル内に、子プロセスのpidに対してシグナルを送るようにすればよいわけですが、psコマンドで頑張るのもなかなか難しいので、いっそのこと子プロセス用のpidファイルを設置するようにしてみました。

このパッチではpid_fileオプションを指定した場合、そのパスに各子プロセスのpidを書きだしたpidファイルを作成してくれます。

<source>
  type multiprocess
  <process>
    cmdline -c /etc/td-agent/td-agent_child1.conf --log /var/log/td-agent/td-agent_child1.log
    sleep_before_start 3s
    pid_file /var/run/td-agent/td-agent_child1.pid
  </process>
  <process>
    cmdline -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_child2.log
    sleep_before_start 3s
    pid_file /var/run/td-agent/td-agent_child2.pid
  </process>
</source>

$ ls -l /var/run/td-agent
total 12
-rw-r--r-- 1 td-agent 5 Dec 24 10:22 td-agent.pid
-rw-rw-rw- 1 td-agent 5 Dec 24 10:22 td-agent_child1.pid
-rw-rw-rw- 1 td-agent 5 Dec 24 10:22 td-agent_child2.pid

$ ps afx |grep td-agent
21826 ?        Sl     0:00 /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
21829 ?        Sl     0:00  \_ /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --daemon /var/run/td-agent/td-agent.pid
21838 ?        Sl     0:00      \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_child2.log
21840 ?        Sl     0:00      |   \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child2.conf --log /var/log/td-agent/td-agent_child2.log
21844 ?        Sl     0:00      \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child1.conf --log /var/log/td-agent/td-agent_child1.log
21846 ?        Sl     0:00          \_ /opt/td-agent/embedded/bin/ruby /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.12/lib/fluent/command/fluentd.rb -c /etc/td-agent/td-agent_child1.conf --log /var/log/td-agent/td-agent_child1.log

$ cat /var/run/td-agent/td-agent_child1.pid
21844

$ cat /var/run/td-agent/td-agent_child2.pid
21838

このpidファイルを利用するとログローテートファイルは以下のようにかけます。

/var/log/td-agent/td-agent_child1.log {
  daily
  rotate 30
  compress
  delaycompress
  notifempty
  create 640 td-agent td-agent
  sharedscripts
  postrotate
    pid=/var/run/td-agent/td-agent_child1.pid
    test -s $pid && kill -USR1 "$(cat $pid)"
  endscript
}

また、手動で強制flushさせたい場合にも、このpidファイルを利用することで簡単に実現できるようになるはずです。

$ sudo kill -USR1 `cat /var/run/td-agent/td-agnet_child1.pid`

まとめ

multiprocess pluginの挙動についてさっくりとですが紹介しました。親プロセス、子プロセスのログファイルを両方確認すること、psコマンドでプロセスの状態を確認することがより大事なようです。また、利便性を考慮してpid_fileを作成するためのオプションを追加するパッチを書きました。instance_variable_getを使っていたりするので、こうしたほうが良いといったコメントいただけると幸いです。

実際に長期運用してみないとわからないこともあるかと思いますので、こんなことがあった！こんなふうに使うと便利だよ！等ありましたらぜひぜひ教えて下さい！ : )