Repro インフラチーム (SRE + 分析基盤) の伊豆です。今回は、Repro のデータ収集基盤で私たちが遭遇した問題を紹介したいと思います。
具体的には、AWS Network Load Balancer(NLB) + Fluentd の構成でファイルディスクリプタが枯渇する謎の現象に遭遇したので、その問題の調査記録と解決策を共有します。また、この問題を解消するにあたり Fluentd に PR を送ったのでそれの紹介もします。
https://github.com/fluent/fluentd/pull/2352
データ収集基盤の構成
Repro のデータ収集基盤はFlunetd High Availability Configをもとに構成され、大まかに次のようになっています。
SDK からアップロードされたデータは、転送用 Fluentd(log forwarders)を経由して集約用 Fluentd(log aggregators)に集約され、S3 や BigQuery などさまざまなデータストアへ転送されます。集約用 Fluentd は NLB の配下にあり、NLB が集約用 Fluentd の負荷分散を担っています。また、ECS 上で動いているコンテナのログも集約用 Fluentd に送信し、S3 や CloudWatch Logs といったサービスに転送しています。
No file descriptors availableに悩まされる
上記の構成で運用していたところ、集約用 Fluentd が起動してから数週間経つとNo file descriptors availableが発生する問題に遭遇しました。集約用 Fluentd の ulimit や /proc/sys/fs/file-max は起動する転送用 Fluentd とコンテナの数に対して十分大きな値を設定しているため、不可解に思いながら調査を始めました。
調査の結果、No file descriptors availableの原因は、次のようになっていることが分かりました。
- 集約用 Fluentd と転送用 Fluentd もしくはコンテナとの間で確立したコネクションが、何らかの理由でそれらが終了した後もクローズされずに残り続ける
- そのため、集約用 Fluentd で確立済みのコネクションが増え続け、使用可能なファイルディスクリプタが枯渇する
さらに詳しく調べると、クローズされずに残り続けるコネクションの多くは接続先がターミネートされたインスタンスの IP アドレスになっていました。
下記は集約用 Fluentd が動いているインスタンスでnetstatを実行した結果の一部です。
$ netstat -atp Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 0.0.0.0:ssh 0.0.0.0:* LISTEN - tcp 0 0 localhost:smtp 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:24220 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:24221 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:24224 0.0.0.0:* LISTEN - tcp 0 0 ecs-repro-fluentd:24224 sfr-repro-staging:20640 ESTABLISHED - tcp 0 0 ecs-repro-fluentd:24224 172.31.27.152:58296 ESTABLISHED - tcp 0 0 ecs-repro-fluentd:24224 172.31.26.95:52414 ESTABLISHED - tcp 0 0 ecs-repro-fluentd:24224 172.31.18.99:41334 ESTABLISHED - tcp 0 0 ecs-repro-fluentd:24224 172.31.31.146:57346 ESTABLISHED - tcp 0 0 ecs-repro-fluentd:24224 172.31.17.245:47058 ESTABLISHED - tcp 0 0 ecs-repro-fluentd:24224 172.31.19.115:64470 ESTABLISHED - (snip)
ecs-repro-fluentdは集約用 Fluentd のホスト名です。上記のように集約用 Fluentd には、 Local Address が集約用 Fluentd のホスト名、Foreign Addressは IP アドレスとなっているコネクションが多く存在していました。それらの IP アドレスを調べてみると、すべてターミネートされたインスタンスのものとなっていました。
そのため、最初は Fluentd プロセスが終了する際にコネクションがクローズされない不具合を疑いましたが、同様の問題は再現しませんでした。
増え続けるコネクションの原因を特定する
結論からいうと、集約用 Fluentd でコネクションが増え続けた原因は、アイドルタイムアウトが発生したときの NLB の挙動にありました。NLB は、通信のないアイドル状態が 350 秒以上続くと、該当のコネクションをクローズします。その後、そのコネクションを利用する通信があった場合、NLB は送信元(クライアント)に RST パケットを送りますが、送信先(ターゲット)には RST パケットを送らない仕様になっています。
アイドルタイムアウトよりも長い時間、クライアントからもターゲットからもその接続経由でデータが送信されない場合、接続は閉じられます。アイドルタイムアウト期間の経過後にクライアントがデータを送信した場合、TCP RST パケットを受信して、接続が無効になったことを示します。
つまり、クライアントが転送用 Fluentd の場合、次のような流れで集約用 Fluentd のコネクションが増え続けます。
- 転送用 Fluentd が NLB の配下の集約用 Fluentd にデータを送信する
- NLB のアイドルタイムアウト(350 秒)以上の時間が経過する
- 転送用 Fluentd が NLB の配下の集約用 Fluentd にデータを送信する
- 転送用 Fluentd は NLB から RST パケットを受け取りコネクションを切断する
- 転送用 Fluentd は集約用 Fluentd と再接続しデータを送信する
- 集約用 Fluentd にはステップ 1 と 5 で確立されたコネクションが存在する
集約用 Fluentd のようにクライアントからデータを受信し続けるプロセスの場合、NLB から RST パケットを受け取る機会がないため、アイドルタイムアウトが発生したコネクションはクローズされずに残り続けます。この問題は NLB のアイドルタイムアウト値以上の間、通信のないことが発生条件となっているため、データの送受信の少ないステージング環境や開発環境で再現しやすいです。
この NLB の挙動に気づくきっかけとなったのは、コンテナの Fluentd logging driver のログに、NLB からコネクションを切断された記録が残っていたことです。
$ sudo journalctl -u docker.service (snip) 2月 20 08:02:12 sfr-repro-staging-i-0b8ab7f17da57e247 dockerd[3928]: time="2019-02-20T08:02:12.883766967Z" level=error msg="Failed to log msg \"\" for logger fluentd: write tcp 172.31.9.238:24096->172.31.15.218:24224: write: connection reset by peer" 2月 20 08:02:12 sfr-repro-staging-i-0b8ab7f17da57e247 dockerd[3928]: time="2019-02-20T08:02:12.988078563Z" level=error msg="Failed to log msg \"\" for logger fluentd: fluent#send: can't send logs, client is reconnecting"
172.31.15.21は NLB の IP アドレスです。上記のログは、NLB がコネクションを切断したため、再接続して集約用 Fluentd にログを送信したことを示しています。実際にnetstatで調べてみると、172.31.9.238:24096と172.31.15.218:24224間のコネクションが、コンテナが起動しているインスタンスになく集約用 Fluentd にはESTABLISHEDのまま存在していました。
なお、このように接続先に切断されたことが伝わらずに、アクティブの状態で残り続けるコネクションはハーフオープンの状態にあると言われるようです。
Half-Open Connections and Other Anomalies
An established connection is said to be "half-open" if one of the TCPs has closed or aborted the connection at its end without the knowledge of the other, or if the two ends of the connection have become desynchronized owing to a crash that resulted in loss of memory
解決策
集約用 Fluentd のようにデータを受信し続けるプロセスで、ハーフオープンなコネクションが増え続けるのを防ぐにはどうすればよいか調査したところ、TCP keepalive と呼ばれる仕組みを利用できそうだということが分かりました。
TCP keepalive とは、カーネルが一定期間通信のないコネクションに対してキープアライブパケットを送信し、応答がない場合にコネクションを切断する機能です(参考: TCP Keepalive HOWTO)。TCP keepalive はデフォルトで無効になっているため、ソケットオプションを利用して明示的に有効化する必要があります。
Fluentd のin_forwardプラグインには、データを受信するたびに接続を切断するdeny_keepaliveオプションはありますが、TCP keepalive を有効にするためのオプションがありませんでした。そのため、in_forwardプラグインに TCP keepalive を有効化するための PR を送りました。
https://github.com/fluent/fluentd/pull/2352
上記の PR では、in_forwardプラグインにsend_tcp_keepaliveというパラメータを追加し、それが設定されていればBasicSocket#setsockoptを利用して TCP keepalive を有効化します。
TCP keepalive が有効になった場合、Linux では次の 3 つのパラメータによって挙動が制御されます。
$ sysctl -A | grep "net.ipv4.tcp_keepalive" net.ipv4.tcp_keepalive_intvl = 75 net.ipv4.tcp_keepalive_probes = 5 net.ipv4.tcp_keepalive_time = 7200
上記の場合、最後のパケットが送信されてから 7200 秒経過したときに、75 秒間隔で 5 回キープアライブパケットが送信され、応答がない場合そのコネクションは切断されます。
Fluentd のドキュメントにはまだ記載されていませんが、 send_tcp_keepaliveは Fluentd 1.4.2 から使用可能になっています。実際に問題が発生した環境で Fluentd をアップデートし TCP keepalive を有効化したところ、集約用 Fluentd でコネクションが増え続ける問題は解消し、今のところNo file descriptors availableは発生していません。
まとめ
今回は、Repro のデータ収集基盤で起こった、ファイルディスクリプタが枯渇する問題とその原因、解決策を紹介しました。この問題の原因を特定し解決するまでに、ソケットがクローズされないケースを調べたり、NLB の挙動を実験したり試行錯誤を繰り返したため、予想以上に時間がかかってしまいました。本記事が、同様の問題を調査するときの参考になれば幸いです。
最後に、インフラチーム (SRE + 分析基盤) ではエンジニアを募集中です！もし興味を持っていただけるようでしたら、ぜひご応募ください。
