ISUCON10 やらかしリスト

ISUCON10お疲れさまでした。運営の皆さん、ありがとうございました。

ボク、@sekai67はNaruseJunチームの一員として出場しました。結果はこう。

予選では、本選出場圏内の点数を取って余裕をカマしていましたが、追試をパスできずに予選落ち。
本選では、本選ライブの企画で、並行チームとして問題に取り組ませてもらう。
- 競技中最高得点 52567 を記録するものの、追試をパスできず記録なし。伝統芸能

これは記念写真です。

まあ追試で落ちてるんですけどね！

参加記はチームメイトの@to_hutohuと@takashi_trapが書いてくれると信じて、ボクはちょっとしたこぼれ話を書いていきます。

やらかしリスト

予選、本選どちらにおいても、思い返すとまあいろいろやらかしたんですが、今回は興味深かった2つを抜粋して掘り下げます。

予選時、再起動試験を5回ぐらいして、追試落ちは絶対ない状態まで持っていったのに無事追試落ちした話
本選開始後、初手でサーバの1台を使い物にならなくしてチームメイトを困惑させた話

予選の追試で落ちた

経緯

予選では、チームメイトの2人がわりとギリギリまでアプリ実装のバグ取りを詰めていたので、ボクが1人で再起動試験や後片付けを担当することになりました。去年も再起動後に正しく動作させることができずに予選落ちしていますので、今年こそは！と念入りに何度も行っていました。

5回ほど再起動してもOK、再起動後にもデータも正しく引き継がれている。絶対落ちないだろコレは！！！と自信満々で競技を終えたわけですが、結果発表でチーム名が呼ばれることはありませんでした……

夜中、凹みつつも競技で使ったサーバの様子を見に行ってみると…… DBサーバが落ちてるやんけ！！！！！なんで？？！？！？？！？？！！！

理由

apparmorのポリシー(mysql-serverパッケージに入ってる/etc/apparmor.d/usr.sbin.mysqld)が生きていて、systemdがmariadbの起動を検知できておらず、systemctl stop相当の処理がかかったため。

Ubuntuで、最初にmysqlが動いている状態から、これをmariadbに置き換えると起動しなくなるという事例があります。こちらの記事が詳しいです。

疑問1: mariadbに入れ替えたときにto-hutohuが`aa-remove-unknown`でポリシーを消したのでは？

先ほど紹介した記事を書いたのはボクです。ですので、もちろんこの挙動については知っていました。上記記事で紹介されている対策法をもちろん講じています。

が、これはそもそも恒久対応ではありませんでした……！わかりにくい書き方でゴメンナサイ。

先の記事で言及している、

/etc/apparmor.d/usr.sbin.mysqldは空のファイルで上書きされますが、AppArmorがすでに読み込んでいるプロファイルは削除されません。また、systemctl reload apparmorしても、OSを再起動しても、一度読み込まれたプロファイルが勝手に削除されることはありません。

ここの理解が曖昧、あるいは間違っています。

ポリシーがOSを再起動しても消えない原因は、apparmorのポリシーキャッシュのせいで、/etc/apparmor.d/cache/usr.sbin.mysqldが存在して、かつ/etc/apparmor.d/usr.sbin.mysqldよりタイムスタンプが新しい場合、キャッシュのほうが読み込まれるという挙動をします。

/etc/apparmor.d/cache/usr.sbin.mysqldが作成されるのは、mysql-serverインストール時。
- つまりタイムスタンプは → Sep 11 11:34
/etc/apparmor.d/usr.sbin.mysqldのタイムスタンプは、mariadbパッケージが作成された時。
- つまりタイムスタンプは → Jul 20 10:50

ですので、/etc/apparmor.d/usr.sbin.mysqldが更新されたにも関わらず、キャッシュのほうがずっと読み込まれ続けてしまうのでした……！

正しい対応は、systemctl reload apparmorでした。これでキャッシュのflushが走り、正しくmariadbに起動するようになります。

例の記事については、そのうち書き換えておきますね……

疑問2: sekaiが再起動試験を行ったときにうまく動作していたのは何故？

再起動後15分以内にのみ試験していたからです。

AppArmorのせいでmariadbに起動に失敗するというのは、厳密に言うと、 mariadbは起動に成功しているんだけどsystemdがそれを検知できていない ということ。 systemdは一定時間（デフォルトで15分）以内にサービスの起動を確認できないと、ご丁寧にExecStopを走らせてくれるのです……！

sekaiが再起動したのは 11:39:26 UTC ごろ。

-- Reboot --
Sep 12 11:39:26 s2 systemd[1]: Starting MariaDB 10.1.44 database server...
Sep 12 11:39:32 s2 mysqld[1244]: 2020-09-12 11:39:32 139768179551360 [Note] /usr/sbin/mysqld (mysqld 10.1.44-MariaDB-0ubuntu0.18.04.1) starting as process 1244 ...
Sep 12 11:45:11 s2 systemd[1]: Stopped MariaDB 10.1.44 database server.
-- Reboot --

11:45:11にStopしてるのは、このあともう一度再起動試験したためです。

この付近のkern.logは以下。

Sep 12 11:39:35 s2 kernel: [   42.180656] audit: type=1400 audit(1599910775.956:18): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/mysqld" name="run/systemd/notify" pid=1244 comm="mysqld" requested_mask="w" denied_mask="w" fsuid=111 ouid=0

sd-notify失敗してるので、この時点でもAppArmorのポリシーが生きています。 systemdはこのときずっとmariadbが上がってくるのを待っている状態です。ただし、mariadb自体は起動しているので、アプリへのリクエストは通る状態です。（sekaiのこの状態でずっと再起動試験をしていたわけです。バカですねえ。）

一方で、運営による再起動が行われたと思われる時刻(14:20:38 UTC つまり 23:20:38 JST)付近のログは以下のとおり。

-- Reboot --
Sep 12 14:20:38 s2 systemd[1]: Starting MariaDB 10.1.44 database server...
Sep 12 14:20:42 s2 mysqld[1100]: 2020-09-12 14:20:42 140238334753920 [Note] /usr/sbin/mysqld (mysqld 10.1.44-MariaDB-0ubuntu0.18.04.1) starting as process 1100 ...
Sep 12 14:35:41 s2 systemd[1]: mariadb.service: Start operation timed out. Terminating.
Sep 12 14:35:43 s2 systemd[1]: mariadb.service: Failed with result 'timeout'.
Sep 12 14:35:43 s2 systemd[1]: Failed to start MariaDB 10.1.44 database server.

15分立ったのでmariadbがshutdownされたと思われます。以下は/var/lib/mysql/error.logです。

2020-09-12 14:35:41 140238333712128 [Note] /usr/sbin/mysqld: Normal shutdown
2020-09-12 14:35:41 140238333712128 [Note] Event Scheduler: Purging the queue. 0 events
2020-09-12 14:35:41 140236692629248 [Note] InnoDB: FTS optimize thread exiting.
2020-09-12 14:35:41 140238333712128 [Note] InnoDB: Starting shutdown...
2020-09-12 14:35:41 140238333712128 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2020-09-12 14:35:43 140238333712128 [Note] InnoDB: Shutdown completed; log sequence number 3710056674
2020-09-12 14:35:43 140238333712128 [Note] /usr/sbin/mysqld: Shutdown complete

実際にアプリにリクエストが来たのは、15:03:13 UTCでした。

Sep 12 14:20:45 s1 isuumo[903]: ⇨ http server started on [::]:1323
Sep 12 15:03:13 s1 isuumo[903]: [mysql] 2020/09/12 15:03:13 packets.go:122: closing bad idle connection: unexpected read from socke
Sep 12 15:03:13 s1 isuumo[903]: [mysql] 2020/09/12 15:03:13 connection.go:158: driver: bad connection
Sep 12 15:03:13 s1 isuumo[903]: [mysql] 2020/09/12 15:03:13 packets.go:122: closing bad idle connection: unexpected read from socke
Sep 12 15:03:13 s1 isuumo[903]: [mysql] 2020/09/12 15:03:13 connection.go:158: driver: bad connection

このとき、もうmariadbはshutdown済みなので、当然アプリは動かないわけですね……

開始後即サーバを破壊

経緯

本選始まって直後の話。

NaruseJunチームでは、Makefileをタスクランナー的に使っていて、ここにデプロイコマンドを書いていました。 sekaiがアプリにpprofを埋め込んだコードをプッシュし、サーバ上にデプロイしようとしてmake deployを叩いたところ、なぜか途中でsh: Command not foundのエラーが出てmakeが終了しました。

アレ？shって存在しないんだっけと思い、今度はls -l /usr/bin/shを実行してみると、今度はbash: /usr/bin/ls: No such file or directoryが…… ここで全てを悟ります。これ、シェル組み込みのコマンド以外、全て使えなくなってるな……？

心当たりがないわけではありませんでした。3人共、ある会話が頭をよぎりました…… あれは予選時のことです――――

sekai「ミドルウェアの設定ファイルなども、リポジトリに含めてしまって、デプロイ時にrsyncで配置するようにしませんか？」
takashi「rsyncですか？どうやってやるんですか」
sekai「コマンド一発でできますよ。こうですね」

$ ls files
etc/       home/      lib/
$ sudo rsync -r files/ /

takashi「これってもともとサーバ上にあるファイルが消えたりしませんか？」←ここフラグ
sekai「大丈夫ですよ。ほら、追加したファイルだけ更新されてるでしょ？」

予選では確かに、このコマンドでうまくデプロイできていました。ですので、本選でも同じように設定ファイル類を配置しようとしていました。

しかしながら、事実、サーバが壊れました。何故でしょう…… このときのログはこうでした。

〜〜〜略〜〜〜
make[1]: Leaving directory '/home/isucon/isucon10-final/app/webapp/golang'
sudo rsync -v -r s1/ /
sending incremental file list
deploy.sh
skipping non-regular file "etc/mysql/my.cnf"
etc/envoy/config.yaml
etc/mysql/debian-start
etc/mysql/debian.cnf
etc/mysql/my.cnf.fallback
etc/mysql/mysql.cnf
etc/mysql/conf.d/mysql.cnf
etc/mysql/conf.d/mysqldump.cnf
etc/mysql/mysql.conf.d/mysql.cnf
etc/mysql/mysql.conf.d/mysqld.cnf
etc/systemd/system/envoy.service
etc/systemd/system/xsuportal-api-golang.service
etc/systemd/system/xsuportal-web-golang.service
home/isucon/env
lib/
lib/systemd/
lib/systemd/system/
lib/systemd/system/mysql.servicesent 11,952 bytes  received 375 bytes  24,654.00 bytes/sec
total size is 10,449  speedup is 0.85
sh s1/deploy.sh
make: sh: Command not found
make: *** [Makefile:54: start] Error 127

う〜ん、--deleteオプションも付けてないし、このログを見ても特におかしくないしなあ。本選時はそう思っていました。

ここを詳しく調査する時間がもったいないので、運営にサーバをリセットしてもらい（ご迷惑おかけしました……）、とりあえず危険なMakefileは使用禁止として競技に戻りました。

その後

競技は無事(?)終了し、翌日。ちゃんと調査しました。

さて、件のログをよ〜く見ると、なんだかヤバそうなところが見つかりますね！？

正解はlib/とだけ書いてある行です。これは、rsyncによってlib/というディレクトリ、今回は宛先が/なので、要は/libが作成されたという意味です。んん？？それはマズくないか？？？？？

マズいです。コマンドがほぼ使えなくなったのは、間違いなく/libにある共有ライブラリなどが消滅したからでしょう。

でも、予選時はちゃんと動いていたんです。じゃあなんで？？？

答えは、Ubuntuのバージョン違いにありました。予選では18.04、本選では20.04です。各バージョンでのルートディレクトリがどうなっているかと言うと……

18.04では、こう。

# ls -l /
total 64
drwxr-xr-x   2 root root 4096 Sep 21 17:17 bin
drwxr-xr-x   2 root root 4096 Apr 24  2018 boot
drwxr-xr-x   5 root root  360 Oct  4 07:46 dev
drwxr-xr-x   1 root root 4096 Oct  4 07:46 etc
drwxr-xr-x   2 root root 4096 Apr 24  2018 home
drwxr-xr-x   8 root root 4096 May 23  2017 lib
drwxr-xr-x   2 root root 4096 Sep 21 17:16 lib64
drwxr-xr-x   2 root root 4096 Sep 21 17:14 media
drwxr-xr-x   2 root root 4096 Sep 21 17:14 mnt
drwxr-xr-x   2 root root 4096 Sep 21 17:14 opt
dr-xr-xr-x 174 root root    0 Oct  4 07:46 proc
drwx------   2 root root 4096 Sep 21 17:17 root
drwxr-xr-x   1 root root 4096 Sep 25 22:33 run
drwxr-xr-x   1 root root 4096 Sep 25 22:33 sbin
drwxr-xr-x   2 root root 4096 Sep 21 17:14 srv
dr-xr-xr-x  13 root root    0 Oct  4 07:46 sys
drwxrwxrwt   2 root root 4096 Sep 21 17:17 tmp
drwxr-xr-x   1 root root 4096 Sep 21 17:14 usr
drwxr-xr-x   1 root root 4096 Sep 21 17:17 var

一方で20.04では……？

# ls -l /
total 48
lrwxrwxrwx   1 root root    7 Sep 25 01:20 bin -> usr/bin
drwxr-xr-x   2 root root 4096 Apr 15 11:09 boot
drwxr-xr-x   5 root root  360 Oct  4 07:46 dev
drwxr-xr-x   1 root root 4096 Oct  4 07:46 etc
drwxr-xr-x   2 root root 4096 Apr 15 11:09 home
lrwxrwxrwx   1 root root    7 Sep 25 01:20 lib -> usr/lib
lrwxrwxrwx   1 root root    9 Sep 25 01:20 lib32 -> usr/lib32
lrwxrwxrwx   1 root root    9 Sep 25 01:20 lib64 -> usr/lib64
lrwxrwxrwx   1 root root   10 Sep 25 01:20 libx32 -> usr/libx32
drwxr-xr-x   2 root root 4096 Sep 25 01:20 media
drwxr-xr-x   2 root root 4096 Sep 25 01:20 mnt
drwxr-xr-x   2 root root 4096 Sep 25 01:20 opt
dr-xr-xr-x 171 root root    0 Oct  4 07:46 proc
drwx------   2 root root 4096 Sep 25 01:23 root
drwxr-xr-x   1 root root 4096 Sep 25 22:34 run
lrwxrwxrwx   1 root root    8 Sep 25 01:20 sbin -> usr/sbin
drwxr-xr-x   2 root root 4096 Sep 25 01:20 srv
dr-xr-xr-x  13 root root    0 Oct  4 07:46 sys
drwxrwxrwt   2 root root 4096 Sep 25 01:23 tmp
drwxr-xr-x   1 root root 4096 Sep 25 01:20 usr
drwxr-xr-x   1 root root 4096 Sep 25 01:23 var

アッ……（完全に理解）

Ubuntu 20.04では、/libは通常のディレクトリではなく、/usr/libへのシンボリックリンクでした！ rsyncでは、デフォルトではシンボリックリンクの先がディレクトリであっても、それを辿ってその先にコピーをしたりしません。ソース側のディレクトリでそのまま上書きして、もとのリンクは消してしまうんですね……！

教訓

この悲劇を回避するには、rsyncの--keep-dirlinksというオプションを使うべきでした。以下、man rsyncより引用です。

-K, --keep-dirlinks This option causes the receiving side to treat a symlink to a directory as though it were a real directory, but only if it matches a real directory from the sender. Without this option, the receiver's symlink would be deleted and replaced with a real directory. For example, suppose you transfer a directory lqfoorq that contains a file lqfilerq, but lqfoorq is a symlink to directory lqbarrq on the receiver. Without --keep-dirlinks, the receiver deletes symlink lqfoorq, recreates it as a directory, and receives the file into the new directory. With --keep-dirlinks, the receiver keeps the symlink and lqfilerq ends up in lqbarrq.

ちょうどボクが踏んだ罠について言及されています。 rsyncは気をつけて使います……

おしまい

ISUCONは学びが多い。

あと、予選で雑にmysqlの全テーブルをMEMORYストレージエンジンにしたらメモリが完売してSSHできなくなって焦るなどの事件もありました。（運営に再起動してもらって事なきを得ました。）