Skip to content

Mysql root user is not initialized #216

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
Kern046 opened this issue Sep 26, 2016 · 24 comments
Closed

Mysql root user is not initialized #216

Kern046 opened this issue Sep 26, 2016 · 24 comments

Comments

@Kern046
Copy link

Kern046 commented Sep 26, 2016

Hello there !

I am facing some kind of problem with the 5.7 image. The short description is that the container is set up properly, but it is impossible to connect with the root user. My suggestion is that the root password is not initialized properly.

I am using docker-toolbox with Windows (quite sad about it but due to VPN and company group strategies it is quite hard to setup a Unix environment here) and I think Windows permissions are the problem.

I copy here my files :

docker-compose.yml

mysql:
    container_name: my_mysql_container
    build: mysql
    environment:
        - MYSQL_DATABASES=my_database
        - MYSQL_ROOT_PASSWORD=root
        - MYSQL_HOST=127.0.0.1
        - MYSQL_PORT=33306
        - MYSQL_USER=helpless
        - MYSQL_PASSWORD=dev
        - MYSQL_LOYALTY_DATABASE=my_database
    ports:
        # MySQL
        - "33306:3306"
    volumes:
        # Mysql
        - "./volumes/mysql:/var/lib/mysql"

mysql/Dockerfile

FROM mysql:5.7
MAINTAINER Helpless Dev <helpless.dev@wonderful_company.com>

COPY conf.d/*.cnf /etc/mysql/conf.d/
COPY docker-entrypoint-initdb.d/databases.sh /docker-entrypoint-initdb.d/databases.sh
COPY docker-entrypoint-initdb.d/config.sh /docker-entrypoint-initdb.d/config.sh

RUN chmod a+x /docker-entrypoint-initdb.d/config.sh && chown root:root /docker-entrypoint-initdb.d/config.sh
RUN chmod a+x /docker-entrypoint-initdb.d/databases.sh && chown root:root /docker-entrypoint-initdb.d/databases.sh

mysql/conf.d/custom.cnf

[mysqld]
default-storage-engine=INNODB
init-connect='SET NAMES utf8'
character-set-server=utf8
collation-server=utf8_unicode_ci
bind-address        = 0.0.0.0
skip-external-locking
key_buffer      = 16M
max_allowed_packet  = 16M
thread_stack        = 192K
thread_cache_size       = 8
query_cache_limit   = 1M
query_cache_size        = 16M
expire_logs_days    = 10
max_binlog_size         = 100M

[mysqldump]
quick
quote-names
max_allowed_packet  = 16M

[isamchk]
key_buffer      = 16M

docker-entrypoint-initdb.d/config.sh

#!/bin/bash

chmod 644 /etc/mysql/conf.d/custom.cnf

echo "ok"

exec "$@"

docker-entrypoint-initdb.d/databases.sh

#!/bin/bash

mysql=( mysql --protocol=socket -uroot )

if [ ! -z "$MYSQL_ROOT_PASSWORD" ]; then
    mysql+=( -p"${MYSQL_ROOT_PASSWORD}" )
fi

IFS=',' read -a dbs <<< "$MYSQL_DATABASES"

if [ ${#dbs[@]} -gt 0 ];then
    for db in "${dbs[@]}"
    do
        if [ "$db" ]; then
            echo create database $db
            echo "CREATE DATABASE IF NOT EXISTS \`$db\` ;" | "${mysql[@]}"
        fi

    done

    if [ "${dbs[0]}" ]; then
        mysql+=( "${dbs[0]}" )
    fi
fi

if [ "$MYSQL_USER" -a "$MYSQL_PASSWORD" ]; then
    if [ ${#dbs[@]} -gt 0 ]; then
        for db in "${dbs[@]}"
        do
            if [ "$db" ]; then
                echo "GRANT ALL ON \`"$db"\`.* TO '"$MYSQL_USER"'@'%' ;" | "${mysql[@]}"
            fi
        done
    fi

    echo 'FLUSH PRIVILEGES ;' | "${mysql[@]}"
fi

I tried to change the permissions of custom.cnf because it is created in mode 666 and mysql ignores it with the message World writeable config file "custom.cnf" has been ignored. But my script is never executed, nor the databases.sh script which would fail anyway because the root user is not available.

I think the reason is that mysql cannot create the root user when failing at reading the config file, but when I removed the custom.cnf file, I had the following logs :

2016-09-26T11:40:30.936825Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-09-26T11:40:30.939713Z 0 [Note] mysqld (mysqld 5.7.15) starting as process 1 ...
2016-09-26T11:40:30.954868Z 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2016-09-26T11:40:30.956901Z 0 [Note] InnoDB: PUNCH HOLE support available
2016-09-26T11:40:30.959072Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-09-26T11:40:30.959141Z 0 [Note] InnoDB: Uses event mutexes
2016-09-26T11:40:30.959160Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-09-26T11:40:30.959348Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-09-26T11:40:30.959368Z 0 [Note] InnoDB: Using Linux native AIO
2016-09-26T11:40:30.959587Z 0 [Note] InnoDB: Number of pools: 1
2016-09-26T11:40:30.960271Z 0 [Note] InnoDB: Using CPU crc32 instructions
2016-09-26T11:40:30.966106Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2016-09-26T11:40:30.979996Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-09-26T11:40:30.981340Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-09-26T11:40:31.009740Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-09-26T11:40:31.081507Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-09-26T11:40:31.082573Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-09-26T11:40:31.188290Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2016-09-26T11:40:31.189949Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-09-26T11:40:31.190054Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-09-26T11:40:31.190480Z 0 [Note] InnoDB: Waiting for purge to start
2016-09-26T11:40:31.240774Z 0 [Note] InnoDB: 5.7.15 started; log sequence number 12135621
2016-09-26T11:40:31.241113Z 0 [Note] Plugin 'FEDERATED' is disabled.
2016-09-26T11:40:31.242288Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool



2016-09-26T11:40:31.248585Z 0 [Warning] World-writable config file './auto.cnf' is ignored.
2016-09-26T11:40:31.249364Z 0 [Warning] World-writable config file './auto.cnf' has been removed.





2016-09-26T11:40:31.249913Z 0 [Note] Salting uuid generator variables, current_pid: 1, server_start_time: 1474890030, bytes_sent: 0,
2016-09-26T11:40:31.250064Z 0 [Note] Generated uuid: '0775897e-83de-11e6-8440-0242ac110002', server_start_time: 281476451600687, bytes_sent: 68492832
2016-09-26T11:40:31.250115Z 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: 0775897e-83de-11e6-8440-0242ac110002.
2016-09-26T11:40:31.259733Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2016-09-26T11:40:31.260256Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2016-09-26T11:40:31.260418Z 0 [Note] IPv6 is available.
2016-09-26T11:40:31.260458Z 0 [Note]   - '::' resolves to '::';
2016-09-26T11:40:31.260500Z 0 [Note] Server socket created on IP: '::'.
2016-09-26T11:40:31.274069Z 0 [Note] InnoDB: Buffer pool(s) load completed at 160926 11:40:31
2016-09-26T11:40:31.289454Z 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-09-26T11:40:31.289812Z 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-09-26T11:40:31.360977Z 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-09-26T11:40:31.487421Z 0 [Note] Event Scheduler: Loaded 0 events
2016-09-26T11:40:31.487685Z 0 [Note] mysqld: ready for connections.
Version: '5.7.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server (GPL)

I put in evidence the file permissions problems.

In the Dockerfile, I tried to run chmod 644, but after investigation, it is impossible with docker toolbox to modify the "o" permissions. I can do chmod u=rw,g=r but not u=rw,go=r or even a=r. I tried several combinations before concluding that it is impossible with docker toolbox on windows to change the "o" permissions during the building. I do not know if I have to do an issue in Docker Machine repository or Toolbox.

I would be glad if you can help me, that would avoid a Vagrant box on my Windows, which would be sad for me and my team :D !

Thanks a lot, and have a nice day !

@ltangvald
Copy link
Collaborator

Is there already a database (or any files or directories) in .volumes/mysql? If so, database init will be skipped, and that includes execution of the scripts in docker-entrypoint-initdb.d

Also, the scripts will be executed at the end of database init, so the script for fixing the permissions will be run after the first database startup, which might create an inconsistent setup for things like setting the default storage engine. A better solution might be to set the permission in Dockerfile.

@Kern046
Copy link
Author

Kern046 commented Sep 26, 2016

The problem is that the container exits with code 1 when I tried to change the permissions to 644 !

But I tried to build the container from scratch after removing the volumes/mysql folder, and I have new evidences of the problem :

Initializing database
mysqld: [Warning] World-writable config file '/etc/mysql/conf.d/custom.cnf' is ignored.
2016-09-26T13:18:03.829257Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-09-26T13:18:03.834098Z 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2016-09-26T13:18:04.328638Z 0 [Warning] InnoDB: New log files created, LSN=45790
2016-09-26T13:18:04.427158Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2016-09-26T13:18:04.486357Z 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: a84283b1-83eb-11e6-81d6-0242ac110002.
2016-09-26T13:18:04.489057Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2016-09-26T13:18:04.490699Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2016-09-26T13:18:05.518667Z 1 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:05.518813Z 1 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:05.518934Z 1 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:05.519086Z 1 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:05.519221Z 1 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
Database initialized
MySQL init process in progress...
mysqld: [Warning] World-writable config file '/etc/mysql/conf.d/custom.cnf' is ignored.
2016-09-26T13:18:08.561601Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-09-26T13:18:08.564188Z 0 [Note] mysqld (mysqld 5.7.15) starting as process 47 ...
2016-09-26T13:18:08.567039Z 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2016-09-26T13:18:08.568265Z 0 [Note] InnoDB: PUNCH HOLE support available
2016-09-26T13:18:08.568344Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-09-26T13:18:08.568377Z 0 [Note] InnoDB: Uses event mutexes
2016-09-26T13:18:08.568406Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-09-26T13:18:08.568492Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-09-26T13:18:08.568525Z 0 [Note] InnoDB: Using Linux native AIO
2016-09-26T13:18:08.568728Z 0 [Note] InnoDB: Number of pools: 1
2016-09-26T13:18:08.568831Z 0 [Note] InnoDB: Using CPU crc32 instructions
2016-09-26T13:18:08.569989Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2016-09-26T13:18:08.576881Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-09-26T13:18:08.578389Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-09-26T13:18:08.601909Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-09-26T13:18:08.636201Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-09-26T13:18:08.636991Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-09-26T13:18:08.686772Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2016-09-26T13:18:08.688076Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-09-26T13:18:08.688155Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-09-26T13:18:08.688563Z 0 [Note] InnoDB: Waiting for purge to start
2016-09-26T13:18:08.739186Z 0 [Note] InnoDB: 5.7.15 started; log sequence number 2528505
2016-09-26T13:18:08.739528Z 0 [Note] Plugin 'FEDERATED' is disabled.
2016-09-26T13:18:08.740724Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2016-09-26T13:18:08.753770Z 0 [Warning] World-writable config file './auto.cnf' is ignored.
2016-09-26T13:18:08.755074Z 0 [Warning] World-writable config file './auto.cnf' has been removed.

2016-09-26T13:18:08.756082Z 0 [Note] Salting uuid generator variables, current_pid: 47, server_start_time: 1474895888, bytes_sent: 0,
2016-09-26T13:18:08.756541Z 0 [Note] Generated uuid: 'aace1830-83eb-11e6-84d6-0242ac110002', server_start_time: 13229325380296767, bytes_sent: 72023696
2016-09-26T13:18:08.756642Z 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: aace1830-83eb-11e6-84d6-0242ac110002.
2016-09-26T13:18:08.769161Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2016-09-26T13:18:08.781724Z 0 [Note] InnoDB: Buffer pool(s) load completed at 160926 13:18:08
2016-09-26T13:18:09.267746Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:09.267963Z 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:09.268322Z 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:09.268575Z 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:09.298055Z 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-09-26T13:18:09.400163Z 0 [Note] Event Scheduler: Loaded 0 events
2016-09-26T13:18:09.400387Z 0 [Note] mysqld: ready for connections.
Version: '5.7.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server (GPL)
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process failed.

Ty for your quick answer :) !

@yosifkit
Copy link
Member

@Kern046, it looks like you still need to add a chmod to the Dockerfile for your custom.cnf and do a docker build. Then you can get rid of docker-entrypoint-initdb.d/config.sh.

@Kern046
Copy link
Author

Kern046 commented Sep 30, 2016

@yosifkit, my problem actually was that I was unable to make the container run with a RUN chmod 644 /etc/mysql/conf.d/custom.cnf instruction in the Dockerfile. The container exited every time with 1 code without any log. That was the core of my problem and I think it is related to my Windows host, because running ``chmod u=rw,g=rworked fine but notchmod u=rw,go=r`.

My solution was to give up Docker Toolbox and Docker Machine and create a VM with Vagrant.

I do not have permissions problems anymore with Ubuntu Xenial (my VM OS), but the scripts in /docker-entrypoint-initdb.d are still not executed, root stills have empty password, and no host is able to connect except localhost (event 127.0.0.1 is forbidden)

@yosifkit
Copy link
Member

If the container fails to start, then it is not a problem with the chown, but a problem with the config itself. The problem is that our entrypoint script does a mysqld --verbose --help to find out what the datadir is and if your config is improper, it will just fail at that point (we need to fix it to print the error rather than just dying; I'm going to look for a solution) (

DATADIR="$(_datadir "$@")"
).

So to find the problem, I copied your cnf file and ran the following:

$ docker run -it --rm -v $PWD/my.cnf:/etc/mysql/conf.d/my.cnf --name mysql -e MYSQL_ROOT_PASSWORD=12345 mysql:5.7 bash
root@fd0ebe7e491c:/# mysqld --verbose --help > /dev/null
2016-09-30T18:06:45.828087Z 0 [ERROR] unknown variable 'key_buffer=16M'
2016-09-30T18:06:45.829979Z 0 [ERROR] Aborting

@yosifkit
Copy link
Member

I made #218 to print the errors so that you don't get a stopped container with no output.

@ltangvald
Copy link
Collaborator

Ah right, I didn't spot that.
The key_buffer option has been deprecated for some time, and in 5.7 it was removed completely. It was simply renamed to key_buffer_size, so changing the name in the config should fix it.

@Kern046
Copy link
Author

Kern046 commented Oct 3, 2016

Hello there !

Thanks for the answers ! I updated the configuration file but it still does not work ! I tested also your useful command to detect any other error, but it does not produce any output !

I tried to just launch the mysqld command, which produces the following output :

2016-10-03T12:07:50.242779Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-10-03T12:07:50.243505Z 0 [Note] mysqld (mysqld 5.7.15) starting as process 16 ...
2016-10-03T12:07:50.245262Z 0 [ERROR] Fatal error: Please read "Security" section of the manual to find out how to run mysqld as root!

2016-10-03T12:07:50.247328Z 0 [ERROR] Aborting

2016-10-03T12:07:50.247882Z 0 [Note] Binlog end
2016-10-03T12:07:50.248365Z 0 [Note] mysqld: Shutdown complete

I've read the mentionned Security section and tried to launch mysqld --user=mysql. The following output was produced :

2016-10-03T12:14:31.822087Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-10-03T12:14:31.823143Z 0 [Note] mysqld (mysqld 5.7.15) starting as process 10 ...
2016-10-03T12:14:31.827072Z 0 [Note] InnoDB: PUNCH HOLE support available
2016-10-03T12:14:31.827108Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-10-03T12:14:31.827114Z 0 [Note] InnoDB: Uses event mutexes
2016-10-03T12:14:31.827117Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-10-03T12:14:31.827121Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-10-03T12:14:31.827125Z 0 [Note] InnoDB: Using Linux native AIO
2016-10-03T12:14:31.827344Z 0 [Note] InnoDB: Number of pools: 1
2016-10-03T12:14:31.827449Z 0 [Note] InnoDB: Using CPU crc32 instructions
2016-10-03T12:14:31.829139Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2016-10-03T12:14:31.835906Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-10-03T12:14:31.837815Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-10-03T12:14:31.848097Z 0 [Note] InnoDB: The first innodb_system data file 'ibdata1' did not exist. A new tablespace will be created!
2016-10-03T12:14:31.848374Z 0 [Note] InnoDB: Setting file './ibdata1' size to 12 MB. Physically writing the file full; Please wait ...
2016-10-03T12:14:32.335076Z 0 [Note] InnoDB: File './ibdata1' size is now 12 MB.
2016-10-03T12:14:32.335782Z 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
2016-10-03T12:14:33.197097Z 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
2016-10-03T12:14:34.177164Z 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2016-10-03T12:14:34.177351Z 0 [Warning] InnoDB: New log files created, LSN=45790
2016-10-03T12:14:34.177417Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-10-03T12:14:34.177483Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-10-03T12:14:34.486927Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2016-10-03T12:14:34.487217Z 0 [Note] InnoDB: Doublewrite buffer not found: creating new
2016-10-03T12:14:34.534460Z 0 [Note] InnoDB: Doublewrite buffer created
2016-10-03T12:14:34.539580Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-10-03T12:14:34.539628Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-10-03T12:14:34.539799Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2016-10-03T12:14:34.542263Z 0 [Note] InnoDB: Foreign key constraint system tables created
2016-10-03T12:14:34.542343Z 0 [Note] InnoDB: Creating tablespace and datafile system tables.
2016-10-03T12:14:34.543018Z 0 [Note] InnoDB: Tablespace and datafile system tables created.
2016-10-03T12:14:34.543130Z 0 [Note] InnoDB: Creating sys_virtual system tables.
2016-10-03T12:14:34.543497Z 0 [Note] InnoDB: sys_virtual table created
2016-10-03T12:14:34.543984Z 0 [Note] InnoDB: Waiting for purge to start
2016-10-03T12:14:34.594451Z 0 [Note] InnoDB: 5.7.15 started; log sequence number 0
2016-10-03T12:14:34.594749Z 0 [Note] Plugin 'FEDERATED' is disabled.
mysqld: Table 'mysql.plugin' doesn't exist
2016-10-03T12:14:34.594973Z 0 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
2016-10-03T12:14:34.595625Z 0 [Note] Salting uuid generator variables, current_pid: 10, server_start_time: 1475496871, bytes_sent: 0,
2016-10-03T12:14:34.595844Z 0 [Note] Generated uuid: 'f2479c0c-8962-11e6-b935-0242ac110002', server_start_time: 2814751242603441, bytes_sent: 35373488
2016-10-03T12:14:34.595880Z 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: f2479c0c-8962-11e6-b935-0242ac110002.
2016-10-03T12:14:34.596584Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2016-10-03T12:14:34.596708Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2016-10-03T12:14:34.597520Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2016-10-03T12:14:34.597564Z 0 [Note] IPv6 is available.
2016-10-03T12:14:34.597571Z 0 [Note]   - '::' resolves to '::';
2016-10-03T12:14:34.597661Z 0 [Note] Server socket created on IP: '::'.
2016-10-03T12:14:34.598733Z 0 [Warning] Failed to open optimizer cost constant tables

2016-10-03T12:14:34.599077Z 0 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.user' doesn't exist
2016-10-03T12:14:34.599480Z 0 [ERROR] Aborting

2016-10-03T12:14:34.599587Z 0 [Note] Binlog end
2016-10-03T12:14:34.599624Z 0 [Note] Shutting down plugin 'ngram'
2016-10-03T12:14:34.599700Z 0 [Note] Shutting down plugin 'BLACKHOLE'
2016-10-03T12:14:34.599708Z 0 [Note] Shutting down plugin 'partition'
2016-10-03T12:14:34.599710Z 0 [Note] Shutting down plugin 'ARCHIVE'
2016-10-03T12:14:34.599713Z 0 [Note] Shutting down plugin 'MEMORY'
2016-10-03T12:14:34.599716Z 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL'
2016-10-03T12:14:34.599719Z 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2016-10-03T12:14:34.599721Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2016-10-03T12:14:34.599724Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2016-10-03T12:14:34.599726Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2016-10-03T12:14:34.599729Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2016-10-03T12:14:34.599731Z 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2016-10-03T12:14:34.599733Z 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2016-10-03T12:14:34.599735Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2016-10-03T12:14:34.599840Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2016-10-03T12:14:34.599846Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2016-10-03T12:14:34.599848Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2016-10-03T12:14:34.599851Z 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2016-10-03T12:14:34.599865Z 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2016-10-03T12:14:34.599868Z 0 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2016-10-03T12:14:34.599870Z 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2016-10-03T12:14:34.599873Z 0 [Note] Shutting down plugin 'INNODB_METRICS'
2016-10-03T12:14:34.599875Z 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO'
2016-10-03T12:14:34.599889Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2016-10-03T12:14:34.599892Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2016-10-03T12:14:34.599895Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2016-10-03T12:14:34.599897Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2016-10-03T12:14:34.599948Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2016-10-03T12:14:34.599952Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2016-10-03T12:14:34.599955Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM'
2016-10-03T12:14:34.599957Z 0 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2016-10-03T12:14:34.599960Z 0 [Note] Shutting down plugin 'INNODB_CMP'
2016-10-03T12:14:34.599974Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2016-10-03T12:14:34.599977Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2016-10-03T12:14:34.599979Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2016-10-03T12:14:34.599982Z 0 [Note] Shutting down plugin 'InnoDB'
2016-10-03T12:14:34.600079Z 0 [Note] InnoDB: FTS optimize thread exiting.
2016-10-03T12:14:34.600288Z 0 [Note] InnoDB: Starting shutdown...
2016-10-03T12:14:34.701721Z 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2016-10-03T12:14:34.702082Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 161003 12:14:34
2016-10-03T12:14:36.425461Z 0 [Note] InnoDB: Shutdown completed; log sequence number 1209961
2016-10-03T12:14:36.429470Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2016-10-03T12:14:36.429534Z 0 [Note] Shutting down plugin 'MyISAM'
2016-10-03T12:14:36.429632Z 0 [Note] Shutting down plugin 'MRG_MYISAM'
2016-10-03T12:14:36.429676Z 0 [Note] Shutting down plugin 'CSV'
2016-10-03T12:14:36.429685Z 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2016-10-03T12:14:36.429747Z 0 [Note] Shutting down plugin 'sha256_password'
2016-10-03T12:14:36.429822Z 0 [Note] Shutting down plugin 'mysql_native_password'
2016-10-03T12:14:36.430196Z 0 [Note] Shutting down plugin 'binlog'
2016-10-03T12:14:36.430937Z 0 [Note] mysqld: Shutdown complete

With docker-compose, my container stills start well, but without any password to my root user and without executing my scripts.

Thank you both for your answers :) !

@ltangvald
Copy link
Collaborator

I think you're missing the mysqld --initialize run that the container does when started with compose or default docker run command.
i.e. mysqld --initialize-insecure --user=mysql
(--initialize-insecure creates the root user with an empty password, while --intialize generates a random password for it)

@Kern046
Copy link
Author

Kern046 commented Oct 3, 2016

Indeed ! It starts fine.

I think I'm coming to get it. Reviewing the Dockerfile of the image, I notice the following piece of code :

for i in {30..0}; do
    if echo 'SELECT 1' | "${mysql[@]}" &> /dev/null; then
        break
    fi
    echo 'MySQL init process in progress...'
    sleep 1
done
if [ "$i" = 0 ]; then
    echo >&2 'MySQL init process failed.'
    exit 1
fi

This is exactly what is coming in my logs when I launch the container the first time after removing volumes/mysql :

Initializing database
2016-10-03T12:47:51.217644Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-10-03T12:47:51.604379Z 0 [Warning] InnoDB: New log files created, LSN=45790
2016-10-03T12:47:51.644572Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2016-10-03T12:47:51.822911Z 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: 98b84632-8967-11e6-b063-0242ac110002.
2016-10-03T12:47:51.824140Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2016-10-03T12:47:51.824636Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2016-10-03T12:47:52.702722Z 1 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:52.702917Z 1 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:52.702972Z 1 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:52.703005Z 1 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:52.703129Z 1 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
Database initialized
MySQL init process in progress...
2016-10-03T12:47:54.893601Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-10-03T12:47:54.905406Z 0 [Note] mysqld (mysqld 5.7.15) starting as process 49 ...
2016-10-03T12:47:54.909800Z 0 [Note] InnoDB: PUNCH HOLE support available
2016-10-03T12:47:54.915323Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-10-03T12:47:54.915331Z 0 [Note] InnoDB: Uses event mutexes
2016-10-03T12:47:54.915335Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-10-03T12:47:54.915338Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-10-03T12:47:54.915341Z 0 [Note] InnoDB: Using Linux native AIO
2016-10-03T12:47:54.915539Z 0 [Note] InnoDB: Number of pools: 1
2016-10-03T12:47:54.915617Z 0 [Note] InnoDB: Using CPU crc32 instructions
2016-10-03T12:47:54.922526Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2016-10-03T12:47:54.935973Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-10-03T12:47:54.942648Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-10-03T12:47:54.954253Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-10-03T12:47:54.966434Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-10-03T12:47:54.966490Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-10-03T12:47:55.062688Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2016-10-03T12:47:55.063293Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-10-03T12:47:55.063306Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-10-03T12:47:55.065968Z 0 [Note] InnoDB: Waiting for purge to start
2016-10-03T12:47:55.116747Z 0 [Note] InnoDB: 5.7.15 started; log sequence number 2528505
2016-10-03T12:47:55.121017Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2016-10-03T12:47:55.121273Z 0 [Note] Plugin 'FEDERATED' is disabled.
2016-10-03T12:47:55.126550Z 0 [Note] InnoDB: Buffer pool(s) load completed at 161003 12:47:55
2016-10-03T12:47:55.133994Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2016-10-03T12:47:55.146552Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:55.146694Z 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:55.146765Z 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:55.146812Z 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:55.148147Z 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-10-03T12:47:55.163313Z 0 [Note] Event Scheduler: Loaded 0 events
2016-10-03T12:47:55.166612Z 0 [Note] mysqld: ready for connections.
Version: '5.7.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server (GPL)
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process in progress...
MySQL init process failed.

When I launched it the second time I haven't the initialization part and everything seemed to work, but the code modifying the root user is after the initialization code which failed. Everything is coming clear, unless the cause of the error :p !

We're getting close ! Thank for your patience !

EDIT : I don't know if I said it earlier, but the visible problem is that mysqld hasn't any binded port when initializing, maybe iet's a clue.

@RCooLeR
Copy link

RCooLeR commented Oct 12, 2016

Any success on this? How to resolve the issue?

@Kern046
Copy link
Author

Kern046 commented Oct 13, 2016

@RCooLeR None for the moment, I'd like to get some time to try to solve it myselfn I hope in the next few days. Did you experience the same issue ?

@RCooLeR
Copy link

RCooLeR commented Oct 13, 2016

Yes. I rebuild my docker with mysql/mysql-server but I think all thing is in timing... It just doesn't create/update users in time.

I have also noticed another issue with docker-compose

@Kern046
Copy link
Author

Kern046 commented Oct 13, 2016

In fact, I think the main clue is here :

Version: '5.7.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server (GPL)

Why port 0 ? Why the port is not the configured one ? It seems quite logic that the check fails with this. The thing is that the second time that I launch the container, the port is set correctly, but due to the fact that there are files in the volumes/mysql folder, the initialization script is not triggered, and then the user scripts and database initialization are simply not executed.

If we succeed to fix the port 0 the first time after the container building, I think we would be done with that issue.

@yosifkit
Copy link
Member

The port: 0 line is expected and means no networking at all. mysqld is started twice on the first initialization. The first is started without network access so that scripts from the /docker-entrypoint-initdb.d directory are the only things that can access the server. After the scripts finish, it is killed and then started again to replace pid 1 in the container. This way you can know the database initialization, user setup, and your extra scripts from initdb.d are done when you can access mysql from another container or your host.

This first "extra" start of mysql is only done when the mysql datadir does not have a mysql directory, so only on the first start of the container. The repeated MySQL init process in progress... means that this first start of mysqld failed and usually points to a conflicting configuration issue. The problem then arises when you restart this container that the datadir was initialized but none of the user creation or custom scripts were run.

When it runs correctly I get both of these lines in the output:

Version: '5.7.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server (GPL)

Version: '5.7.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server (GPL)

@Kern046
Copy link
Author

Kern046 commented Oct 14, 2016

Ok, I understand. The thing is, I removed my configuration file to try to init the container without it, and I have the same issue. I do not understand why the init fails in both cases.

I'm still searching the possible cause.

@Kern046
Copy link
Author

Kern046 commented Oct 14, 2016

I FOUND IT :D !!!!

It is rather mysterious to me, but it was the environment variable MYSQL_HOST which was the cause of this m*ss. In my docker-compose.yml, I just left it empty, as suggested in #82 !

I do not understand at all why I cannot set this variable, but in fact the problem is solved, everything is working at least. I'm in paradise.

I hope I didn't waste too much of your time. I close the issue !

Thank you all :D !

@Kern046 Kern046 closed this as completed Oct 14, 2016
@RCooLeR
Copy link

RCooLeR commented Oct 14, 2016

Hey. Can you add example of correct config pls?

@Kern046
Copy link
Author

Kern046 commented Oct 14, 2016

Yes I can :D !

I was just testing if I could set a value to MYSQL_HOST and the answer iiiiis... YES !

So there is my new docker-compose.yml :

mysql:
    container_name: my_mysql
    build: mysql
    environment:
        - MYSQL_DATABASES=my_database
        - MYSQL_ROOT_PASSWORD=password
        - MYSQL_HOST=localhost
        - MYSQL_PORT=33306
        - MYSQL_USER=my_user
        - MYSQL_PASSWORD=my_password
        - MYSQL_LOYALTY_DATABASE=my_database
    ports:
        # MySQL
        - "33306:3306"
    volumes:
        # Mysql
        - "./volumes/mysql:/var/lib/mysql"

I hope I can help you :) !

@ltangvald
Copy link
Collaborator

I think the cause is we start mysqld with --skip-networking, and when it tries to connect to 127.0.0.1 it is denied while localhost works.

Simplest fix might be to add a -hlocalhost to the client call in the entrypoint script, which will make it ignore the MYSQL_HOST environment variable for that call.

@ltangvald
Copy link
Collaborator

Actually, even without --skip-networking it will fail, though with «access denied» instead of «can't connect»

@ltangvald
Copy link
Collaborator

We could maybe also change this to store stderr output so that if the init times out, the error from the last attempt can be passed to the user: https://github.com/docker-library/mysql/blob/master/5.7/docker-entrypoint.sh#L73

@Kern046
Copy link
Author

Kern046 commented Oct 14, 2016

It's true that the failure errors are not talkative ones, but I do not know which part is related to this repository, and which part is due to MySQL itself.

@ltangvald
Copy link
Collaborator

MySQL's behavior here is by design; When the database is initialized, the user 'root'@'localhost' will be created, and can only be logged in through the host "localhost", which mysql treats as a local unix socket connection rather than going through the networking interface. So for a fresh database you can't log in as 'root'@'127.0.0.1', only 'root'@'localhost'

So you get two problems when trying to start a fresh container with MYSQL_HOST=127.0.0.1:

  1. 127.0.0.1 is blocked because the server is started with --skip-networking during container init.
  2. During database init the script changes the root user from 'root'@'localhost' to 'root'@'%' to allow outside access, but this change requires logging in, which is denied when the host is set to 127.0.0.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants