Tech Notes

要点

• 自社サイトが月に数回、数分から2時間ほど応答しなくなっていた
• CPUもメモリも余っていた。原因はデータベースのコネクション枯渇だった
• 引き金は、存在しないファイルを1秒に81回探しに来るスキャナ
• 403はApacheだけで返るのでサーバーに負荷がかからないが、404はWordPressが起動してデータベースに繋ぐ
• 対策は同時実行数を「上げる」ではなく「下げる」だった

きっかけは、ときどき届くアラートメール

Route 53のヘルスチェックを仕込んであるので、サイトが応答しなくなるとメールが飛ぶ。それが月に数回届いていた。毎回すぐ復旧するので、後回しにしていた。

記録を遡ってみたら、後回しにしていい頻度ではなかった。

発生	継続
9月20日	19分
9月26日	24分
10月11日	1時間47分
10月11日	24分
10月17日	11分

1か月で5回。そのうち1回は2時間近く落ちている。

まず、犯人でないものを消す

原因を当てにいく前に、違うものを潰した。クラウドの監視値が残っていたので、そこから消せる。

• インスタンス自体のステータスチェックは、全期間を通して一度も失敗していない。仮想マシンは落ちていない
• CPUバースト残量は十分に残っていた。クレジット切れによる速度制限ではない
• CPU使用率は飽和していなかった。処理能力を使い切ってはいない

インフラは正常で、CPUは余っている。にもかかわらず応答しない。

ヘルスチェックのエラー内容が、次の手がかりになった。

The endpoint did not respond within the timeout limit
SSL communication failure: SSL handshake timeout

SSLハンドシェイクのタイムアウトが効いた。これはTCP接続自体は成立している（カーネルが受け付けた）のに、Apacheがその接続を拾いに来なかったことを意味する。つまり、処理する側が全部塞がっていた。

犯人はデータベースだった

MariaDBのログに、答えがそのまま書いてあった。

[Warning] Aborted connection ... (Too many connections)
[Warning] Aborted connection ... (Too many connections)
[Warning] Aborted connection ... (Too many connections)

これが出ていた時刻と、アラームの発生から復旧までの時間帯が、ぴったり重なっていた。接続数の上限に達した記録も残っていた。

CPUが低いままだったのも、これで説明がつく。計算していたのではなく、全員がデータベースの順番待ちをしていたからだ。

引き金は1秒81回の404

では、何がデータベースを使い切ったのか。障害の3分前、1分間に328リクエストを投げている相手がいた。叩いていたパスはこれである。

/x.php          /smtp.yml       /pyproject.toml
/phpinfo        /media/.env     /db.sql
/index.php/phpinfo              /dashboard/phpinfo.php

設定ファイルと機密ファイルの探索だ。ユーザーエージェントはChromeを偽装、結果は全部404。

ログ全体で同じことを調べ直したら、これは日常だった。1秒あたりの404の数を数えると、上位はこうなる。

81 件/秒
75 件/秒
65 件/秒
61 件/秒

送信元はいずれもクラウド事業者のIPレンジ。そしてユーザーエージェントを集計したら、名前が出た。

8483  feroxbuster/2.13.1

feroxbusterはRust製のディレクトリ総当たりスキャナで、既定で数十本の並列リクエストを投げる。1秒81回という数字の説明がついた。

403はApacheが返す。404はWordPressが返す

ここが、この件でいちばん面白かったところだ。

同じ時間帯、他のIPからの攻撃はサーバーに何の影響も与えていなかった。 エラーログがそれを示している。

client denied by server configuration: ...
client denied by server configuration: ...

これらは .htaccess で弾いているので、Apacheが403を返した時点で処理が終わる。PHPもデータベースも動かない。サーバーの負荷はほぼ発生しない。

ところがferoxbusterが狙ったパスは、どのルールにも該当しない。すると何が起きるか。

GET /xmlrpc.php   → .htaccess が 403 を返す。ここで終了

GET /smtp.yml     → ファイルが存在しない
                  → RewriteRule . /index.php（WordPress の標準リライト）
                  → WordPress が丸ごと起動
                  → データベースに接続
                  → 「そんなページは無い」と判定
                  → 404 を返す

404を1回返すために消費するサーバー資源は、403とは桁が違う。 PHPのプロセスが1つ占有され、データベースの接続が1つ使われ、その間ずっと解放されない。それを1秒に81回やられると、接続数の上限に達する。

「存在しないファイルを探されているだけだから何も起きない」という感覚は、WordPressでは成立しない。WordPressにとって404は、ページを1枚表示するのとほぼ同じ仕事量である。 つまりスキャナの総当たりは、実質的にアクセス集中と同じことをサーバーに強いている。

対策1：探索をApacheで止める

WordPressまで到達していた404を、Apacheが返す403に変える。.htaccess にリライト規則を足した。

ここに落とし穴が2つある。

1つ目。<Files> による指定では止まらない。 存在しないファイルは index.php に書き換えられるので、ファイル名の照合が成立しない。<Files xmlrpc.php> のような指定が効くのは、そのファイルが実在するからだ。存在しないパスを止めるには、リライトの段階で落とす必要がある。

2つ目。WordPressが書き出す規則より前に置く必要がある。 あのブロックの最後に RewriteRule . /index.php [L] があり、[L] で処理が打ち切られる。後ろに書いた規則は実行されない。

構成を擬似的に書くと、こうなる。

WordPress の標準リライトより前
  ├ 公開する必要のない拡張子へのアクセス  → 403 を返して終了
  └ ドットから始まるパスへのアクセス      → 403 を返して終了
       ※ 証明書更新で使うパスだけは除外する

WordPress の標準リライト（自動生成される部分。触らない）

証明書更新用のパスを除外しておくことは必須である。ここを塞ぐとLet’s Encryptの更新が止まる。実際、このサイトでは5か月で2,693件の更新用アクセスがあった。除外していなければ、更新のたびに自分で自分を遮断していたことになる。

スキャナのユーザーエージェントも弾いた。偽装されれば抜けられるが、8,483件が既定の名前をそのまま名乗っていたので、効果はある。

対策2：同時実行数を「下げる」

設定を見直して、見逃せないことに気づいた。

Apacheの MaxRequestWorkers の既定値と、MariaDBの max_connections の既定値は、ほぼ同じ数字である。 つまり標準構成のままだと、Apacheが受け付けられる上限いっぱいまでリクエストが来て、その全部がデータベースに繋ぎに行った時点で、データベースはちょうど限界になる。余裕が設計されていない。

しかも構成は mpm_prefork + mod_php だった。Apacheのプロセス1つごとにPHPが丸ごと載る方式で、1プロセスあたり数十MBを消費する。小さなインスタンスに既定値ぶんのプロセスが並ぶ余地は、そもそも存在しない。

つまりこの既定値は、達成されないまま、その手前でデータベースを使い切る。だからメモリ不足にもならず、Apacheの上限警告も出ず、データベースだけが先に倒れていた。

そこで上限を下げた。勘で決めるのではなく、実測から1プロセスあたりの増分を割り出して算出する。

ps -ylC apache2 | awk 'NR>1 {s+=$8; n++} END {printf "%d プロセス / 平均RSS %.1fMB\n", n, s/n/1024}'

ここで注意がある。平均RSSをそのまま使ってはいけない。 RSSは共有メモリを各プロセスで二重計上するので、プロセス数を掛けると実際の消費量を大きく超える。実際、このサーバーでもRSSの合計は free が示す使用量を上回っていた。

正しい手順はこうなる。

1. メモリの実使用量から、OSとデータベースの分を引く
2. 残りをプロセス数で割り、1プロセスあたりの増分を出す
3. 使えるメモリの予算を増分で割り、上限値を決める

あわせて、待機プロセスの上限も下げた。使われないプロセスを何個も確保しておく設定になっていて、それだけでかなりのメモリを遊ばせていた。見直した結果、実際に空きメモリが増えた。

ちなみに算出してみると、このサイトの実需に対して既定値は2桁以上かけ離れていた。既定の150という数字には、このサイトにとっての根拠が何もなかった。

これで挙動がこう変わる。

変更前  Apache が全部受ける → 既定値まで並列を増やそうとする
        → DB の接続数を使い切る → 本物の訪問者もエラー → 落ちる

変更後  Apache は算出した数だけ処理し、残りは待ち行列へ
        → DB は上限に届かない → 一時的に重いが、全員にページは返る

「落ちる」を「遅くなる」に変える。 限界を上げるのではなく、先に倒れる場所を選び直す作業だった。

対策3：そもそも届かせない

ここまでは、届いてしまったリクエストをサーバーに負荷をかけずに返す話だった。最後に、入口で落とす仕組みを入れた。fail2banで、短時間に大量の403／404を出すIPをファイアウォールごと遮断する。Apacheまで届かなくなるので、サーバー側では何も処理しなくなる。

閾値は、スキャナなら即座に引っかかり、普通の訪問者はまず届かない水準に置く。壊れたリンクや欠けた画像を多数含むページがあると誤爆の余地があるので、導入後しばらくは遮断されたIPの一覧を見ておく。

導入でいちばん大事な工程は、起動前の正規表現の検証である。

fail2ban-regex /var/log/apache2/access.log /etc/fail2ban/filter.d/<自作フィルター>.conf

ここで一致件数が0なら、fail2banは静かに何もしない。「入れたから安心」がいちばん危ない状態なので、実ログに当たることを確かめてから起動する。

起動して10秒後、1件目が入った。エラーログで403を返し続けていた相手と同じIPだった。

ログに残っていたその他のもの

調べるついでに、5か月分のログを通して読んだ。出てきたものを並べておく。

バックドアの落ち穂拾い。 shell.php、wp-conflg.php（configの綴り違い）といったファイル名を、既知のリストで総当たりしてくる。自分で侵入するのではなく、他人が先に仕掛けた裏口を拾いに来る動きだ。全部404だった。

リファラ欄に仕込まれた攻撃コード。 Shellshock（CVE-2014-6278）のプローブがリファラに入っていた。参照元というのは送信側が自由に書ける文字列なので、こういう使い方をされる。ログを機械的に処理するなら、この欄は信用できない入力として扱う必要がある。

偽装されたリファラ。 大手取引所のドメインを名乗るアクセスが4,259件あった。最初は参照元スパムかと思ったが、単一のIPが /wp-includes/ 配下のディレクトリを列挙していただけだった。件数だけ見て判断すると読み間違える。

APIを使うコメントスパム。 コメント欄は表示していないのに承認待ちが溜まっていた。ログを見たらこうだった。

GET  /wp-json/wp/v2/posts   200   ← REST API で投稿一覧を取得
POST /wp-comments-post.php  302   ← 3秒後に投稿

記事ページを一度も開いていない。フォームを表示していないことは、受付口を閉じたことにはならない。投稿のコメント設定が開いていれば、受付用のURLは生きている。

ログイン名の調査から始まる総当たり。 ある1日に、1つのIPから72,257回のログイン試行と54,189回のXML-RPC呼び出しが記録されていた。その直前に3件だけ、別の記録がある。

/?author=1
/?author=2
/wp-json/wp/v2/users/

先にログイン名を調べ、それを使って叩く。順序がはっきり読める。なお回数で見ればXML-RPCのほうが本命で、こちらは1リクエストに数百回分の試行を詰め込める仕組みがあるため、実際の試行回数は桁が1つ2つ違う。

この件でいちばんの教訓

ここまでの分析はすべて、アクセスログが8か月分残っていたからできた。

そして、残っていた理由は褒められるものではない。logrotateが入っていなかった。

設定ファイル /etc/logrotate.d/apache2 は正しく存在していた。だから見落とした。あれはApacheのパッケージが置いていくファイルで、logrotate本体が入っているかどうかとは無関係に配置される。

$ sudo logrotate --debug /etc/logrotate.d/apache2
sudo: logrotate: command not found

cronも入っていなかった。クラウドの標準イメージは小さく作られているので、こういう省略がある。設定ファイルの存在は、それを読むプログラムの存在を意味しない。

結果、961万行・1.8GBまで膨らんでいた。ディスクに余裕があったので事故には至らなかったが、アクセスの多いサイトなら埋まっていた。

導入して、保持期間を180日に延ばし、ファイル名に日付を入れた。これで期間を絞った検索ができる。

access.log-20261017.gz

# 5月分だけを検索する
zgrep '探したい文字列' /var/log/apache2/access.log-202605*.gz

1日あたり数MB、gzipが10倍近く効くので、180日分でも大した容量にはならない。

サイトが落ちていた原因も、コメントスパムの入口も、5か月前のログが残っていなければ「気のせい」で終わっていた。測れていないものは、直せたかどうかも分からない。