はじめに
先日、VPC Lattice をサービス間通信採用しているシステムで、1日に数回 TCP コネクションリセットによる通信エラーが発生することを発見しました。
今回は、原因調査とその解決法についてまとめていきます。
事象について
弊社はオブザーバビリティサービスとして、Datadog を利用しております。
普段エラーログの監視を行う中で、特定のエラーが1日に数回起きていることがわかりました。
エラー内容は以下のとおりです。
Error: read ECONNRESET
これはNode.js アプリケーションから、通信先にTCP通信を行う際、ターゲット（VPC Lattice Service）から強制的に接続が中断されたことを意味します。
今回の構成だと、ECS on Fargate 上で動作するアプリケーション（以下、クライアントと呼ぶ）から、別の ECS 上のアプリケーション（以下、ターゲットと呼ぶ）へ VPC Lattice Service 経由で通信を行なっていますが、この経路のどこかで接続がリセットされたと考えられます。
原因調査
まず、比較的簡単に取得できる、以下のログを CloudWatch 経由で収集します。
- VPC Lattice アクセスログ
- VPC フローログ
そして、問題の事象が起きた時点のログを確認していきます。
この調査で以下のことがわかりました。
- クライアントからの通信は正常に記録されている
- ターゲットの VPC アクセスログおよび VPC フローログに該当の通信が記録されていない
このことから、おそらく VPC Lattice Service が RST パケットを送信しているのではないかと推測できました。
次に、もう少し詳細なパケットの流れを把握するため、ECS のタスク上の TCP パケットを tcpdump で取得していきます。
こちらは、先ほどのログ取得とは違って、ECS Exec コマンドを利用して、コンテナ内にアクセスし、tcpdump を実行する必要があり、比較的手間がかかる作業でした。
事象が起きた時刻での TCP パケットを確認してみます。
VPC Lattice のターゲットリスナーのポートは 80 で設定してあるので、grep コマンドを使用し、ポート 80 でフィルターします。
03:22:43.794429 IP ip-x-x-x-x.service.example.local.41728 > y.y.y.y.80: Flags [P.], ...
03:22:43.794896 IP y.y.y.y.80 > ip-x-x-x-x.service.example.local.41728: Flags [.], ...
03:22:43.881892 IP y.y.y.y.80 > ip-x-x-x-x.service.example.local.41728: Flags [R.], ...
上記のログから、ECS タスク（ip-x-x-x-x.service.example.local）が VPC Lattice Service のエンドポイント（y.y.y.y）にパケットを送信した直後に、Lattice 側から R フラグ が立っているパケットを返していることがわかります。
つまり、アプリケーションのデータ送信要求に対して、Lattice 側が RST パケットを返しています。
では、この TCP コネクションが確立されたのはいつでしょうか。
もう少し過去のログを遡ってみると以下が記録されていました。
03:21:22.760166 IP ip-x-x-x-x.service.example.local.41728 > y.y.y.y.80: Flags [S], ...
03:21:22.761468 IP y.y.y.y.80 > ip-x-x-x-x.service.example.local.41728: Flags [S.], ...
エフェメラルポートが 41728 番で一致しているかつ、Sフラグ が立っているため、このパケットが TCP コネクションの確立時のパケットであること可能性が高いです。
さらに、これらのパケットのタイムスタンプから、コネクション確立から次のパケットを送信するまでの時間の差分は約 60秒間 であることがわかります。
この調査結果から、AWS サポートチームにも確認を取ったところ以下のことがわかりました。
VPC Lattice Service のアイドル時間である 60秒 から Lattice Serviceが FIN パケットを送信する 66秒 の間に、クライアントが同じ TCP 接続を使用してパケット送信を行うと、強制的に RST パケットが返される仕様となっているとのことでした。
対応策
原因調査の結果、クライアントが VPC Lattice Service へ最後にパケットを送信してから 60秒 ~ 66秒 の間に再度パケットを送信すると、TCP接続がリセットされてしまうことがわかりました。
この問題に対する解決策として考えられるのは2つです。
- アプリケーションのアイドルタイムアウト時間を 60秒 以下にする
- アイドル時間が 60秒 を超えないように、定期的にパケットを送信する
そもそも TCP 接続では、パケット送信を行う際、接続の確立（3ウェイハンドシェイク）処理が実行されます。
しかし、パケット送信の頻度が増えてくると、毎回接続の確立を行う必要があり、それによるパフォーマンスの低下が起きてしまいます。
HTTP/1.1 以降の HTTP 通信では、オーバーヘッドの回避策として、一定時間同じ接続を使い回すという特徴あります。
つまり、その同じ接続の使い回しがタイムアウトする時間（パケットが送られなくなってからの時間）をアイドルタイムアウト時間と呼びますが、これを短くすればするほど、オーバーヘッドが増える可能性があります。
今回は、VPC Lattice Serivce のアイドル時間が 60秒 で固定であることと、アプリケーションのアイドルタイム時間を短くすることによるパフォーマンスの低下はほぼないと判断したことから、解決策の1つ目の アプリケーションのアイドルタイムアウト時間を 60秒 以下にする という対応を行うことにしました。
アプリケーションのアイドルタイムアウト時間を変更した後は、同一の事象は起きなくなったことが確認できました。
おわりに
今回は、意図しない TCP コネクションリセット現象の調査と対策を行いました。
VPC Lattice 上での事象でしたが、マネージドサービスだと、技術的な細かい設定から解放されるというメリットがある反面、制約が大きいことが多いです。
ドキュメントに明示的に書かれていない仕様も存在するため、使う際には十分に調査と検証を行った上で使用するようにすべきですが、本番環境を完全に模倣した検証を行うことは困難な場合が多いです。
本番環境で起こったトラブルについて、調査するスキルが重要になってくると改めて感じた瞬間でした。
この記事が、TCP レイヤーでのインシデント調査について、少しでも役に立てたら幸いです。
Discussion