Gatewayに握りつぶされていたエンジニアの佐藤です。今回はネットワークインフラのお話を書かせていただきたいと思います。始まりは不具合連絡から猛暑が続くある日のこと、お客さまから、とある開発システムの、とある機能が「動かないんだけど」という連絡を受けました。筆者はすぐに問題現象を確認しましたが、確実に再現し、弁解の余地はありません。お詫びして、原因調査に取りかかりました。この機能の実装はこうです。Salesforce(Visualforceページ)からApex処理を経て外部システムAにRESTリクエストを送信する。外部システムAはさらに外部システムSにRESTリクエストを送信する。レスポンスは順次回収され、適宜加工され、結果がSalesforce画面に表示される、というものです。図に描くとこんな感じです。報告された問題現象とは、ブラウザが10秒ほど応答停止したのちに、エラーが画面に表示されるというものです。エラーの内容から、筆者は、Salesforceがまともなレスポンスを受け取っていないんだろうと推測しました。10秒ブロックですから、一連のリクエスト連鎖のどこかでタイムアウトしたんだろうと思いました。筆者は外部システムAのログを観察しました。外部システムSをリクエストする直前のログを最後に足取りが途絶えていました。SalesforceからシステムAへのリクエストが10秒でタイムアウトし、Visualforceページのエラーへとつながっていったのでしょう。図に描くとこんな感じです。次に筆者が疑ったのは、システムSです。実はシステムSは今回の機能開発に合わせて平行開発されたもので、開発中は多少問題があったこともあったのです。筆者はシステムAの内部から、Pythonの即席コードでシステムSにリクエストしてみました。何の問題もなくレスポンスがあります。「他人を最初に疑うのは良くないよな」と反省した筆者は、問題現象発生時のパケットキャプチャを採取することにしました。システムSへのリクエストはそもそも送信されていないことがわかりました。そんなバカなと思って2度3度やってみましたが、結果は変わりません。技術者たる者、事実の前には謙虚でなくてはなりません。リクエストがタイムアウトしたのではなく、そもそもリクエストしていなかったのです。ここで筆者は困ってしまいました。いうのも、このシステムA、他にも似たような処理を常時続けており、そちらには何の問題もないからです。DockerコンテナのJava実装された単一のプロセスで、あっちはよくてこっちはダメという状態なのです。システムAからリクエスト可能であることは、図3で確認されていますから、原因はシステムA側にあるはずです。筆者はこの段階で、Dockerコンテナの再起動を考えました。考えてもおかしいので、コンテナプロセス内部に何か一時的な問題が起こっているのだろうと考えたのです。ロードバランサ化のコンテナクラスタで、ドレーンしてから再起動することで無停止再起動が可能でしたので、許可を得て実行しました。ログにソケット強制クローズの警告が数十個出力されました。「リクエストしたが、返事が来る前に、棄てられた。システムSへのリクエストは、システムAにログインしてPython即席コードを実行すれば、通るのですよ。受信待機になるはずがないのです。DockerコンテナでBridgeネットワークを経由している点がPython即席コードと違うといえば違いますが、リクエスト先がシステムS以外の場合は成功しており、Dockerが原因とは考えにくい。その一方で、コンテナ再起動により当初の機能は回復しました。レスポンス待ちのソケットを強制クローズすれば、システムAからシステムSの、新しいリクエストは通るのです。謎は以下2つに絞り込まれました。受信待機のソケットが多数発生したのか。送信されなくなるのか。思っていた筆者でしたが、翌日再びお客さまから「やっぱり、動かないんだけど」の連絡が。なるともう逃げ道はない。筆者は覚悟を決めて徹底追及することにしました。筆者は再び機能不全に陥ったシステムAを調査し、Dockerコンテナプロセスに多数の受信待ちソケットがあることを確認しました。このようなソケットが発生するのか?筆者が次に疑ったのは、NATでした。VPCのプライベートネットワークセグメントに立てられたECSクラスタ上のサービスとして実装されており、アウトバウンドリクエストはVPCのNATゲートウェイを経由することにしていたのです。NATゲートウェイの詳細な仕様は以下の公式ページに書かれています。Gatewayshttps://docs.aws.amazon.com/AmazonVPC/latest/UserGuide/vpc-nat-comparison.html詳しく読んでいくと、タイムアウトに関する以下のような記述がありました。AMI)を提供して適宜使ってくれという姿勢でしたが、ある時からこれがサービス化され、NATゲートウェイと名付けられました。その際になぜか、仕様が変わったようです。今回使っているのはNATゲートウェイですから、仮にもしシステムSへのリクエストがタイムアウトすると、システムA側には、何も通知されない。HTTPリクエストが終わっていて、TCPキープアライブも設定されていなければ(今回は設定されていない)、そのような催促はない。疑い深い筆者は、Python即席コードで悪いHTTPサーバーを書いて、受信待機ソケットの再現を試みました。httpd.serve_forever()このサーバー、リクエストされたら指定秒数間スリープしたのち、何も言わずにソケットをクローズするという迷惑なものです。クライアントは同じくPythonで以下のように実装しました。これ以上ない簡単な実装です。requests.get(address)print(res)手元で実験すると、以下のようになりました。response',))なお、requests、特別に指定しないとタイムアウトはなし、つまり返信があるまで無制限待機となります。http://docs.python-requests.org/en/master/user/advanced/#timeoutsこれをNATゲートウェイ越しで動作させると。できました!サーバー側で360秒後にソケットをクローズしたにも関わらず、クライアント側では受信待機のソケットが、「来ぬ人を」待ち続けています。タイムアウトを設定し、問題現象は解決へここまで来ると受信待機ソケットの滞留を防止する方法は、タイムアウト設定ということになります。筆者は以下のようにタイムアウトを設定しました。RestTemplate((ClientHttpRequestFactory)requestFactory);しかしこのタイムアウト、デフォルトでは無制限なのでしょうか?調査すると、なんと「デフォルトでは無制限」のようでした。timeout).このコードをコミットすると、見事に問題現象が起こらなくなりました。問題現象の原因要因に正しくアプローチできたようです。送信されなくなるのか。問題現象が解決してしまったのでこの点は謎なままなのですが、筆者は「リクエストスレッドプールが違っていたから」だと考えています。Componentsで呼び出していました。2つのリクエストスレッドプールが独立して確保されていたので、システムS側のプールスレッドが全部受信待機になったとしても、システムD側のプールスレッドには影響しなかったのでしょう。そもそものきっかけは何なのか最後の謎として、「システムSが通常応答するなら、なぜタイムアウトになったのか」という点があります。これについては、いまだに特定されていません。すると普段は順調なのに夜間はダメとかなのかもしれません。最後に今回の問題を反省に、リクエストには必ずタイムアウトを設定する習慣をつけたいものです。Componentsも、既定のタイムアウトは「なし」なのです。なんらかの理由でパケットが棄てられたら、「来ぬ人を」永久待機ということに容易になってしまいます。最後までお読みくださり、ありがとうございました。Gatewayに握りつぶされていたTweet関連記事2020-02-13SalesforceのプラットフォームイベントをPostmanから発行するこんにちは、技術開発室の藤野です。実行するには技術開発室の佐藤です。(12/3)みなさん初めまして、CI事業部のウエダです。今回が初のre:inv...2019-04-30多量のリクエストを送信するにはエンジニアの佐藤です。3はじめまして、CI事業部の金子です。専門知識に合格しました月別アーカイブはてなブログをはじめよう!flect_techさんは、はてなブログを使っています。ブログを報告するスターをつけました引用をストックしましたストック一覧を見る閉じる引用するにはまずログインしてくださいログイン閉じる引用をストックできませんでした。再度お試しください閉じる限定公開記事のため引用できません。