Connection refused エラーの検証と原因の特定方法

###前提・実現したいこと
Webのサーバーサイド(APIなど)の開発を行っていて502エラーが発生するようになってしまいました。

現在複数台のサーバーでサービス動かしており
流れとしては以下のような感じです。

ユーザーがUserのGETのリクエストを飛ばす
UserサーバーがGET処理を実行
UserサーバーのGET処理の中でInfoのGETを実行

  InfoサーバーでGET処理を実行

  InfoサーバーのGET処理の中でDataのGETを実行

    DataサーバーでGET処理を実行

    DataサーバーからInfoサーバーにレスポンスを返す

  Infoサーバーがレスポンスを受け取りデータを整形

  InfoサーバーからUserサーバーにレスポンスを返す

Userサーバーがレスポンスを受け取りデータを整形
Userサーバーがユーザーにレスポンスを返す
ユーザーがレスポンスを受け取る

502エラーが発生する原因は
infoサーバー内ででているConnection refusedエラーが原因だと思っています。

これを解決する方法を探しています。

###発生している問題・エラーメッセージ

userサーバーで起きているエラー

urllib.error.HTTPError: HTTP Error 502: Bad Gateway

infoサーバーで起きているエラー
「InfoサーバーのGET処理の中でDataのGETを実行する」
このタイミングでエラーが発生します。

urllib.error.URLError: <urlopen error [Errno 111] Connection refused>

###設定周りの情報

gunicornの設定です。
関係ありそうな部分だけ抜粋しました。

workers = multiprocessing.cpu_count() * 2 + 1
worker_class = 'sync'
worker_connections = 1000
max_requests = 0
timeout = 30
keepalive = 2

nginxの.confではアクセス数やレスポンスまでの時間制限などの設定は行っていないです。

試したこと

Connection refusedは必ず発生するわけではありませんでした。
頻度としては7回に1回ほどエラーが出ます。
発生しない場合は取得したかった内容が取得できています。

###補足情報(言語/FW/ツール等のバージョンなど)
取得しているデータは文字列で半角英数字記号で500字ほど。
json形式で取得します。
成否問わずレスポンスは0.5秒かからず返ってきます。

環境情報
EC2インスタンス
Linux
nginx
Python3
gunicorn

RDSインスタンス
MySQL

APIの取得の確認は主にChromeで行っています。

追記、試したこと1

gunicornの設定の下記2つを変更しての動作を確認してみました。
変更したところインスタンスを作成してから
約1時間ほどで適当に百数回以上GETを試しましたが502エラーは発生しませんでした。
しかし、時間がたってからGETを行ったところ502が発生。
以降発生するのは変わりませんが頻度は少しだけ減ったように感じます。
（1/7から1/10くらいに変化）

timeout = 30 -> 3000
keepalive = 2 -> 20

追記

nginxのキャッシュが溜まっているとかそういう面について調べましたが
キャッシュは作られていませんでした。（設定もしてないです）

また現在サーバーの再起動や何やらは切ってある状態で試しているため
もし停止したら停止しっぱなしになります。

追記2

Dockerで同じような状況を作って試してみました。
DockerでMySQLサーバーを立てて、
CentOSのサーバーを立てて、
AWSのEC2インスタンスとRDSインスタンスと同じ内容を詰め込んで
Docker内でやり取りさせてみました。

そして、502エラーが発生するまで無限ループを行うようスクリプトを準備し
それを12個ほどcmdから実行しています。
現在30分ほど経ちましたが今のところ502エラーは発生していません。
AWSでも同じことをして試してみます。

追記3：メモリが怪しそうです

free コマンドでメモリの使用量を確認したところ以下のように表示されました。
また、GETを繰り返すたびにMem-usedの値が上がっていくのが確認できました。
Mem-cachedはすぐには上がりませんでしたがココらへんについてもう少し深く調査してみようと思います。

[ec2-user@ip-172-31-29-13 ~]$ free -m
             total       used       free     shared    buffers     cached
Mem:           995        871        123          0         32        682
-/+ buffers/cache:        157        838
Swap:            0          0          0

追記4：メモリに負荷をかけてリクエストの結果

stress コマンドでメモリに負荷をかけて

stress --vm 2 --vm-bytes 400M --timeout 10m

10のプロセスから各1000回づつ、10/sでリクエストの送信を行っている状態での
vmstatコマンドの結果です。

2017/01/26 11:05:25 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
2017/01/26 11:05:25  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
2017/01/26 11:05:25  2  0      0 291484   4024  18948    0    0    10    25   77   85  1  1 98  0  0	
2017/01/26 11:05:26  2  0      0 266260   4032  18940    0    0     0    48  265  298 13 87  0  0  0	
2017/01/26 11:05:27  2  0      0 261168   4032  18940    0    0     0     0  251  258 16 84  0  0  0	
2017/01/26 11:05:28  3  0      0 179840   4044  20852    0    0  1940     0 1979 1332 32 68  0  0  0	

...省略

メモリに負荷をかけていない状態ではcpu の id に余裕がありましたが、
負荷をかけた状態では上記のようになっています。

仕様について追記

nginxを起動後、gunicornを起動させて
その状態でずっと稼働しっぱなしにして動かしています。

そして、問題の502が起きるのは、しばらくアクセスを繰り返した後に発生し始めること
アクセスするたびにメモリが減っていく様子が確認できたことからそこら辺に原因があるかもしれないと思っています。

現在の状況

InfoサーバーやDataサーバーから取得するデータ量を減少させたて、
タイムアウトまでの時間を伸ばすことでほぼ502エラーが出ないことが確認できました。
一応以前は502エラーが発生していた時以上にはアクセスを繰り返してもエラーは発生しませんでした。
例としては 10プロセスから 10/s で各1千回リクエストを飛ばすと行ったことをしましたが
エラーは発生せずに終えることができました。

また、UserサーバーからInfoサーバーにリクエストを飛ばした際に
正常な結果が得られるまでリクエストを飛ばすことで、無理やり押し通すことが出来るのも確認しました。
（これはコメントアウトした状態で検証しています。）

ただ、どちらも対処療法の領域をでておらず、
原因の特定に至っていないためまだ調査中と言った感じです。

ワーカープロセスについて

今回のことで初めて調べたのであっているかわかりませんがご了承ください。
nginx,gunicorn共にすべてのサーバーで同じ設定を行っています。
サーバーのスペックも同スペックで作成しています。

まずこちらのサイトを参考にCPUや最大プロセス数を調べたところ
http://www.crystalsnowman.com/?p=344

CPU : 1
最大プロセス数： 1024

とわかりました。
また、nginxにはワーカープロセスについての設定を行って無い状態でした。

gunicornでは以下の設定は行っていました。
workers = multiprocessing.cpu_count() * 2 + 1 worker_class = 'sync' worker_connections = 1000 max_requests = 0

以下は動いているnginxとgunicornのプロセスを確認したものです。

[ec2-user@ip-xxx-xx-xx-xx ~]$ ps aux |grep nginx |grep -v grep
root     17576  0.0  0.1  58088  1080 ?        Ss   11:58   0:00 nginx: master process nginx
ec2-user 17578  0.0  0.4  58600  4756 ?        S    11:58   0:00 nginx: worker process
[ec2-user@ip-xxx-xx-xx-xx ~]$ ps aux |grep gunicorn |grep -v grep
ec2-user 17614  0.0  2.1 202156 22332 ?        S    11:58   0:01 /home/ec2-user/.pyenv/versions/3.5.2/bin/python3.5 /home/ec2-user/.pyenv/versions/3.5.2/bin/gunicorn run:app --config guniconf.py
ec2-user 17646  0.4  2.5 223292 25996 ?        S    11:58   0:44 /home/ec2-user/.pyenv/versions/3.5.2/bin/python3.5 /home/ec2-user/.pyenv/versions/3.5.2/bin/gunicorn run:app --config guniconf.py
ec2-user 17647  0.3  2.5 223296 26000 ?        S    11:58   0:38 /home/ec2-user/.pyenv/versions/3.5.2/bin/python3.5 /home/ec2-user/.pyenv/versions/3.5.2/bin/gunicorn run:app --config guniconf.py
ec2-user 17648  0.4  2.5 223248 26004 ?        S    11:58   0:41 /home/ec2-user/.pyenv/versions/3.5.2/bin/python3.5 /home/ec2-user/.pyenv/versions/3.5.2/bin/gunicorn run:app --config guniconf.py

t_obara

2017/01/16 08:02

同時アクセスが許容範囲を超えているということでもないのでしょうか？

suvera

2017/01/16 08:27

設定周りの情報を追記しました。付け足したり増減してためした方がいい設定があれば教えてください。

行動規範の内容に同意します

回答1件

ベストアンサー

Connection refused は、送信サーバ側が ICMP の port unreachable パケットを受信することによって起こります。誰がこのパケットを送ってくるかというと、相手側サーバか経路途中のファイアウォールです。原因の１位は「ポート番号が間違っている」で、２位は「ファイアウォールで拒否されている」なんですが、大量に負荷をかけているわけでもないのに７回に１回しか発生しないという状況からこれらが原因ではないでしょう。

Dataサーバのサービスがたまに落ちているということはないでしょうか？ systemctl や superviserd などで、落ちても自動的に再起動する仕組みを入れてたりすると、こういう現象になるかもです。

また、DataサーバのIPが他のサーバと重複しているとか、MACアドレスが重複しているとかで、別のサーバに飛んでいっているというようなことはないでしょうか？（とも思いましたが、 EC2 だとそうなりにくいですね）

Linux なので、 tcpdump でパケットキャプチャすることで、ICMPを誰が送ってきてるかを探ることはできます。他のサイトから例をコピペしますが、

$ sudo tcpdump -n icmp 
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode

listening on enp14s0, link-type EN10MB (Ethernet), capture size 262144 bytes 13:03:24.149897 IP 192.0.2.1 > 192.0.2.2: ICMP 192.0.2.1 tcp port 22222 unreachable, length 68

というように出力されれば、 ICMP の拒否パケットを送信しているのは、 192.0.2.1 だというのがわかります。これがサーバだったり、ファイアウォールだったりします。

この tcpdump を Data サーバ側と info サーバ側の両方で採取してみて、一致するならデータサーバ側のサービスが落ちているか攻撃防御機能が働いているかが原因でしょう。一致しないなら、DataサーバのIPが他のサーバと重複しているとか、MACアドレスが重複しているとかで、別のサーバに飛んでいっている可能性があります。

投稿2017/01/16 08:56

編集2017/01/16 09:58

mit0223

総合スコア3401

suvera

2017/01/18 05:53

sudo tcpdump -n icmp 実行すると以下のように出力されました。 [ec2-user@ip-xxx-xxx-xxx-xxx ~]$ sudo tcpdump -n icmp tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes この後に続く文字は何もありません。特に更新もされませんでした。

mit0223

2017/01/20 00:03

これは、 info サーバで実行し、urllib.error.URLError: <urlopen error [Errno 111] Connection refused> が出た瞬間にも何も表示されなかったということでしょうか？あと、この EC2 のネットワークインタフェースは一つでしょうか？もし、複数ネットワークインタフェースがある場合は、 tcpdump の -i オプションで data サーバに接続されているインタフェースのパケットキャプチャを取る必要があります。

mit0223

2017/01/25 11:40

高負荷時に発生するのでしょうか？それであれば、ポート番号が枯渇しているとかいうことはないでしょうか？ http://d.hatena.ne.jp/download_takeshi/20091013/1255443592

suvera

2017/01/26 02:57 編集

この質問の回答、先日の質問に続いてコメントして頂き本当に有難うございます。ポートの枯渇は知らない問題でした。これについても調べます。メモリにstressコマンドで負荷をかけた状態で検証を行ったところレスポンスを受け取るまでに普段の2倍以上の時間がかかる場合がありました。また、サーバーは受け取ったリクエストを1つづつ処理するようになっていてリクエストのプロセスが常に溜まって、CPUもフル稼働と言った感じでした。質問のところにvmstatの結果を一部載せておきます。

mit0223

2017/01/26 16:04

vmstatを見ましたがsystem の割合が高いですね。プロセスの起動終了を激しく繰り返しているとかではないですか？nginx と gunicornのワーカープロセスは増減してますか？

suvera

2017/01/27 05:52

確認して頂きありがとうございます。ワーカープロセスについて調べて一応情報を載せては見ました。ただ、起動と終了を繰り返しているのかどうかの変動を確認する方法がわかりませんでした。良ければ教えてください。

suvera

2017/01/27 07:31

遅れまして上記で指摘していただいたポート番号の枯渇問題についてですが大量のリクエストを送信した後、 netstatコマンドを利用してポートの確認を行ったところ大量のポートが並んでいることが確認でき、リプエストを受け取った後もTIME_WAITで残っていることが確認できました。

mit0223

2017/01/28 00:22

ワーカープロセスのほうは、時間が経過した後にプロセスIDが変化しているかどうかを見ることで確認できますが、そもそもプロセスの数が少ないので、シロだと思って良いと思います。 > TIME_WAITで残っていることが確認できました。一番効果的な対策は infoサーバから data サーバへの接続をリクエスト毎に行わずに再利用することです。状況から見て大幅な性能改善が見込めます。普通に構築すると、 Webサーバ（リバースプロキシ）からアプリケーションサーバへの接続は keep alive で再利用されますし、アプリケーションサーバからデータベースへの接続はコネクションプーリングにより再利用されます。サーバ間のネットワーク接続をリクエストごとに毎回接続すると性能問題になるのは避けられません。再利用するのが常套手段なのですが、そこがうまくできていないのではないでしょうか。

mit0223

2017/01/28 00:33

python に詳しくないのですが、 infoサーバから data サーバへの接続は HTTP GET でしょうか？そのときは urllib3 というライブラリを使われていますか？もし、 urllib3 を使われているのであれば、自動的にコネクションプーリング（接続再利用）が行われるので、リクエスト毎の接続は行われず、ソケットが大量に TIME_WAIT になることはないはずです。 https://urllib3.readthedocs.io/en/latest/ http://stackoverflow.com/questions/18466079/can-i-change-the-connection-pool-size-for-pythons-requests-module

suvera

2017/01/30 06:57 編集

urllibを利用しています。確かに再利用を意識した作りをしていなかったのでそこら辺はできていませんでした。 urllib3 にはコネクションプーリングが組み込まれてるようですので利用するのをurllibからurllib3に代えて様子を見てみます。コネクションプーリングは今までで一番しっくり来る指摘でした。お陰様で解決しそうです。少々変更範囲が大きくなり時間も掛かりそうなのでこちらの質問はここで閉じさせていただきます。本当に長々とお付き合い頂き誠にありがとうございました。

mit0223

2017/01/30 16:19

こちらこそ、ベストアンサーをいただき、ありがとうございました。最初、ネットワーク系の問題と思い回答しましたが、性能系の問題だったので的外れでした。コネクションプーリングで解決しない場合は、また、質問を投稿してください。

行動規範の内容に同意します