apacheで408エラーが突然大量発生したけれど・・・

昨日・今日になってApacheのアクセスログに大量の408が記録されるようになりました。何が起きたのか確認してみます。

1.発端

毎朝届くLogwatchメールを見ていたら、普段とは異なるログが残ってました。アクセス先もUAもリファラも何も表示されていませんね・・・

Attempts to use known hacks by 122 hosts were logged 385 time(s) from:
    X24.44.182.5X: 27 Time(s)
    1X3.220.39.1X8: 18 Time(s)
    21X.142.98.X96: 17 Time(s)
    210.X39.21X.215: 14 Time(s)
    124.3X.3X.82: 12 Time(s)
    125.17X.138.136: 12 Time(s)
    210.1X2.X9.198: 12 Time(s)
..
.

408 Request Timeout
       null: 377 Time(s)
...
..
.

408 Request Timeoutが大量発生となると真っ先に攻撃が思い浮かびますが、合計回数も1ノードからのアクセス回数も少ないしIPアドレスもバラバラで悪意は感じられないし。ということでサーバのログを調査してみます。

2.サーバ側の原因調査

まずは408がいつから発生したのかCentOS6のapacheアクセスログを確かめます。

# cat /var/log/httpd/ssl_access_log |grep " 408 "
192.0.2.191 - - [13/Jul/2017:07:24:56 +0900] "-" 408 - "-" "-"
198.51.100.167 - - [13/Jul/2017:07:34:18 +0900] "-" 408 - "-" "-"
203.0.113.192 - - [13/Jul/2017:07:37:18 +0900] "-" 408 - "-" "-"
203.0.113.192 - - [13/Jul/2017:07:37:18 +0900] "-" 408 - "-" "-"
198.51.100.188 - - [13/Jul/2017:07:54:07 +0900] "-" 408 - "-" "-"
...
..
.

朝7時。この時間にサーバ作業はしないので設定変更のオペミスではなさそう。朝に何かあるとすればyum-cronかな？とログを見てみるとhttpdのアップデートがありました。

# cat /var/log/yum.log|grep "Jul 13"
..
Jul 13 05:50:58 Updated: httpd-tools-2.2.15-60.el6.centos.4.x86_64
Jul 13 05:50:59 Updated: httpd-2.2.15-60.el6.centos.4.x86_64
..

念のため別のCentOS6ウェブサーバでもログを確認してみましたが、こちらもhttpdのアップデート後から408が記録されています。サーバが「httpd-2.2.15-60」にアップデートされたことが今回の原因の一つと考えられます。

3.根本原因を探す

まだ根本原因は不明です。何のアクセスが408を引き起こしているのか「tail -f」でリアルタイムにログを見ていると、どうやら自分のPCからのアクセスでも408が起きているようです。
さらに複数のブラウザでサイトにアクセスして挙動を確かめると、IE/Edge/Firefoxでは発生せず、Chrome/Operaでは発生することがわかりました。

「Chrome 408」などのキーワードで調査したところ原因はChrome系の「ネットワーク動作を予測してページの読み込み速度を向上させる」設定でした。ブラウザの履歴や統計情報を見て、予め多めにTCPセッションを張っておくようです。

この設定を切ってみると確かに408は起きなくなります。原因はわかりましたがサーバ側の問題ではないということもわかりました。

4.対処方法は？

ネット上では「タイムアウトさせなければ408は出ない」という対策をしている人もいるようです。CentOS6+Apache2.2の場合、デフォルトで無効になっているApacheのDDoS対策機能「reqtimeout_module」を有効化し、RequestReadTimeoutを設定・調整すればいいとのことです。

●reqtimeout_module(mod_reqtimeout.so)の確認

# ll /etc/httpd/modules/
-rwxr-xr-x 1 root root   85360 Jul 12 22:33 mod_proxy.so
-rwxr-xr-x 1 root root   18672 Jul 12 22:33 mod_reqtimeout.so
-rwxr-xr-x 1 root root   64560 Jul 12 22:33 mod_rewrite.so
-rwxr-xr-x 1 root root   14576 Jul 12 22:33 mod_setenvif.so

●reqtimeout_module(mod_reqtimeout.so)をApache2.2に追加しRequestReadTimeoutを設定する

# vi /etc/httpd/conf/httpd.conf- Timeout 8
+ # Timeout 8

+ # reqtimeout_module(mod_reqtimeout.so)をapacheに追加
+ LoadModule reqtimeout_module modules/mod_reqtimeout.so

+ # タイムアウト(408)させない設定
+ RequestReadTimeout header=0 body=0

※本来の設定例
+ # HTTPヘッダーのタイムアウト20秒、ただし1秒間に500バイト以上通信がある場合は40秒まで拡張
+ RequestReadTimeout header=20-40,minrate=500
+ # HTTPデータの1秒間に500バイト以上の通信がないと10秒でタイムアウト。
+ RequestReadTimeout body=10,minrate=500

+ # 上記のheader/body設定を一行で行う場合。
+ RequestReadTimeout header=20-40,minrate=500 body=10,minrate=500

ただしこの方法、エラーログを出さないようにするために防御を解くという本末転倒で安直な方法なので採用するのは止めました。Redhatのエラッタを見てもこの症状が仕様変更によるものではなさそうなのでバグなのかもしれませんし、しばらくは様子見とします。