Mysql: MySQL Restarts

[seangerhardt-wf]

Problem:

MySQL is shutting down after startup - even after mysqld reports "ready for connections". I'm using the publicly available mysql image. I've tried both 5.6 and 5.7.

The logs don't include any errors that would indicate a restart would happen. After the one restart, the database appears to work fine, with the port specified.

On the first startup, it reports port 0. On the second startup, it reports the custom port I specify in the docker command (--port=3307).

Expected Behavior

MySQL starts up once with the port specified.

Config

docker-compose entry:

  database:
    image: mysql:5.7
    environment:
      - MYSQL_DATABASE=database
      - MYSQL_ROOT_PASSWORD=Fake
    command:
      - --port=3307
      - --sql-mode=NO_ENGINE_SUBSTITUTION
      - --max_allowed_packet=16M

Logs

Initializing database
2016-12-15 17:29:09 0 [Note] Ignoring --secure-file-priv value as server is running with --bootstrap.
2016-12-15 17:29:09 0 [Note] /usr/sbin/mysqld (mysqld 5.6.35) starting as process 37 ...
2016-12-15 17:29:09 37 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-12-15 17:29:09 37 [Note] InnoDB: The InnoDB memory heap is disabled
2016-12-15 17:29:09 37 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-12-15 17:29:09 37 [Note] InnoDB: Memory barrier is not used
2016-12-15 17:29:09 37 [Note] InnoDB: Compressed tables use zlib 1.2.8

2016-12-15 17:29:09 37 [Note] InnoDB: Using Linux native AIO
2016-12-15 17:29:09 37 [Note] InnoDB: Using CPU crc32 instructions
2016-12-15 17:29:09 37 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2016-12-15 17:29:09 37 [Note] InnoDB: Completed initialization of buffer pool
2016-12-15 17:29:09 37 [Note] InnoDB: The first specified data file ./ibdata1 did not exist: a new database to be created!
2016-12-15 17:29:09 37 [Note] InnoDB: Setting file ./ibdata1 size to 12 MB
2016-12-15 17:29:09 37 [Note] InnoDB: Database physically writes the file full: wait...
2016-12-15 17:29:09 37 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
2016-12-15 17:29:09 37 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
2016-12-15 17:29:09 37 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2016-12-15 17:29:09 37 [Warning] InnoDB: New log files created, LSN=45781
2016-12-15 17:29:09 37 [Note] InnoDB: Doublewrite buffer not found: creating new
2016-12-15 17:29:09 37 [Note] InnoDB: Doublewrite buffer created
2016-12-15 17:29:09 37 [Note] InnoDB: 128 rollback segment(s) are active.
2016-12-15 17:29:09 37 [Warning] InnoDB: Creating foreign key constraint system tables.
2016-12-15 17:29:09 37 [Note] InnoDB: Foreign key constraint system tables created
2016-12-15 17:29:09 37 [Note] InnoDB: Creating tablespace and datafile system tables.
2016-12-15 17:29:09 37 [Note] InnoDB: Tablespace and datafile system tables created.
2016-12-15 17:29:09 37 [Note] InnoDB: Waiting for purge to start

2016-12-15 17:29:09 37 [Note] InnoDB: 5.6.35 started; log sequence number 0

2016-12-15 17:29:10 37 [Note] Binlog end
2016-12-15 17:29:10 37 [Note] InnoDB: FTS optimize thread exiting.
2016-12-15 17:29:10 37 [Note] InnoDB: Starting shutdown...

2016-12-15 17:29:12 37 [Note] InnoDB: Shutdown completed; log sequence number 1625977




2016-12-15 17:29:12 0 [Note] Ignoring --secure-file-priv value as server is running with --bootstrap.
2016-12-15 17:29:12 0 [Note] /usr/sbin/mysqld (mysqld 5.6.35) starting as process 60 ...

2016-12-15 17:29:12 60 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-12-15 17:29:12 60 [Note] InnoDB: The InnoDB memory heap is disabled
2016-12-15 17:29:12 60 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-12-15 17:29:12 60 [Note] InnoDB: Memory barrier is not used

2016-12-15 17:29:12 60 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-12-15 17:29:12 60 [Note] InnoDB: Using Linux native AIO
2016-12-15 17:29:12 60 [Note] InnoDB: Using CPU crc32 instructions

2016-12-15 17:29:12 60 [Note] InnoDB: Initializing buffer pool, size = 128.0M

2016-12-15 17:29:12 60 [Note] InnoDB: Completed initialization of buffer pool

2016-12-15 17:29:12 60 [Note] InnoDB: Highest supported file format is Barracuda.

2016-12-15 17:29:12 60 [Note] InnoDB: 128 rollback segment(s) are active.
2016-12-15 17:29:12 60 [Note] InnoDB: Waiting for purge to start

2016-12-15 17:29:12 60 [Note] InnoDB: 5.6.35 started; log sequence number 1625977

2016-12-15 17:29:12 60 [Note] Binlog end
2016-12-15 17:29:12 60 [Note] InnoDB: FTS optimize thread exiting.
2016-12-15 17:29:12 60 [Note] InnoDB: Starting shutdown...

2016-12-15 17:29:14 60 [Note] InnoDB: Shutdown completed; log sequence number 1625987

Note: new default config file not created.
Please make sure your config file is current

WARNING: Default config file /etc/mysql/my.cnf exists on the system
This file will be read by default by the MySQL server
If you do not want to use this, either remove it, or use the
--defaults-file argument to mysqld_safe when starting the server


Database initialized

MySQL init process in progress...

2016-12-15 17:29:14 0 [Note] mysqld (mysqld 5.6.35) starting as process 83 ...
2016-12-15 17:29:14 83 [Note] Plugin 'FEDERATED' is disabled.
2016-12-15 17:29:14 83 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-12-15 17:29:14 83 [Note] InnoDB: The InnoDB memory heap is disabled
2016-12-15 17:29:14 83 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-12-15 17:29:14 83 [Note] InnoDB: Memory barrier is not used

2016-12-15 17:29:14 83 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-12-15 17:29:14 83 [Note] InnoDB: Using Linux native AIO
2016-12-15 17:29:14 83 [Note] InnoDB: Using CPU crc32 instructions
2016-12-15 17:29:14 83 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2016-12-15 17:29:14 83 [Note] InnoDB: Completed initialization of buffer pool
2016-12-15 17:29:14 83 [Note] InnoDB: Highest supported file format is Barracuda.

2016-12-15 17:29:14 83 [Note] InnoDB: 128 rollback segment(s) are active.
2016-12-15 17:29:14 83 [Note] InnoDB: Waiting for purge to start

2016-12-15 17:29:14 83 [Note] InnoDB: 5.6.35 started; log sequence number 1625987
2016-12-15 17:29:14 83 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been ad-c2eb-11e6-89e9-0242ac120005.
2016-12-15 17:29:14 83 [Warning] 'user' entry 'root@blahblahfake' ignored in --skip-name-resolve mode.
2016-12-15 17:29:14 83 [Warning] 'user' entry '@blahblahfake' ignored in --skip-name-resolve mode.
2016-12-15 17:29:14 83 [Warning] 'proxies_priv' entry '@ root@blahblahfake' ignored in --skip-name-resolve mode.
2016-12-15 17:29:14 83 [Note] Event Scheduler: Loaded 0 events
2016-12-15 17:29:14 83 [Note] mysqld: ready for connections.
Version: '5.6.35'  socket: '/var/run/mysqld/mysqld.sock'  port: 0  MySQL Community Server (GPL)

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.

2016-12-15 17:29:16 83 [Warning] 'proxies_priv' entry '@ root@blahblahfake' ignored in --skip-name-resolve mode.
Warning: Using a password on the command line interface can be insecure.

2016-12-15 17:29:16 83 [Note] mysqld: Normal shutdown

2016-12-15 17:29:16 83 [Note] Giving 0 client threads a chance to die gracefully
2016-12-15 17:29:16 83 [Note] Event Scheduler: Purging the queue. 0 events
2016-12-15 17:29:16 83 [Note] Shutting down slave threads

2016-12-15 17:29:16 83 [Note] Forcefully disconnecting 0 remaining clients
2016-12-15 17:29:16 83 [Note] Binlog end
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'partition'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_METRICS'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'

2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_CMPMEM'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_CMP'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'

2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_LOCKS'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'INNODB_TRX'
2016-12-15 17:29:16 83 [Note] Shutting down plugin 'InnoDB'
2016-12-15 17:29:16 83 [Note] InnoDB: FTS optimize thread exiting.

2016-12-15 17:29:16 83 [Note] InnoDB: Starting shutdown...

2016-12-15 17:29:18 83 [Note] InnoDB: Shutdown completed; log sequence number 1625997
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'BLACKHOLE'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'ARCHIVE'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'MRG_MYISAM'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'MyISAM'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'CSV'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'MEMORY'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'sha256_password'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'mysql_old_password'

2016-12-15 17:29:18 83 [Note] Shutting down plugin 'mysql_native_password'
2016-12-15 17:29:18 83 [Note] Shutting down plugin 'binlog'
2016-12-15 17:29:18 83 [Note] mysqld: Shutdown complete



MySQL init process done. Ready for start up.


2016-12-15 17:29:18 0 [Note] mysqld (mysqld 5.6.35) starting as process 1 ...
2016-12-15 17:29:18 1 [Note] Plugin 'FEDERATED' is disabled.
2016-12-15 17:29:18 1 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-12-15 17:29:18 1 [Note] InnoDB: The InnoDB memory heap is disabled
2016-12-15 17:29:18 1 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-12-15 17:29:18 1 [Note] InnoDB: Memory barrier is not used
2016-12-15 17:29:18 1 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-12-15 17:29:18 1 [Note] InnoDB: Using Linux native AIO
2016-12-15 17:29:18 1 [Note] InnoDB: Using CPU crc32 instructions

2016-12-15 17:29:18 1 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2016-12-15 17:29:18 1 [Note] InnoDB: Completed initialization of buffer pool
2016-12-15 17:29:18 1 [Note] InnoDB: Highest supported file format is Barracuda.

2016-12-15 17:29:18 1 [Note] InnoDB: 128 rollback segment(s) are active.
2016-12-15 17:29:18 1 [Note] InnoDB: Waiting for purge to start

2016-12-15 17:29:18 1 [Note] InnoDB: 5.6.35 started; log sequence number 1625997
2016-12-15 17:29:18 1 [Note] Server hostname (bind-address): '*'; port: 3307
2016-12-15 17:29:18 1 [Note] IPv6 is available.
2016-12-15 17:29:18 1 [Note]   - '::' resolves to '::';
2016-12-15 17:29:18 1 [Note] Server socket created on IP: '::'.
2016-12-15 17:29:18 1 [Warning] 'proxies_priv' entry '@ root@blahblahfake' ignored in --skip-name-resolve mode.
2016-12-15 17:29:18 1 [Note] Event Scheduler: Loaded 0 events
2016-12-15 17:29:18 1 [Note] mysqld: ready for connections.

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

[ltangvald]

This is intended behavior: On the first run, the database starts up once in order to setup specified user credentials, run included init scripts etc. This run is done with --skip-networking because the database is not ready for use yet, hence the log reporting port 0 (main issue here is that this isn't really clear from the logs). After database init is done the server is restarted, and this second run is the "main" one.

[ltangvald]

Basically, everything above «MySQL init process done. Ready for start up.» is part of the initialization process.

[seangerhardt-wf]

@ltangvald Thanks for the explanation. As you said, the main issue is that this really isn't clear from the logs. I understand it now, so I'll wait until the appropriate time to connect to the database, but it may not be clear for others.

[tianon]

Closing given that this is working as designed. Hopefully this issue serves as a good reference point for future travelers. :+1: