概要
構築したWebサービスのレスポンスがエラーにはならないもの、1分近くかかる事があり、原因がわからず先輩エンジニアさんに泣きついたところ、突き止め方を教えてもらえたので経験としてまとめておく。
この場を借り先輩エンジニアさん方には改めてお礼申し上げます。本当にお力添え感謝致します。ありがとうございます。
また、本記事は奇跡を記したもので、解決方法は一切記載していない。
症状
ブラウザからの当該Webサービス上での継続リクエストでは特段問題ないものの、数分ブラウザを放置し、その後リクエストを送るとレスポンスが帰るまで約1分くらいかかる。
エラーは出ないものの（最初は別件でエラーが出ていたのでこちらで解決した→https://qiita.com/miriwo/items/a681350ba37164f5c3ea）
構成概略図
本当はもっと複雑だが簡単に図にしておく。矢印がクライアントからのリクエストを表す。もちろんレスポンスはこの矢印とは逆の方向でクライアントに戻る。
自身の場合の原因（確定ではない）
Route53でのAレコード名前解決で1分強かかっておりここで時間を食っている模様
（ちなみに先輩エンジニアさんは症状を聞いただけで原因がDNS周りであることを予想されておりました。）
問題を突き止めるまでの奇跡
軌跡を記す前にメタい情報をまとめておく（本件はあくまで手動計測なので厳密ではない）
- ブラウザの画面駆動でリクエストを投げた時間： 23:50:30くらい
- ブラウザでレスポンスがあって画面が切り替わった時間： 23:51:45くらい
Apacheのログ確認
まずは最深部のログを確認する。
これによりApacheがいつレスポンスを返したかを確認できる
Apacheのログの場所は下記記事でまとめた。
HTTPメソッドとリクエストパス内容からログを特定し、Apacheが最初にリクエストを受け取ったのは 23:51:42である事がわかった。
これはクライアントにレスポンスが帰る直前ということであり、Apacheからレスポンスが返る処理の間時間がかかっているわけではないことが分かった。
Nginxのログ確認
次にリバプロのNginxのログを確認する。
これにより、下記図の赤色丸部分で余計に時間がかかっていないかを確認する。
Nginxのログの場所は下記記事でまとめた。
HTTPメソッドとリクエストURLの内容からログを特定し、Nginxが最初にリクエストを受け取ったのはApacheと同じ23:51:42である事が分かった。
これも時間的にレスポンスが帰る直前ということであり、Nginx → Apacheで時間がかかっているわけではないことが分かった。
ALBのアクセスログと接続ログ確認
次にALBのアクセスログと接続ログを確認する。
これにより、下記図の赤丸部分で余計に時間がかかっていないかを確認する。
ALBのアクセスログと接続ログは自動で出力されない。別途設定が必要なので下記を参考に設定をしていただきたい。
まずアクセスログで、HTTPメソッドとリクエストURLの内容でログを特定し、ALBに最初にアクセスがあったのはこれまでと同じ23:51:42である事が分かった。更にリクエストを送ったクライアントIPもログから読み取ることができた。
更にALBから最深部側の処理が0.011ミリ秒で完了しているっぽい情報もログから読み取れた。これでALBより深い場所で悪い事が起きている可能性はほぼなくなった。
更に接続ログで、アクセスログから分かったクライアントIPでログを特定し、ALBに到達したリクエストはsuccessステータスで返っていることが分かった。
Route53のクエリログ確認
最後にRoute53での名前解決クエリログを確認する。
これにより、下記図の赤丸部分で余計に時間がかかっていないかを確認する。
Route53のクエリログは自動で出力されない。別途設定が必要なので下記を参考に設定をしていただきたい。（ログ出力先のCloudWatchのリージョンはバージニア北部になる。ご注意いただきたい。）
ログを確認すると「ブラウザの画面駆動でリクエストを投げた時間： 23:50:30くらい」と「ブラウザでレスポンスがあって画面が切り替わった時間： 23:51:45くらい」の間でAレコード → Aレコード → AAAレコード → HTTPSレコードというように名前解決をしているログが発見された。※クエリログにリクエストの情報は記載されていない。そのためリクエストを投げた大体の時間とレスポンスがあった大体の時間からこれらの問い合わせログがあり、更に自身以外インターネットからのリクエストが絶対無いと言い切れる状態だったのでこのログが今回のリクエストであると断定した。（もちろんヘルスチェックは動いているがALBの外からのアクセスは自分だけだった。）
ログを確認したところ、1個目のAレコードクエリタイムスタンプが23:50:27で、2個目のAレコードクエリタイムスタンプが23:51:42となっていた。ここで1分強時間がかかっている。おそらくここが悪さしている。
ちなみに、AAAレコード、HTTPSレコードのクエリは23:51:42のタイムスタンプになっている。このことからこのクエリでは時間はかかっていない。
そのため先に「原因」で記載したように今回の根本原因は名前解決時に何かしらの問題で時間がかかっているためだと予想した。
後日談
実は本件の原因は名前解決ではなかった。
筆者が作成したサブネットの構成がおかしかった。
本来、ALBを設置するパブリックサブネットとALBのターゲットのインスタンスが設置されるプライベートサブネットは同様のAZである必要がある。しかし筆者はパブリックサブネット → 1a、プライベートサブネット → 1dに設定しておりここで通信がうまくいかなかった模様である。
弊チームのインフラエンジニア様が原因を突き止めてくださいました。本当にありがとうございます。お手数をおかけしてすみませんでした。
