CPUもDBも余裕なのに全ショップ同時ダウン。犯人は『ゆっくり読むだけ』のbotでした
ある朝、1台のサーバに相乗りしていた複数のECショップが、一斉に「応答タイムアウト」で監視に引っかかりました。 先に正直に書いておきます。障害そのものは約5分で自然回復しました。派手な復旧劇はありません。 この記事の主役は、その5分ではなく、「容疑者が全員シロなのに、サイトだけ落ちている」という気持ち悪さをどう詰めたかです。
舞台は、1台で数十のECショップを相乗りさせた共有Webサーバ(Apache prefork) こういう構成、運用している方なら胃が痛くなるやつです。1ショップのトラブルが、隣のショップを巻き込む。
ある朝、全ショップの監視が一斉に赤くなった
監視が一斉に鳴りました。複数ショップが同時に “socket timeout”。 共有サーバで全ショップ同時となると、まず疑うのは「土台が死んだ」系です。CPU、メモリ、DB、そのあたり。
ところが、見にいくと様子がおかしい。 落ちているのに、サーバはピンピンしているんです。
定番の容疑者が、全員シロだった
順番に潰していきました。
- CPU: idle 84%。暇している。
- DB: ピークでも飽和していない。詰まっていない。
- メモリ: OOMkillerの形跡なし。プロセスの再起動もなし。
負荷障害の定番容疑者が、きれいに全員シロです。 なのに監視は “socket timeout” を返し続ける。つまりTCPの接続は張れているのに、その先で応答が返ってこない。
ここで一つ、頭の片隅が引っかかります。 CPUもDBも余裕で、メモリも無事。それでも応答が返らないとしたら、足りなくなっているのは「計算資源」ではなく「応答を捌く枠」ではないか、と。 Apache preforkでいうと、リクエストを処理するワーカープロセスの数です。
頼みのerror.logが、実は死んでいた
「MaxRequestWorkersに到達したなら、error.logにそう書いてあるはず」 そう思ってグローバルのerror.logを開いて、二度見しました。
何も、書いていない。
調べると、原因はログのパイプラインでした。 ErrorLogをsyslogに流していたのですが、そのとき付けていた固定タグが、rsyslog側の振り分け正規表現に一致していなかった。 結果、サーバスコープ(個別のVirtualHostではなく、サーバ全体)のエラーが、どこにも着地せず宙に消えていたんです。 「MaxRequestWorkersに到達した」という、今いちばん欲しい一行すら、残っていませんでした。
これ、地味ですが一番こわい話です。 障害の最中に、頼りにしていた計器がそもそも繋がっていなかった。 (この件は後日、振り分け側を直して、サーバスコープのエラーがちゃんと残るようにしました。詳しくは最後に書きます)
アクセスログの%Dを見て、背筋が冷えた
error.logが死んでいるので、生きているログ、アクセスログに戻ります。
ここで効いたのが、応答時間のフィールド(%D、マイクロ秒)でした。
件数で集計していた頃には見えなかったものが、%D でソートした瞬間に出てきます。
応答に15秒以上かかったリクエストが159本。最長はなんと17分(1040秒)にわたって、ワーカーを1本占有しっぱなし。
Webのリクエストで17分です。普通は速ければミリ秒、遅くても秒の世界。それが分単位。 しかもそれらは、全部1つのショップ・全部1つのIPに集中していました。
件数ベースの集計だと、この手の相手は絶対に上位に出てきません。 そこが今回いちばんの教訓だったので、太字にしておきます。 詰まりを探すなら、件数ではなく滞留時間(%D)でソートする。
犯人は「件数の多いやつ」ではなかった
そのIPを調べると、海外の商用プロキシ/スクレイピング業者でした。しかも古いChromeを騙るUA、ブラウザのふりです。 で、ここが一番いやらしいところ。
そいつは8分ほどで217リクエスト、レートにして約0.45 req/秒。むしろ低い。 当時入れていたconnlimit/hashlimit(同時20接続超、毎秒1リクエスト超で弾く)を、ど真ん中ですり抜ける遅さです。 普通のレート制限は「速すぎるやつ」を捕まえる仕掛けなので、「わざと遅いやつ」には無力でした。
何をしていたか。 リクエストはさっさと送るくせに、こちらが返す応答を、わざとちょびちょびとしか受け取らない。 受信が終わるまでワーカーは解放できないので、その1本が10分、15分と枠を占有し続ける。 これを何本も同時にやられると、preforkのワーカーが順番に埋まって、上限(128)に達した瞬間、全ショップ分の枠が枯れる。 土台(CPU/DB)はずっと暇なまま、サイトだけが落ちる——今回の気持ち悪さの正体です。
これ、有名なslowloris(リクエストをちびちび送ってワーカーを占有する攻撃)の、応答側バージョンです。 俗に low-and-slow と呼ばれる手口で、「速さ」ではなく「遅さ」で殴ってくる。 派手なトラフィックスパイクが出ないので、負荷グラフを眺めていても気づけません。
その場でやったこと(応急)
正体が割れたので、まずは出血を止めます。 やったことはシンプルで、その単一IPを即ブロック。 具体的には、ファイアウォール(iptables)の先頭にDROPを1行。念のため適用前の状態をバックアップしてから入れて、巻き添えになっていた他ショップがちゃんと200で返ることを確認しました。
ただ、ここは正直に書きます。
これは今殴ってきている手を止めただけの応急処置で、恒久対策ではありません。
相手はIPを変えてくる商用業者なので、IP遮断はどうしてもいたちごっこになる。
しかも、よく対策に挙がる mod_reqtimeout は「リクエストを受け取る側」が遅いケース(=本家slowloris)を見るもので、今回のように「応答を読む側がわざと遅い」ケースは、リクエスト側のタイムアウトでは捕まえきれません。
単純なレート制限がすり抜けられたのと、根っこは同じ理由です。
本当の解は「速い遅いを吸収する前段」だと思う
ここからは、実際にやったことではなく、今回の結論・宿題として書きます(まだ入れていません、正直に)
preforkの素のApacheに動的コンテンツを喋らせていると、「クライアントが応答を読み終わるまでワーカーが拘束される」という構造そのものは消えません。 なので筋のいい解は、Apacheの前に応答をバッファリングしてくれる前段を置くことだと思っています。 CDNなりリバースプロキシなりで、いったん応答を全部受け取ってから、遅いクライアントには前段がゆっくり付き合う。 そうすればApacheのワーカーは応答を吐き終わった時点で解放され、「遅いやつ」に枠を人質に取られなくなる。 あわせて、出力側・アイドル側のタイムアウト(応答を流している最中の無進捗を切る)も効きます。
要は、遅いクライアントの相手は、枠が貴重なApacheではなく、枠が潤沢な前段にやらせる。これが構造的な答えだと考えています。
結局、何を学んだか
暗号でもアルゴリズムでもない、地味だけど効く教訓を3つ残します。
1. CPU/DBに余裕があるのにsocket timeoutなら、ワーカー/接続の枯渇を疑う。 負荷グラフではなく、ワーカープールの空き枠を見る。資源は余っていても「枠」は枯れます。
2. 詰まりは件数ではなく滞留時間(%D)で探す。
低レートのlow-and-slowは件数集計に出てきません。%D でソートして初めて顔を出します。
3. 監視ログ自体の死活を、平時に確かめておく。 障害のときに限ってerror.logが死んでいた、は笑えません。計器が宙に消える設定になっていないか、何も起きていない日に一度見ておく。今回はこれが一番こたえました。
派手な攻撃ではないからこそ、気づきにくい。 皆様のワーカープール、ちゃんと空いていますか？ 件数は少ないのに、やたら長居するお客さんには、くれぐれもお気をつけください。