Ubuntu18.04環境でMySQL5.7が起動しなくなった

medalotte技術

ローカルにインストールしていたMySQLを久々に触る機会があったのですが、パッケージマネージャ経由であれこれしていたところ起動しなくなってしまいました。

  1. $ mysql -v
  2. ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)

どうやらmysql-serverとの通信に使用するソケットファイルにアクセス出来ていないようです。

結論

MySQLの状態を初期化し、 ‘/var/lib’ 下の関連するファイルの所有者を正しく設定する必要がありました。

  1. $ sudo mysqld --initialize
  2. $ sudo mkdir /var/lib/mysql-files
  3. $ sudo chown mysql:mysql /var/lib/mysql-files
  4. $ sudo chown -R mysql:mysql /var/lib/mysql

初期化後にrootログインするためのパスワードは、1行目のコマンドを実行した際にランダムに生成されます。コンソールに出力されるので忘れずに確認しましょう。

顛末

気合でログを追う。

さて、まずはデーモンの状態を確認してみます。

  1. $ sudo systemctl status mysql
  2. ● mysql.service - MySQL Community Server
  3.    Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
  4.    Active: failed (Result: exit-code) since Sun 2019-07-28 03:00:15 JST; 5s ago
  5.   Process: 13034 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre (code=exited, status=1/FAILURE)
  6.  
  7.  7月 28 03:00:15 ThinkPad systemd[1]: mysql.service: Service hold-off time over, scheduling restart.
  8.  7月 28 03:00:15 ThinkPad systemd[1]: mysql.service: Scheduled restart job, restart counter is at 5.
  9.  7月 28 03:00:15 ThinkPad systemd[1]: Stopped MySQL Community Server.
  10.  7月 28 03:00:15 ThinkPad systemd[1]: mysql.service: Start request repeated too quickly.
  11.  7月 28 03:00:15 ThinkPad systemd[1]: mysql.service: Failed with result 'exit-code'.
  12.  7月 28 03:00:15 ThinkPad systemd[1]: Failed to start MySQL Community Server.

何やら起動に失敗していますね。

mysqldが起動していなければソケットファイルは存在しないので、これが先程のエラーの原因のようです。

ところで、$systemctl statusで表示されるログは粒度が荒く、何が原因なのかよく分かりません。

11行目に‘exit-code’と書かれており、これを返したプロセスの情報が分かれば良さそうです。

幸い、これは5行目に書かれています。

  1. Process: 13034 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre (code=exited, status=1/FAILURE)

直接 $/usr/share/mysql/mysql-systemd-start pre を実行してみれば良さそうです。

  1. $ /usr/share/mysql/mysql-systemd-start pre
  2. MySQL system database not found in /var/lib/mysql. Please run mysqld --initialize.

データベースが存在しないらしいです（$apt purgeしたから…？）。

言われたとおりに初期化してみます。

  1. $ sudo mysqld --initialize
  2. 2019-07-27T18:01:10.547310Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
  3. 2019-07-27T18:01:10.866872Z 0 [Warning] InnoDB: New log files created, LSN=45790
  4. 2019-07-27T18:01:10.941214Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
  5. 2019-07-27T18:01:11.007602Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: <略>.
  6. 2019-07-27T18:01:11.011673Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
  7. 2019-07-27T18:01:11.012839Z 1 [Note] A temporary password is generated for root@localhost: <rootのパスワード>

Warningが出ていますが、よしなにやってくれたと信じて起動します。

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

起動しません…

  1. $ sudo systemctl status mysql
  2. ● mysql.service - MySQL Community Server
  3.    Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
  4.    Active: failed (Result: exit-code) since Sun 2019-07-28 03:01:28 JST; 3s ago
  5.   Process: 13270 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre (code=exited, status=1/FAILURE)
  6.  
  7.  7月 28 03:01:28 ThinkPad systemd[1]: mysql.service: Service hold-off time over, scheduling restart.
  8.  7月 28 03:01:28 ThinkPad systemd[1]: mysql.service: Scheduled restart job, restart counter is at 5.
  9.  7月 28 03:01:28 ThinkPad systemd[1]: Stopped MySQL Community Server.
  10.  7月 28 03:01:28 ThinkPad systemd[1]: mysql.service: Start request repeated too quickly.
  11.  7月 28 03:01:28 ThinkPad systemd[1]: mysql.service: Failed with result 'exit-code'.
  12.  7月 28 03:01:28 ThinkPad systemd[1]: Failed to start MySQL Community Server.

また同じコマンドでエラーが出ていますね。実行してみます。

  1. $ /usr/share/mysql/mysql-systemd-start pre
  2. ERROR: Unable to start MySQL server:
  3. mysqld: Error on realpath() on '/var/lib/mysql-files' (Error 2 - No such file or directory)
  4. 2019-07-27T18:01:38.847319Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
  5. 2019-07-27T18:01:38.847426Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
  6. 2019-07-27T18:01:38.847832Z 0 [ERROR] Failed to access directory for --secure-file-priv. Please make sure that directory exists and is accessible by MySQL Server. Supplied value : /var/lib/mysql-files
  7. 2019-07-27T18:01:38.853230Z 0 [ERROR] Aborting
  8. Please take a look at https://wiki.debian.org/Teams/MySQL/FAQ for tips on fixing common upgrade issues.
  9. Once the problem is resolved, restart the service.

内容が変わっています。

realpath() として設定されている ‘/var/lib/mysql-files’ が存在しないようです。

作りましょう。

  1. $ sudo mkdir /var/lib/mysql-files
  2. $ sudo chown mysql:mysql /var/lib/mysql-files

再度実行してみます。

  1. $ /usr/share/mysql/mysql-systemd-start pre

すんなり通りました。やったか！？

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

ダメでした。状態を見てみます。

  1. $ sudo systemctl status mysql
  2. ● mysql.service - MySQL Community Server
  3.    Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
  4.    Active: activating (start-pre) since Sun 2019-07-28 03:02:59 JST; 8ms ago
  5.   Process: 13535 ExecStart=/usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid (code=exited, status=1/FAILURE)
  6. Cntrl PID: 13565 (mysql-systemd-s)
  7.     Tasks: 0 (limit: 4915)
  8.    CGroup: /system.slice/mysql.service
  9.            └─13565 /bin/bash /usr/share/mysql/mysql-systemd-start pre
  10.  
  11.  7月 28 03:02:59 ThinkPad systemd[1]: Starting MySQL Community Server...

先程はExecStartPreに設定されているコマンドでエラーが出ていましたが、次はExecStartに設定されているコマンドでエラーが出ています。

同様に直接実行してみます。

  1. $ /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid
  2. Please enable --log-error option or set appropriate redirections for standard output and/or standard error in daemon mode.
  3. $ /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid --log-error
  4. 2019-07-27T18:04:00.729323Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
  5. 2019-07-27T18:04:00.729466Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
  6. 2019-07-27T18:04:00.880432Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
  7. 2019-07-27T18:04:00.880487Z 0 [Warning] Can't create test file /var/lib/mysql/ThinkPad.lower-test
  8. 2019-07-27T18:04:00.880496Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
  9. 2019-07-27T18:04:00.880511Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.27-0ubuntu0.18.04.1) starting as process 13629 ...
  10. 2019-07-27T18:04:00.882355Z 0 [Warning] Can't create test file /var/lib/mysql/ThinkPad.lower-test
  11. 2019-07-27T18:04:00.882366Z 0 [Warning] Can't create test file /var/lib/mysql/ThinkPad.lower-test
  12. 2019-07-27T18:04:00.882591Z 0 [ERROR] Could not open file '/run/mysqld/mysqld.err' for error logging: No such file or directory
  13. 2019-07-27T18:04:00.882610Z 0 [ERROR] Aborting
  14.  
  15. 2019-07-27T18:04:00.882630Z 0 [Note] Binlog end
  16. Initialization of mysqld failed: 0
  17. 2019-07-27T18:04:00.882672Z 0 [Note] /usr/sbin/mysqld: Shutdown complete

色々なWarningが出ていますが、7行目が怪しくみえます。

  1. 2019-07-27T18:04:00.880487Z 0 [Warning] Can't create test file /var/lib/mysql/ThinkPad.lower-test

‘/var/lib/mysql‘ を確認してみます。

  1. $ ls -la /var/lib/mysql
  2. total 110628
  3. drwxr-xr-x  5 mysql mysql     4096  7月 28 03:02 .
  4. drwxr-xr-x 88 root  root      4096  7月 28 03:02 ..
  5. -rw-r-----  1 root  root        56  7月 28 03:01 auto.cnf
  6. -rw-r-----  1 root  root       424  7月 28 03:01 ib_buffer_pool
  7. -rw-r-----  1 root  root  12582912  7月 28 03:01 ibdata1
  8. -rw-r-----  1 root  root  50331648  7月 28 03:01 ib_logfile0
  9. -rw-r-----  1 root  root  50331648  7月 28 03:01 ib_logfile1
  10. drwxr-x---  2 root  root      4096  7月 28 03:01 mysql
  11. drwxr-x---  2 root  root      4096  7月 28 03:01 performance_schema
  12. drwxr-x---  2 root  root     12288  7月 28 03:01 sys

ファイルやディレクトリの所有者がrootになっていますね。これを変更すれば良さそうです。

  1. $ sudo chown -R mysql:mysql /var/lib/mysql
  2. $ ls -la /var/lib/mysql/
  3. total 122916
  4. drwxr-xr-x  5 mysql mysql     4096  7月 28 03:47 .
  5. drwxr-xr-x 88 root  root      4096  7月 28 03:02 ..
  6. -rw-r-----  1 mysql mysql       56  7月 28 03:01 auto.cnf
  7. -rw-r-----  1 mysql mysql      351  7月 28 03:18 ib_buffer_pool
  8. -rw-r-----  1 mysql mysql 12582912  7月 28 03:47 ibdata1
  9. -rw-r-----  1 mysql mysql 50331648  7月 28 03:47 ib_logfile0
  10. -rw-r-----  1 mysql mysql 50331648  7月 28 03:01 ib_logfile1
  11. drwxr-x---  2 mysql mysql     4096  7月 28 03:01 mysql
  12. drwxr-x---  2 mysql mysql     4096  7月 28 03:01 performance_schema
  13. drwxr-x---  2 mysql mysql    12288  7月 28 03:01 sys

さて、再度実行してみます。

  1. $ /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid --log-error
  2. 2019-07-27T18:05:21`.729323Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
  3. 2019-07-27T18:05:21`.729466Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
  4. 2019-07-27T18:05:21`.880432Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
  5. 2019-07-27T18:05:21`.880487Z 0 [Warning] Can't create test file /var/lib/mysql/ThinkPad.lower-test
  6. 2019-07-27T18:05:21`.880496Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
  7. 2019-07-27T18:05:21`.880511Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.27-0ubuntu0.18.04.1) starting as process 13629 ...
  8. 2019-07-27T18:05:21`.882355Z 0 [Warning] Can't create test file /var/lib/mysql/ThinkPad.lower-test
  9. 2019-07-27T18:05:21`.882366Z 0 [Warning] Can't create test file /var/lib/mysql/ThinkPad.lower-test
  10. 2019-07-27T18:05:21`.882591Z 0 [ERROR] Could not open file '/run/mysqld/mysqld.err' for error logging: No such file or directory
  11. 2019-07-27T18:05:21`.882610Z 0 [ERROR] Aborting
  12.  
  13. 2019-07-27T18:05:21`.882630Z 0 [Note] Binlog end
  14. Initialization of mysqld failed: 0
  15. 2019-07-27T18:05:21`.882672Z 0 [Note] /usr/sbin/mysqld: Shutdown complete

あれ…変わってない…

あ、これは管理者権限が必要ですね。

  1. $ sudo /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid --log-error
  2. 2019-07-27T18:05:39.416098Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
  3. 2019-07-27T18:05:39.417188Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
  4. 2019-07-27T18:05:39.417216Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.27-0ubuntu0.18.04.1) starting as process 16339 ...
  5. 2019-07-27T18:05:39.418220Z 0 [ERROR] Fatal error: Please read "Security" section of the manual to find out how to run mysqld as root!
  6.  
  7. 2019-07-27T18:05:39.418238Z 0 [ERROR] Aborting
  8.  
  9. 2019-07-27T18:05:39.418259Z 0 [Note] Binlog end
  10. Initialization of mysqld failed: 0
  11. 2019-07-27T18:05:39.418302Z 0 [Note] /usr/sbin/mysqld: Shutdown complete

どうなんでしょう…エラーが出ていますが…。

試しにデーモンの起動を行ってみます。

  1. $ sudo systemctl start mysql
  2. $ sudo systemctl status mysql
  3. ● mysql.service - MySQL Community Server
  4.    Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
  5.    Active: active (running) since Sun 2019-07-28 03:06:07 JST; 7s ago
  6.   Process: 13722 ExecStart=/usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid (code=exited, status=0/SUCCESS)
  7.   Process: 13696 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
  8.  Main PID: 13724 (mysqld)
  9.     Tasks: 27 (limit: 4915)
  10.    CGroup: /system.slice/mysql.service
  11.            └─13724 /usr/sbin/mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid
  12.  
  13.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.068534Z 0 [Note] InnoDB: Buffer pool(s) load completed at 190728  3:06:07
  14.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.077511Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and priva
  15.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.078509Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
  16.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.078569Z 0 [Note] IPv6 is available.
  17.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.078581Z 0 [Note]   - '::' resolves to '::';
  18.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.078608Z 0 [Note] Server socket created on IP: '::'.
  19.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.096346Z 0 [Note] Event Scheduler: Loaded 0 events
  20.  7月 28 03:06:07 ThinkPad mysqld[13722]: 2019-07-27T18:06:07.096663Z 0 [Note] /usr/sbin/mysqld: ready for connections.
  21.  7月 28 03:06:07 ThinkPad mysqld[13722]: Version: '5.7.27-0ubuntu0.18.04.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu)
  22.  7月 28 03:06:07 ThinkPad systemd[1]: Started MySQL Community Server.

動きました（え…）。

たまたまですが、 ‘/var/lib/mysql’ の所有者が正しくなかったのが原因だったようです。

コメントを残す

メールアドレスが公開されることはありません。 ※ が付いている欄は必須項目です