モヒカンは正義

プログラマー風林火山で言う「風のエンジニア」になりたい(比較的)若者Webエンジニアの備忘録

MySQL8をバージョンアップしたら起動しなくなった

背景

  • 個人プロダクト用にMySQL8を運用していて定期的にバージョンアップを行っている
  • 8.0.14 から 8.0.16 にマイナーバージョンアップしたところMySQLが起動しなくなった 💀

f:id:pinkumohikan:20190502141209p:plain

調査と対応

おもむろにstartしてみる

$ sudo systemctl start mysql
Job for mysql.service failed because the control process exited with error code.
See "systemctl status mysql.service" and "journalctl -xe" for details.

ですよね〜〜〜

素直にprocessのログを見る

$ sudo journalctl -xe
...
Apr 26 00:39:17 $hostname sudo[5013]: $username : TTY=pts/0 ; PWD=/home/$username ; USER=root ; COMMAND=/bin/systemctl start mysql
Apr 26 00:39:17 $hostname sudo[5013]: pam_unix(sudo:session): session opened for user root by $username(uid=0)
Apr 26 00:39:17 $hostname systemd[1]: Starting MySQL Community Server...
-- Subject: Unit mysql.service has begun start-up
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mysql.service has begun starting up.
Apr 26 00:39:17 $hostname audit[5067]: AVC apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/usr/sbin/mysqld" pid=5067 comm="apparmor_parser"
Apr 26 00:39:17 $hostname kernel: audit: type=1400 audit(1556206757.959:27): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/usr/sbin/mysqld" pid=5067 comm="a
Apr 26 00:39:19 $hostname trace-agent[945]: 2019-04-26 00:39:19 JST | TRACE | INFO | (pkg/trace/agent/service.go:63 in Run) | total number of tracked services: 0
Apr 26 00:39:23 $hostname systemd[1]: mysql.service: Main process exited, code=exited, status=1/FAILURE
Apr 26 00:39:23 $hostname systemd[1]: mysql.service: Failed with result 'exit-code'.
Apr 26 00:39:23 $hostname sudo[5013]: pam_unix(sudo:session): session closed for user root
Apr 26 00:39:23 $hostname systemd[1]: Failed to start MySQL Community Server.
-- Subject: Unit mysql.service has failed
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mysql.service has failed.
--
-- The result is RESULT.
...

うーん、何も分からない(キレ気味)

MySQLのログを見る

$ sudo less /var/log/mysql/error.log
...
2019-04-25T15:41:12.267479Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.16) starting as process 6246
2019-04-25T15:41:13.263343Z 4 [System] [MY-013381] [Server] Server upgrade from '80015' to '80016' started.
2019-04-25T15:41:15.448593Z 4 [ERROR] [MY-013384] [Server] Could not create server upgrade info file at '/var/lib/mysql/'.
2019-04-25T15:41:15.454470Z 0 [ERROR] [MY-013380] [Server] Failed to upgrade server.
2019-04-25T15:41:15.455397Z 0 [ERROR] [MY-010119] [Server] Aborting
2019-04-25T15:41:17.137374Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.16)  MySQL Community Server - GPL.

Could not create server upgrade info file at '/var/lib/mysql/'.

このあたりが怪しそう

おもむろにlsしてみる

$ ls -alh /var/lib/mysql/
...
drwxr-x---  2 mysql mysql 4.0K Apr 26 00:41  mysql
-rw-r-----  1 mysql mysql  56M Apr 26 00:41  mysql.ibd
-rw-r--r--  1 root  root     6 Apr 13 00:08  mysql_upgrade_info
drwxr-x---  2 mysql mysql 4.0K Apr 26 00:28  performance_schema
-rw-------  1 mysql mysql 1.7K Sep 30  2018  private_key.pem
...

一個だけroot所有なファイルが有るぞ...!?

mysql_upgrade_infoは本来rootじゃなくてmysql所有であるべきものっぽいので、所有者をmysqlに変えたら直るんじゃね?

$ sudo chown mysql:mysql mysql_upgrade_info
$ sudo systemctl start mysql
$ sudo systemctl status mysql
● mysql.service - MySQL Community Server
   Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
   Active: active (running) since Fri 2019-04-26 00:51:50 JST; 3s ago
     Docs: man:mysqld(8)
           http://dev.mysql.com/doc/refman/en/using-systemd.html
  Process: 11526 ExecStartPre=/usr/share/mysql-8.0/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 11578 (mysqld)
   Status: "SERVER_OPERATING"
    Tasks: 38 (limit: 1110)
   CGroup: /system.slice/mysql.service
           └─11578 /usr/sbin/mysqld

おかえり

MySQLのログを見ても、バージョンアップ成功してそう

$ sudo less /var/log/mysql/error.log
...
2019-04-25T15:51:39.763174Z 4 [System] [MY-013381] [Server] Server upgrade from '80015' to '80016' started.
2019-04-25T15:51:42.308523Z 4 [System] [MY-013381] [Server] Server upgrade from '80015' to '80016' completed.
...

なぜ mysql_upgrade_info がroot所有になっちゃったのかは謎だけど、原因が2週間前の操作によるものである可能性が高くてもう追えないし、ログを順に辿っていけば解決出来る問題だったのでひとまずこれにて。