tech::hexagram

personal note for technical issue.

さくらのVPS@Ubuntu14.04でmysqlが起動できなかった

mysql

ansibleを利用してmysqlをインストールしていたが、どうもmysqlの起動でコケてしまっていた。 直接ログインして sudo service mysql start を実行してもうんともすんともいわず、困っていた。

mysql.err を見てみると1つWARNINGが出ていたが特に関係のあるものではない。

% sudo tail -n 20 /var/log/mysql.err
171001 22:47:14 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2017-10-01 22:47:14 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-10-01 22:47:14 0 [Note] /usr/sbin/mysqld (mysqld 5.6.37-log) starting as process 24154 ...
171001 22:47:16 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

my.cnf に下記のオプションを追加したことでWARNINGは解消されたが、依然として起動ができなかった。

explicit_defaults_for_timestamp: 1

困ったなと思って syslog を見てみると気になる内容が。

% sudo tail -n 20 /var/log/syslog
Oct  9 14:34:38 www4184uf kernel: [665121.153306] type=1400 audit(1507527278.123:68): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql.err" pid=25878 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=105 ouid=105
Oct  9 14:34:38 www4184uf kernel: [665121.153318] type=1400 audit(1507527278.123:69): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql.err" pid=25878 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=105 ouid=105
Oct  9 14:34:38 www4184uf kernel: [665121.153325] type=1400 audit(1507527278.123:70): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql.err" pid=25878 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=105 ouid=105

apparmorというプロセスに起動を止められている…？WikiPediaによれば、このプロセスはセキュリティを向上させるプログラムとのこと。

AppArmor (Application Armor) とは、Linux Security Modulesの一種であり、各プログラムにセキュリティプロファイルを結びつけ、プログラムのできることに制限をかけるプログラムである。プロファイルは、ネットワークアクセス、Raw socket アクセス、ファイルへの読み書き実行などの機能を制限することができる。

ref. https://ja.wikipedia.org/wiki/AppArmor

とりあえずmysqldに関してapparmorの制限を止める。

sudo ln -s /etc/apparmor.d/usr.sbin.mysqld /etc/apparmor.d/disable/
sudo apparmor_parser -R /etc/apparmor.d/usr.sbin.mysqld

再度mysqlを立ち上げようとすると再び止まってしまっていたので mysql.err を見る。

% sudo tail -n 20 /var/log/mysql.err
/usr/sbin/mysqld: Table 'mysql.plugin' doesn't exist
2017-10-09 15:21:34 15344 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
2017-10-09 15:21:34 15344 [Note] InnoDB: Using atomics to ref count buffer pool pages
2017-10-09 15:21:34 15344 [Note] InnoDB: The InnoDB memory heap is disabled
2017-10-09 15:21:34 15344 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-10-09 15:21:34 15344 [Note] InnoDB: Memory barrier is not used
2017-10-09 15:21:34 15344 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-10-09 15:21:34 15344 [Note] InnoDB: Using Linux native AIO
2017-10-09 15:21:34 15344 [Note] InnoDB: Using CPU crc32 instructions
2017-10-09 15:21:34 15344 [Note] InnoDB: Initializing buffer pool, size = 256.0M
2017-10-09 15:21:34 15344 [Note] InnoDB: Completed initialization of buffer pool
2017-10-09 15:21:34 15344 [Note] InnoDB: Highest supported file format is Barracuda.
2017-10-09 15:21:34 15344 [Note] InnoDB: 128 rollback segment(s) are active.
2017-10-09 15:21:34 15344 [Note] InnoDB: Waiting for purge to start
2017-10-09 15:21:34 15344 [Note] InnoDB: 5.6.37 started; log sequence number 1601046
2017-10-09 15:21:34 15344 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2017-10-09 15:21:34 15344 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
2017-10-09 15:21:34 15344 [Note] Server socket created on IP: '0.0.0.0'.
2017-10-09 15:21:34 15344 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.user' doesn't exist
171009 15:21:34 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

/var/lib/mysql 配下の内容を見てみると、古いplaybookの適用時の残骸が残っていたようで、ファイルの作成日時がばらばらになっていた。

% ls -la /var/lib/mysql
total 143380
drwxr-xr-x  4 mysql mysql     4096 10月  9 15:21 .
drwxr-xr-x 50 root  root      4096 10月  1 22:12 ..
-rw-rw----  1 mysql mysql       56 10月  1 21:37 auto.cnf
-rw-rw----  1 mysql mysql 67108864 10月  9 15:21 ib_logfile0
-rw-rw----  1 mysql mysql 67108864 10月  1 22:47 ib_logfile1
-rw-rw----  1 mysql mysql 12582912 10月  1 23:09 ibdata1
drwx------  2 mysql mysql     4096 10月  1 21:30 mysql
drwx------  2 mysql mysql     4096 10月  1 21:30 test

一旦きれいな状態からインストール作業を試みるためディレクトリごと削除し、mysql-common, mysql-serverのpackageを削除し、再度ansibleを実行してみた。するとmysqlのplaybookは正常に最後まで適用できた。

色々とハマりどころがあったのでなかなか厄介だった。。