エンジニアの佐藤です。こんにちは。今回はネットワークインフラのお話を書かせていただきたいと思います。
始まりは不具合連絡から
猛暑が続くある日のこと、お客さまから、とある開発システムの、とある機能が「動かないんだけど」という連絡を受けました。
筆者はすぐに問題現象を確認しましたが、確実に再現し、弁解の余地はありません。お詫びして、原因調査に取りかかりました。
この機能の実装はこうです。Salesforce(Visualforceページ)からApex処理を経て外部システムAにRESTリクエストを送信する。外部システムAはさらに外部システムSにRESTリクエストを送信する。レスポンスは順次回収され、適宜加工され、結果がSalesforce画面に表示される、というものです。
図に描くとこんな感じです。
報告された問題現象とは、ブラウザが10秒ほど応答停止したのちに、エラーが画面に表示されるというものです。エラーの内容から、筆者は、Salesforceがまともなレスポンスを受け取っていないんだろうと推測しました。そして10秒ブロックですから、一連のリクエスト連鎖のどこかでタイムアウトしたんだろうと思いました。筆者は外部システムAのログを観察しました。すると。。。外部システムSをリクエストする直前のログを最後に足取りが途絶えていました。
きっとSalesforceからシステムAへのリクエストが10秒でタイムアウトし、Visualforceページのエラーへとつながっていったのでしょう。
図に描くとこんな感じです。
システムSは「シロ」
次に筆者が疑ったのは、システムSです。実はシステムSは今回の機能開発に合わせて平行開発されたもので、開発中は多少問題があったこともあったのです。筆者はシステムAの内部から、Pythonの即席コードでシステムSにリクエストしてみました。すると。。。何の問題もなくレスポンスがあります。
原因は「聞か猿」ではなく「言わ猿」
「他人を最初に疑うのは良くないよな」と反省した筆者は、問題現象発生時のパケットキャプチャを採取することにしました。すると。。。システムSへのリクエストはそもそも送信されていないことがわかりました。そんなバカなと思って2度3度やってみましたが、結果は変わりません。技術者たる者、事実の前には謙虚でなくてはなりません。 リクエストがタイムアウトしたのではなく、そもそもリクエストしていなかったのです。
ここで筆者は困ってしまいました。というのも、このシステムA、他にも似たような処理を常時続けており、そちらには何の問題もないからです。DockerコンテナのJava実装された単一のプロセスで、あっちはよくてこっちはダメという状態なのです。システムAからリクエスト可能であることは、図3で確認されていますから、原因はシステムA側にあるはずです。
リブートで回復するが、再び発生
筆者はこの段階で、Dockerコンテナの再起動を考えました。どう考えてもおかしいので、コンテナプロセス内部に何か一時的な問題が起こっているのだろうと考えたのです。幸いロードバランサ化のコンテナクラスタで、ドレーンしてから再起動することで無停止再起動が可能でしたので、許可を得て実行しました。すると。。。ログにソケット強制クローズの警告が数十個出力されました。スローされた例外は org.apache.http.impl.execchain.RequestAbortedException 、「リクエストしたが、返事が来る前に、棄てられた。」
そんなばかな。システムSへのリクエストは、システムAにログインしてPython即席コードを実行すれば、通るのですよ。受信待機になるはずがないのです。DockerコンテナでBridgeネットワークを経由している点がPython即席コードと違うといえば違いますが、リクエスト先がシステムS以外の場合は成功しており、Dockerが原因とは考えにくい。
その一方で、コンテナ再起動により当初の機能は回復しました。レスポンス待ちのソケットを強制クローズすれば、システムAからシステムSの、新しいリクエストは通るのです。謎は以下2つに絞り込まれました。
- なぜ受信待機のソケットが多数発生したのか。
- 受信待機のソケットが多数発生すると、なぜシステムSへのリクエスト だけ が送信されなくなるのか。
そのうち調査するか。。。と思っていた筆者でしたが、翌日再びお客さまから「やっぱり、動かないんだけど」の連絡が。。。
そんなばかな。。。こうなるともう逃げ道はない。筆者は覚悟を決めて徹底追及することにしました。
NATに目をつけ、受信待機ソケットの再現に成功
筆者は再び機能不全に陥ったシステムAを調査し、Dockerコンテナプロセスに多数の受信待ちソケットがあることを確認しました。
なぜこのようなソケットが発生するのか？筆者が次に疑ったのは、NATでした。実はこのシステムA、AWS VPCのプライベートネットワークセグメントに立てられたECSクラスタ上のサービスとして実装されており、アウトバウンドリクエストはVPCのNATゲートウェイを経由することにしていたのです。NATゲートウェイの詳細な仕様は以下の公式ページに書かれています。
Comparison of NAT Instances and NAT Gateways
https://docs.aws.amazon.com/AmazonVPC/latest/UserGuide/vpc-nat-comparison.html
詳しく読んでいくと、タイムアウトに関する以下のような記述がありました。
Timeout behavior
NAT Gateway: When a connection times out, a NAT gateway returns an RST packet to any resources behind the NAT gateway that attempt to continue the connection (it does not send a FIN packet).
NAT Instance: When a connection times out, a NAT instance sends a FIN packet to resources behind the NAT instance to close the connection.
NATについては、以前AWSはNAT用に特別調整したAMI(NAT Instance AMI)を提供して適宜使ってくれという姿勢でしたが、ある時からこれがサービス化され、NATゲートウェイと名付けられました。そして、その際になぜか、仕様が変わったようです。今回使っているのはNATゲートウェイですから、仮にもしシステムSへのリクエストがタイムアウトすると、システムA側には、何も通知されない。システムAから何か催促すればRSTパケットを返すとありますが、 HTTPリクエストが終わっていて、TCPキープアライブも設定されていなければ(今回は設定されていない)、そのような催促はない。永久待機です。
疑い深い筆者は、Python即席コードで悪いHTTPサーバーを書いて、受信待機ソケットの再現を試みました。
PORT = 8000
def Handler(request, client_address, server):
n = int(sys.argv[1])
print('wait {} secs'.format(str(n)))
time.sleep(n)
print('no response return')
with socketserver.TCPServer(("", PORT), Handler) as httpd:
print("serving at port", PORT)
httpd.serve_forever()
このサーバー、リクエストされたら指定秒数間スリープしたのち、何も言わずにソケットをクローズするという迷惑なものです。
クライアントは同じくPythonで以下のように実装しました。これ以上ない簡単な実装です。
address = sys.argv[1]
print('requesting ' + address)
res = requests.get(address)
print(res)
手元で実験すると、以下のようになりました。
$ python3 innocent_client.py http://localhost:8000
requesting http://localhost:8000
(中略)
requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response',))
なお、requests、特別に指定しないとタイムアウトはなし、つまり返信があるまで無制限待機となります。
http://docs.python-requests.org/en/master/user/advanced/#timeouts
これをNATゲートウェイ越しで動作させると。。。できました！サーバー側で360秒後にソケットをクローズしたにも関わらず、クライアント側では受信待機のソケットが、「来ぬ人を」待ち続けています。
タイムアウトを設定し、問題現象は解決へ
ここまで来ると受信待機ソケットの滞留を防止する方法は、タイムアウト設定ということになります。筆者は以下のようにタイムアウトを設定しました。
CloseableHttpClient httpClient = HttpClients.custom()
(中略)
.build();
HttpComponentsClientHttpRequestFactory requestFactory = new HttpComponentsClientHttpRequestFactory();
requestFactory.setHttpClient(httpClient);
requestFactory.setConnectTimeout(connectionTimeout); // タイムアウト追加
requestFactory.setReadTimeout(readTimeout); // タイムアウト追加
RestTemplate restTemplate = new RestTemplate((ClientHttpRequestFactory)requestFactory);
しかしこのタイムアウト、デフォルトでは無制限なのでしょうか？
調査すると、なんと「デフォルトでは無制限」のようでした。。。
https://hc.apache.org/httpcomponents-client-4.2.x/tutorial/html/connmgmt.html
CoreConnectionPNames.SO_TIMEOUT='http.socket.timeout': (中略) If this parameter is not set, connect operations will not time out (infinite timeout).
このコードをコミットすると、見事に問題現象が起こらなくなりました。どうやら問題現象の原因要因に正しくアプローチできたようです。
受信待機のソケットが多数発生すると、なぜシステムSへのリクエスト だけ が送信されなくなるのか。
問題現象が解決してしまったのでこの点は謎なままなのですが、筆者は「リクエストスレッドプールが違っていたから」だと考えています。図4に戻りますが、システムDはAWS SDKを使用して呼び出しており、システムSはApache HTTP Componentsで呼び出していました。2つのリクエストスレッドプールが独立して確保されていたので、システムS側のプールスレッドが全部受信待機になったとしても、システムD側のプールスレッドには影響しなかったのでしょう。
そもそものきっかけは何なのか
最後の謎として、「システムSが通常応答するなら、なぜタイムアウトになったのか」という点があります。これについては、いまだに特定されていません。ひょっとすると普段は順調なのに夜間はダメとかなのかもしれません。
最後に
今回の問題を反省に、リクエストには必ずタイムアウトを設定する習慣をつけたいものです。今回調べたPythonのRequestsライブラリもJavaのApache HTTP Componentsも、既定のタイムアウトは「なし」なのです。なんらかの理由でパケットが棄てられたら、「来ぬ人を」永久待機ということに容易になってしまいます。
最後までお読みくださり、ありがとうございました。
