初めに
先日ALBに対してブラウザでアクセスを行う際一定確率(20~30アクセスに1度程度)で遅延するという現象に出会いました。
メトリクスを確認しても5XXエラーやALBからターゲットへの遅延も見られず原因のあたりをつけるのに若干手間取ったため備忘録として残しておきます。
原因
ELBに割り当てる特定のサブネットがプライベートサブネットになっていたことが原因でした。
これによりブラウザがプライベートサブネットに含まれるAZ側にアクセスが行われた際に接続が確立できず失敗するが、ブラウザ側がよしなに再試行してくれることで最終的に成功となることで「遅延」のように見えておりました。
現象
ブラウザからの観測
前述の通りこちらの現象必ずしも起きるわけではなく確率的に発生しました。
Google Chrome(MAC)でも数十アクセスに１度程度ではありますが定期的に発生が確認でき、またクライアントが別環境であっても同様の現象が発生していたため、当初はクライアント起因と考えておりましたがサーバ起因も十分考えられる状態でした。
まず事象を正確に把握するために遅延が発生した際の状態をChromeの開発者モードで確認したところ「初期接続」に大きく時間がかかっており、それ以降の通信については通常時と明確な差異は見られないものとなっておりました。
通常時は以下の通りで数百ミリ秒程度で応答を返します。
問題が発生する場合は以下のようにTLS確立前の初期接続段階で1分ほど時間がかかる状態です。
パケットの観測
これについてより詳細な状況を確認するためにパケットをキャプチャしたところ以下のような結果となりました、
状況としては1分と少しクライアント側からSYNをサーバに投げているもののその応答(SYN/ACK)がALBから帰ってこない状態となっており、その後別TCPストリームが開始しそれについては即時応答が返却されTLSハンドシェイクが始まっていることが確認できます。
(パケットを取った当時すぐに気づかなかったのですが)よく見てみると成功しているとTCPストリームと失敗しているTCPストリームで疎通先(ALB)側のIPが異なっている状態となりました。
今回実行した際ALBには以下のIPが割り当てられていました。
% dig half-public-alb-xxxxx.ap-northeast-1.elb.amazonaws.com a +short
35.72.82.187
176.34.27.49curlで上記IPを直接指定しアクセスしたところ35.72.82.187側は応答を返しますが、176.34.27.49側はタイムアウトを返すことがわかりました。
% curl http://35.72.82.187 -I
HTTP/1.1 200 OK
Date: Thu, 18 Jan 2024 04:48:33 GMT
Content-Type: text/html; charset=UTF-8
Connection: keep-alive
Host: 35.72.82.187
% curl http://176.34.27.49 -I
curl: (28) Failed to connect to 176.34.27.49 port 80 after 75007 ms: Couldn't connect to serverなお該当時刻前後のVPCフローログを接続元のIPで検索してみましたがALBにに割り当てているパブリックサブネットのIPのみが疎通先として表示されるため、プライベートサブネット側はそこまで到達できていないことが確認できます。
$ grep "yyy.yyy.yyy.yyy" *.log.gz
xxxxx eni-xxxxx yyy.yyy.yyy.yyy 192.168.3.131 60064 443 6 347 25369 1705552019 1705552041 ACCEPT OK
xxxxx eni-xxxxx 192.168.3.131 yyy.yyy.yyy.yyy 443 60064 6 749 1074220 1705552019 1705552041 ACCEPT OK
xxxxx eni-xxxxx yyy.yyy.yyy.yyy 192.168.3.131 60065 443 6 32 3576 1705552109 1705552129 ACCEPT OK
xxxxx eni-xxxxx yyy.yyy.yyy.yyy 192.168.3.131 60066 443 6 28 3598 1705552109 1705552129 ACCEPT OK
xxxxx eni-xxxxx 192.168.3.131 yyy.yyy.yyy.yyy 443 60066 6 24 21008 1705552109 1705552129 ACCEPT OK
xxxxx eni-xxxxx 192.168.3.131 yyy.yyy.yyy.yyy 443 60065 6 23 20935 1705552109 1705552129 ACCEPT OK明確に片側のAZで問題があることが確認できたためサブネットの設定等に問題がないかを確認したところ片系統がプライベートサブネットであることが発覚し、パブリックサブネットに変更することで解消を確認できました。
ブラウザにより結果は異なる
この現象は公式のドキュメントが見当たりませんでしたが以下のstack overflowの投稿を見る限り今回の状況で1分遅延するのはChrome側でタイムアウトがこの時間に設定されているからのようです(設定により異なる可能性有？)。
Chromeの仕様も絡んでいそうなので他のいくつかのブラウザはどのような挙動となるか確認してみます。
Firefoxの場合
Firefox(for MAC)で確認してみたところこちらは約5秒程度で見切りをつけてもう片側にアクセスしに行くようです。
また開発者モードで確認する限りこちらでは接続ではなくブロックとして解釈されていました。
ただバックエンド立ち上げ忘れて502 Bad Gatewayが返される状態で試した際にはもっと長い再試行を繰り返すケースも存在していました(以降再現せず)。
Safariの場合
Safariについては何度繰り返しても遅延が発生しないのでどうなってるんだろうと思ったのですが、SYN一発で応答がなければ再送処理を行なわずすぐさま次のIPに接続試行するようです。
※ 分かりづらいですが先頭の1パケットだけ別のTCPストリームになっています。
終わりに
良くも悪くもALBの冗長化に加えブラウザでよしなに処理されていたため誤設定により本来接続できない状況があるにも関わらずうまく処理されてしまっていた事案となりました。
こういったクライアント側の処理のおかげで多少のシステムトラブルも影響をクライアント側に感じさせにくい形で継続することができますが、原因特定がしづらくなる要素もあるのでなかなか難しいところです(利用者側から見れば良い面しかない気はしますが)。
今回の調査もあくまで私が観測したデータに基づくものでクライアント設定によってどの程度再試行が行われるか等異なる場合もありますのでご注意ください。
0
