背景
- 個人プロダクト用にMySQL8を運用していて定期的にバージョンアップを行っている
- 8.0.14 から 8.0.16 にマイナーバージョンアップしたところMySQLが起動しなくなった 💀
ファーーーーーーー pic.twitter.com/FrFW5kfi1K
— ぴんくもひかん (@pinkumohikan) April 25, 2019
調査と対応
おもむろに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週間前の操作によるものである可能性が高くてもう追えないし、ログを順に辿っていけば解決出来る問題だったのでひとまずこれにて。
