sonots:blog

まとめとく。out_forward プラグインのパラメータ一覧はオフィシャルドキュメントへ

detached forwarding server phi=xxx

ログメッセージの例

2014-03-11 00:53:34 +0900 [warn]: detached forwarding server 'host:22442' host="host" port=22442 phi=12.123

説明

heartbeat の結果、サーバが応答せず phi_threashold を超えてしまった場合に出るメッセージ。

なお、ここで言う heartbeat とは、out_forward プラグインが in_forward プラグインに対して 1s (デフォルト)毎に udp (デフォルト)パケットを送信し、さらに in_forward がそれに対して udp パケットを返却することで行っている死活監視。 

該当コード行

out_forward.rb#L407

よくある原因

受信側の Fluentd において、内部処理でブロックしている。

• 結果、in_forward イベントループ内の heartbeat の受信/返却処理に入れていない。(heartbeat_interval はデフォルト 1s なので１秒以上かかっているような場合はアウト)

送信元の Fluentd において、内部処理でブロックしている。

• 結果、out_forward イベントループ内の heartbeat の返却を待ち受ける処理に入れていない。 返却が来るまで時間がかかったと判断されてしまう

そもそも heartbeat パケットを送れていない

heartbeat_interval を変更したたために、適切な phi_threshold の値が変わってしまっている。

out_forward 関連パラメタ

• heartbeat_type (デフォルト: udp)
• heartbeat_interval (デフォルト: 1s)
• phi_threshold (デフォルト: 8)

対応策

CPU使用率が高い場合(送信・受信いずれか、または両方)

• 増設する
• phi_threashold を増やして誤摩化す。エラーメッセージに出ている phi の値を見て、それより大きい値を phi_threshold に設定する。すぐに recovered な warn メッセージが出ているようであれば、phi_threshold を増やすという手はアリだろう。
• heartbeat_interval の値を増やしてみる。udp heartbeat のパケットが減って cpu 使用率が減少する(筆者の環境では 1s を 10s にすることで 1/2 になった)。いじった場合、phi_threshold の調節も必要。また、recover_wait / heartbeat_interval の比率を保つように recover_wait の値も変更するとよい。

プラグインがブロックしている場合(送信・受信いずれか、または両方)

• ブロックしないように改修する. こちらが参考になるだろう => fluentdのoutputプラグインでブロックするものはBufferedOutputを使うべき — still deeper

そもそも heartbeat パケットが届いていない

• ネットワーク設定で udp をふさいでいないか確認。udp を空けたくないなら heartbeat_type で tcp へ変更も可能

heartbeat_interval を変更したら適切な phi_threshold の値が変わってしまった

• エラーメッセージに出ている phi の値を見て、それより大きい値を phi_threshold に設定する

問答無用で detach したくない場合

• とても大きな値にする

おまけ

そもそも phi ってなんぞ

• cassandra の論文を読みましょう、とのこと => The Phi Accural Failure Detector

detached forwarding server hard_timeout=true

ログメッセージの例

2014-03-11 00:53:34 +0900 [warn]: detached forwarding server 'host:22442' host="host" port=22442 hard_timeout=true

説明

hard_timeout (デフォルト 60s) の間、heartbeat への反応がなかった場合に出るメッセージ。 phi_threshold で detach されるよりも状況が逼迫していると思って良い。

該当コード行

out_forward.rb#L397

out_forward 関連パラメタ

• heartbeat_type (デフォルト: udp)
• heartbeat_interval (デフォルト: 1s)
• phi_threshold (デフォルト: 8)
• hard_timeout (デフォルト: 60s)
• send_tiemout (デフォルト: 60s) heartbeat_type tcp の場合のみ有効

よくある原因

基本的には phi_threshold の場合と同様。

対応策

基本的には phi_threshold の場合と同様。hard_timeout を大きくして誤摩化したところで 60s 以上の遅延が発生しているのだから対策を打った方がよい。

ネットワーク設定も疑ったほうがよい。次の章にまとめて記述する。

temporarily failed to flush the buffer 

2014-03-11 12:37:37 +0900 [warn]: temporarily failed to flush the buffer. next_retry=2014-03-11 12:37:37 +0900 error_class="Errno::ECONNREFUSED" error="Connection refused - connect(2) for \"192.168.0.2\" port 22442" instance=70182894105380

説明

こちらは heartbeat ではなくメッセージ送信が失敗した場合に出るメッセージ。実際のエラーはログの error_class などを見てググると良い。

さらに retry 上限を超えると retry count exceeds limit の warn メッセージが出る 

該当コード行

output.rb#L343

out_forward 関連パラメタ

• flush_interval (デフォルト: 60s) データを送信するインターバル。うちは 1s 運用。
• retry_wait (デフォルト: 1.0s)
• retry_limit (デフォルト: 17)
• max_retry_wait (デフォルト: なし)
• send_tiemout (デフォルト: 60s) データ送信のタイムアウト

よくある原因

受信側の Fluentd において、内部処理で時間がかかるなどしてブロックしている。

• 結果、in_forward のイベントループ内のデータを受け取る処理に入れていない

開いているソケットの数が多くなりすぎて１プロセスが開けるファイルディスクリプタの数を超えてしまっている。

• ログに Too many open files と出ている、など

受け付けられるTCP接続要求の上限値を超えている。

• ECONNREFUSED がたくさん出ている、など

対応策

CPU使用率が高い場合(受信)

• 増設する

プラグインがブロックしている場合(受信)

• ブロックしないように改修する. こちらが参考になるだろう => fluentdのoutputプラグインでブロックするものはBufferedOutputを使うべき — still deeper

開いているソケットの数が多くなりすぎて１プロセスが開けるファイルディスクリプタの数を超えてしまっている(送信・受信いずれか、または両方)

• Fluentd の out_forward はデータ送信のたびに TCP connection を貼り直すので、瞬間的に open socket の数が上昇しがち。開けるファイルの数を増やしておく。
• 起動スクリプトに「ulimit -n N」を書いて上限を増やす。limits.conf の設定を行う、などなど。
• lsof -p [PID] | wc -l や cat /proc/sys/fs/file-nr で開いているファイルの数を確認。

• 参考になるサイトのリンクを貼っておくが、ググって欲しい

  • Linux サーバでの「Too many open files」対策について - akishin999の日記
  • ulimitが効かない不安を無くす設定 | 外道父の匠
  • ファイルオープン数が上限値に達した|ざる魂

受け付けられる接続要求の上限値を超えている(送信・受信いずれか、または両方)

• 同様に、受け付けられる接続要求の数を増やしておく。
• net.core.somaxconn の値を引き上げる、など
• こちらも  cat /proc/sys/fs/file-nr で開いているファイルの数を確認。

• 参考になるサイトのリンクを貼っておくが、ググってほしい。

  • net.core.somaxconnについて調べてみた
  • DSAS開発者の部屋:高負荷サイトのボトルネックを見つけるには

今まで fluent-agent-lite の生存監視には fluent-plugin-ping-messge を利用していたのだが、agent を動かしているサーバをつぶしただけでアラートが飛んできたり、in_ping_message を動かしているノードがCPUあまってるのにデータを受け付けてくれなくて誤検知したり、元から agent が死んでいるとそもそも検知できない、などの問題があったので引退して普通に生存監視することにした。fluent-agent-lite の監視方法をまとめておく。

1. bin/fluent-agent-lite の生存監視

ふつうに ps auxww | grep fluent-agent-lite してみるのがよい。fluent-agent-lite は init スクリプト内でログごとにプロセスを立ち上げるので、/etc/fluent-agent-lite.conf のログ一覧をとってきて、さらにログパスで grep し、ヒットする行がなければ死んでいるという判断をする必要あり。

fluent-agent-lite.conf はシェルスクリプトなのでログ一覧は $LOGS を変数展開すれば取得できる。

bin/fluent-agent-lite が死んだ場合のログ

INFO レベルで出るが、デフォルトでは INFO ログは出ない。conf で LOG_VERBOSE=yes を設定すると出る。

2014-03-12T15:51:24 [INFO] (25118) SIGHUP (or SIGTERM) received at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 195
2014-03-12T15:51:24 [INFO] (25118) disconnecting to current server at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 199
2014-03-12T15:51:24 [INFO] (25118) disconnected. at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 204
2014-03-12T15:51:24 [WARN] (25118) SIGTERM received at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 206
2014-03-12T15:51:24 [INFO] (25118) process exit at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 209
2014-03-12T15:51:24 [INFO] (25118) Sending TERM to pid 25127 at /usr/local/fluent-agent-lite/bin/fluent-agent-lite line 262
2014-03-12T15:51:24 [INFO] (25118) process exit. at /usr/local/fluent-agent-lite/bin/fluent-agent-lite line 273

WARN レベルなのは、SIGTERM received だけなので、シグナル以外のなんらかの理由で不意に死んだことがわからない。 LOG_VERBOSE=yes にして、INFO ログも出力しておくことが推奨される（なお、INFOログの量はたいしたことない. DEBUGログは１つもない)

2. tail 子プロセスの生存監視

tail プロセスが死んだ場合は bin/fluent-agent-lite も死ぬのでそちらの死活監視だけでまかなえそう
=> 訂正: やっぱり defunct な tail プロセスがいないか監視したほうがよさそう(理由は後述)

子プロセスが死んだ場合どうなるか

1. fluent-agent-lite も死ぬ
2. 死んだことが検知された場合は、以下のエラーメッセージがログにでる

2014-03-12T15:42:19 [WARN] (8711) failed to read from child process, maybe killed. at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 227
give up to read tailing fd, see logs at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 228.
        Fluent::AgentLite::drain('Fluent::AgentLite=HASH(0x88e7d10)', 'IO::Handle=GLOB(0x88ca9c8)', undef) called at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 168
        Fluent::AgentLite::execute('Fluent::AgentLite=HASH(0x88e7d10)', 'HASH(0x88ca098)') called at /usr/local/fluent-agent-lite/bin/fluent-agent-lite line 252
        main::main() called at /usr/local/fluent-agent-lite/bin/fluent-agent-lite line 271

可能性としては、

I/O error with tail fd

がでることもありそう。

訂正: 対向 fluentd サーバにつながらないなどして reconnect ループしている場合は、tail のエラー処理に入れず fluent-agent-lite が死なない模様。そして tail が defunct (ゾンビ) の状態で残ってしまう。該当コード。

このレアケースもカバーしたい完璧主義な方は ps auxww | grep tail | grep defunct がヒットしないか監視すると良い。 うちはやらないことにしたけど。

コラム: tail 子プロセスのプロセス表示名はいじれるか？

tail プロセスの ps での表示名をいじって、通常の tail プロセスと区別がつきやすいようにしたかったのだが（誰かに間違って kill されたことがあると事例をきいたので、間違い防止のため)、どうも無理そうだった。tail コマンド自体をいじって中で prctl(2) を呼ぶとかできるようにしないと無理っぽい。

3. fluent-agent-lite の接続監視

送信に失敗した場合や、KEEPALIVE_TIME を過ぎた場合は、ランダムでノードを選択して reconnect する。

その接続失敗時にログに出る "waiting xx seconds to reconnect" の頻度(２回以上など)で監視する。
xx の値が 30 秒(任意)より大きいログが何度も出ているようならアラートを飛ばす、のようにすると良い。

実際に出るログは以下のようなかんじ

2014-03-12T16:49:55 [WARN] (5444) failed to connect to server ['localhost','20000'] : 接続を拒否されました at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 330
2014-03-12T16:49:55 [WARN] (5444) failed to connect to server ['localhost','21000'] : 接続を拒否されました at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 330
2014-03-12T16:49:55 [WARN] (5444) failed to connect servers, primary: ['localhost','20000'], secondary: ['localhost','21000'] at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 135
2014-03-12T16:49:55 [WARN] (5444) waiting 4 seconds to reconnect at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 136
2014-03-12T16:49:59 [WARN] (5444) waiting 8 seconds to reconnect at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 136

4. fluent-agent-lite の送信失敗監視

接続失敗時に、ログに "Cannot send data" と出るのでその頻度で監視できる。

実際に出るログは以下のようなかんじ

2013-11-21T21:11:21 [WARN] (21263) Cannot send data: パイプが切断されました at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 305.\n at /usr/local/fluent-agent-lite/bin/../lib/Fluent/AgentLite.pm line 321

このエラーが出ると別ノードへの再接続を試みるので、複数プロセスを立ち上げて Fluentd クラスタを組んでいる場合、エラーが出続けて問題になることはない。うちでは、不要とした。

5. inotify 監視

以下のようなエラーが出ていることがあった

/usr/bin/tail: inotify cannot be used, reverting to polling: Too many open files

$ cat /proc/sys/fs/file-nr
16320	0	2423842
$ sudo sysctl -a | grep fs.inotify
fs.inotify.max_user_instances = 128
fs.inotify.max_user_watches = 8192
fs.inotify.max_queued_events = 16384

$ ( sudo strace -s 1024 tail -F /var/log/boot.log 2>&1 ) | grep inotify
inotify_init()                          = 3
inotify_add_watch(3, "/var/log", IN_ATTRIB|IN_MOVED_TO|IN_CREATE) = 1
inotify_add_watch(3, "/var/log/boot.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF) = -1 EACCES (Permission denied)

$ ls -l /proc/${pid}/fd/
lr-x------ 1 sonots sonots 64 Nov 19 12:56 5 -> anon_inode:inotify
$ cat /proc/${pid}/fdinfo/5
pos:    0
flags:  00
inotify wd:2 ino:520054 sdev:800001 mask:800ac06 ignored_mask:0 fhandle-bytes:8 fhandle-type:1 f_handle:540052009caa5375
inotify wd:1 ino:520053 sdev:800001 mask:800ac06 ignored_mask:0 fhandle-bytes:8 fhandle-type:1 f_handle:5300520095aa5375