ストーリー仕立てで書いておりますので、対応方法のみを知りたい方はページ最下部「対応方法」、「まとめ」を参照ください。
408がapacheのログにめっちゃ出てる。。。
(client) - ELB - EC2
な構成で動かしていたんですけど、下記のようなログが50秒程おきに出ていました
ELB1 - - [31/Jul/2014:05:44:20 +0000] "-" 408 - "-" "-"
ELB2 - - [31/Jul/2014:05:44:21 +0000] "-" 408 - "-" "-"
ELB1 - - [31/Jul/2014:05:45:11 +0000] "-" 408 - "-" "-"
ELB2 - - [31/Jul/2014:05:45:13 +0000] "-" 408 - "-" "-"
ELB1 - - [31/Jul/2014:05:46:03 +0000] "-" 408 - "-" "-"
ELB2 - - [31/Jul/2014:05:46:05 +0000] "-" 408 - "-" "-"
- ELB1, ELB2はそれぞれELBのIPアドレス
408...request timeoutか・・・（＝"＝
調査：ググる
最初は定期的に出ているので『ELBのHealth Checkなのかな〜？』と思い調べていました。
すると以下のような記事達に出会いました。
ELBがapacheに対して張りっぱなしにしようとしてる予備のコネクションがある。
apacheはmod_requesttimeoutでそれを切断する。
apacheのログに408が記録される。
ELBはまた接続してくる。以下繰り返し。
その結果、TIME_WAITなコネクションが常に溜まってる。
実はググる前にパケットを軽く眺めていたのですが、確かにそんな風に見えていました。
それに対する、設定方法がamazonのforumにありました。
RequestReadTimeout header=0 body=0
元々mod_reqtimeoutはDoS対策として導入されたもので、上記設定をするとdisableになってしまいます。
amazonさんならDoS対策しているのでは？
amazonさんなら、DoS対策をしてくれているような気もしたのですが、どこのレイヤーで、どういうものをしてくれているのかは分からない様子。
誠に勝手ながら公開情報以上のものはお答えいたしかねます。
ご理解頂けますようお願いいたします。
Amazon を世界最大のオンライン小
売業者としたエンジニアリング技術と、同じエンジニアリング技術を利用することが出来ます。特許取得済みの、
DDoS 緩和技術も適用されています。
うーん・・・ドウシヨウ（＝”＝
forumの対応方法への感想
先程のforumに出ていた「header=0 body=0」という設定をして、mod_reqtimeoutをdisableにするぐらいなら、そもそもload_moduleしなくて良いじゃないか？
LoadModule reqtimeout_module modules/mod_reqtimeout.so
それにDoSの緩和moduleを外すのは、最後の手段で良いような気もします。
調査：本当にHealth Checkが犯人なの？
どうしようかと愚痴を漏らしていたら、「Health Checkが犯人ならそのポートだけ専用のを作れば良いじゃない」というアドバイスを頂きました。
そこで、以下のような設定をして、Health Checkで使うポートをマネージメントコンソールから30080に変更してみましたが、やはり同じ408が出続けます。
LISTEN 30080
<VirtualHost *:30080>
KeepAlive On
KeepAliveTimeout 120
RequestReadTimeout header=0 body=0
</VirtualHost>
ここで『実は犯人別人じゃね？』という思いが出てきます。
試しに、AWSのマネージメントコンソールから、Health CheckのIntervalを30 secondsから60secondsにしましたが、なぜか約50秒周期で408が出続けます。
『Health Checkよ。疑って悪かった。』
そういえば、ELBはクライアントからのアクセスの高速化をするため、バックエンドのEC2とコネクションを張りっぱなしにします。
アナタが犯人か？！
また、後述しますが、パケットを眺める限り、Health Checkはちゃんとコネクションを開放しています。
パケットを眺める
最初は何が起きていたのか分からなかったので、後でwiresharkでじっくり眺めようと以下のオプションで収集していました。
sudo tcpdump -i eth0 -s0 -n -v -w health_check.pcap
結果的には、コンソール上で眺める程度で良かったようなので、以下ではそのログを貼っておきます。
health Check
分かりやすいように、30080ポートに来てもらう設定にしています。
（実際には80に来ていますが、apacheへの通信と混ざって見辛いので）
sudo tcpdump -i eth0 -n port 30080 and host ELB1
- ELB1はIPアドレス
07:10:17.398796 IP ELB1.7509 > EC2.30080: Flags [S], seq 1954705710, win 14600, options [mss 1460,sackOK,TS val 180580918 ecr 0,nop,wscale 8], length 0
07:10:17.398814 IP EC2.30080 > ELB1.7509: Flags [S.], seq 1118619224, ack 1954705711, win 14480, options [mss 1460,sackOK,TS val 193444167 ecr 180580918,nop,wscale 7], length 0
07:10:17.401008 IP ELB1.7509 > EC2.30080: Flags [.], ack 1, win 58, options [nop,nop,TS val 180580919 ecr 193444167], length 0
07:10:17.403409 IP ELB1.7509 > EC2.30080: Flags [F.], seq 1, ack 1, win 58, options [nop,nop,TS val 180580919 ecr 193444167], length 0
07:10:17.403701 IP EC2.30080 > ELB1.7509: Flags [F.], seq 1, ack 2, win 114, options [nop,nop,TS val 193444168 ecr 180580919], length 0
07:10:17.405859 IP ELB1.7509 > EC2.30080: Flags [.], ack 2, win 58, options [nop,nop,TS val 180580920 ecr 193444168], length 0
しばらく眺めていましたが、きっちりとコネクションの開放をしていますし、seqやackにも不自然な点はありませんでした。
ELB
sudo tcpdump -i eth0 -n port 80 and host ELB1
- ELB1はIPアドレス
06:53:34.351593 IP ELB1.15871 > EC2.http: Flags [S], seq 1752385158, win 14600, options [mss 1460,sackOK,TS val 180330156 ecr 0,nop,wscale 8], length 0
06:53:34.351627 IP EC2.http > ELB1.15871: Flags [S.], seq 78396007, ack 1752385159, win 14480, options [mss 1460,sackOK,TS val 193193405 ecr 180330156,nop,wscale 7], length 0
06:53:34.353787 IP ELB1.15871 > EC2.http: Flags [.], ack 1, win 58, options [nop,nop,TS val 180330157 ecr 193193405], length 0
06:54:05.580781 IP EC2.http > ELB1.15871: Flags [S.], seq 78396007, ack 1752385159, win 14480, options [mss 1460,sackOK,TS val 193201213 ecr 180330157,nop,wscale 7], length 0
06:54:05.583090 IP ELB1.15871 > EC2.http: Flags [.], ack 1, win 58, options [nop,nop,TS val 180337964 ecr 193201213,nop,nop,sack 1 {0:1}], length 0
06:54:25.600906 IP EC2.http > ELB1.15871: Flags [F.], seq 1, ack 1, win 114, options [nop,nop,TS val 193206218 ecr 180337964], length 0
06:54:25.603526 IP ELB1.15871 > EC2.http: Flags [F.], seq 1, ack 2, win 58, options [nop,nop,TS val 180342969 ecr 193206218], length 0
06:54:25.603538 IP EC2.http > ELB1.15871: Flags [.], ack 2, win 114, options [nop,nop,TS val 193206218 ecr 180342969], length 0
3wayハンドシェイクの後、HTTPデータが来ないためなのか（？）、apacheが一度SYN+ACKを再送しているのが健気ですね。
その後、しびれを切らしてapacheからFIN+ACKを送りつけている様子が見て取れます。
対応方法
調査結果より以下の事が分かりました。
TCPコネクションを張ったあと、HTTPデータが来ないため、mod_reqtimeoutがDoSと判定して、apacheがコネクションを終了させている。
以上の事から、対応方法は2つ。
- ELBのConnection Settingsをmod_reqtimeoutのheaderの初期値より短くする
- mod_reqtimeoutのheaderの値を長くする
Connection Settings
「Connection Settings: Idle Timeout」という設定があります。
デフォルトでは60となっていたのですが、mod_reqtimeoutのheaderの初期値である20-40より短くしてみましょう。
今回は30を指定してみましたところ、発生しなくなりました。
実は、この設定、最近出来るようになったそうです。(2014/07/14？)
【AWS発表】Elastic Load Balancingのコネクションタイムアウト管理
mod_reqtimeout
再度今回の件を考えると以下です。
- TCPコネクションを張ったのに、HTTPが来ないから困る。
- 言い換えると、TCP 3wayハンドシェイクが完了したのに、HTTPヘッダーが来ない。
- ならHTTPヘッダーに関してはタイムアウトしなければ良い。
先に書いたように、mod_reqtimeoutのheaderの初期値は20-40です。
RequestReadTimeout header=70
これを設定して、httpd reloadすると、408がログに出なくなりました。
でも、これだと、headerを遅く送られるのを許す事にはなっちゃうので、先の対応方法の方が良いですね。
まとめ
ELBのバックエンドEC2で408が一杯でてしまう時は、ELBの「Connection Settings Idle Timeout」をmod_reqtimeoutのheaderよりも短くしましょう！！
久しぶりにtcpdumpと仲良くしてた〜（＾＾
しかし、ELBさんは自動的にスケーリングするとは伺っていましたが、最初から二人掛かりで迫ってきているんですね〜。
追記
投稿後に気づきましたが、ELBがコネクションを出来る限り使い回すってことは、Idle Timeoutの方の対応だと、接続が多いサイトではダメかもしれませんね・・・。
まだ試していませんが、ダメなら、mod_reqtimeoutを外す方にしないとイケナイかもしれません。。。orz
様子見で（＝ｗ＝；