分散ストリーミングミドルウェア「Apache Kafka」
岡田遥来氏：ではセッションを始めます。よろしくお願いいたします。
こんにちは。岡田遥来と申します。LINEでシニアソフトウェアエンジニアをやっていて、全社的に利用されるApache Kafkaプラットフォームの開発・運用を担当しています。
ご存じの方も多いかもしれませんが、Apache Kafkaは分散ストリーミングミドルウェアで、LINEでは最もよく使われるミドルウェアの1つです。高いスケーラビリティを備えているほか、ACLやQuotaといった機能も持っており、マルチテナントな運用が可能であるという特徴が挙げられます。
Kafkaについて簡単に説明します。1つのKafkaクラスターは、通常複数のブローカーと呼ばれるサーバーで構成されます。また、このKafkaにメッセージを送信するクライアントをProducerと呼び、同様にメッセージを受信してなんらかの処理をするクライアントをConsumerと呼びます。
私たちはLINEにおいて、単一のKafkaクラスターを複数のサービスで共有するという、マルチテナントモデルを採用しています。LINEやLINE公式アカウント、LINE広告を始めとしたさまざまなサービスが、私たちの提供するKafkaクラスターのユーザーです。
それぞれのサービスが、それぞれたくさんのProducerサーバー、Consumerサーバーを持っていて、それらに対するメッセージの転送を、私たちのクラスターが担っています。
現在、私たちのクラスターを利用するサービスの数は、100以上にのぼります。また、送信されるメッセージ数はピーク時で1,500万メッセージ毎秒、また1日当たりに流れる総トラフィックの量は1.4ペタバイトで、世界でも有数の規模です。
このような大規模なKafkaクラスターを高いサービスレベルで維持するため、私たちは日々パフォーマンスの計測や最適化、トラブルシューティングに努めています。私たちがこれまで行ってきた施策やトラブルシュートの事例などに興味のある方は、ぜひ2019年のLINE DEVELOPER DAYにおける私たちの発表もご覧ください。
さて、本日お話しするのも、私たちのクラスターにおいて発生した、とある問題についての紹介です。まず、発生した事象の概要についてお話しした後、どのような調査を行ったか、そして最終的にどのように問題を解決したかについて紹介いたします。
KafkaへのメッセージのProduceが失敗し始める
ある日のことです。私たちがちょっとしたKafkaに対する設定変更をロールアウトするために、Kafkaブローカーをローリング・リスタートしている最中、あるサービスの開発者から「私たちのサービスでKafkaへのメッセージのProduceが失敗し始めたんだけど、何か問題が起きていますか」との報告を受けました。
開発者から提供してもらったログから、Producerでリクエストがタイムアウトしてしまっているということがわかりました。これは設定されたタイムアウト内に、メッセージをKafkaに送信することができなかったことを意味します。ここで送信できなかったデータは失われてしまうため、これは大変クリティカルな事象です。私たちは、すぐさま調査を開始しました。
まず私たちは、Produceリクエストに対するブローカーのレスポンスタイムの上昇、これは例えばレプリケーションが遅延してしまっているなど、そういった理由で起こり得るため、これを疑ったんですが、ブローカーの示すメトリクスは、至って正常なままでした。
次に、なんらかの理由でProduceリクエストを継続的にリジェクトし続けてしまっている、例えばこれはレプリカがもう複数死んでしまっているような状況など、そういうのがあり得るのですが、これを疑いました。
しかしこれも、サーバー側でも特にエラーは出ていなかったし、Producer側でもリクエストタイムアウト以外のログは確認できず、該当しませんでした。
さらに調査を続けていくと、非常に奇妙な現象を観測しました。ブローカー側で計測しているレスポンスタイムは、先ほど見たとおり、いたって正常だったにもかかわらず、Producer側で計測されたリクエストレイテンシーは16秒以上といった、極めて異常な数値となっていました。
レイテンシーがこのレベルまで悪化しているとすると、先ほどリクエストタイムアウト起こっていましたが、これも自然に起こることが考えられます。
さらに奇妙な現象として、このような異常なレイテンシーの上昇が、Producerから特定のブローカーに対してProduceする際にのみ起こっていることもわかりました。そしてこのレイテンシーの悪化ですが、これはその特定のブローカーを、私たちがリスタートした直後から発生し始めたということもわかりました。
まとめると、私たちがそのあるブローカーをリスタートした直後から、Produceリクエストレイテンシーが顕著に悪化し始めた。しかしそのブローカーサイドのレスポンスタイムのメトリクスは、いたって正常なままという状況です。
この時点では、根本原因はまったく不明でしたが、私たちは一刻も早く、今まさに起こってしまっているデータロストに対処する必要がありました。
本来であれば、こういった現象に対しては、十分な調査の時間を取りたいところではありましたが、とりあえず問題のブローカーをもう1度リスタートしてみることにしました。そうすると、実際に現象がピタリとおさまってしまいました。
根本原因はどこにあるのか
さて、ひとまず状況は落ち着いたものの、再発を防ぐためには根本原因を突き止めなければなりません。まずはProducerとブローカー双方におけるレスポンスタイムのメトリクスが非常に大きなギャップを示していたということ、これがなぜ起こっているのか、理解する必要がありました。
Kafkaのコードを確認してみたところ、リクエストの送信自体に時間がかかると、こういったギャップが起こり得るという仮説が得られました。
どういうこというかといいますと、まずこの図のとおり、リクエストの処理時間が、どのように計測されているのかを考えてみます。
Producer側ではリクエストを生成して、それをブローカーに送信し始めて、それがブローカー側に届いて、ブローカーで処理をされて、かつ、ブローカーがレスポンスをクライアントに送り返して、そのレスポンスを完全に受信しきったところまで、というのがレイテンシーとしてカウントされます。
一方、ブローカー側のレスポンスタイムメトリクスというのは、リクエストを受信しきったところから、計測が始まります。したがって、リクエストの送信自体がなんらかの理由で遅延してしまうと、ブローカーのメトリクスにはそれが現れないということになります。
このようなリクエスト送信自体の遅延、これを引き起こす原因として、まず私たちはProducerのSenderスレッドという、ノンブロッキングI/Oを行っているスレッドがあり、これがなんらかの理由でスタックしてしまっていた、という仮説を立てました。
再現できない現象
この仮説を検証するためには、Producer側のデバックログや、ProducerはJavaで動いていますので、JVMのasync-profilerのプロファイルといった、クライアントサイドの詳細な情報が必要不可欠となります。
そこで私たちは、現象が発生したサービスの開発者に協力を要請し、本番環境で再現実験を試みることにしました。
具体的には、まずプロファイルを取る準備をしたうえで、再現してしまった際に素早く対応できるようにモニタリングをしておきます。そして問題が起こった同じブローカーをもう1度、もしくは再現するまで何度かリスタートしてみる、という実験です。
さて、実験を行ってみたものの、何度かブローカーをリスタートしてみたんですが、結局現象を再現することはできず、失敗に終わりました。
現在のところ、得られている材料が少ないうえに、このように再現性も低く、Producerがなんらかの理由でスタックしていたかどうか、検証するのは非常に難しいということが判明しました。
次に、もう1つリクエスト送信自体の遅延を引き起こし得る原因として、問題のあったProducerとブローカーという、特定のネットワークの経路において、ネットワークのパフォーマンスが悪化してしまっていたのでは、と仮説を立てました。
こちらについても、簡単にpingでレイテンシーを計測してみたんですが、こちらは至って正常でした。また、他にTCPのリトランスミッションが増えていたり、もしくは帯域がサチュレーションしてしまっていたりといった、ネットワークレベルの遅延を引き起こし得るような他の現象も観測されませんでした。
さてこのように、調査は非常に難航しました。そうこうしているうちに、残念ながら今度は前回最初に起きた時とは異なるサービス、また異なるブローカーにおいて、まったく同じ問題が再発してしまいました。
観測された現象は初回とまったく同じで、その問題が起きたブローカーをリスタートした直後から、Producer側で急激にリクエストが遅延し始める。しかしブローカー側で取っているレスポンスタイムのメトリクスおよび他のパフォーマンスのメトリクスは至って正常なまま。また、そのブローカーを再度リスタートすることで直ってしまう、というものでした。
遅延に関連し得るパターンを探す
さて、複数回の発生事例を得たことから、私たちはこれらの事例に共通するような、リクエスト送信の遅延に関連し得るなんらかのパターンを見つけられないか、と探ってみることにしました。
数多くあるメトリクスを注意深く一つひとつ観測していくと、ブローカーをリスタートした際に、nodeエクスポーターのSyncookiesSentというメトリクスがあるんですが、これが問題が発生する場合のみ、顕著なスパイクを示しているということがわかりました。
このSyncookiesSentメトリクスの上昇というのは、何を意味しているのでしょうか。これについて説明したいのですが、まずこのためにTCP SYN Cookiesというものについて簡単に紹介します。
TCP SYN Cookiesというのは、いわゆるSYN flood攻撃に対処するためのメカニズムです。まずTCPの3-way handshakeについて、簡単に復習します。
TCPでは、まずクライアントがコネクションを開きたい時、サーバーに対してSYNパケットを送信します。サーバーはそれをSYN Queueに追加した後、SYN ACKパケットをクライアントに対して返信します。最後にクライアントはそれを受けてACKをサーバーに送り返します。そしてそれを受けてサーバーはSYN Queueに取っておいたSYNエントリーを取り出して、コネクションを確立し、handshakeが完了となります。
SYN flood攻撃では、まず悪意のあるクライアントが、大量のSYNパケットをサーバーに対して送信します。ここでhandshakeの最後のステップとして、本来SYN ACKが送り返しされてきて、それに対してクライアントがACKをサーバーに送り返す必要があるんですが、これを悪意のあるクライアントは送らずに、サーバーからのSYN ACKを無視します。
こうなると、サーバーはずっと完了しないSYNをSYN Queueに放置し続けることになり、いずれSYN Queueがいっぱいになります。そして、悪意のない通常のクライアントからの接続も受け付けられなくなってしまうという、1種のDoS攻撃です。
TCP SYN Cookiesというのは、このようにSYN floodが起きてしまっている状態においても、クライアントからの接続を受け付けられるようにするための仕組みです。
ここではLinuxカーネルを前提として話を進めますが、このようにSYN floodが起きてSYN Queueがいっぱいになってしまうと、LinuxカーネルはSYNパケットをSYN Queueに格納する代わりに、SYNに含まれている情報をうまいことinitial sequence numberにエンコードして、SYN ACKパケットに埋め込んでクライアントに送り返します。そして、もうSYN Queueには入れないで、Reply and forgetしてしまいます。
そして、後でクライアントがSYN ACKを受けてACKを送り返してきた時に、sequence number、そこにSYN Cookiesがエンコードされているので、これをデコードして、もともと持っていたSYNの情報を取り出して、コネクションを確立して、handshakeを完了します。
SYN CookiesSentメトリクスのスパイクは、クライアントからSYNを受け取ったが、SYN Queueがいっぱいだったので、代わりにこのような、今見てきたフローのとおりSYN Cookiesを送って、通常とは異なる方法でhandshakeを行った数を示します。
なぜSYN floodが起こってしまったのか
さて、SYN CookiesSentメトリクスがスパイクしていたということは、つまりブローカーがSYN flood状態にあったということです。なぜSYN floodが起こってしまったのかを考えます。
まず問題が起こったブローカーを含めて、私たちのクラスターのブローカーは、たくさんのProducerやConsumerといったクライアントからの接続を受けています。
ここでブローカーをリスタートした時に何が起こるかというと、まずこのブローカーに接続していたクライアントのコネクションは、すべて1度他のブローカーにフェイルオーバーします。
そしてブローカーのリスタートが完了して戻ってくると、もともと接続していたクライアントたちが一気に元のブローカーに再接続を行います。これが実質的に攻撃のような状況を引き起こして、ブローカーがSYN flood状態になってしまったというわけです。
問題が起こってしまったブローカーは、18,000を超えるクライアントからのコネクションを持っていたため、こういったことが起こり得ることは、自然に考えられました。
（後半につづく）
