mysqlが起動しないため、dockerのコンテナが上がってこない

[hidemifukamachi]

概要

./anemoeter /path/to/slow.logを実行した時にmysqlが起動していないため、
https://github.com/yoku0825/anemoeater/blob/master/anemoeater#L119-L120
で接続できず、処理が進みません。

実行環境

CentOS Linux release 7.4.1708
Docker version 1.13.1, build 774336d/1.13.1
perl v5.16.3
pt-tookkit 3.0.4

再現手順

概要にある通り、./anemoeter /path/to/slow.log　(dockerhunのanemoeaterを利用)を実行した際に、https://github.com/yoku0825/anemoeater/blob/master/anemoeater#L119-L120
のMySQL接続部分で起動していないMySQLへの接続を待ってしまい、処理が先に進みません。
その時のdocker側のlogを確認しますと、

# docker logs e2a1674593f3
Starting MySQL (Percona Server)..... ERROR! The server quit without updating PID file (/var/lib/mysql/e2a1674593f3.pid).

とでており、MySQLが起動しきれていない状況になっていました。
Dockerfileのmysql起動部分を下記のように編集し --localオプションを利用して起動すると正常に起動することができました。

# git diff
diff --git a/Dockerfile b/Dockerfile
index 8479707..41722ab 100644
--- a/Dockerfile
+++ b/Dockerfile
@@ -13,7 +13,8 @@ RUN yum install -y Percona-Server-client-56 Percona-Server-shared-56 Percona-Ser
 RUN yum install -y httpd php php-mysql php-bcmath && yum clean all

 RUN git clone https://github.com/box/Anemometer.git /var/www/html/anemometer
-RUN /etc/init.d/mysql start && mysql -uroot < /var/www/html/anemometer/install.sql && mysql -uroot < /var/www/html
+RUN chown -R mysql. /var/lib/mysql && /etc/init.d/mysql start && mysql -uroot < /var/www/html/anemometer/install.s
+
 RUN ln -sf /var/www/html/anemometer/conf/sample.config.inc.php /var/www/html/anemometer/conf/config.inc.php

 COPY . /opt/setup
@@ -21,5 +22,5 @@ RUN patch /etc/php.ini /opt/setup/php.ini.patch
 RUN patch /var/www/html/anemometer/lib/Anemometer.php /opt/setup/Anemometer.patch

 EXPOSE 80
-CMD /etc/init.d/mysql start && /etc/init.d/httpd start && tail -f /dev/null
+CMD chown -R mysql. /var/lib/mysql && /etc/init.d/mysql start && /etc/init.d/httpd start && tail -f /dev/null

[yoku0825]

ありがとうございます！ 手元でも再現しました！

image_id: e1caf448b023 のイメージは起動できるけれど、 image_id: 983645c99a96 のイメージは確かに起動できない…。

1. dockerイメージの起動に失敗した時に anemoeater がタイムアウトするように修正する
2. yoku0825/anemoeater を起動できるようにする

[yoku0825]

ビルドしてあるdatadirが壊れていそうな予感

$ sudo docker run -it --entrypoint=/bin/bash yoku0825/anemoeater
# cat /var/log/mysqld.log
2018-04-02 16:46:24 178 [Note] Plugin 'FEDERATED' is disabled.
2018-04-02 16:46:24 178 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

2018-04-02 16:46:24 178 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-04-02 16:46:24 178 [Note] InnoDB: The InnoDB memory heap is disabled
2018-04-02 16:46:24 178 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-04-02 16:46:24 178 [Note] InnoDB: Memory barrier is not used
2018-04-02 16:46:24 178 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-04-02 16:46:24 178 [Note] InnoDB: Using Linux native AIO
2018-04-02 16:46:24 178 [Note] InnoDB: Using CPU crc32 instructions
2018-04-02 16:46:24 178 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-04-02 16:46:24 178 [Note] InnoDB: Completed initialization of buffer pool
2018-04-02 16:46:24 178 [Note] InnoDB: Highest supported file format is Barracuda.
2018-04-02 16:46:24 178 [Note] InnoDB: 128 rollback segment(s) are active.
2018-04-02 16:46:24 178 [Note] InnoDB: Waiting for purge to start
2018-04-02 16:46:24 178 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.39-83.1 started; log sequence number 1632006
2018-04-02 16:46:24 178 [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: f13f9583-3649-11e8-bf87-0242ac110003.
2018-04-02 16:46:24 178 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2018-04-02 16:46:24 178 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2018-04-02 16:46:24 178 [Note] Server hostname (bind-address): '*'; port: 3306
2018-04-02 16:46:24 178 [Note] IPv6 is available.
2018-04-02 16:46:24 178 [Note]   - '::' resolves to '::';
2018-04-02 16:46:24 178 [Note] Server socket created on IP: '::'.
2018-04-02 16:46:24 178 [Note] Event Scheduler: Loaded 0 events
2018-04-02 16:46:24 178 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.39-83.1'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Percona Server (GPL), Release 83.1, Revision da5a1c2923f

# \rm /var/log/mysqld.log
# /etc/init.d/mysql start
Starting MySQL (Percona Server).. ERROR! The server quit without updating PID file (/var/lib/mysql/dbf50880cf00.pid).

# cat /var/log/mysqld.log
2018-04-03 17:45:59 394 [Note] Plugin 'FEDERATED' is disabled.
/usr/sbin/mysqld: Table storage engine for 'plugin' doesn't have this option
2018-04-03 17:45:59 394 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
2018-04-03 17:45:59 394 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

2018-04-03 17:45:59 394 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-04-03 17:45:59 394 [Note] InnoDB: The InnoDB memory heap is disabled
2018-04-03 17:45:59 394 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-04-03 17:45:59 394 [Note] InnoDB: Memory barrier is not used
2018-04-03 17:45:59 394 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-04-03 17:45:59 394 [Note] InnoDB: Using Linux native AIO
2018-04-03 17:45:59 394 [Note] InnoDB: Using CPU crc32 instructions
2018-04-03 17:45:59 394 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-04-03 17:45:59 394 [Note] InnoDB: Completed initialization of buffer pool
2018-04-03 17:45:59 394 [Note] InnoDB: Highest supported file format is Barracuda.
2018-04-03 17:45:59 394 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1632006
2018-04-03 17:45:59 394 [Note] InnoDB: Database was not shutdown normally!
2018-04-03 17:45:59 394 [Note] InnoDB: Starting crash recovery.
2018-04-03 17:45:59 394 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-04-03 17:45:59 394 [Note] InnoDB: Restoring possible half-written data pages
2018-04-03 17:45:59 394 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1699583
2018-04-03 17:45:59 394 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
2018-04-03 17:45:59 394 [Note] InnoDB: 128 rollback segment(s) are active.
2018-04-03 17:45:59 394 [Note] InnoDB: Waiting for purge to start
2018-04-03 17:45:59 394 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.39-83.1 started; log sequence number 1699583
2018-04-03 17:45:59 394 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2018-04-03 17:45:59 394 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2018-04-03 17:45:59 394 [Note] Server hostname (bind-address): '*'; port: 3306
2018-04-03 17:45:59 394 [Note] IPv6 is available.
2018-04-03 17:45:59 394 [Note]   - '::' resolves to '::';
2018-04-03 17:45:59 394 [Note] Server socket created on IP: '::'.
2018-04-03 17:45:59 394 [ERROR] Fatal error: Can't open and lock privilege tables: Table storage engine for 'user' doesn't have this option

[yoku0825]

chown が何故対策に…と思ったらSELinuxコンテキスト周りな気がしてきた…？

[yokogawa-k]

原因はファイルシステムの問題のはずです。
原因をきちんと特定してからと思ってたのですが、おそらく Storage Driver に overlayfs(2) を使ってるからだと思います。（xfs と組み合わせたときのみなのか ext4 だと大丈夫なのかはまだ調べていません）
わたしの環境（debian/aufs）では問題ありませんでした。

[yoku0825]

@yokogawa-k ありがとうございます！
手元の環境で差異が確認できました！

再現環境

CentOS Linux release 7.4.1708 (Core)
kernel-3.10.0-693.21.1.el7.x86_64
docker-1.13.1-53.git774336d.el7.centos.x86_64
Storage Driver: overlay2

再現しない環境

CentOS Linux release 7.4.1708 (Core)
kernel-3.10.0-693.21.1.el7.x86_64
docker-1.13.1-53.git774336d.el7.centos.x86_64
Storage Driver: devicemapper

---

再現する環境で /etc/sysconfig/docker-storage を編集してストレージドライバーをdevicemapperに変えてみたらちゃんと起動しました。

@hidemifukamachi docker info | grep Storage の結果を確認してもらえますか？

[yoku0825]

ワークアラウンドを追加したDockerfileでビルドされたイメージがDocker Hubに上がったので、今なら実行するだけでも起動する…といいな！

[hidemifukamachi]

ありがとうございます！！
おっしゃる通り、overlay2でした。

# docker info | grep Storage
Storage Driver: overlay2

変更すると、docker buildが通る事が確認できました。

[yoku0825]

@hidemifukamachi 変更後のDockerイメージで overlay2 でも使えるようになったことを確認できたら、クローズしてもらってもいいですか？

[hidemifukamachi]

overlay2でも実行できることが確認できました！！
ご対応いただきありがとうございます。