search

docker-library / mysql

Docker Official Image packaging for MySQL Community Server
https://dev.mysql.com/
GNU General Public License v2.0
2.47k stars 2.2k forks source link

Initialization script crashes with MYSQL_RANDOM_ROOT_PASSWORD #860

Closed akors closed 2 years ago

akors commented 2 years ago

The latest build of the image crashes when initializing a new database if MYSQL_RANDOM_ROOT_PASSWORD was set.

Run the following command:

docker run -e MYSQL_RANDOM_ROOT_PASSWORD=1  --rm -it mysql:5.7

Observe the following error message:

ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)
/usr/local/bin/docker-entrypoint.sh: line 251:    77 Killed                  "$@" --skip-networking --default-time-zone=SYSTEM --socket="${SOCKET}"

Note that this DOES occur with the label 5.7.38, but it does NOT occur with 5.7.28. Something must've gone wrong in the last update.

This works just fine:

docker run -e MYSQL_RANDOM_ROOT_PASSWORD=1  --rm -it mysql:5.7.28

Docker version: 

docker version
Client: Docker Engine - Community
 Version:           20.10.16
 API version:       1.41
 Go version:        go1.17.10
 Git commit:        aa7e414
 Built:             Thu May 12 09:18:13 2022
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.16
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.17.10
  Git commit:       f756502
  Built:            Thu May 12 09:15:57 2022
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.4
  GitCommit:        212e8b6fa2f44b9c21b2798135fc6fb7c53efc16
 runc:
  Version:          1.1.1
  GitCommit:        v1.1.1-0-g52de29d
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Full log:

2022-05-27 15:54:35+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.38-1debian10 started.
2022-05-27 15:54:58+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2022-05-27 15:54:58+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.38-1debian10 started.
2022-05-27 15:55:21+00:00 [Note] [Entrypoint]: Initializing database files
2022-05-27T15:55:28.517638Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2022-05-27T15:55:28.659931Z 0 [Warning] InnoDB: New log files created, LSN=45790
2022-05-27T15:55:28.681218Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2022-05-27T15:55:28.736724Z 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: 6e2580fa-ddd5-11ec-a5d8-0242ac110002.
2022-05-27T15:55:28.737871Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2022-05-27T15:55:29.180769Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T15:55:29.180783Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T15:55:29.181137Z 0 [Warning] CA certificate ca.pem is self signed.
2022-05-27T15:55:29.224720Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2022-05-27 15:55:32+00:00 [Note] [Entrypoint]: Database files initialized
2022-05-27 15:55:32+00:00 [Note] [Entrypoint]: Starting temporary server
2022-05-27 15:55:32+00:00 [Note] [Entrypoint]: Waiting for server startup
2022-05-27T15:55:39.141824Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2022-05-27T15:55:39.143861Z 0 [Note] mysqld (mysqld 5.7.38) starting as process 77 ...
2022-05-27T15:55:39.148693Z 0 [Note] InnoDB: PUNCH HOLE support available
2022-05-27T15:55:39.148716Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2022-05-27T15:55:39.148719Z 0 [Note] InnoDB: Uses event mutexes
2022-05-27T15:55:39.148721Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2022-05-27T15:55:39.148722Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-05-27T15:55:39.148724Z 0 [Note] InnoDB: Using Linux native AIO
2022-05-27T15:55:39.148881Z 0 [Note] InnoDB: Number of pools: 1
2022-05-27T15:55:39.148974Z 0 [Note] InnoDB: Using CPU crc32 instructions
2022-05-27T15:55:39.151420Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2022-05-27T15:55:39.162076Z 0 [Note] InnoDB: Completed initialization of buffer pool
2022-05-27T15:55:39.164840Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2022-05-27T15:55:39.180462Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2022-05-27T15:55:39.195586Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-05-27T15:55:39.195697Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-05-27T15:55:39.217857Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-05-27T15:55:39.218606Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2022-05-27T15:55:39.218620Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2022-05-27T15:55:39.219177Z 0 [Note] InnoDB: 5.7.38 started; log sequence number 2749976
2022-05-27T15:55:39.219324Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2022-05-27T15:55:39.219578Z 0 [Note] Plugin 'FEDERATED' is disabled.
2022-05-27T15:55:39.223082Z 0 [Note] InnoDB: Buffer pool(s) load completed at 220527 15:55:39
2022-05-27T15:55:39.228017Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2022-05-27T15:55:39.228037Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2022-05-27T15:55:39.228047Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T15:55:39.228052Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T15:55:39.228941Z 0 [Warning] CA certificate ca.pem is self signed.
2022-05-27T15:55:39.228983Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2022-05-27T15:55:39.230608Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2022-05-27T15:55:39.253859Z 0 [Note] Event Scheduler: Loaded 0 events
2022-05-27T15:55:39.254025Z 0 [Note] mysqld: ready for connections.
Version: '5.7.38'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server (GPL)
2022-05-27 15:55:39+00:00 [Note] [Entrypoint]: Temporary server started.
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)
/usr/local/bin/docker-entrypoint.sh: line 251:    77 Killed                  "$@" --skip-networking --default-time-zone=SYSTEM --socket="${SOCKET}"
wglambert commented 2 years ago

There's a couple issues of users getting Can't connect to local MySQL server through socket https://github.com/docker-library/mysql/issues/844, https://github.com/docker-library/mysql/issues/845

But I'm not able to reproduce the issue

$ docker run -d --name mysql -e MYSQL_RANDOM_ROOT_PASSWORD=1 mysql:5.7.38
0094f8c8cf85210f36dc70332ee9dfd7ea5ef7f3ccab86fd6ef882674680bd2f

$ docker logs mysql 2>&1 | grep -i generated
2022-05-27 16:15:31+00:00 [Note] [Entrypoint]: GENERATED ROOT PASSWORD: RSIGBdjF5W53dGJdMOu32HIWD8EisVGb

$ docker exec -it mysql mysql -pRSIGBdjF5W53dGJdMOu32HIWD8EisVGb
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.7.38 MySQL Community Server (GPL)

Copyright (c) 2000, 2022, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>
docker logs ```console $ docker logs mysql 2022-05-27 16:15:25+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.38-1debian10 started. 2022-05-27 16:15:25+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql' 2022-05-27 16:15:25+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.38-1debian10 started. 2022-05-27 16:15:25+00:00 [Note] [Entrypoint]: Initializing database files 2022-05-27T16:15:25.357231Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2022-05-27T16:15:25.898805Z 0 [Warning] InnoDB: New log files created, LSN=45790 2022-05-27T16:15:25.983889Z 0 [Warning] InnoDB: Creating foreign key constraint system tables. 2022-05-27T16:15:26.043079Z 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: 37cbf572-ddd8-11ec-bc25-0242ac110002. 2022-05-27T16:15:26.044183Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened. 2022-05-27T16:15:26.298953Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher. 2022-05-27T16:15:26.298990Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher. 2022-05-27T16:15:26.299688Z 0 [Warning] CA certificate ca.pem is self signed. 2022-05-27T16:15:26.472849Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option. 2022-05-27 16:15:28+00:00 [Note] [Entrypoint]: Database files initialized 2022-05-27 16:15:28+00:00 [Note] [Entrypoint]: Starting temporary server 2022-05-27 16:15:28+00:00 [Note] [Entrypoint]: Waiting for server startup 2022-05-27T16:15:29.216474Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2022-05-27T16:15:29.220509Z 0 [Note] mysqld (mysqld 5.7.38) starting as process 76 ... 2022-05-27T16:15:29.225954Z 0 [Note] InnoDB: PUNCH HOLE support available 2022-05-27T16:15:29.226199Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2022-05-27T16:15:29.226274Z 0 [Note] InnoDB: Uses event mutexes 2022-05-27T16:15:29.226344Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2022-05-27T16:15:29.226412Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2022-05-27T16:15:29.226483Z 0 [Note] InnoDB: Using Linux native AIO 2022-05-27T16:15:29.227245Z 0 [Note] InnoDB: Number of pools: 1 2022-05-27T16:15:29.227790Z 0 [Note] InnoDB: Using CPU crc32 instructions 2022-05-27T16:15:29.232112Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M 2022-05-27T16:15:29.254379Z 0 [Note] InnoDB: Completed initialization of buffer pool 2022-05-27T16:15:29.262378Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2022-05-27T16:15:29.281613Z 0 [Note] InnoDB: Highest supported file format is Barracuda. 2022-05-27T16:15:29.299863Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2022-05-27T16:15:29.299974Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2022-05-27T16:15:29.369572Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2022-05-27T16:15:29.371060Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active. 2022-05-27T16:15:29.371099Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active. 2022-05-27T16:15:29.371949Z 0 [Note] InnoDB: 5.7.38 started; log sequence number 2749976 2022-05-27T16:15:29.372201Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool 2022-05-27T16:15:29.372439Z 0 [Note] Plugin 'FEDERATED' is disabled. 2022-05-27T16:15:29.374737Z 0 [Note] InnoDB: Buffer pool(s) load completed at 220527 16:15:29 2022-05-27T16:15:29.386560Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them. 2022-05-27T16:15:29.386608Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory. 2022-05-27T16:15:29.386616Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher. 2022-05-27T16:15:29.386619Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher. 2022-05-27T16:15:29.387528Z 0 [Warning] CA certificate ca.pem is self signed. 2022-05-27T16:15:29.387584Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory. 2022-05-27T16:15:29.389386Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory. 2022-05-27T16:15:29.401475Z 0 [Note] Event Scheduler: Loaded 0 events 2022-05-27T16:15:29.401739Z 0 [Note] mysqld: ready for connections. Version: '5.7.38' socket: '/var/run/mysqld/mysqld.sock' port: 0 MySQL Community Server (GPL) 2022-05-27 16:15:29+00:00 [Note] [Entrypoint]: Temporary server started. Warning: Unable to load '/usr/share/zoneinfo/iso3166.tab' as time zone. Skipping it. Warning: Unable to load '/usr/share/zoneinfo/leap-seconds.list' as time zone. Skipping it. Warning: Unable to load '/usr/share/zoneinfo/zone.tab' as time zone. Skipping it. Warning: Unable to load '/usr/share/zoneinfo/zone1970.tab' as time zone. Skipping it. 2022-05-27 16:15:31+00:00 [Note] [Entrypoint]: GENERATED ROOT PASSWORD: RSIGBdjF5W53dGJdMOu32HIWD8EisVGb 2022-05-27 16:15:31+00:00 [Note] [Entrypoint]: Stopping temporary server 2022-05-27T16:15:31.969530Z 0 [Note] Giving 0 client threads a chance to die gracefully 2022-05-27T16:15:31.969575Z 0 [Note] Shutting down slave threads 2022-05-27T16:15:31.969581Z 0 [Note] Forcefully disconnecting 0 remaining clients 2022-05-27T16:15:31.969594Z 0 [Note] Event Scheduler: Purging the queue. 0 events 2022-05-27T16:15:31.969835Z 0 [Note] Binlog end 2022-05-27T16:15:31.971512Z 0 [Note] Shutting down plugin 'ngram' 2022-05-27T16:15:31.971531Z 0 [Note] Shutting down plugin 'partition' 2022-05-27T16:15:31.971534Z 0 [Note] Shutting down plugin 'BLACKHOLE' 2022-05-27T16:15:31.971538Z 0 [Note] Shutting down plugin 'ARCHIVE' 2022-05-27T16:15:31.971541Z 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA' 2022-05-27T16:15:31.971574Z 0 [Note] Shutting down plugin 'MRG_MYISAM' 2022-05-27T16:15:31.971581Z 0 [Note] Shutting down plugin 'MyISAM' 2022-05-27T16:15:31.971593Z 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL' 2022-05-27T16:15:31.971689Z 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES' 2022-05-27T16:15:31.971719Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES' 2022-05-27T16:15:31.971755Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS' 2022-05-27T16:15:31.971761Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN' 2022-05-27T16:15:31.971764Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS' 2022-05-27T16:15:31.971766Z 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS' 2022-05-27T16:15:31.971768Z 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES' 2022-05-27T16:15:31.971770Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS' 2022-05-27T16:15:31.971772Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES' 2022-05-27T16:15:31.971774Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE' 2022-05-27T16:15:31.971776Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE' 2022-05-27T16:15:31.971778Z 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG' 2022-05-27T16:15:31.971780Z 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED' 2022-05-27T16:15:31.971782Z 0 [Note] Shutting down plugin 'INNODB_FT_DELETED' 2022-05-27T16:15:31.971784Z 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD' 2022-05-27T16:15:31.971786Z 0 [Note] Shutting down plugin 'INNODB_METRICS' 2022-05-27T16:15:31.971787Z 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO' 2022-05-27T16:15:31.971789Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS' 2022-05-27T16:15:31.971791Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU' 2022-05-27T16:15:31.971793Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE' 2022-05-27T16:15:31.971795Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET' 2022-05-27T16:15:31.971797Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX' 2022-05-27T16:15:31.971807Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET' 2022-05-27T16:15:31.971813Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM' 2022-05-27T16:15:31.971816Z 0 [Note] Shutting down plugin 'INNODB_CMP_RESET' 2022-05-27T16:15:31.971819Z 0 [Note] Shutting down plugin 'INNODB_CMP' 2022-05-27T16:15:31.971822Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS' 2022-05-27T16:15:31.971825Z 0 [Note] Shutting down plugin 'INNODB_LOCKS' 2022-05-27T16:15:31.971828Z 0 [Note] Shutting down plugin 'INNODB_TRX' 2022-05-27T16:15:31.971831Z 0 [Note] Shutting down plugin 'InnoDB' 2022-05-27T16:15:31.971970Z 0 [Note] InnoDB: FTS optimize thread exiting. 2022-05-27T16:15:31.972160Z 0 [Note] InnoDB: Starting shutdown... 2022-05-27T16:15:32.072889Z 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool 2022-05-27T16:15:32.073319Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 220527 16:15:32 2022-05-27T16:15:33.290161Z 0 [Note] InnoDB: Shutdown completed; log sequence number 12659904 2022-05-27T16:15:33.291814Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 2022-05-27T16:15:33.291872Z 0 [Note] Shutting down plugin 'MEMORY' 2022-05-27T16:15:33.291879Z 0 [Note] Shutting down plugin 'CSV' 2022-05-27T16:15:33.291884Z 0 [Note] Shutting down plugin 'sha256_password' 2022-05-27T16:15:33.291886Z 0 [Note] Shutting down plugin 'mysql_native_password' 2022-05-27T16:15:33.292043Z 0 [Note] Shutting down plugin 'binlog' 2022-05-27T16:15:33.293423Z 0 [Note] mysqld: Shutdown complete 2022-05-27 16:15:33+00:00 [Note] [Entrypoint]: Temporary server stopped 2022-05-27 16:15:33+00:00 [Note] [Entrypoint]: MySQL init process done. Ready for start up. 2022-05-27T16:15:34.267194Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2022-05-27T16:15:34.269298Z 0 [Note] mysqld (mysqld 5.7.38) starting as process 1 ... 2022-05-27T16:15:34.272695Z 0 [Note] InnoDB: PUNCH HOLE support available 2022-05-27T16:15:34.272727Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2022-05-27T16:15:34.272731Z 0 [Note] InnoDB: Uses event mutexes 2022-05-27T16:15:34.272734Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2022-05-27T16:15:34.272737Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2022-05-27T16:15:34.272740Z 0 [Note] InnoDB: Using Linux native AIO 2022-05-27T16:15:34.273033Z 0 [Note] InnoDB: Number of pools: 1 2022-05-27T16:15:34.273187Z 0 [Note] InnoDB: Using CPU crc32 instructions 2022-05-27T16:15:34.275514Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M 2022-05-27T16:15:34.284725Z 0 [Note] InnoDB: Completed initialization of buffer pool 2022-05-27T16:15:34.287963Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2022-05-27T16:15:34.302572Z 0 [Note] InnoDB: Highest supported file format is Barracuda. 2022-05-27T16:15:34.317273Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2022-05-27T16:15:34.317359Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2022-05-27T16:15:34.376579Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2022-05-27T16:15:34.377430Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active. 2022-05-27T16:15:34.377451Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active. 2022-05-27T16:15:34.378199Z 0 [Note] InnoDB: 5.7.38 started; log sequence number 12659904 2022-05-27T16:15:34.378557Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool 2022-05-27T16:15:34.378893Z 0 [Note] Plugin 'FEDERATED' is disabled. 2022-05-27T16:15:34.383952Z 0 [Note] InnoDB: Buffer pool(s) load completed at 220527 16:15:34 2022-05-27T16:15:34.387376Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them. 2022-05-27T16:15:34.387415Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory. 2022-05-27T16:15:34.387421Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher. 2022-05-27T16:15:34.387423Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher. 2022-05-27T16:15:34.388375Z 0 [Warning] CA certificate ca.pem is self signed. 2022-05-27T16:15:34.388440Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory. 2022-05-27T16:15:34.389497Z 0 [Note] Server hostname (bind-address): '*'; port: 3306 2022-05-27T16:15:34.389654Z 0 [Note] IPv6 is available. 2022-05-27T16:15:34.389710Z 0 [Note] - '::' resolves to '::'; 2022-05-27T16:15:34.389749Z 0 [Note] Server socket created on IP: '::'. 2022-05-27T16:15:34.390781Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory. 2022-05-27T16:15:34.400746Z 0 [Note] Event Scheduler: Loaded 0 events 2022-05-27T16:15:34.401198Z 0 [Note] mysqld: ready for connections. Version: '5.7.38' socket: '/var/run/mysqld/mysqld.sock' port: 3306 MySQL Community Server (GPL) ```
akors commented 2 years ago

@wglambert

I can still completely reliably reproduce this 100% of the time. With 5.7.36 it starts, with 5.7.37 it crashes.

Looks like something happened between 5.7.36 and 5.7.37. What changed in this version?

What information do you need for debugging this issue?

akors commented 2 years ago

It's the mysql_socket_fix function for issue #829. If I comment out all invocations, startup works perfectly fine.

edit: to be more specific, it's this line: https://github.com/docker-library/mysql/blob/32aecb725b28afa043a5e879977a7947dfb64c14/5.7/docker-entrypoint.sh#L115

tianon commented 2 years ago

Since we can't reproduce, do you get any more interesting output if you remove the 2>/dev/null from line 104? :bow:

https://github.com/docker-library/mysql/blob/32aecb725b28afa043a5e879977a7947dfb64c14/5.7/docker-entrypoint.sh#L104

tianon commented 2 years ago

(It would also be helpful to add set -x to the script so we can see exactly what's running and where it's failing.)

akors commented 2 years ago

Since we can't reproduce, do you get any more interesting output if you remove the 2>/dev/null from line 104? bow

This has no effect, output is not changed.

(It would also be helpful to add set -x to the script so we can see exactly what's running and where it's failing.)

script output with set -x 
+ _verboseHelpArgs=(--verbose --help --log-bin-index="$(mktemp -u)")
++ mktemp -u
+ _is_sourced
+ '[' 2 -ge 2 ']'
+ '[' _is_sourced = _is_sourced ']'
+ '[' main = source ']'
+ _main mysqld
+ '[' m = - ']'
+ '[' mysqld = mysqld ']'
+ _mysql_want_help mysqld
+ local arg
+ for arg in "$@"
+ case "$arg" in
+ return 1
+ mysql_note 'Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
+ mysql_log Note 'Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
+ local type=Note
+ shift
+ local 'text=Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
+ dt='2022-05-27 21:55:05+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:55:05+00:00' Note 'Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
2022-05-27 21:55:05+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.38-1debian10 started.
+ mysql_check_config mysqld
+ toRun=("$@" "${_verboseHelpArgs[@]}")
+ local toRun errors
++ mysqld --verbose --help --log-bin-index=/tmp/tmp.ph3MTtn9KZ
+ errors=
+ docker_setup_env mysqld
+ declare -g DATADIR SOCKET
++ mysql_get_config datadir mysqld
++ local conf=datadir
++ shift
++ mysqld --verbose --help --log-bin-index=/tmp/tmp.ph3MTtn9KZ
++ awk -v conf=datadir '$1 == conf && /^[^ \t]/ { sub(/^[^ \t]+[ \t]+/, ""); print; exit }'
+ DATADIR=/var/lib/mysql/
++ mysql_get_config socket mysqld
++ local conf=socket
++ shift
++ mysqld --verbose --help --log-bin-index=/tmp/tmp.ph3MTtn9KZ
++ awk -v conf=socket '$1 == conf && /^[^ \t]/ { sub(/^[^ \t]+[ \t]+/, ""); print; exit }'
+ SOCKET=/var/run/mysqld/mysqld.sock
+ file_env MYSQL_ROOT_HOST %
+ local var=MYSQL_ROOT_HOST
+ local fileVar=MYSQL_ROOT_HOST_FILE
+ local def=%
+ '[' '' ']'
+ local val=%
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_ROOT_HOST=%
+ MYSQL_ROOT_HOST=%
+ unset MYSQL_ROOT_HOST_FILE
+ file_env MYSQL_DATABASE
+ local var=MYSQL_DATABASE
+ local fileVar=MYSQL_DATABASE_FILE
+ local def=
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_DATABASE=
+ MYSQL_DATABASE=
+ unset MYSQL_DATABASE_FILE
+ file_env MYSQL_USER
+ local var=MYSQL_USER
+ local fileVar=MYSQL_USER_FILE
+ local def=
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_USER=
+ MYSQL_USER=
+ unset MYSQL_USER_FILE
+ file_env MYSQL_PASSWORD
+ local var=MYSQL_PASSWORD
+ local fileVar=MYSQL_PASSWORD_FILE
+ local def=
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_PASSWORD=
+ MYSQL_PASSWORD=
+ unset MYSQL_PASSWORD_FILE
+ file_env MYSQL_ROOT_PASSWORD
+ local var=MYSQL_ROOT_PASSWORD
+ local fileVar=MYSQL_ROOT_PASSWORD_FILE
+ local def=```
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_ROOT_PASSWORD=
+ MYSQL_ROOT_PASSWORD=
+ unset MYSQL_ROOT_PASSWORD_FILE
+ declare -g DATABASE_ALREADY_EXISTS
+ '[' -d /var/lib/mysql//mysql ']'
+ docker_create_db_directories
+ local user
++ id -u
+ user=0
+ mkdir -p /var/lib/mysql/
+ '[' 0 = 0 ']'
+ find /var/lib/mysql/ '!' -user mysql -exec chown --no-dereference mysql '{}' +
++ id -u
+ '[' 0 = 0 ']'
+ mysql_note 'Switching to dedicated user '\''mysql'\'''
+ mysql_log Note 'Switching to dedicated user '\''mysql'\'''
+ local type=Note
+ shift
+ local 'text=Switching to dedicated user '\''mysql'\'''
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
+ dt='2022-05-27 21:55:27+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:55:27+00:00' Note 'Switching to dedicated user '\''mysql'\'''
+ exec gosu mysql /usr/local/bin/docker-entrypoint.sh mysqld
2022-05-27 21:55:27+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
+ _verboseHelpArgs=(--verbose --help --log-bin-index="$(mktemp -u)")
++ mktemp -u
+ _is_sourced
+ '[' 2 -ge 2 ']'
+ '[' _is_sourced = _is_sourced ']'
+ '[' main = source ']'
+ _main mysqld
+ '[' m = - ']'
+ '[' mysqld = mysqld ']'
+ _mysql_want_help mysqld
+ local arg
+ for arg in "$@"
+ case "$arg" in
+ return 1
+ mysql_note 'Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
+ mysql_log Note 'Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
+ local type=Note
+ shift
+ local 'text=Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
+ dt='2022-05-27 21:55:27+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:55:27+00:00' Note 'Entrypoint script for MySQL Server 5.7.38-1debian10 started.'
2022-05-27 21:55:27+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.38-1debian10 started.
+ mysql_check_config mysqld
+ toRun=("$@" "${_verboseHelpArgs[@]}")
+ local toRun errors
++ mysqld --verbose --help --log-bin-index=/tmp/tmp.z8ILnx7S1C
+ errors=
+ docker_setup_env mysqld
+ declare -g DATADIR SOCKET
++ mysql_get_config datadir mysqld
++ local conf=datadir
++ shift
++ mysqld --verbose --help --log-bin-index=/tmp/tmp.z8ILnx7S1C
++ awk -v conf=datadir '$1 == conf && /^[^ \t]/ { sub(/^[^ \t]+[ \t]+/, ""); print; exit }'
+ DATADIR=/var/lib/mysql/
++ mysql_get_config socket mysqld
++ local conf=socket
++ shift
++ mysqld --verbose --help --log-bin-index=/tmp/tmp.z8ILnx7S1C
++ awk -v conf=socket '$1 == conf && /^[^ \t]/ { sub(/^[^ \t]+[ \t]+/, ""); print; exit }'
+ SOCKET=/var/run/mysqld/mysqld.sock
+ file_env MYSQL_ROOT_HOST %
+ local var=MYSQL_ROOT_HOST
+ local fileVar=MYSQL_ROOT_HOST_FILE
+ local def=%
+ '[' % ']'
+ '[' '' ']'
+ local val=%
+ '[' % ']'
+ val=%
+ export MYSQL_ROOT_HOST=%
+ MYSQL_ROOT_HOST=%
+ unset MYSQL_ROOT_HOST_FILE
+ file_env MYSQL_DATABASE
+ local var=MYSQL_DATABASE
+ local fileVar=MYSQL_DATABASE_FILE
+ local def=
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_DATABASE=
+ MYSQL_DATABASE=
+ unset MYSQL_DATABASE_FILE
+ file_env MYSQL_USER
+ local var=MYSQL_USER
+ local fileVar=MYSQL_USER_FILE
+ local def=
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_USER=
+ MYSQL_USER=
+ unset MYSQL_USER_FILE
+ file_env MYSQL_PASSWORD
+ local var=MYSQL_PASSWORD
+ local fileVar=MYSQL_PASSWORD_FILE
+ local def=
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_PASSWORD=
+ MYSQL_PASSWORD=
+ unset MYSQL_PASSWORD_FILE
+ file_env MYSQL_ROOT_PASSWORD
+ local var=MYSQL_ROOT_PASSWORD
+ local fileVar=MYSQL_ROOT_PASSWORD_FILE
+ local def=
+ '[' '' ']'
+ local val=
+ '[' '' ']'
+ '[' '' ']'
+ export MYSQL_ROOT_PASSWORD=
+ MYSQL_ROOT_PASSWORD=
+ unset MYSQL_ROOT_PASSWORD_FILE
+ declare -g DATABASE_ALREADY_EXISTS
+ '[' -d /var/lib/mysql//mysql ']'
+ docker_create_db_directories
+ local user
++ id -u
+ user=999
+ mkdir -p /var/lib/mysql/
+ '[' 999 = 0 ']'
++ id -u
+ '[' 999 = 0 ']'
+ '[' -z '' ']'
+ docker_verify_minimum_env
+ '[' -z '' -a -z '' -a -z 1 ']'
+ '[' '' = root ']'
+ '[' -n '' ']'
+ '[' -z '' ']'
+ '[' -n '' ']'
+ ls /docker-entrypoint-initdb.d/
+ docker_init_database_dir mysqld
+ mysql_note 'Initializing database files'
+ mysql_log Note 'Initializing database files'
+ local type=Note
+ shift
+ local 'text=Initializing database files'
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
+ dt='2022-05-27 21:55:49+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:55:49+00:00' Note 'Initializing database files'
+ mysqld --initialize-insecure --default-time-zone=SYSTEM
2022-05-27 21:55:49+00:00 [Note] [Entrypoint]: Initializing database files
2022-05-27T21:55:55.902074Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2022-05-27T21:55:56.037090Z 0 [Warning] InnoDB: New log files created, LSN=45790
2022-05-27T21:55:56.060432Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2022-05-27T21:55:56.116448Z 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: c911c1b7-de07-11ec-9b25-0242ac110002.
2022-05-27T21:55:56.117956Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2022-05-27T21:55:56.524786Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T21:55:56.524799Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T21:55:56.525179Z 0 [Warning] CA certificate ca.pem is self signed.
2022-05-27T21:55:56.657163Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
+ mysql_note 'Database files initialized'
+ mysql_log Note 'Database files initialized'
+ local type=Note
+ shift
+ local 'text=Database files initialized'
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
2022-05-27 21:55:59+00:00 [Note] [Entrypoint]: Database files initialized
+ dt='2022-05-27 21:55:59+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:55:59+00:00' Note 'Database files initialized'
+ mysql_note 'Starting temporary server'
+ mysql_log Note 'Starting temporary server'
+ local type=Note
+ shift
+ local 'text=Starting temporary server'
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
2022-05-27 21:55:59+00:00 [Note] [Entrypoint]: Starting temporary server
+ dt='2022-05-27 21:55:59+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:55:59+00:00' Note 'Starting temporary server'
+ docker_temp_server_start mysqld
+ '[' 5.7 = 5.7 ']'
+ mysql_note 'Waiting for server startup'
+ mysql_log Note 'Waiting for server startup'
+ local type=Note
+ shift
+ local 'text=Waiting for server startup'
+ mysqld --skip-networking --default-time-zone=SYSTEM --socket=/var/run/mysqld/mysqld.sock
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
+ dt='2022-05-27 21:55:59+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:55:59+00:00' Note 'Waiting for server startup'
2022-05-27 21:55:59+00:00 [Note] [Entrypoint]: Waiting for server startup
+ local i
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ sleep 1
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ sleep 1
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ sleep 1
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ sleep 1
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ sleep 1
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ sleep 1
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ sleep 1
2022-05-27T21:56:06.596425Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2022-05-27T21:56:06.598279Z 0 [Note] mysqld (mysqld 5.7.38) starting as process 77 ...
2022-05-27T21:56:06.603795Z 0 [Note] InnoDB: PUNCH HOLE support available
2022-05-27T21:56:06.603825Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2022-05-27T21:56:06.603828Z 0 [Note] InnoDB: Uses event mutexes
2022-05-27T21:56:06.603830Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2022-05-27T21:56:06.603832Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-05-27T21:56:06.603833Z 0 [Note] InnoDB: Using Linux native AIO
2022-05-27T21:56:06.604052Z 0 [Note] InnoDB: Number of pools: 1
2022-05-27T21:56:06.604150Z 0 [Note] InnoDB: Using CPU crc32 instructions
2022-05-27T21:56:06.605675Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2022-05-27T21:56:06.614045Z 0 [Note] InnoDB: Completed initialization of buffer pool
2022-05-27T21:56:06.616494Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2022-05-27T21:56:06.632121Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2022-05-27T21:56:06.641813Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-05-27T21:56:06.641885Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-05-27T21:56:06.655601Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-05-27T21:56:06.656282Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2022-05-27T21:56:06.656292Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2022-05-27T21:56:06.656712Z 0 [Note] InnoDB: Waiting for purge to start
2022-05-27T21:56:06.706873Z 0 [Note] InnoDB: 5.7.38 started; log sequence number 2749976
2022-05-27T21:56:06.707033Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2022-05-27T21:56:06.707140Z 0 [Note] Plugin 'FEDERATED' is disabled.
2022-05-27T21:56:06.711911Z 0 [Note] InnoDB: Buffer pool(s) load completed at 220527 21:56:06
2022-05-27T21:56:06.713782Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2022-05-27T21:56:06.713791Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2022-05-27T21:56:06.713793Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T21:56:06.713794Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher.
2022-05-27T21:56:06.714228Z 0 [Warning] CA certificate ca.pem is self signed.
2022-05-27T21:56:06.714250Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2022-05-27T21:56:06.715851Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2022-05-27T21:56:06.736498Z 0 [Note] Event Scheduler: Loaded 0 events
2022-05-27T21:56:06.736628Z 0 [Note] mysqld: ready for connections.
Version: '5.7.38'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server (GPL)
+ for i in {30..0}
+ extraArgs=()
+ '[' -z '' ']'
+ extraArgs+=('--dont-use-mysql-root-password')
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ break
+ '[' 23 = 0 ']'
+ mysql_note 'Temporary server started.'
+ mysql_log Note 'Temporary server started.'
+ local type=Note
+ shift
+ local 'text=Temporary server started.'
+ '[' 1 -eq 0 ']'
+ local dt
++ date --rfc-3339=seconds
+ dt='2022-05-27 21:56:07+00:00'
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-05-27 21:56:07+00:00' Note 'Temporary server started.'
2022-05-27 21:56:07+00:00 [Note] [Entrypoint]: Temporary server started.
+ mysql_socket_fix
+ local defaultSocket
++ mysql_get_config socket mysqld --no-defaults
++ local conf=socket
++ shift
++ mysqld --no-defaults --verbose --help --log-bin-index=/tmp/tmp.z8ILnx7S1C
++ awk -v conf=socket '$1 == conf && /^[^ \t]/ { sub(/^[^ \t]+[ \t]+/, ""); print; exit }'
+ defaultSocket=/var/run/mysqld/mysqld.sock
+ '[' /var/run/mysqld/mysqld.sock '!=' /var/run/mysqld/mysqld.sock ']'
+ docker_setup_db
+ '[' -z '' ']'
+ mysql_tzinfo_to_sql /usr/share/zoneinfo
+ sed 's/Local time zone must be set--see zic manual page/FCTY/'
+ docker_process_sql --dont-use-mysql-root-password --database=mysql
+ passfileArgs=()
+ '[' --dont-use-mysql-root-password = --dont-use-mysql-root-password ']'
+ passfileArgs+=("$1")
+ shift
+ '[' -n '' ']'
+ mysql --defaults-extra-file=/dev/fd/63 --protocol=socket -uroot -hlocalhost --socket=/var/run/mysqld/mysqld.sock --comments --database=mysql
++ _mysql_passfile --dont-use-mysql-root-password
++ '[' --dont-use-mysql-root-password '!=' --dont-use-mysql-root-password ']'
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)

I have now discovered that it is actually a memory issue and the process is killed by OOMkiller. Watching with while true ; do docker top priceless_chaplygin axk comm o pid,pcpu,pmem,rss,args ; sleep 0.2 ; done

this command quickly consumes most of my 16GB memory: mysqld --verbose --help --log-bin-index=/tmp/tmp.bHB5qiQI0X. Memory balloons up and then dies down again during script execution.

Here are the last readings of the output:

PID                 %CPU                %MEM                RSS                 COMMAND
38218               0.0                 0.0                 2276                /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld
41844               91.3                85.2                13667636            mysqld --skip-networking --default-time-zone=SYSTEM --socket=/var/run/mysqld/mysqld.sock
42298               0.0                 0.0                 688                 sleep 1
PID                 %CPU                %MEM                RSS                 COMMAND
38218               0.0                 0.0                 2276                /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld
41844               95.3                85.3                13674808            mysqld --skip-networking --default-time-zone=SYSTEM --socket=/var/run/mysqld/mysqld.sock
42298               0.0                 0.0                 688                 sleep 1
PID                 %CPU                %MEM                RSS                 COMMAND
38218               0.0                 0.0                 2280                /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld
41844               99.3                85.3                13681412            mysqld --skip-networking --default-time-zone=SYSTEM --socket=/var/run/mysqld/mysqld.sock
42371               0.0                 0.0                 684                 sleep 1
PID                 %CPU                %MEM                RSS                 COMMAND
38218               0.0                 0.0                 2280                /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld
41844               103                 85.5                13708304            mysqld --skip-networking --default-time-zone=SYSTEM --socket=/var/run/mysqld/mysqld.sock
42371               0.0                 0.0                 684                 sleep 1
PID                 %CPU                %MEM                RSS                 COMMAND
38218               0.0                 0.0                 2280                /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld
41844               92.5                85.7                13739632            mysqld --skip-networking --default-time-zone=SYSTEM --socket=/var/run/mysqld/mysqld.sock
42371               0.0                 0.0                 684                 sleep 1
PID                 %CPU                %MEM                RSS                 COMMAND
38218               0.0                 0.0                 2280                /bin/bash /usr/local/bin/docker-entrypoint.sh mysqld
41844               95.8                85.4                13691280            mysqld --skip-networking --default-time-zone=SYSTEM --socket=/var/run/mysqld/mysqld.sock
42371               0.0                 0.0                 684                 sleep 1

Weirdly enough, when commenting out mysql_socket_fix calls, the memory ballooning still happens, but it is not killed and completes correctly. Note that the newest script mounted into the 5.7.36 mysql image also crashes.

BTW is it possible that you are on MacOS? I'm on Fedora 35 with Kernel 5.17.9-200.fc35.x86_64

tianon commented 2 years ago

From your ps output, it's the temporary mysqld server, not the --verbose --help that's eating all memory and dying. :grimacing:

We typically use pure Linux (specifically Debian with a 5.x kernel).

From the output you've shared, the place the server is dying is in the following block:

https://github.com/docker-library/mysql/blob/32aecb725b28afa043a5e879977a7947dfb64c14/5.7/docker-entrypoint.sh#L127-L138

So it starts mysqld in the background, then loops to wait for it to be started and working -- what I'm not clear on is why it might be ballooning there with nothing but repeated attempts to SELECT 1 (which are apparently failing in some way) -- it would probably be useful to remove &> /dev/null there and see what error those mysql invocations are getting.

Another thing to try would be attaching strace in another terminal to the mysqld instance once it's started to see if maybe there's some repeated failure there that could give a clue as to why it's ballooning.

(I think the fact that commenting out mysql_socket_fix makes it work is a red herring and there's gotta be something deeper going on here, especially since from the output you shared, that function is literally doing nothing :grimacing:)

yosifkit commented 2 years ago

It sounds like a duplicate of https://github.com/docker-library/mysql/issues/840 and so likely caused by https://github.com/containerd/containerd/issues/6707

akors commented 2 years ago

It sounds like a duplicate of https://github.com/docker-library/mysql/issues/840 and so likely caused by https://github.com/containerd/containerd/issues/6707

Thanks for this. You are probably right, because the LimitNOFILE workaround from that containerd issue also works for me. I'm also on Fedora 35 just like the commenters there.

tianon commented 2 years ago

Nice, glad we got it figured out! :+1:

(Going to close as I don't think there's anything more we can do here :see_no_evil:)