WebSocketで送信できているように見えるデータが欠損している件を調査した件

Network WebSocket
このエントリーをはてなブックマークに追加 follow us in feedly

こんにちは。プラットフォーム事業部の中村です。

以前の記事を執筆した際はR&Dチームに所属していたのですが、異動の機会があったので他サービスも経験して幅を広げたいなぁという思いで、それに乗っかって異動してはや2年くらい経ちました。 OPTiMでは言語だとかフレームワークだとか開発に関する裁量がチームにあるため、社内異動しただけでもかなり新鮮味があって刺激的な毎日を過ごしています。提供するサービスの広さがこういった世界観を生み出してるんだと思います。

閑話休題。

タイトルが某テレビ番組っぽくなりましたが、先日私が所属しているチーム内で開発しているAPIサーバーへ、別チームが開発しているクライアントから送信しているデータの一部が欠損するという事象が発生していました。これに対して調査を行っていたのですが、無事にクローズへと持っていけそうになったので残しておこうと思います。大それた内容ではないですが、バグやこういった事象に対してどういうアプローチをしていったかという点をお伝えできればと思います。

発端

とあるクライアントからサーバーに対してデータを定期的に送信するシステムがあり、細かいデータを連続して送る必要があるという特性を考慮して、WebSocketでデータをサーバー側へ送るという実装になっていました。ところがある日データを確認すると、いくつか送信したはずなのにサーバー側で格納されていないデータが存在するということが分かりました。この時クライアント上のログにはエラーがなく、クライアントから見るとサーバー側へのデータ送信は成功しているように見えていたので、私のチームへ確認の依頼が来ました。

調査過程

1.ログとデータを見る、再現環境を作る、そして祈る

まずは範囲を絞りたいので (1)クライアント側の問題なのか、(2)経路上の問題なのか、(3)サーバー側の問題なのかに目星をつけるために、それぞれのログを確認しました。クライアント側にもネットワーク起因で再接続したログなどはありましたが、欠損時間帯に近い時刻でのエラーログのようなものはこの時見つかりませんでした。

欠損したデータを確認していくと、常に発生するというわけではなく稀にしか発生しない現象だということがわかりました。再現条件を整えることが困難だと判断したため、再現する可能性のある環境を整える方向に舵を切り、クライアント側の開発チームと連携して開発環境でも本番と似たような状態を作り、再現するのをお祈りできる状態を作りました。併せてサーバー側はより詳細なログを取れるように、WebSocketで到着したデータの内部情報までログに出力する変更を行い、より詳細な検証ができる状態にしたものを開発環境へデプロイしました。

2.データ欠損のパターンを見る

上記対応を入れて放置すること数週間、同様にデータ欠損が開発環境でも無事に再現しました。この段階で環境差分による要因ではないということが併せて確認できました。同じようにログを確認すると、クライアント側のログにはデータ欠損のあったほぼ同時刻にはエラーは記録されておらず、継続してデータを送信しているログとなっていました。一方でサーバー側のログでは、そもそもに欠損したデータが到着した形跡がないことが分かりました。

ログの出力内容が正しいという前提で、この結果から(1)クライアントと(3)サーバーの問題ではなく、(2)経路の問題である可能性が高くなりました。現在OPTiMでは週3出社を原則としたレギュレーションになっており1、この時の情報の整理や洗い出しは出社日にメンバーでホワイトボードを囲みながら行っていました。オンラインホワイトボードサービスを利用してはいますが、こういった時は顔を合わせて「あれでもない」「これでもない」とディスカッションする方がスピードも、アイデアの幅も広いなと感じました。あくまで当人比です。

再現した際のログをより読み込んで欠損パターンを見ると、ポツポツと穴抜けに欠損するのではなく、一度欠損が始まるとしばらくの間（数分間）データ到着した形跡がサーバーのログから消え、しばらくすると届くようになるという事象になっていることが分かりました。以降、経路が不安定になっていたりするのではなく、何かのイベントを契機としてデータの欠損が起きているという 仮説をおいて確認を進めることにしました。

3. ログの範囲拡大して確認する

サーバー側はk8s(EKS)上に構築されており、ログ収集にDatadogを用いていました。Datadogより欠損が始まった同時刻に何かしらのイベントがないかを経路やEKSを中心に確認していくと、欠損が始まった時間帯にサーバーのPodのうちの1つがRestartしていることが分かりました。WebSocketの性質上ロードバランシングが難しく、対象のPodが落ちた場合に通信が切れてしまいますが、すぐに再接続すれば別の生きているPodに繋がるため、数分間欠損するということは考えにくいです。またPodのRestart自体も数十秒で完了するため、数分間の欠損とは時間が合いませんでした。

クライアント側では同時刻に切断イベントのエラーは出ていないという点、ネットワークアダプタをOffにして切断してみるとコネクションエラーは発生しており、再接続のロジックは機能しているという点など不可解な点は残りつつも、ここでは欠損は接続先のサーバー側のPodがRestartなどで落ちるイベントがトリガーになっているということが分かり、再現条件が整ってきました。

4. 仮定をもとに再現確認を行う

条件が整ったため、これらをもとに再度クライアント側のチームと連携して再現確認を行うと、確かにPodを強制的に落とすと数分間のデータ欠損が発生していることが分かり、確実に再現することがわかりました。調査を進めていると、PodがRestartして通信が切れているはずの時刻から ほぼ3分後に クライアント側でWebSocketの切断ログが出ているということが判明しました。この後、再接続ロジックが機能して再度サーバー側に接続された後に関しては再度データが正常に送信され、サーバー側でも受信できているという状態になっていることが確認できました。つまり、実際の切断タイミングとクライアント側でそれを認識するタイミングがほぼ3分遅れている 状態になっていました。

ここで発生している事象の全容がほぼほぼ把握でき、以下のように整理されました。

  1. サーバー側のPodがRestartするなど、Podが落ちるタイミングで欠損が起きる
  2. クライアント側で切断を検知するタイミングに必ず3分前後の遅延がある
  3. 3分間の遅延中に送られたデータが欠損扱いとなる
  4. 切断検知から再接続した後は正常な挙動に戻る

実際にWebSocketの接続が切れているタイミングから、クライアント側がコード上でそれを検知するまでの約3分間に送信したデータが欠損扱いとなっているというのが事象のようでした。

5. 原因を詰める

必ず約3分の遅延が生じるというみるからにキリの良い数字が出てきたので、次はこの数字がどこからきているのかを確認しました。試しに手元でPythonスクリプトを書いて同じような挙動をさせてみましたが、このスクリプトだとPodのRestartから20秒ほどで切断検知していました。WebSocket通信周りは以下のライブラリを使用しました。

ライブラリのドキュメントを見ていると内部でPing-Pongを自動的にやってくれており、このインターバルのデフォルト値が20秒だったので切断検知までの遅延と一致していました。(ドキュメントの引数のping_intervalを参照)

この結果をもとにクライアント側の実装を確認するとPing-Pongの機構は入っておらず、かつライブラリ側も自動で的に裏でPing-Pongをしてくれるわけではなかったため、コネクションの死活監視ができていなかったという点がわかりました。しかし遅延はするもののCloseイベントは呼び出されていたことから、TCPにおいてサーバー側が切断したときに流すRSTパケットの到着が3分遅れている可能性がありそうだということになりました。RFC6455 - 1.4. Closing Handshake参照のこと

この時にサーバー側のメンバーがインフラ周りの設定を確認してくださり、その結果として経路内のロードバランサー（Envoy）に以下の設定がされていることが確認されました。

httpConnectionManagerConfig:
  server_header_transformation: PASS_THROUGH 
  use_remote_address: true
# ....
  delayed_close_timeout: 180s

このdelayed_close_timeout: 180sに関してドキュメントを見ると、まさに今回の事象の通りとなっており、この設定値が引き金になってサーバー側が流したRSTパケットをLBが3分遅延させているという状態になっていました。デフォルトからの変更に関しては、過去に別問題に対しての解消案として変更が入っていたという経緯があったため、これをデフォルト値に戻せるかどうかは要検証という形でした。(デフォルトは1秒です)

対応策に関しては短期的にはクライアント側にPing-Pongの機構を入れ、現状よりは遅延を短くして検知できるように進める形になりそうです。これは欠損したデータに関してクライアント側で再送処理が行われるため、少々の欠損であれば再送処理で対応できるためです。中長期的にはdelayed_close_timeoutの設定値の見直しなど、いくつかインフラ周りで取れる策はありそうなので、継続課題となりそうです。

感想など

今回はバグではなく、過去に問題に対応するための設定値の変更が別の箇所で意図しない挙動をするという形で現れました。バグや不具合系に関して、よほど今年の運勢が良い（引き当てる確率という意味で）場合でなければ、調査して原因を絞り特定することはできると思います。原因を絞り込んでいったり、あたりをつけたりという点においては経験則が働く面もありますが、基本はログやコード、ドキュメントと真摯に向き合うということは大切だと思います。あとはいろいろな観点を持っているチームメンバーが集まることで、見えてくるものはあると思うので、めげずに頑張っていきましょう！

そしてOPTiMではバグや不具合調査が楽しめるメンバーも募集しています、採用ページもご一読ください。

謝辞

記事内いらすと素材： いらすとや 様

  1. 出社ルールは都度見直されているため、このブログを読んでいる現在変更されている可能性があります。↩