search

MariaDB / mariadb-docker

Docker Official Image packaging for MariaDB
https://mariadb.org
GNU General Public License v2.0
779 stars 442 forks source link

MySQL init process hangs when using image mariadb 10.1.42, 10.2.27, 10.3.18, 10.4.8 #262

Closed marc-legendre closed 4 years ago

marc-legendre commented 5 years ago

I am using mariadb:10.3, and there seems to be an issue with the current version (10.3 == 10.3.18 == sha256:17a2a44fb692a7a4b244b104de0f286b51b29083b794ae964e3ed5aab8259358), where the MySQL init process is stuck when running a "fresh" docker (I mean, with no existing database in a volume).

For example, with 10.3.18 the output looks like this:

docker run -e MYSQL_ROOT_PASSWORD=wut mariadb:10.3.18
[...]
MySQL init process in progress...
[...]
Version: '10.3.18-MariaDB-1:10.3.18+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
# stuck here

Whereas, with 10.3.17, the output looks like this:

docker run -e MYSQL_ROOT_PASSWORD=wut mariadb:10.3.17
[...]
MySQL init process in progress...
[...]
MySQL init process done. Ready for start up.
[...]
# life goes on

Here is the full output when using 10.3.18:

$ docker run -e MYSQL_ROOT_PASSWORD=wut mariadb:10.3.18
Initializing database

PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following commands:

'/usr/bin/mysqladmin' -u root password 'new-password'
'/usr/bin/mysqladmin' -u root -h  password 'new-password'

Alternatively you can run:
'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

Database initialized
MySQL init process in progress...
2019-09-20 14:31:51 0 [Note] mysqld (mysqld 10.3.18-MariaDB-1:10.3.18+maria~bionic) starting as process 109 ...
2019-09-20 14:31:51 0 [Note] InnoDB: Using Linux native AIO
2019-09-20 14:31:51 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-20 14:31:51 0 [Note] InnoDB: Uses event mutexes
2019-09-20 14:31:51 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-09-20 14:31:51 0 [Note] InnoDB: Number of pools: 1
2019-09-20 14:31:51 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-09-20 14:31:51 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-09-20 14:31:51 0 [Note] InnoDB: Completed initialization of buffer pool
2019-09-20 14:31:51 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-09-20 14:31:51 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-09-20 14:31:51 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-09-20 14:31:51 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-09-20 14:31:51 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-09-20 14:31:51 0 [Note] InnoDB: 10.3.18 started; log sequence number 1630860; transaction id 21
2019-09-20 14:31:51 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-09-20 14:31:51 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-09-20 14:31:51 0 [Note] InnoDB: Buffer pool(s) load completed at 190920 14:31:51
2019-09-20 14:31:51 0 [Warning] 'user' entry 'root@bfd3fc90f6f5' ignored in --skip-name-resolve mode.
2019-09-20 14:31:51 0 [Warning] 'user' entry '@bfd3fc90f6f5' ignored in --skip-name-resolve mode.
2019-09-20 14:31:51 0 [Warning] 'proxies_priv' entry '@% root@bfd3fc90f6f5' ignored in --skip-name-resolve mode.
2019-09-20 14:31:51 0 [Note] Reading of all Master_info entries succeeded
2019-09-20 14:31:51 0 [Note] Added new Master_info '' to hash table
2019-09-20 14:31:51 0 [Note] mysqld: ready for connections.
Version: '10.3.18-MariaDB-1:10.3.18+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
wglambert commented 5 years ago

I can reproduce it hanging, with the log output missing the line from the entrypoint https://github.com/docker-library/mariadb/blob/bf675caa56e4a1b462c665d1cded137f13c33753/10.3/docker-entrypoint.sh#L194

Related to or maybe duplicate of https://github.com/docker-library/mariadb/issues/261

$ docker run -d --rm --name mariadb -e MYSQL_ROOT_PASSWORD=pass mariadb:10.3.18                                       
d4a3b782337dd471738e7d6a054d60f6c7f268448f9095785b40288ef810d7b5

$ time grep -iq "ready for connections" <(docker logs -f mariadb 2>&1)                                                

real    0m22.382s                                                                                                                                 
user    0m0.000s                                                                                                                                  
sys     0m0.007s
diff -y 10.3.17 10.3.18 ```console $ docker run -d --rm --name mariadb-18 -e MYSQL_ROOT_PASSWORD=pass mariadb:10.3.18 db458b3f567abb6e70d778bd361e57471af5322ecb57e8f77f17341c38d19cc5 $ docker run -d --rm --name mariadb-17 -e MYSQL_ROOT_PASSWORD=pass mariadb:10.3.17 10c01a8b60179fb7e017726fc8340691f6ffc4c91eef84deabb216e6b0991c5a $ diff -y <(docker logs mariadb-17 2>&1) <(docker logs mariadb-18 2>&1) Initializing database Initializing database PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER ! PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER ! To do so, start the server, then issue the following commands To do so, start the server, then issue the following commands '/usr/bin/mysqladmin' -u root password 'new-password' '/usr/bin/mysqladmin' -u root password 'new-password' '/usr/bin/mysqladmin' -u root -h password 'new-password' '/usr/bin/mysqladmin' -u root -h password 'new-password' Alternatively you can run: Alternatively you can run: '/usr/bin/mysql_secure_installation' '/usr/bin/mysql_secure_installation' which will also give you the option of removing the test which will also give you the option of removing the test databases and anonymous user created by default. This is databases and anonymous user created by default. This is strongly recommended for production servers. strongly recommended for production servers. See the MariaDB Knowledgebase at http://mariadb.com/kb or the See the MariaDB Knowledgebase at http://mariadb.com/kb or the MySQL manual for more instructions. MySQL manual for more instructions. Please report any problems at http://mariadb.org/jira Please report any problems at http://mariadb.org/jira The latest information about MariaDB is available at http://m The latest information about MariaDB is available at http://m You can find additional information about the MySQL part at: You can find additional information about the MySQL part at: http://dev.mysql.com http://dev.mysql.com Consider joining MariaDB's strong and vibrant community: Consider joining MariaDB's strong and vibrant community: https://mariadb.org/get-involved/ https://mariadb.org/get-involved/ Database initialized Database initialized MySQL init process in progress... MySQL init process in progress... 2019-09-20 17:07:09 0 [Note] mysqld (mysqld 10.3.17-MariaDB-1 | 2019-09-20 17:06:54 0 [Note] mysqld (mysqld 10.3.18-MariaDB-1 2019-09-20 17:07:09 0 [Note] InnoDB: Using Linux native AIO | 2019-09-20 17:06:54 0 [Note] InnoDB: Using Linux native AIO 2019-09-20 17:07:09 0 [Note] InnoDB: Mutexes and rw_locks use | 2019-09-20 17:06:54 0 [Note] InnoDB: Mutexes and rw_locks use 2019-09-20 17:07:09 0 [Note] InnoDB: Uses event mutexes | 2019-09-20 17:06:54 0 [Note] InnoDB: Uses event mutexes 2019-09-20 17:07:09 0 [Note] InnoDB: Compressed tables use zl | 2019-09-20 17:06:54 0 [Note] InnoDB: Compressed tables use zl 2019-09-20 17:07:09 0 [Note] InnoDB: Number of pools: 1 | 2019-09-20 17:06:54 0 [Note] InnoDB: Number of pools: 1 2019-09-20 17:07:09 0 [Note] InnoDB: Using SSE2 crc32 instruc | 2019-09-20 17:06:54 0 [Note] InnoDB: Using SSE2 crc32 instruc 2019-09-20 17:07:09 0 [Note] InnoDB: Initializing buffer pool | 2019-09-20 17:06:54 0 [Note] InnoDB: Initializing buffer pool 2019-09-20 17:07:09 0 [Note] InnoDB: Completed initialization | 2019-09-20 17:06:54 0 [Note] InnoDB: Completed initialization 2019-09-20 17:07:09 0 [Note] InnoDB: If the mysqld execution | 2019-09-20 17:06:54 0 [Note] InnoDB: If the mysqld execution MySQL init process in progress... MySQL init process in progress... MySQL init process in progress... MySQL init process in progress... 2019-09-20 17:07:11 0 [Note] InnoDB: 128 out of 128 rollback | 2019-09-20 17:06:57 0 [Note] InnoDB: 128 out of 128 rollback 2019-09-20 17:07:11 0 [Note] InnoDB: Creating shared tablespa | 2019-09-20 17:06:57 0 [Note] InnoDB: Creating shared tablespa 2019-09-20 17:07:11 0 [Note] InnoDB: Setting file './ibtmp1' | 2019-09-20 17:06:57 0 [Note] InnoDB: Setting file './ibtmp1' 2019-09-20 17:07:11 0 [Note] InnoDB: File './ibtmp1' size is | 2019-09-20 17:06:57 0 [Note] InnoDB: File './ibtmp1' size is 2019-09-20 17:07:11 0 [Note] InnoDB: 10.3.17 started; log seq | 2019-09-20 17:06:57 0 [Note] InnoDB: Waiting for purge to sta 2019-09-20 17:07:11 0 [Note] Plugin 'FEEDBACK' is disabled. | 2019-09-20 17:06:57 0 [Note] InnoDB: 10.3.18 started; log seq 2019-09-20 17:07:11 0 [Note] InnoDB: Loading buffer pool(s) f | 2019-09-20 17:06:57 0 [Note] InnoDB: Loading buffer pool(s) f 2019-09-20 17:07:12 0 [Warning] 'user' entry 'root@10c01a8b60 | 2019-09-20 17:06:57 0 [Note] Plugin 'FEEDBACK' is disabled. 2019-09-20 17:07:12 0 [Warning] 'user' entry '@10c01a8b6017' | 2019-09-20 17:06:57 0 [Note] InnoDB: Buffer pool(s) load comp 2019-09-20 17:07:12 0 [Warning] 'proxies_priv' entry '@% root | 2019-09-20 17:06:57 0 [Warning] 'user' entry 'root@db458b3f56 2019-09-20 17:07:12 0 [Note] InnoDB: Buffer pool(s) load comp | 2019-09-20 17:06:57 0 [Warning] 'user' entry '@db458b3f567a' 2019-09-20 17:07:12 0 [Note] Reading of all Master_info entri | 2019-09-20 17:06:57 0 [Warning] 'proxies_priv' entry '@% root 2019-09-20 17:07:12 0 [Note] Added new Master_info '' to hash | 2019-09-20 17:06:57 0 [Note] Reading of all Master_info entri 2019-09-20 17:07:12 0 [Note] mysqld: ready for connections. | 2019-09-20 17:06:57 0 [Note] Added new Master_info '' to hash Version: '10.3.17-MariaDB-1:10.3.17+maria~bionic' socket: '/ | 2019-09-20 17:06:57 0 [Note] mysqld: ready for connections. Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.lis | Version: '10.3.18-MariaDB-1:10.3.18+maria~bionic' socket: '/ 2019-09-20 17:07:14 10 [Warning] 'proxies_priv' entry '@% roo < < 2019-09-20 17:07:14 0 [Note] mysqld (initiated by: unknown): < 2019-09-20 17:07:14 0 [Note] Event Scheduler: Purging the que < 2019-09-20 17:07:14 0 [Note] InnoDB: FTS optimize thread exit < 2019-09-20 17:07:14 0 [Note] InnoDB: Starting shutdown... < 2019-09-20 17:07:14 0 [Note] InnoDB: Dumping buffer pool(s) t < 2019-09-20 17:07:14 0 [Note] InnoDB: Buffer pool(s) dump comp < 2019-09-20 17:07:16 0 [Note] InnoDB: Shutdown completed; log < 2019-09-20 17:07:16 0 [Note] InnoDB: Removed temporary tables < 2019-09-20 17:07:16 0 [Note] mysqld: Shutdown complete < < < MySQL init process done. Ready for start up. < < 2019-09-20 17:07:16 0 [Note] mysqld (mysqld 10.3.17-MariaDB-1 < 2019-09-20 17:07:16 0 [Note] InnoDB: Using Linux native AIO < 2019-09-20 17:07:16 0 [Note] InnoDB: Mutexes and rw_locks use < 2019-09-20 17:07:16 0 [Note] InnoDB: Uses event mutexes < 2019-09-20 17:07:16 0 [Note] InnoDB: Compressed tables use zl < 2019-09-20 17:07:16 0 [Note] InnoDB: Number of pools: 1 < 2019-09-20 17:07:16 0 [Note] InnoDB: Using SSE2 crc32 instruc < 2019-09-20 17:07:16 0 [Note] InnoDB: Initializing buffer pool < 2019-09-20 17:07:16 0 [Note] InnoDB: Completed initialization < 2019-09-20 17:07:16 0 [Note] InnoDB: If the mysqld execution < 2019-09-20 17:07:17 0 [Note] InnoDB: 128 out of 128 rollback < 2019-09-20 17:07:17 0 [Note] InnoDB: Creating shared tablespa < 2019-09-20 17:07:17 0 [Note] InnoDB: Setting file './ibtmp1' < 2019-09-20 17:07:17 0 [Note] InnoDB: File './ibtmp1' size is < 2019-09-20 17:07:17 0 [Note] InnoDB: 10.3.17 started; log seq < 2019-09-20 17:07:17 0 [Note] InnoDB: Loading buffer pool(s) f < 2019-09-20 17:07:17 0 [Note] Plugin 'FEEDBACK' is disabled. < 2019-09-20 17:07:17 0 [Note] InnoDB: Buffer pool(s) load comp < 2019-09-20 17:07:17 0 [Note] Server socket created on IP: ':: < 2019-09-20 17:07:17 0 [Warning] 'proxies_priv' entry '@% root < 2019-09-20 17:07:17 0 [Note] Reading of all Master_info entri < 2019-09-20 17:07:17 0 [Note] Added new Master_info '' to hash < 2019-09-20 17:07:17 0 [Note] mysqld: ready for connections. < Version: '10.3.17-MariaDB-1:10.3.17+maria~bionic' socket: '/ < ```
wglambert commented 5 years ago

Over 25 minutes later it still hasn't initialized

$ docker exec mariadb-18 ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND                                                                          
mysql        1  0.0  0.0  18508  3216 ?        Ss   17:06   0:00 /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld                             
mysql      109  6.2  0.8 2252904 95980 ?       Sl   17:06   1:35 mysqld --skip-networking --socket=/var/run/mysqld/mysqld.sock                    
mysql      152  0.0  0.0  10324  2496 ?        S    17:06   0:00 mysql_tzinfo_to_sql /usr/share/zoneinfo                                          
mysql      153  0.0  0.0  13560  1116 ?        S    17:06   0:00 sed s/Local time zone must be set--see zic manual page/FCTY/                     
mysql      154  0.0  0.0  41200  8428 ?        S    17:06   0:00 mysql --protocol=socket -uroot -hlocalhost --socket=/var/run/mysqld/mysqld.sock mysql                                                                                                                                              
root       583  0.0  0.0  34400  2780 ?        Rs   17:32   0:00 ps aux

$ docker exec --privileged mariadb-18 netstat -tulpn                                                                  
Active Internet connections (only servers)                                                                                                        
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name

What it looks like on an initialized 10.3.17:

$ docker exec mariadb-17 ps aux                                                                  
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND                                                                          
mysql        1  0.1  0.7 1924884 86576 ?       Ssl  17:06   0:02 mysqld                                                                           
root       577  0.0  0.0  34400  2892 ?        Rs   17:32   0:00 ps aux

$ docker exec --privileged mariadb-17 netstat -tulpn                                                                  
Active Internet connections (only servers)                                                                                                        
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name                                                  
tcp6       0      0 :::3306                 :::*                    LISTEN      1/mysqld

One that I had running in the background just finished after 40 minutes

$ docker logs mariadb
Initializing database
. . .
Database initialized
MySQL init process in progress...
2019-09-20 17:00:22 0 [Note] mysqld (mysqld 10.3.18-MariaDB-1:10.3.18+maria~bionic) starting as process 109 ...
. . .
2019-09-20 17:00:26 0 [Note] mysqld: ready for connections.
Version: '10.3.18-MariaDB-1:10.3.18+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.
2019-09-20 17:39:34 10 [Warning] 'proxies_priv' entry '@% root@d4a3b782337d' ignored in --skip-name-resolve mode.
. . .
2019-09-20 17:39:44 0 [Note] mysqld: ready for connections.
Version: '10.3.18-MariaDB-1:10.3.18+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
2019-09-20 17:39:44 0 [Note] InnoDB: Buffer pool(s) load completed at 190920 17:39:44
wglambert commented 5 years ago

Running tests from https://github.com/docker-library/official-images/pull/6627#issuecomment-531035166

$ git clone --depth 1 https://github.com/docker-library/official-images.git
Cloning into 'official-images'...
remote: Enumerating objects: 1061, done.
remote: Counting objects: 100% (1061/1061), done.
remote: Compressing objects: 100% (878/878), done.
remote: Total 1061 (delta 63), reused 810 (delta 43), pack-reused 0
Receiving objects: 100% (1061/1061), 1.03 MiB | 0 bytes/s, done.
Resolving deltas: 100% (63/63), done.
Checking connectivity... done.

$ cd official-images/

$ git filter-branch --prune-empty --subdirectory-filter test HEAD
Rewrite bf242b5d33c5bda0e0d0d91d04675942bd9eb179 (1/1) (0 seconds passed, remaining 0 predicted)    
Ref 'refs/heads/master' was rewritten

$ ls
clean.sh*  config.sh  README.md  retry.sh*  run.sh*  tests/

$ ./run.sh mariadb:10.3.17
testing mariadb:10.3.17
        'utc' [1/7]...passed
        'cve-2014--shellshock' [2/7]...passed
        'no-hard-coded-passwords' [3/7]...passed
        'override-cmd' [4/7]...passed
        'mysql-basics' [5/7]......passed
        'mysql-initdb' [6/7]......passed
        'mysql-log-bin' [7/7]......passed

$ ./run.sh mariadb:10.3.18
testing mariadb:10.3.18                                                                                                                
        'utc' [1/7]...passed                                                                                                           
        'cve-2014--shellshock' [2/7]...passed                                                                                          
        'no-hard-coded-passwords' [3/7]...passed                                                                                       
        'override-cmd' [4/7]...passed                                                                                                  
        'mysql-basics' [5/7]................................mariadb:10.3.18 failed to accept connections in a reasonable amount of time!                                                                                                                                      
++ docker logs e2e3e52741d5a3df7265e3536e99b397d0d201573f8320375a8ee4bd22742259                                                        
Initializing database                                                                                                                  

PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !                                                                          
To do so, start the server, then issue the following commands:                                                                         

'/usr/bin/mysqladmin' -u root password 'new-password'                                                                                  
'/usr/bin/mysqladmin' -u root -h  password 'new-password'

Alternatively you can run:
'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

Database initialized
MySQL init process in progress...
2019-09-20 18:11:18 0 [Note] mysqld (mysqld 10.3.18-MariaDB-1:10.3.18+maria~bionic) starting as process 109 ...
2019-09-20 18:11:18 0 [Note] InnoDB: Using Linux native AIO
2019-09-20 18:11:18 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-20 18:11:18 0 [Note] InnoDB: Uses event mutexes
2019-09-20 18:11:18 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-09-20 18:11:18 0 [Note] InnoDB: Number of pools: 1
2019-09-20 18:11:18 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-09-20 18:11:18 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-09-20 18:11:18 0 [Note] InnoDB: Completed initialization of buffer pool
2019-09-20 18:11:18 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
MySQL init process in progress...
2019-09-20 18:11:20 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-09-20 18:11:20 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-09-20 18:11:20 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-09-20 18:11:20 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
MySQL init process in progress...
2019-09-20 18:11:20 0 [Note] InnoDB: 10.3.18 started; log sequence number 1631163; transaction id 21
2019-09-20 18:11:20 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-09-20 18:11:20 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-09-20 18:11:20 0 [Note] InnoDB: Buffer pool(s) load completed at 190920 18:11:20
2019-09-20 18:11:20 0 [Warning] 'user' entry 'root@e2e3e52741d5' ignored in --skip-name-resolve mode.
2019-09-20 18:11:20 0 [Warning] 'user' entry '@e2e3e52741d5' ignored in --skip-name-resolve mode.
2019-09-20 18:11:20 0 [Warning] 'proxies_priv' entry '@% root@e2e3e52741d5' ignored in --skip-name-resolve mode.
2019-09-20 18:11:21 0 [Note] Reading of all Master_info entries succeeded
2019-09-20 18:11:21 0 [Note] Added new Master_info '' to hash table
2019-09-20 18:11:21 0 [Note] mysqld: ready for connections.
Version: '10.3.18-MariaDB-1:10.3.18+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
++ eval 'echo '\''SELECT 1'\'' | mysql'
+++ echo 'SELECT 1'
+++ mysql
+++ docker run --rm -i --link mysql-container-19063-24904:mysql --entrypoint mysql -e 'MYSQL_PWD=my cool mysql password' mariadb:10.3.18 -hmysql -u0123456789012345 --silent 'my cool mysql database'
ERROR 2002 (HY000): Can't connect to MySQL server on 'mysql' (115)
failed
        'mysql-initdb' [6/7]................................mariadb:10.3.18 failed to accept connections in a reasonable amount of time!
. . .
        'mysql-log-bin' [7/7]................................mariadb:10.3.18 failed to accept connections in a reasonable amount of time!
. . .
foolswood commented 5 years ago

I think we're hitting this too, for us it manifests an intermittent issue in the CI, which doesn't happen if we pin to 10.1 (which is what I guess we'll do for a bit).

lucwillems commented 5 years ago

i'm also hitting this issue. after intial DB initialization, it seems to hang before running the running the /docker-entrypoint-initdb.d/ scripts and root account is not yet configured .

mariadb-cp | 2019-09-30T05:01:54.680535478Z mariadb 42 MySQL init process in progress...
mariadb-cp | 2019-09-30T05:01:54.821192533Z mariadb 42 2019-09-30  5:01:54 0 [Note] mysqld (mysqld 10.3.18-MariaDB-1:10.3.18+maria~bionic) starting as process 173 ...
mariadb-cp | 2019-09-30T05:01:54.8509885Z mariadb 42 2019-09-30  5:01:54 0 [Note] RocksDB: 2 column families found
mariadb-cp | 2019-09-30T05:01:54.851050756Z mariadb 42 2019-09-30  5:01:54 0 [Note] RocksDB: Column Families at start:
mariadb-cp | 2019-09-30T05:01:54.851058644Z mariadb 42 2019-09-30  5:01:54 0 [Note]   cf=default
mariadb-cp | 2019-09-30T05:01:54.851065911Z mariadb 42 2019-09-30  5:01:54 0 [Note]     write_buffer_size=67108864
mariadb-cp | 2019-09-30T05:01:54.851070723Z mariadb 42 2019-09-30  5:01:54 0 [Note]     target_file_size_base=67108864
mariadb-cp | 2019-09-30T05:01:54.851076698Z mariadb 42 2019-09-30  5:01:54 0 [Note]   cf=__system__
mariadb-cp | 2019-09-30T05:01:54.851085395Z mariadb 42 2019-09-30  5:01:54 0 [Note]     write_buffer_size=67108864
mariadb-cp | 2019-09-30T05:01:54.851096444Z mariadb 42 2019-09-30  5:01:54 0 [Note]     target_file_size_base=67108864
mariadb-cp | 2019-09-30T05:01:54.869652415Z mariadb 42 2019-09-30  5:01:54 0 [Note] RocksDB: Table_store: loaded DDL data for 0 tables
mariadb-cp | 2019-09-30T05:01:54.88509981Z mariadb 42 2019-09-30  5:01:54 0 [Note] RocksDB: global statistics using get_sched_indexer_t indexer
mariadb-cp | 2019-09-30T05:01:54.885152525Z mariadb 42 2019-09-30  5:01:54 0 [Note] MyRocks storage engine plugin has been successfully initialized.
mariadb-cp | 2019-09-30T05:01:54.885282479Z mariadb 42 2019-09-30  5:01:54 0 [Note] CONNECT: Version 1.06.0010 June 01, 2019
mariadb-cp | 2019-09-30T05:01:54.901203887Z mariadb 42 2019-09-30  5:01:54 0 [Note] InnoDB: Using Linux native AIO
mariadb-cp | 2019-09-30T05:01:54.901242002Z mariadb 42 2019-09-30  5:01:54 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
mariadb-cp | 2019-09-30T05:01:54.901248925Z mariadb 42 2019-09-30  5:01:54 0 [Note] InnoDB: Uses event mutexes
mariadb-cp | 2019-09-30T05:01:54.901253851Z mariadb 42 2019-09-30  5:01:54 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
mariadb-cp | 2019-09-30T05:01:54.90142919Z mariadb 42 2019-09-30  5:01:54 0 [Note] InnoDB: Number of pools: 1
mariadb-cp | 2019-09-30T05:01:54.901578246Z mariadb 42 2019-09-30  5:01:54 0 [Note] InnoDB: Using SSE2 crc32 instructions
mariadb-cp | 2019-09-30T05:01:54.902676593Z mariadb 42 2019-09-30  5:01:54 0 [Note] InnoDB: Initializing buffer pool, total size = 4G, instances = 4, chunk size = 128M
mariadb-cp | 2019-09-30T05:01:55.063550087Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: Completed initialization of buffer pool
mariadb-cp | 2019-09-30T05:01:55.064018473Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
mariadb-cp | 2019-09-30T05:01:55.171738991Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
mariadb-cp | 2019-09-30T05:01:55.172426793Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: Creating shared tablespace for temporary tables
mariadb-cp | 2019-09-30T05:01:55.172523057Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
mariadb-cp | 2019-09-30T05:01:55.172533939Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
mariadb-cp | 2019-09-30T05:01:55.174335619Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: 10.3.18 started; log sequence number 1630815; transaction id 21
mariadb-cp | 2019-09-30T05:01:55.174484762Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
mariadb-cp | 2019-09-30T05:01:55.174707981Z mariadb 42 2019-09-30  5:01:55 0 [Note] Plugin 'FEEDBACK' is disabled.
mariadb-cp | 2019-09-30T05:01:55.177372465Z mariadb 42 2019-09-30  5:01:55 0 [Warning] 'user' entry 'root@5497cb2b2189' ignored in --skip-name-resolve mode.
mariadb-cp | 2019-09-30T05:01:55.17738354Z mariadb 42 2019-09-30  5:01:55 0 [Warning] 'user' entry '@5497cb2b2189' ignored in --skip-name-resolve mode.
mariadb-cp | 2019-09-30T05:01:55.177387494Z mariadb 42 2019-09-30  5:01:55 0 [Warning] 'proxies_priv' entry '@% root@5497cb2b2189' ignored in --skip-name-resolve mode.
mariadb-cp | 2019-09-30T05:01:55.178132794Z mariadb 42 2019-09-30  5:01:55 0 [Note] InnoDB: Buffer pool(s) load completed at 190930  5:01:55
mariadb-cp | 2019-09-30T05:01:55.179445991Z mariadb 42 2019-09-30  5:01:55 0 [Note] Reading of all Master_info entries succeeded
mariadb-cp | 2019-09-30T05:01:55.17945505Z mariadb 42 2019-09-30  5:01:55 0 [Note] Added new Master_info '' to hash table
mariadb-cp | 2019-09-30T05:01:55.179463886Z mariadb 42 2019-09-30  5:01:55 0 [Note] mysqld: ready for connections.
mariadb-cp | 2019-09-30T05:01:55.179476257Z mariadb 42 Version: '10.3.18-MariaDB-1:10.3.18+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
mariadb-cp | 2019-09-30T05:01:55.784673084Z mariadb 42 2019-09-30  5:01:55 10 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:01:55.784728988Z 255 ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:01:55.785689063Z check.mariadb exited with error: exit status 1
mariadb-cp | 2019-09-30T05:02:00.791107214Z mariadb 42 2019-09-30  5:02:00 11 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:00.791281511Z 259 ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:00.793297796Z check.mariadb exited with error: exit status 1
mariadb-cp | 2019-09-30T05:02:05.792145752Z mariadb 42 2019-09-30  5:02:05 12 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:05.792305227Z 261 ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:05.793920555Z check.mariadb exited with error: exit status 1
mariadb-cp | 2019-09-30T05:02:10.791898474Z mariadb 42 2019-09-30  5:02:10 13 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:10.79204545Z 263 ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:10.793609751Z check.mariadb exited with error: exit status 1
mariadb-cp | 2019-09-30T05:02:15.791498256Z mariadb 42 2019-09-30  5:02:15 14 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:15.791651989Z 265 ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:15.793318054Z check.mariadb exited with error: exit status 1
mariadb-cp | 2019-09-30T05:02:20.791050752Z mariadb 42 2019-09-30  5:02:20 15 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:20.791233244Z 267 ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
mariadb-cp | 2019-09-30T05:02:20.792776665Z check.mariadb exited with error: exit status 1

while this was running for a few minutes i notice it was handling the tzinfo data.

mysql       42    11  0 05:01 ?        00:00:00 /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld --innodb_buffer_pool_size=4G --innodb-buffer-pool-instances=4
mysql      173    42 33 05:01 ?        00:01:02 mysqld --innodb_buffer_pool_size=4G --innodb-buffer-pool-instances=4 --skip-networking --socket=/var/run/mysqld/mysqld.sock
**mysql      252    42  0 05:01 ?        00:00:00 mysql_tzinfo_to_sql /usr/share/zoneinfo**
mysql      253    42  0 05:01 ?        00:00:00 sed s/Local time zone must be set--see zic manual page/FCTY/
mysql      254    42  0 05:01 ?        00:00:00 mysql --protocol=socket -uroot -hlocalhost --socket=/var/run/mysqld/mysqld.sock mysql
root       275     0  0 05:02 pts/0    00:00:00 bash
root       348   275  0 05:05 pts/0    00:00:00 ps -ef
lucwillems commented 5 years ago

see https://github.com/docker-library/mariadb/issues/261#issuecomment-532788199, this seems to be related to https://jira.mariadb.org/browse/MDEV-18778

using MYSQL_INITDB_SKIP_TZINFO=1 seems to workaround, but will not have TZINFO data in the database.

melroy89 commented 5 years ago

I think both mariadb devs as well as the mariadb docker devs could prevent this in the future my running CI. And don't label mariadb as 'latest' while it is unstable/not workable. This could be prevented I think.

I hope you all agree. (I do not want to blame.. but just an open discussion regarding prevention).

yosifkit commented 5 years ago

@danger89, we do run tests that start and connect to the server on every PR here via TravisCI and before it goes to be built for Docker Hub (like https://github.com/docker-library/official-images/pull/6627#issuecomment-531035166), but this issue was not encountered. The reason the test machine from my build test comment did not see the error is that the hard drive is an NVME SSD and I assume the Travis servers must also be SSD since we have only been able to reproduce the error on a spinning disk.

See the mysql-* tests in official-images test for the details of the tests performed on the MariaDB Docker images.

melroy89 commented 5 years ago

@yosifkit So to conclude you miss test coverage of hard-drives (spinning disks).

tianon commented 5 years ago

Yep, we don't have any CI providers which offer that (it's kind of a weird ask from their perspective; most folks likely want to go the other direction).

lachnerd commented 5 years ago

hi there, we are experiencing this issue on SSD Storage. (IOPS r 7500/w 5000) Every mariadb version bigger than 10.3.16 may be stuck on initialisation with first boot of the database.

yosifkit commented 5 years ago

7500/5000 is still very slow compared to a local nvme ssd that is around 680,000/360,000 iops (https://cloud.google.com/compute/docs/disks/performance#type_comparison)

rdlmda commented 5 years ago

261 is related

foolswood commented 4 years ago

This is now hitting in the latest 10.1 image too, so we're now using the TZ workaround,

jgb commented 4 years ago

So what is the story here? Is this a confirmed bug? Will this be fixed in a new version of mariadb? Or will a new docker image be published?

andryyy commented 4 years ago

Can someone look into this? Edit: Sad smiley here.

yosifkit commented 4 years ago

This is an upstream issue and not something we can fix in the image. The cause is https://jira.mariadb.org/browse/MDEV-18778 and I don't see a new issue linking to it, so it probably still needs to be reported to them.

The multiple workarounds are:

  1. use a faster disk
  2. MYSQL_INITDB_SKIP_TZINFO=1 and add tzdata yourself
  3. use an older version (before 10.1.42, 10.2.27, 10.3.18, 10.4.8)
  4. use an alternative SQL like MySQL or Percona Server for MySQL
GeoffMonteeMariaDB commented 4 years ago

The cause of this might be the following bug:

https://jira.mariadb.org/browse/MDEV-21209

mysql_tzinfo_to_sql is unnecessarily executing some ALTER TABLE statements, and this may be causing the slow startup issues that users have been seeing.

yosifkit commented 4 years ago

From the movement in https://jira.mariadb.org/browse/MDEV-21209, it looks like there might be a fix in 10.1.45, 10.2.31, 10.3.22, 10.4.12, and 10.5.1, but I don't see a commit in https://github.com/MariaDB/server :confused:

GeoffMonteeMariaDB commented 4 years ago

@yosifkit,

The commit is currently in the 10.1 branch:

https://github.com/MariaDB/server/commit/2b7e461cc06ea5ca167e16ff643f0b597aba118d

Prior to those releases, the commit will be merged upwards to 10.2, 10.3, 10.4, and 10.5.

w7089 commented 4 years ago

Affected by MDEV-18778 versions crash with below error during MariaDB first start (no data exists):

[Note] [Entrypoint]: Temporary server started.
**ERROR 1047** (08S01) at line 5: WSREP has not yet prepared node for application use

Downgrading to versions below the affected versions and setting MYSQL_INITDB_SKIP_TZINFOto 1 helped. Crash doesn't happen and MariaDB starts fast.

Full stacktrace:

2019-12-15 13:13:55+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.10+maria~bionic started.
2019-12-15 13:13:56+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2019-12-15 13:13:56+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.4.10+maria~bionic started.
2019-12-15 13:13:57+00:00 [Note] [Entrypoint]: Initializing database files
wsrep loader: [INFO] wsrep_load(): loading provider library 'none'

PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following commands:

'/usr/bin/mysqladmin' -u root password 'new-password'
'/usr/bin/mysqladmin' -u root -h  password 'new-password'

Alternatively you can run:
'/usr/bin/mysql_secure_installation'

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.

Please report any problems at http://mariadb.org/jira

The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/

2019-12-15 13:14:14+00:00 [Note] [Entrypoint]: Database files initialized
2019-12-15 13:14:14+00:00 [Note] [Entrypoint]: Starting temporary server
2019-12-15 13:14:14+00:00 [Note] [Entrypoint]: Waiting for server startup
2019-12-15 13:14:14 0 [Note] mysqld (mysqld 10.4.10-MariaDB-1:10.4.10+maria~bionic) starting as process 190 ...
2019-12-15 13:14:14 0 [Note] WSREP: Loading provider /usr/lib/libgalera_smm.so initial position: 00000000-0000-0000-0000-000000000000:-1
wsrep loader: [INFO] wsrep_load(): loading provider library '/usr/lib/libgalera_smm.so'
wsrep loader: [INFO] wsrep_load(): Galera 26.4.3(r4535) by Codership Oy <info@codership.com> loaded successfully.
2019-12-15 13:14:14 0 [Note] WSREP: CRC-32C: using "slicing-by-8" algorithm.
2019-12-15 13:14:14 0 [Warning] WSREP: Could not open state file for reading: '/var/lib/mysql//grastate.dat'
2019-12-15 13:14:14 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1
2019-12-15 13:14:14 0 [Note] WSREP: GCache DEBUG: opened preamble:
Version: 0
UUID: 00000000-0000-0000-0000-000000000000
Seqno: -1 - -1
Offset: -1
Synced: 0
2019-12-15 13:14:14 0 [Note] WSREP: Skipped GCache ring buffer recovery: could not determine history UUID.
2019-12-15 13:14:14 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 10.0.0.25; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 500M; gcache.recover = yes; gcache.size = 500M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = fal
2019-12-15 13:14:15 0 [Note] WSREP: Start replication
2019-12-15 13:14:15 0 [Note] WSREP: Connecting with bootstrap option: 1
2019-12-15 13:14:15 0 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1
2019-12-15 13:14:15 0 [Note] WSREP: protonet asio version 0
2019-12-15 13:14:15 0 [Note] WSREP: Using CRC-32C for message checksums.
2019-12-15 13:14:15 0 [Note] WSREP: backend: asio
2019-12-15 13:14:15 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2019-12-15 13:14:15 0 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
2019-12-15 13:14:15 0 [Note] WSREP: restore pc from disk failed
2019-12-15 13:14:15 0 [Note] WSREP: GMCast version 0
2019-12-15 13:14:15 0 [Note] WSREP: (cae09b76, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
2019-12-15 13:14:15 0 [Note] WSREP: (cae09b76, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
2019-12-15 13:14:15 0 [Note] WSREP: EVS version 1
2019-12-15 13:14:15 0 [Note] WSREP: gcomm: bootstrapping new group 'maria-cluster'
2019-12-15 13:14:15 0 [Note] WSREP: start_prim is enabled, turn off pc_recovery
2019-12-15 13:14:15 0 [Note] WSREP: EVS version upgrade 0 -> 1
2019-12-15 13:14:15 0 [Note] WSREP: PC protocol upgrade 0 -> 1
2019-12-15 13:14:15 0 [Note] WSREP: Node cae09b76 state prim
2019-12-15 13:14:15 0 [Note] WSREP: view(view_id(PRIM,cae09b76,1) memb {
    cae09b76,0
} joined {
} left {
} partitioned {
})
2019-12-15 13:14:15 0 [Note] WSREP: save pc into disk
2019-12-15 13:14:15 0 [Note] WSREP: gcomm: connected
2019-12-15 13:14:15 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2019-12-15 13:14:15 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2019-12-15 13:14:15 0 [Note] WSREP: Opened channel 'maria-cluster'
2019-12-15 13:14:15 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
2019-12-15 13:14:15 0 [Note] WSREP: Starting new group from scratch: cb0146ea-1f3c-11ea-a0b9-ceb3ba9cf01e
2019-12-15 13:14:15 0 [Note] WSREP: STATE_EXCHANGE: sent state UUID: cb014984-1f3c-11ea-9f3c-2b635f0cf73f
2019-12-15 13:14:15 0 [Note] WSREP: STATE EXCHANGE: sent state msg: cb014984-1f3c-11ea-9f3c-2b635f0cf73f
2019-12-15 13:14:15 0 [Note] WSREP: STATE EXCHANGE: got state msg: cb014984-1f3c-11ea-9f3c-2b635f0cf73f from 0 (vm)
2019-12-15 13:14:15 0 [Note] WSREP: Quorum results:
    version    = 6,
    component  = PRIMARY,
    conf_id    = 0,
    members    = 1/1 (joined/total),
    act_id     = 0,
    last_appl. = 0,
    protocols  = 2/10/4 (gcs/repl/appl),
    vote policy= 0,
    group UUID = cb0146ea-1f3c-11ea-a0b9-ceb3ba9cf01e
2019-12-15 13:14:15 0 [Note] WSREP: Flow-control interval: [16, 16]
2019-12-15 13:14:15 0 [Note] WSREP: Restored state OPEN -> JOINED (1)
2019-12-15 13:14:15 0 [Note] WSREP: Member 0.0 (vm) synced with group.
2019-12-15 13:14:15 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 1)
2019-12-15 13:14:15 1 [Note] WSREP: Starting rollbacker thread 1
2019-12-15 13:14:15 2 [Note] WSREP: Starting applier thread 2
2019-12-15 13:14:15 2 [Note] WSREP: ####### processing CC 1, local, ordered
2019-12-15 13:14:15 2 [Note] WSREP: REPL Protocols: 10 (5, 3)
2019-12-15 13:14:15 2 [Note] WSREP: ####### My UUID: cae09b76-1f3c-11ea-83f3-1fbf34daa351
2019-12-15 13:14:15 2 [Note] WSREP: Server vm connected to cluster at position cb0146ea-1f3c-11ea-a0b9-ceb3ba9cf01e:1 with ID cae09b76-1f3c-11ea-83f3-1fbf34daa351
2019-12-15 13:14:15 2 [Note] WSREP: Server status change disconnected -> connected
2019-12-15 13:14:15 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-12-15 13:14:15 2 [Note] WSREP: ####### ST not required
2019-12-15 13:14:15 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: no
2019-12-15 13:14:15 0 [Note] WSREP: Service thread queue flushed.
2019-12-15 13:14:15 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: 5
2019-12-15 13:14:15 2 [Note] WSREP: ####### Adjusting cert position: -1 -> 1
2019-12-15 13:14:15 0 [Note] WSREP: Service thread queue flushed.
2019-12-15 13:14:15 2 [Note] WSREP: ####### Setting monitor position to 1
2019-12-15 13:14:15 2 [Note] WSREP: Lowest cert indnex boundary for CC from group: 1
2019-12-15 13:14:15 2 [Note] WSREP: Min available from gcache for CC from group: 1
2019-12-15 13:14:15 2 [Note] WSREP: ================================================
View:
  id: cb0146ea-1f3c-11ea-a0b9-ceb3ba9cf01e:1
  status: primary
  protocol_version: 4
  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
  final: no
  own_index: 0
  members(1):
    0: cae09b76-1f3c-11ea-83f3-1fbf34daa351, vm
=================================================
2019-12-15 13:14:15 2 [Note] WSREP: Server status change connected -> joiner
2019-12-15 13:14:15 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-12-15 13:14:15 2 [Note] WSREP: Server status change joiner -> initializing
2019-12-15 13:14:15 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-12-15 13:14:15 0 [Note] InnoDB: Using Linux native AIO
2019-12-15 13:14:15 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-12-15 13:14:15 0 [Note] InnoDB: Uses event mutexes
2019-12-15 13:14:15 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-12-15 13:14:15 0 [Note] InnoDB: Number of pools: 1
2019-12-15 13:14:15 0 [Note] InnoDB: Using generic crc32 instructions
2019-12-15 13:14:15 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2019-12-15 13:14:15 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-12-15 13:14:15 0 [Note] InnoDB: Completed initialization of buffer pool
2019-12-15 13:14:15 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-12-15 13:14:19 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-12-15 13:14:19 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-12-15 13:14:19 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-12-15 13:14:19 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-12-15 13:14:19 0 [Note] InnoDB: Waiting for purge to start
2019-12-15 13:14:19 0 [Note] InnoDB: 10.4.10 started; log sequence number 139992; transaction id 21
2019-12-15 13:14:19 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-12-15 13:14:19 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-12-15 13:14:21 0 [Warning] 'user' entry 'root@vm' ignored in --skip-name-resolve mode.
2019-12-15 13:14:21 0 [Warning] 'user' entry '@vm' ignored in --skip-name-resolve mode.
2019-12-15 13:14:21 0 [Warning] 'proxies_priv' entry '@% root@vm' ignored in --skip-name-resolve mode.
2019-12-15 13:14:21 0 [Note] WSREP: wsrep_init_schema_and_SR (nil)
2019-12-15 13:14:21 0 [Note] InnoDB: Buffer pool(s) load completed at 191215 13:14:21
2019-12-15 13:14:22 0 [Note] WSREP: Server initialized
2019-12-15 13:14:22 0 [Note] WSREP: Server status change initializing -> initialized
2019-12-15 13:14:22 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-12-15 13:14:22 2 [Note] WSREP: Bootstrapping a new cluster, setting initial position to 00000000-0000-0000-0000-000000000000:-1
2019-12-15 13:14:22 9 [Note] WSREP: Cluster table is empty, not recovering transactions
2019-12-15 13:14:22 2 [Note] WSREP: Server status change initialized -> joined
2019-12-15 13:14:22 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-12-15 13:14:22 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-12-15 13:14:22 0 [Note] mysqld: ready for connections.
Version: '10.4.10-MariaDB-1:10.4.10+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
2019-12-15 13:14:23+00:00 [Note] [Entrypoint]: Temporary server started.
ERROR 1047 (08S01) at line 5: WSREP has not yet prepared node for application use
w7089 commented 4 years ago

@yosifkit

The multiple workarounds are:

  1. use a faster disk
  2. MYSQL_INITDB_SKIP_TZINFO=1 and add tzdata yourself ...

What do you mean by

add tzdata yourself ?

Running

mysql_tzinfo_to_sql /usr/share/zoneinfo | sed 's/Local time zone must be set--see zic manual page/FCTY/' | mysql -uuser -ppass --database=mysql

similarly to docker-entrypoint.sh?

I ran the above commands against one node after MariaDB cluster of 3 nodes went up successfully. Execution of commands took ~12 minutes and they finished with warning:

Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it.

In addition, there were errors in the logs of other 2 nodes in the cluster like:

[ERROR] Slave SQL: Error 'Column 'Time_zone_id' cannot be null' on query. Default database: 'mysql'. Query: 'INSERT INTO time_zone_name (Name, Time_zone_id) VALUES ('Africa/Abidjan', @time_zone_id)', Internal MariaDB error code: 1048

yosifkit commented 4 years ago

Running

mysql_tzinfo_to_sql /usr/share/zoneinfo | sed 's/Local time zone must be set--see zic manual page/FCTY/' | mysql -uuser -ppass --database=mysql

similarly to docker-entrypoint.sh?

@w7089, Yes, that is what I was alluding to. Perhaps an older or newer version of mysql_tzinfo_to_sql would help. For older versions, you then run into https://jira.mariadb.org/browse/MDEV-18778 when on an clustered environment (as you mentioned in a previous comment).

My initial guess is that you need to restart all of the servers after loading in the timezone data, but I'd recommend a trying a forum dedicated to MariaDB (clustering), since your question is about specifics when running a cluster and this GitHub repo is more about bugs with containerization.

After populating the time zone tables, you should usually restart the server so that the new time zone data is correctly loaded.

- https://mariadb.com/kb/en/library/mysql_tzinfo_to_sql/

(As far as I know, the warning about leap-seconds can be ignored)

quazgar commented 4 years ago

Upstream at https://jira.mariadb.org/browse/MDEV-21209 says it should be fixed with 10.4.12. The latest release of 10.4 as of now is 10.4.11.

marc-legendre commented 4 years ago

Quick test: if I run the tests pointed by @wglambert, 10.3.22 passes, but 10.4.12 still fails.

$ ./run.sh mariadb:10.3.22
testing mariadb:10.3.22
        'utc' [1/7]...passed
        'cve-2014--shellshock' [2/7]...passed
        'no-hard-coded-passwords' [3/7]...passed
        'override-cmd' [4/7]...passed
        'mysql-basics' [5/7]......passed
        'mysql-initdb' [6/7]......passed
        'mysql-log-bin' [7/7].......passed
$ ./run.sh mariadb:10.4.12                                                       
testing mariadb:10.4.12                                                                              
        'utc' [1/7]...passed                                                                                                 
        'cve-2014--shellshock' [2/7]...passed                                                                                     
        'no-hard-coded-passwords' [3/7]...passed                                     
        'override-cmd' [4/7]...passed                                                             
        'mysql-basics' [5/7]................................mariadb:10.4.12 failed to accept connections in a reasonable amount of time!
[...]
        'mysql-initdb' [6/7]................................mariadb:10.4.12 failed to accept connections in a reasonable amount of time!
[...]
        'mysql-log-bin' [7/7]................................mariadb:10.4.12 failed to accept connections in a reasonable amount of time!
[...]
failed

Complete output here: run-10.4.12.log

rdlmda commented 4 years ago

@almightykiwi can you please share the script you've used to perform the tests, if possible? I'd be really grateful.

yosifkit commented 4 years ago

@rdlmda, that ./run.sh should just be the one in official-images tests and the specific tests are in the tests directory.

wglambert commented 4 years ago

Mariadb:10.5.1

$ docker run -d --rm -e MYSQL_ROOT_PASSWORD=pass --name maria mariadb:10.5.1                                                         
ad431a9614af951b7d1e3f414587528078a7336b70b4015ca194d41ba0f8a7a2

$ time grep -iq "ready for start up" <(docker logs -f maria 2>&1)

real    7m37.987s                                                                                                                                             
user    0m0.000s                                                                                                                                              
sys     0m0.007s

Mysql:8.0.19

$ docker run -d --rm -e MYSQL_ROOT_PASSWORD=pass --name mysql mysql:8.0.19
43961cb98d14f7d1551d41cdc9f4c0a12d9fff9003275ffdb2ecca5e78312d04

$ time grep -iq "ready for start up" <(docker logs -f mysql 2>&1)                                                                    

real    2m7.173s                                                                                                                                              
user    0m0.003s                                                                                                                                              
sys     0m0.003s

Mariadb:10.5.1 with MYSQL_INITDB_SKIP_TZINFO=1

$ docker run -d --rm -e MYSQL_ROOT_PASSWORD=pass -e MYSQL_INITDB_SKIP_TZINFO=1 --name maria mariadb:10.5.1
93a068d331cefdc6d20166ec5f15fb303482daef2aba6b4529f907eed7e0404c

$ time grep -iq "ready for start up" <(docker logs -f maria 2>&1)

real    0m20.795s
user    0m0.004s
sys     0m0.000s
ezawadzki commented 4 years ago

The same with version 1.5.1.

numericalatina commented 4 years ago

I can confirm that this issue still happens on v. 10.4.12 and not in v. 10.3.22

From the possible workarounds i will choose sticking with a working version.

Is 10.3.22 the recommended working version then? or is it any of 10.2.27, 10.3.18, 10.4.8?

numericalatina commented 4 years ago

Well 10.4.8 still has this same bug according to #261 so I guess I'll stick with 10.3.18 then

lingxiankong commented 4 years ago

Adding -e MYSQL_INITDB_SKIP_TZINFO=1 works for me.

boiddude commented 4 years ago

I wish someone on here could have put where the file is on the docker mariadb or what command to run? If I run mysql_tzinfo_to_sql on the Mariadb Docker container it just complains that the command doens't exist. Can anyone please help with where or what or when or how that command is to be entered to stop the timezone issue?

Adding -e MYSQL_INITDB_SKIP_TZINFO=1 works for me.

Where do you add it to????

tianon commented 4 years ago

That's the syntax for adding an environment variable via docker run -- if you're using Kubernetes or similar, you would just add MYSQL_INITDB_SKIP_TZINFO (set to 1) as an environment variable on your container.

grooverdan commented 4 years ago

https://jira.mariadb.org/browse/MDEV-23326 created on the 10.3 -> 10.4 performance drop.

grooverdan commented 4 years ago

All, to summarise a long issue that you have all endured:

Timezone initialization speed has been corrected in:

MariaDB 10.1.44, 10.2.31, 10.3.22 because of https://jira.mariadb.org/browse/MDEV-21209 MariaDB 10.4.14, 10.5.5 per #320

As you all can understand, having multiple issues at the same time can make it easy to loose sight of what is/isn't fixed. On behalf of the MariaDB Foundation I apologise that this upstream issue lingered so long.

The docker library team of @tianon and @yosifkit have provided you with an excellent expertise in packaging MariaDB containers for you. To grab the attention of MariaDB developers on issues that are beyond the realm of the container initialization please report those to MariaDB directly https://mariadb.com/kb/en/mariadb-community-bug-reporting/.

Retesting the latest versions released yesterday:

Start times (Samsung SSD 970 EVO Plus NVME M.2):

Version With tz Without tz
10.1.46 0m13.543s 0m12.041s
10.2.23 0m5.292s 0m4.539s
10.3.24 0m5.542s 0m4.799s
10.4.14 0m6.042s 0m4.793s
10.5.5 0m5.572s 0m4.315s

Many of you encountered issues under slow disk. So here's the same results on my 5400 rpm Western Digital Green WD40EZRX-00SPEB0:

Version With tz Without tz
10.1.46 0m17.548s 0m16.048s
10.2.23 0m6.796s 0m6.292s
10.3.24 0m6.790s 0m5.285s
10.4.14 0m12.797s 0m8.294s
10.5.5 0m11.297s 0m7.037s

ref: test script

While slower hardware still incurs a relatively high penalty in 10.4+ it is still slow with regard to time zone initialisation, I hope these improvements make it usable if you desire its functionality.

Upstream issues continue to remain open to further improve performance of initialization particularly in the 10.4+

If you are encountering any problems regarding unacceptably slow initialization from the versions above or newer onwards please create a new issue.

note: @w7089 your galera issue might be solved by some variant of #253. If it is still present in a version above or later than, please create a new issue.