CPCTFでサーバーにとどめを刺しました。ごめんなさい。

謝罪

2日目の競技終了間際に、スコアサーバーの応答が無くなり、問題の閲覧、フラグの提出などができない状況になりました。ご迷惑をおかけしてしまい、申し訳ありませんでした。

この記事では、CPCTF2024インフラチームがやったことを紹介し、スコアサーバーが落ちた原因とその解決策を説明します。

準備

昨年からの変更点をスコアサーバーに反映し、サーバーを立てて問題のデプロイを行いました。

スコアサーバーの昨年からの主な変更点は、

X(旧Twitter)との連携機能（アイコン取得のため）を削除し、アイコン画像をアップロードできるようにする
ビジュアライザが無くなったことを受けてコードの修正をする

の2点です。

サーバーはConoHaのVPSを使い、ansibleでスコアサーバーや監視基盤、WebShell、Web問題の環境などをデプロイしました。スコアサーバーは3コア、メモリ2GBのVPSを使っています。

今年のスコアサーバーです。かっこいいですね

当日

競技当日は、問題の修正などの緊急対応を行う予定でした。

1日目

10:00

競技開始と同時に「終了しました」とスコアサーバーに表示されます。これはikura-hamuが終了時刻を2023年に設定してしまっていたことが原因でした。
競技開始直前に再度設定の確認をpirosikiがしましたが、それでも気づきませんでした。私の目は節穴です。

17:00ごろ

一部の問題に機械的な総当たり提出を行っている参加者がいることが分かりました。
この後も何度かそのような傾向が見られたので、運営の人にアナウンスを出してもらいました。

これはCPCTFが終わった後のユーザーごとの回答提出回数ですが、Top 3がすごいことになってますね。数自体はでかでかですが、結果として総当たりによってサーバーに過度な負荷がかかることはなかったのでよかったです。

ちなみに正答率 0.037% の超高難易度問題()が誕生していました

23:30

アナウンス後はそのような提出は見られなくなりましたが、念のためフラグの提出にRate Limitをかけてスコアサーバーをデプロイしなおしました。

2日目

午前は何事もなく競技が進みました。

13:00ごろ

急にスコアサーバーのCPU使用率が上がり始め、画面が重くなりました。時間がたつと一時的に下がりましたが、15時ごろにまた負荷が上がり始め、CPU使用率が100%に張り付いた状況が続きます。

ログに流れてくるDBのスロークエリ見て、一部のクエリで1秒以上の時間がかかっていることを確認しました。また、MySQLのPerformance Schemaも見て、適切なインデックスが張られていないのではないかという推測を立てました。
(Performance Schemaで使うクエリはこちらの記事を参考にしましたチーム白金動物園としてISUCON13に参加しました)

15:50ごろ

ここまでの調査を踏まえ、ikura-hamuが手動でDBに不足していそうなインデックスを追加するクエリを実行しました。
CPUが100%に張り付いている状態で、そこそこな量のデータが入っているテーブルにインデックスを貼る操作にサーバーが当然耐えられるはずがなく、スコアサーバーからの応答が無くなりました。

運営の人に競技時間延長のアナウンスを打ってもらい、スコアサーバーを再起動しました。

競技終了後

競技時間が終わってもCPU負荷が高いままだったので、調査を続けました。

サーバーにssh接続して、htopでCPUを占有しているプロセスがmysqldであることを確認しました
- 最初表示がバグってるかと思った
pirosikiが https://github.com/go-sql-driver/mysql?tab=readme-ov-file#important-settings を参考にして、DBコネクションの設定を行いました。
スコアサーバー側の問題と予想し、pprofを有効にして、CPUプロファイルを取得しました
- ボトルネックとなっていそうなものは見つかりませんでした。
実装におかしい点が無いかを確認しました
- 大部分の実装は昨年度以前のものを引き継いだもので把握していない部分も多かったのでコードを読み直しました。
- コードが複雑なのもあり、この時点では見つからず
スコアサーバーが吐き出しているログをGrafanaで無理やりパースしてアクセスログとして確認しました
- 競技終了直前にユーザー取得のリクエストが大量に来ていることが分かりましたが、CPUの負荷が上がったのはもっと前の時間だったので、関係なさそう
ログから476秒かかっているクエリを見つけました。
- ユーザーの正答を取得するエンドポイントでこのクエリが実行されていることが分かりました。

夜遅くなったので、調査は次の日に持ち越しました。

3日目(競技終了翌日)

14:00ごろ

急激にCPUの使用率が上がり始め、100%で張り付きました。ですが、このタイミングでpprofのプロファイルを実行してもやはりアプリに負荷がかかっている様子はありませんでした。

調査を続けましたが、原因はわからず、負荷も下がったので調査をやめました。

20:00ごろ

ここまでMySQLのPerformance Schemaを使って実行されたクエリの分析を行っていましたが、スロークエリログを有効化して、クエリ実行時間が60秒以上の非常に長いクエリだけをファイルに書き出すようにしました。

また、Grafanaのログから、昼に負荷が上がったタイミングで回答提出が極端に多い人がログインしていたことが分かりました。
怪しいですね。

24:00ごろ

スロークエリログを確認すると、1つクエリが確認できました。

bash-4.4# cat slow-query.log
/usr/sbin/mysqld, Version: 8.0.36 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2024-04-22T15:21:57.502721Z
# User@Host: root[root] @  [***.***.***.***]  Id:   132
# Query_time: 936.482695  Lock_time: 0.000003 Rows_sent: 27  Rows_examined: 508637916

use scoreserver;
SET timestamp=1713798381;
SELECT
        an_a.challenge_id AS challenge_id,
        an_a.correct AS correct,
        an_a.created_at AS created_at,
        IF(an_a.correct = 0, 0, cs.score) AS acquired_score
FROM answers AS an_a
LEFT JOIN challenge_scores AS cs ON cs.challenge_id = an_a.challenge_id AND cs.hint_level = an_a.hint_level
WHERE an_a.user_id = {ユーザーのID}
AND an_a.id = (
        SELECT an_b.id
        FROM answers AS an_b
        WHERE an_a.user_id = an_b.user_id AND an_a.challenge_id = an_b.challenge_id
        ORDER BY an_b.created_at DESC
        LIMIT 1
);

Rows Examined: 508637916、5億?!

このクエリは、特定のユーザーについて、今まで提出した問題のid、正解したかどうか、最新の回答はいつか、そしてその問題によって得られた得点を取得するものです。これは問題一覧ページを確認すると実行されます。

このクエリで使われていたユーザーIDは、回答の提出が多いユーザーのものでした。つまり、このユーザーが問題一覧ページを見るたびに、サーバーが爆発していたのです。

夜遅かったので、調査はさらに次の日に持ち越すことにしました。

4日目(競技終了後翌々日)

前日遅いことが分かったクエリをより深く調べていきます。
まずEXPLAINを実行しました。

*************************** 1. row ***************************
           id: 1
  select_type: PRIMARY
        table: an_a
   partitions: NULL
         type: ref
possible_keys: fk_answers_user
          key: fk_answers_user
      key_len: 144
          ref: const
         rows: 20742
     filtered: 100.00
        Extra: Using index condition; Using where
*************************** 2. row ***************************
           id: 1
  select_type: PRIMARY
        table: cs
   partitions: NULL
         type: ref
possible_keys: fk_challenge_scores_challenge
          key: fk_challenge_scores_challenge
      key_len: 144
          ref: scoreserver.an_a.challenge_id
         rows: 4
     filtered: 100.00
        Extra: Using where
*************************** 3. row ***************************
           id: 2
  select_type: DEPENDENT SUBQUERY
        table: an_b
   partitions: NULL
         type: ref
possible_keys: fk_answers_user,fk_answers_challenge
          key: fk_answers_user
      key_len: 144
          ref: scoreserver.an_a.user_id
         rows: 246
     filtered: 10.00
        Extra: Using where; Using filesort
3 rows in set, 3 warnings (0.01 sec)

行数の多いテーブルのJOINと相関サブクエリが原因ではないかと考えていました。
（相関サブクエリ: https://zenn.dev/kou_row_line/articles/6acb7d888c9f32749c41 ）

相関サブクエリでは、メインの方の行の数だけ(ここでは20742回)サブクエリが実行されてしまいます。とんでもなく遅いです。

このクエリを高速化するため、まずanswersテーブルとchallenge_scoresテーブルにインデックスを貼ってみました。EXPLAIN結果は少し改善していましたが、まだ使えるレベルではありません。

このままのクエリでは改善が難しいと考え、クエリ自体を書き換えることにしました。
answersテーブルにレコードが追加されるのはそのユーザーがまだ問題に正答していないときのみです。GROUP BYを用いて正解したかどうかと解答時刻をMAXで取得することでクエリを軽くできました。

WITH uc 
    AS (SELECT an.challenge_id, MAX(an.correct) AS correct, MAX(an.hint_level) AS hint_level , MAX(an.created_at) AS created_at 
    FROM answers AS an 
    WHERE an.user_id = {ユーザーID}
    GROUP BY (an.challenge_id)
    )
SELECT uc.challenge_id, uc.correct, uc.created_at, cs.score * uc.correct AS acquired_score 
FROM uc 
JOIN challenge_scores AS cs ON uc.challenge_id = cs.challenge_id AND uc.hin
t_level = cs.hint_level 
ORDER BY uc.challenge_id;

この変更で、クエリの実行時間は6 min 52.81 sec から 0.07 sec になりました。5885.71429倍速くなったらしいです。すごい！ ~~もとのクエリが遅すぎただけ~~

これで解決です。めでたしめでたし。

結論

今回サーバーが落ちた原因をまとめると以下の通りです。

大量に回答を提出するユーザーが現れたことによって、大量の回答がデータベースに蓄積される
想定以上の提出が行われたことで、昨年度まで起きなかったSQLのパフォーマンスの問題が発生し、CPUの使用率が上がる
↑を解決するためにインデックスを貼る操作を行い、とどめを刺す

反省

今回の反省点です。

本番環境を直接操作した
- それはそう
アクセスログやスロークエリログを設定していなかった
- 原因を特定するのが遅れた
フラグの機械的な提出への対策をあらかじめ用意するべきだった

画像

競技中のCPU使用率。濃い青がUser。ときどき100%になっているが、このタイミングで5億行を走査するクエリが発行されたと思われる。

競技終了直後のCPU使用率

感想

ikura-hamu

当日までまさかこんな問題が起こるとは思いもしませんでした。いきなりISUCONをやることになってしかもサーバーを落としちゃったのが悔しすぎるので、来年のCPCTFでリベンジしたいです。来年は絶対に落ちないスコアサーバーを用意して待っています。

pirosiki

初手謝罪です。やらかしまくりでした。申し訳ありませんでした。
自分は主にインフラというより、今年用のスコアサーバーのバックエンドの書き換えをしていました。準備中はうまくいっているように見えたのですが、本番何が起こるかわからないものですね。
今回のような多くの人に使われるサーバーを触ったのは初めてだったのでいい経験になりました。来年の担当者が困らないようにスコアサーバーをさらにいいものにして引き継ぎたいです。

Alt--er

スコアサーバーの設計に一応携わっていました。基本的に他のタスクに追われるなどでikura-hamuさんとpirosikiさんにほぼ仕事を投げている状況でした。すみません&ありがとう!!
今年度のスコアサーバーは来年度以降の基礎となるように改めて機能を整理するなどを行いました。自分もその一環として使わなかった機能の削除などを中心に行なっていました。正直なところまだまだ勉強不足でよくわかっていなかった部分も多いですが、今後の活動を通して知見を得ていき来年度以降もサーバに携わる仕事ができればと思います。次回こそ頑張ります。

おわり

CPCTFに参加してくださった皆さんありがとうございました。来年はこのようなことが起きないようにします。