apparmorのポリシー(mysql-serverパッケージに入ってる/etc/apparmor.d/usr.sbin.mysqld)が生きていて、systemdがmariadbの起動を検知できておらず、systemctl stop相当の処理がかかったため。
これはそもそも恒久対応ではなかった。
/etc/apparmor.d/usr.sbin.mysqldはmariadbインストール時に空になっている。
が、リブート時にはmysql-serverパッケージ由来のapparmorポリシーが適用されているという経験があった
Ubuntuでmysql-serverをmariadb-serverで置き換えるとsystemd経由でmariadbが起動できない - NaruseJunのメモ帳 https://narusejun.com/archives/24/
ここの記事で言ってる、
/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が走る。
ボクのAppArmorに対する理解が甘くて、このへんの挙動を正確に把握できてなかった。
結論: 再起動後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のポリシーが生きている。ただし、mariadb自体は起動しているので、アプリへのリクエストは通る。 systemdはこのときずっとmariadbが上がってくるのを待っている状態。
一方で、運営による再起動が行われたと思われる時刻(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済みなので、当然アプリは動かない。